Log additional NuPlayer information in bug reports
This change adds more logging from NuPlayer when obtaining
a bug report. NuPlayer's renderer will print whether it has occupied
the wake lock and for how much time. In addition, handlers attached
to the player's looper will also log if they are currently executing
a message (at the time of the bug report).
The above logs will help detect if the NuPlayer's wake lock is kept
acquired because the player looper is blocked on a specific handler.
Test: manual on device test, grabbed a bug-report while playing media
Change-Id: I3e91da9ea45a5fe270a0866054f695f5e844e8c7
Bug: 265531109
diff --git a/media/libmediaplayerservice/nuplayer/AWakeLock.cpp b/media/libmediaplayerservice/nuplayer/AWakeLock.cpp
index 25a8ae4..366956c 100644
--- a/media/libmediaplayerservice/nuplayer/AWakeLock.cpp
+++ b/media/libmediaplayerservice/nuplayer/AWakeLock.cpp
@@ -67,6 +67,7 @@
if (status.isOk()) {
mWakeLockToken = binder;
mWakeLockCount++;
+ ALOGI("AwakeLock acquired");
return true;
}
}
@@ -93,6 +94,7 @@
IPCThreadState::self()->restoreCallingIdentity(token);
}
mWakeLockToken.clear();
+ ALOGI("AwakeLock released");
}
}
diff --git a/media/libmediaplayerservice/nuplayer/NuPlayer.cpp b/media/libmediaplayerservice/nuplayer/NuPlayer.cpp
index 5c6c5fd..e5f2b2b 100644
--- a/media/libmediaplayerservice/nuplayer/NuPlayer.cpp
+++ b/media/libmediaplayerservice/nuplayer/NuPlayer.cpp
@@ -3032,6 +3032,16 @@
}
}
+ void NuPlayer::dump(AString& logString) {
+ logString.append("renderer(");
+ if (mRenderer != nullptr) {
+ mRenderer->dump(logString);
+ } else {
+ logString.append("null");
+ }
+ logString.append(")");
+ }
+
// Modular DRM begin
status_t NuPlayer::prepareDrm(const uint8_t uuid[16], const Vector<uint8_t> &drmSessionId)
{
diff --git a/media/libmediaplayerservice/nuplayer/NuPlayerDriver.cpp b/media/libmediaplayerservice/nuplayer/NuPlayerDriver.cpp
index ceea2f4..c6595ba 100644
--- a/media/libmediaplayerservice/nuplayer/NuPlayerDriver.cpp
+++ b/media/libmediaplayerservice/nuplayer/NuPlayerDriver.cpp
@@ -969,13 +969,16 @@
}
if (locked) {
- snprintf(buf, sizeof(buf), " state(%d), atEOS(%d), looping(%d), autoLoop(%d)\n",
+ snprintf(buf, sizeof(buf), " state(%d), atEOS(%d), looping(%d), autoLoop(%d), ",
mState, mAtEOS, mLooping, mAutoLoop);
+ logString.append(buf);
+ mPlayer->dump(logString);
+ logString.append("\n");
mLock.unlock();
} else {
snprintf(buf, sizeof(buf), " NPD(%p) lock is taken\n", this);
+ logString.append(buf);
}
- logString.append(buf);
for (size_t i = 0; i < trackStats.size(); ++i) {
const sp<AMessage> &stats = trackStats.itemAt(i);
diff --git a/media/libmediaplayerservice/nuplayer/NuPlayerRenderer.cpp b/media/libmediaplayerservice/nuplayer/NuPlayerRenderer.cpp
index 0382df3..9dae16e 100644
--- a/media/libmediaplayerservice/nuplayer/NuPlayerRenderer.cpp
+++ b/media/libmediaplayerservice/nuplayer/NuPlayerRenderer.cpp
@@ -478,6 +478,23 @@
msg->postAndAwaitResponse(&response);
}
+void NuPlayer::Renderer::dump(AString& logString) {
+ Mutex::Autolock autoLock(mLock);
+ logString.append("paused(");
+ logString.append(mPaused);
+ logString.append("), offloading(");
+ logString.append(offloadingAudio());
+ logString.append("), wakelock(acquired=");
+ mWakelockAcquireEvent.dump(logString);
+ logString.append(", timeout=");
+ mWakelockTimeoutEvent.dump(logString);
+ logString.append(", release=");
+ mWakelockReleaseEvent.dump(logString);
+ logString.append(", cancel=");
+ mWakelockCancelEvent.dump(logString);
+ logString.append(")");
+}
+
void NuPlayer::Renderer::changeAudioFormat(
const sp<AMessage> &format,
bool offloadOnly,
@@ -792,6 +809,10 @@
{
int32_t generation;
CHECK(msg->findInt32("drainGeneration", &generation));
+ mWakelockTimeoutEvent.updateValues(
+ uptimeMillis(),
+ generation,
+ mAudioOffloadPauseTimeoutGeneration);
if (generation != mAudioOffloadPauseTimeoutGeneration) {
break;
}
@@ -807,6 +828,10 @@
{
int32_t generation;
CHECK(msg->findInt32("drainGeneration", &generation));
+ mWakelockReleaseEvent.updateValues(
+ uptimeMillis(),
+ generation,
+ mAudioOffloadPauseTimeoutGeneration);
if (generation != mAudioOffloadPauseTimeoutGeneration) {
break;
}
@@ -1914,6 +1939,9 @@
void NuPlayer::Renderer::startAudioOffloadPauseTimeout() {
if (offloadingAudio()) {
mWakeLock->acquire();
+ mWakelockAcquireEvent.updateValues(uptimeMillis(),
+ mAudioOffloadPauseTimeoutGeneration,
+ mAudioOffloadPauseTimeoutGeneration);
sp<AMessage> msg = new AMessage(kWhatAudioOffloadPauseTimeout, this);
msg->setInt32("drainGeneration", mAudioOffloadPauseTimeoutGeneration);
msg->post(kOffloadPauseMaxUs);
@@ -1930,6 +1958,9 @@
// Note: The acquired wakelock prevents the device from suspending
// immediately after offload pause (in case a resume happens shortly thereafter).
mWakeLock->release(true);
+ mWakelockCancelEvent.updateValues(uptimeMillis(),
+ mAudioOffloadPauseTimeoutGeneration,
+ mAudioOffloadPauseTimeoutGeneration);
++mAudioOffloadPauseTimeoutGeneration;
}
@@ -2165,4 +2196,14 @@
notify->post();
}
+void NuPlayer::Renderer::WakeLockEvent::dump(AString& logString) {
+ logString.append("[");
+ logString.append(mTimeMs);
+ logString.append(",");
+ logString.append(mEventTimeoutGeneration);
+ logString.append(",");
+ logString.append(mRendererTimeoutGeneration);
+ logString.append("]");
+}
+
} // namespace android
diff --git a/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayer.h b/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayer.h
index adb7075..7dc97ea 100644
--- a/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayer.h
+++ b/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayer.h
@@ -104,6 +104,8 @@
void setTargetBitrate(int bitrate /* bps */);
+ void dump(AString& logString);
+
protected:
virtual ~NuPlayer();
diff --git a/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayerRenderer.h b/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayerRenderer.h
index 3640678..2ca040f 100644
--- a/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayerRenderer.h
+++ b/media/libmediaplayerservice/nuplayer/include/nuplayer/NuPlayerRenderer.h
@@ -83,6 +83,8 @@
bool isStreaming);
void closeAudioSink();
+ void dump(AString& logString);
+
// re-open audio sink after all pending audio buffers played.
void changeAudioFormat(
const sp<AMessage> &format,
@@ -235,6 +237,32 @@
status_t getCurrentPositionFromAnchor(
int64_t *mediaUs, int64_t nowUs, bool allowPastQueuedVideo = false);
+ struct WakeLockEvent{
+ int64_t mTimeMs;
+ int32_t mEventTimeoutGeneration;
+ int32_t mRendererTimeoutGeneration;
+
+ WakeLockEvent():
+ mTimeMs(0),
+ mEventTimeoutGeneration(0),
+ mRendererTimeoutGeneration(0) {}
+
+ void updateValues(int64_t timeMs,
+ int32_t eventGeneration,
+ int32_t rendererGeneration) {
+ mTimeMs = timeMs;
+ mEventTimeoutGeneration = eventGeneration;
+ mRendererTimeoutGeneration = rendererGeneration;
+ }
+
+ void dump(AString& logString);
+ };
+
+ WakeLockEvent mWakelockAcquireEvent;
+ WakeLockEvent mWakelockTimeoutEvent;
+ WakeLockEvent mWakelockReleaseEvent;
+ WakeLockEvent mWakelockCancelEvent;
+
void notifyEOSCallback();
size_t fillAudioBuffer(void *buffer, size_t size);
diff --git a/media/module/foundation/AHandler.cpp b/media/module/foundation/AHandler.cpp
index 7dbbe54..d8b0aaf 100644
--- a/media/module/foundation/AHandler.cpp
+++ b/media/module/foundation/AHandler.cpp
@@ -24,8 +24,10 @@
namespace android {
void AHandler::deliverMessage(const sp<AMessage> &msg) {
+ setDeliveryStatus(true, msg->what(), ALooper::GetNowUs());
onMessageReceived(msg);
mMessageCounter++;
+ setDeliveryStatus(false, 0, 0);
if (mVerboseStats) {
uint32_t what = msg->what();
@@ -38,4 +40,19 @@
}
}
+void AHandler::setDeliveryStatus(bool delivering, uint32_t what, int64_t startUs) {
+ AutoMutex autoLock(mLock);
+ mDeliveringMessage = delivering;
+ mCurrentMessageWhat = what;
+ mCurrentMessageStartTimeUs = startUs;
+}
+
+void AHandler::getDeliveryStatus(bool& delivering, uint32_t& what, int64_t& durationUs) {
+ AutoMutex autoLock(mLock);
+ delivering = mDeliveringMessage;
+ what = mCurrentMessageWhat;
+ durationUs = mCurrentMessageStartTimeUs == 0 ?
+ 0 : ALooper::GetNowUs() - mCurrentMessageStartTimeUs;
+}
+
} // namespace android
diff --git a/media/module/foundation/ALooperRoster.cpp b/media/module/foundation/ALooperRoster.cpp
index 4334f1e..5625c7f 100644
--- a/media/module/foundation/ALooperRoster.cpp
+++ b/media/module/foundation/ALooperRoster.cpp
@@ -143,8 +143,20 @@
s.append(looper->getName());
sp<AHandler> handler = info.mHandler.promote();
if (handler != NULL) {
+ bool deliveringMessages;
+ uint32_t currentMessageWhat;
+ int64_t currentDeliveryDurationUs;
+ handler->getDeliveryStatus(deliveringMessages,
+ currentMessageWhat,
+ currentDeliveryDurationUs);
handler->mVerboseStats = verboseStats;
- s.appendFormat(": %" PRIu64 " messages processed", handler->mMessageCounter);
+ s.appendFormat(": %" PRIu64 " messages processed, delivering "
+ "%d, current msg %" PRIu32 ", current msg "
+ "durationUs %" PRIu64 "",
+ handler->mMessageCounter,
+ deliveringMessages,
+ currentMessageWhat,
+ currentDeliveryDurationUs);
if (verboseStats) {
for (size_t j = 0; j < handler->mMessages.size(); j++) {
char fourcc[15];
diff --git a/media/module/foundation/include/media/stagefright/foundation/AHandler.h b/media/module/foundation/include/media/stagefright/foundation/AHandler.h
index 337460a..c9e4f69 100644
--- a/media/module/foundation/include/media/stagefright/foundation/AHandler.h
+++ b/media/module/foundation/include/media/stagefright/foundation/AHandler.h
@@ -30,7 +30,10 @@
AHandler()
: mID(0),
mVerboseStats(false),
- mMessageCounter(0) {
+ mMessageCounter(0),
+ mDeliveringMessage(false),
+ mCurrentMessageWhat(0),
+ mCurrentMessageStartTimeUs(0){
}
ALooper::handler_id id() const {
@@ -69,8 +72,17 @@
uint64_t mMessageCounter;
KeyedVector<uint32_t, uint32_t> mMessages;
+ Mutex mLock;
+ bool mDeliveringMessage;
+ uint32_t mCurrentMessageWhat;
+ int64_t mCurrentMessageStartTimeUs;
+
void deliverMessage(const sp<AMessage> &msg);
+ void setDeliveryStatus(bool, uint32_t, int64_t);
+ void getDeliveryStatus(bool&, uint32_t&, int64_t&);
+
+
DISALLOW_EVIL_CONSTRUCTORS(AHandler);
};