commit 2148bf0e79c436b8764b9edc4c8f2730cce98a32
author Andy Hung <hunga@google.com> Mon Nov 28 19:01:02 2016 -0800
committer Andy Hung <hunga@google.com> Thu Dec 01 17:36:41 2016 -0800
tree 8d380e3f69e99d4ebf76c08c51a5833dc0eca2ff
parent b54cab90d4bf84745a57232080d72a50c3b731da

Log audio information to ensure complete delivery

Test: Audio playback
Bug: 30572472
Change-Id: Ibad6fc202692cd3480ae726627252afdead083f3

services/audioflinger/Threads.cpp

diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 1d7b946..d45cf21 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1602,6 +1602,7 @@
     dumpInternals(fd, args);
     dumpTracks(fd, args);
     dumpEffectChains(fd, args);
+    mLocalLog.dump(fd, args, "  " /* prefix */);
 }
 
 void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>& args __unused)
@@ -2072,6 +2073,10 @@
             chain->incActiveTrackCnt();
         }
 
+        char buffer[256];
+        track->dump(buffer, ARRAY_SIZE(buffer), false /* active */);
+        mLocalLog.log("addTrack_l    (%p) %s", track.get(), buffer + 4); // log for analysis
+
         status = NO_ERROR;
     }
 
@@ -2097,6 +2102,11 @@
 void AudioFlinger::PlaybackThread::removeTrack_l(const sp<Track>& track)
 {
     track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
+
+    char buffer[256];
+    track->dump(buffer, ARRAY_SIZE(buffer), false /* active */);
+    mLocalLog.log("removeTrack_l (%p) %s", track.get(), buffer + 4); // log for analysis
+
     mTracks.remove(track);
     deleteTrackName_l(track->name());
     // redundant as track is about to be destroyed, for dumpsys only
@@ -3264,6 +3274,10 @@
             }
             if (track->isTerminated()) {
                 removeTrack_l(track);
+            } else { // inactive but not terminated
+                char buffer[256];
+                track->dump(buffer, ARRAY_SIZE(buffer), false /* active */);
+                mLocalLog.log("removeTracks_l(%p) %s", track.get(), buffer + 4);
             }
         }
     }
@@ -3710,6 +3724,15 @@
         FastMixerStateQueue *sq = mFastMixer->sq();
         FastMixerState *state = sq->begin();
         if (!(state->mCommand & FastMixerState::IDLE)) {
+            // Report any frames trapped in the Monopipe
+            MonoPipe *monoPipe = (MonoPipe *)mPipeSink.get();
+            const long long pipeFrames = monoPipe->maxFrames() - monoPipe->availableToWrite();
+            mLocalLog.log("threadLoop_standby: framesWritten:%lld  suspendedFrames:%lld  "
+                    "monoPipeWritten:%lld  monoPipeLeft:%lld",
+                    (long long)mFramesWritten, (long long)mSuspendedFrames,
+                    (long long)mPipeSink->framesWritten(), pipeFrames);
+            mLocalLog.log("threadLoop_standby: %s", mTimestamp.toString().c_str());
+
             state->mCommand = FastMixerState::COLD_IDLE;
             state->mColdFutexAddr = &mFastMixerFutex;
             state->mColdGen++;