Log additional NuPlayer information in bug reports am: 9aacf19579

Original change: https://googleplex-android-review.googlesource.com/c/platform/frameworks/av/+/21920683

Change-Id: I29d6602d5ea2b72ce66474a60aea97c9987fc31b
Signed-off-by: Automerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>
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);
 };