commit 3051df27261e9952c0e642dec548515250e85f6a
author Glenn Kasten <gkasten@google.com> Tue Feb 12 12:12:42 2013 -0800
committer Glenn Kasten <gkasten@google.com> Tue Feb 12 12:40:18 2013 -0800
tree 848a1795333131b9fac0c7be0b791f7f69a330d4
parent 272ab546940054ad7991bef4b3a36f15175721cd

Temporary additional logging to investigate bug

The bug appears related to continuing to use an invalid buffer provider
in fast mixer after track destruction, so focus the added logs in that area.

Also includes a bug fix: was calling log in an unsafe place
near Threads.cpp AudioFlinger::PlaybackThread::createTrack_l line 1250.

Details:
 - include caller pid or client pid where appropriate
 - increase log buffer size

Bug: 6490974
Change-Id: I4c030f171343fe4b483eae0ddea4427118d8d4b1

services/audioflinger/Threads.cpp

diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index ba848d7..8cc5f6c 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1196,6 +1196,8 @@
 
     { // scope for mLock
         Mutex::Autolock _l(mLock);
+        mNBLogWriter->logf("createTrack_l isFast=%d caller=%d",
+                (*flags & IAudioFlinger::TRACK_FAST) != 0, IPCThreadState::self()->getCallingPid());
 
         // all tracks in same audio session must share the same routing strategy otherwise
         // conflicts will happen when tracks are moved from one output to another by audio policy
@@ -1249,7 +1251,6 @@
     if (status) {
         *status = lStatus;
     }
-    mNBLogWriter->logf("createTrack_l");
     return track;
 }
 
@@ -1317,7 +1318,8 @@
 // addTrack_l() must be called with ThreadBase::mLock held
 status_t AudioFlinger::PlaybackThread::addTrack_l(const sp<Track>& track)
 {
-    mNBLogWriter->logf("addTrack_l mName=%d", track->mName);
+    mNBLogWriter->logf("addTrack_l mName=%d mFastIndex=%d caller=%d", track->mName,
+            track->mFastIndex, IPCThreadState::self()->getCallingPid());
     status_t status = ALREADY_EXISTS;
 
     // set retry count for buffer fill
@@ -1351,7 +1353,9 @@
 // destroyTrack_l() must be called with ThreadBase::mLock held
 void AudioFlinger::PlaybackThread::destroyTrack_l(const sp<Track>& track)
 {
-    mNBLogWriter->logf("destroyTrack_l mName=%d", track->mName);
+    mNBLogWriter->logTimestamp();
+    mNBLogWriter->logf("destroyTrack_l mName=%d mFastIndex=%d mClientPid=%d", track->mName,
+            track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1);
     track->mState = TrackBase::TERMINATED;
     // active tracks are removed by threadLoop()
     if (mActiveTracks.indexOf(track) < 0) {
@@ -1361,7 +1365,9 @@
 
 void AudioFlinger::PlaybackThread::removeTrack_l(const sp<Track>& track)
 {
-    mNBLogWriter->logf("removeTrack_l mName=%d", track->mName);
+    mNBLogWriter->logTimestamp();
+    mNBLogWriter->logf("removeTrack_l mName=%d mFastIndex=%d clientPid=%d", track->mName,
+            track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1);
     track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
     mTracks.remove(track);
     deleteTrackName_l(track->name());
@@ -2870,7 +2876,9 @@
     if (CC_UNLIKELY(count)) {
         for (size_t i=0 ; i<count ; i++) {
             const sp<Track>& track = tracksToRemove->itemAt(i);
-            mNBLogWriter->logf("prepareTracks_l remove name=%u", track->name());
+            mNBLogWriter->logTimestamp();
+            mNBLogWriter->logf("prepareTracks_l remove name=%u mFastIndex=%d", track->name(),
+                    track->mFastIndex);
             mActiveTracks.remove(track);
             if (track->mainBuffer() != mMixBuffer) {
                 chain = getEffectChain_l(track->sessionId());