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
 - log mFastIndex when AudioMixer sees an invalid bufferProvider.
 - log both potentially modified and actually modified tracks in FastMixer.
 - fix benign bug where sq->end() was called more than once.
 - log StateQueue push() call and return.

Bug: 6490974
Change-Id: Iee7c8f40e20b6000cd8286c0ec6a14fff4a37af1

7 files changed, 71 insertions, 17 deletions

diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index c3f08f6..593f131 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -227,7 +227,7 @@ public:
     sp<NBLog::Writer>   newWriter_l(size_t size, const char *name);
     void                unregisterWriter(const sp<NBLog::Writer>& writer);
 private:
-    static const size_t kLogMemorySize = 10 * 1024;
+    static const size_t kLogMemorySize = 20 * 1024;
     sp<MemoryDealer>    mLogMemoryDealer;   // == 0 when NBLog is disabled
 public:
 
diff --git a/services/audioflinger/AudioMixer.cpp b/services/audioflinger/AudioMixer.cpp
index 08325ad..30d645c 100644
--- a/services/audioflinger/AudioMixer.cpp
+++ b/services/audioflinger/AudioMixer.cpp
@@ -209,6 +209,7 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
         t->mainBuffer = NULL;
         t->auxBuffer = NULL;
         t->downmixerBufferProvider = NULL;
+        t->fastIndex = -1;
 
         status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask);
         if (status == OK) {
@@ -455,6 +456,9 @@ void AudioMixer::setParameter(int name, int target, int param, void *value)
         //         for a specific track? or per mixer?
         /* case DOWNMIX_TYPE:
             break          */
+        case FAST_INDEX:
+            track.fastIndex = valueInt;
+            break;
         default:
             LOG_FATAL("bad param");
         }
@@ -1111,8 +1115,8 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts)
         t.buffer.frameCount = state->frameCount;
         int valid = t.bufferProvider->getValid();
         if (valid != AudioBufferProvider::kValid) {
-            ALOGE("invalid bufferProvider=%p name=%d frameCount=%d valid=%#x enabledTracks=%#x",
-                    t.bufferProvider, i, t.buffer.frameCount, valid, enabledTracks);
+            ALOGE("invalid bufferProvider=%p name=%d fastIndex=%d frameCount=%d valid=%#x enabledTracks=%#x",
+                    t.bufferProvider, i, t.fastIndex, t.buffer.frameCount, valid, enabledTracks);
             // expect to crash
         }
         t.bufferProvider->getNextBuffer(&t.buffer, pts);
diff --git a/services/audioflinger/AudioMixer.h b/services/audioflinger/AudioMixer.h
index fd21fda..f757351 100644
--- a/services/audioflinger/AudioMixer.h
+++ b/services/audioflinger/AudioMixer.h
@@ -76,6 +76,7 @@ public:
         MAIN_BUFFER     = 0x4002,
         AUX_BUFFER      = 0x4003,
         DOWNMIX_TYPE    = 0X4004,
+        FAST_INDEX      = 0x4005, // for debugging only
         // for target RESAMPLE
         SAMPLE_RATE     = 0x4100, // Configure sample rate conversion on this track name;
                                   // parameter 'value' is the new sample rate in Hz.
@@ -200,7 +201,8 @@ private:
 
         int32_t     sessionId;
 
-        int32_t     padding[2];
+        int32_t     fastIndex;
+        int32_t     padding[1];
 
         // 16-byte boundary
 
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index 80e37ca..b64c8fb 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -120,6 +120,7 @@ bool FastMixer::threadLoop()
         FastMixerState::Command command = next->mCommand;
         if (next != current) {
 
+            logWriter->logTimestamp();
             logWriter->log("next != current");
 
             // As soon as possible of learning of a new dump area, start using it
@@ -301,12 +302,19 @@ bool FastMixer::threadLoop()
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
                     ALOG_ASSERT(bufferProvider != NULL && fastTrackNames[i] == -1);
+                    if (bufferProvider == NULL ||
+                            bufferProvider->getValid() != AudioBufferProvider::kValid) {
+                        logWriter->logTimestamp();
+                        logWriter->logf("added invalid %#x", i);
+                    }
                     if (mixer != NULL) {
                         // calling getTrackName with default channel mask and a random invalid
                         //   sessionId (no effects here)
                         name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555);
                         ALOG_ASSERT(name >= 0);
                         fastTrackNames[i] = name;
+                        mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
+                                (void *) i);
                         mixer->setBufferProvider(name, bufferProvider);
                         mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER,
                                 (void *) mixBuffer);
@@ -322,22 +330,31 @@ bool FastMixer::threadLoop()
                     generations[i] = fastTrack->mGeneration;
                 }
 
-                // finally process modified tracks; these use the same slot
+                // finally process (potentially) modified tracks; these use the same slot
                 // but may have a different buffer provider or volume provider
                 unsigned modifiedTracks = currentTrackMask & previousTrackMask;
                 if (modifiedTracks) {
-                    logWriter->logf("modified %#x", modifiedTracks);
+                    logWriter->logf("pot. mod. %#x", modifiedTracks);
                 }
+                unsigned actuallyModifiedTracks = 0;
                 while (modifiedTracks != 0) {
                     i = __builtin_ctz(modifiedTracks);
                     modifiedTracks &= ~(1 << i);
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     if (fastTrack->mGeneration != generations[i]) {
+                        actuallyModifiedTracks |= 1 << i;
                         AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
                         ALOG_ASSERT(bufferProvider != NULL);
+                        if (bufferProvider == NULL ||
+                                bufferProvider->getValid() != AudioBufferProvider::kValid) {
+                            logWriter->logTimestamp();
+                            logWriter->logf("modified invalid %#x", i);
+                        }
                         if (mixer != NULL) {
                             name = fastTrackNames[i];
                             ALOG_ASSERT(name >= 0);
+                            mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX,
+                                    (void *) i);
                             mixer->setBufferProvider(name, bufferProvider);
                             if (fastTrack->mVolumeProvider == NULL) {
                                 mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0,
@@ -360,6 +377,9 @@ bool FastMixer::threadLoop()
                         generations[i] = fastTrack->mGeneration;
                     }
                 }
+                if (actuallyModifiedTracks) {
+                    logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
+                }
 
                 fastTracksGen = current->mFastTracksGen;
 
@@ -423,6 +443,12 @@ bool FastMixer::threadLoop()
                 }
                 ftDump->mUnderruns = underruns;
                 ftDump->mFramesReady = framesReady;
+                AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
+                if (bufferProvider == NULL ||
+                        bufferProvider->getValid() != AudioBufferProvider::kValid) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("mixing invalid %#x", i);
+                }
             }
 
             int64_t pts;
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index ba848d7..554532d 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1196,6 +1196,8 @@ sp<AudioFlinger::PlaybackThread::Track> AudioFlinger::PlaybackThread::createTrac
 
     { // 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 @@ Exit:
     if (status) {
         *status = lStatus;
     }
-    mNBLogWriter->logf("createTrack_l");
     return track;
 }
 
@@ -1317,7 +1318,8 @@ float AudioFlinger::PlaybackThread::streamVolume(audio_stream_type_t stream) con
 // 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 @@ status_t AudioFlinger::PlaybackThread::addTrack_l(const sp<Track>& track)
 // 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::destroyTrack_l(const sp<Track>& track)
 
 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());
@@ -2839,11 +2845,19 @@ track_is_ready: ;
             block = FastMixerStateQueue::BLOCK_UNTIL_ACKED;
             pauseAudioWatchdog = true;
         }
-        sq->end();
     }
     if (sq != NULL) {
+        unsigned trackMask = state->mTrackMask;
         sq->end(didModify);
+        if (didModify) {
+            mNBLogWriter->logTimestamp();
+            mNBLogWriter->logf("push trackMask=%#x block=%d", trackMask, block);
+        }
         sq->push(block);
+        if (didModify) {
+            mNBLogWriter->logTimestamp();
+            mNBLogWriter->log("pushed");
+        }
     }
 #ifdef AUDIO_WATCHDOG
     if (pauseAudioWatchdog && mAudioWatchdog != 0) {
@@ -2870,7 +2884,9 @@ track_is_ready: ;
     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());
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index fa1e336..8497788 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -315,7 +315,7 @@ protected:
                 // keyed by session ID, the second by type UUID timeLow field
                 KeyedVector< int, KeyedVector< int, sp<SuspendedSessionDesc> > >
                                         mSuspendedSessions;
-                static const size_t     kLogSize = 512;
+                static const size_t     kLogSize = 4096;
                 sp<NBLog::Writer>       mNBLogWriter;
 };
 
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 315cbbc..f679751 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -351,6 +351,7 @@ AudioFlinger::PlaybackThread::Track::Track(
             // Read the initial underruns because this field is never cleared by the fast mixer
             mObservedUnderruns = thread->getFastTrackUnderruns(i);
             thread->mFastTrackAvailMask &= ~(1 << i);
+            thread->mNBLogWriter->logf("new Track mName=%d mFastIndex=%d", mName, mFastIndex);
         }
     }
     ALOGV("Track constructor name %d, calling pid %d", mName,
@@ -360,6 +361,7 @@ AudioFlinger::PlaybackThread::Track::Track(
 AudioFlinger::PlaybackThread::Track::~Track()
 {
     ALOGV("PlaybackThread::Track destructor");
+    // FIXME not sure if safe to log here, would need a lock on thread to do it
 }
 
 void AudioFlinger::PlaybackThread::Track::destroy()
@@ -569,7 +571,8 @@ status_t AudioFlinger::PlaybackThread::Track::start(AudioSystem::sync_event_t ev
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("start mName=%d", mName);
+        thread->mNBLogWriter->logf("start mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
+                IPCThreadState::self()->getCallingPid());
         track_state state = mState;
         // here the track could be either new, or restarted
         // in both cases "unstop" the track
@@ -612,7 +615,8 @@ void AudioFlinger::PlaybackThread::Track::stop()
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("stop mName=%d", mName);
+        thread->mNBLogWriter->logf("stop mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
+                IPCThreadState::self()->getCallingPid());
         track_state state = mState;
         if (state == RESUMING || state == ACTIVE || state == PAUSING || state == PAUSED) {
             // If the track is not active (PAUSED and buffers full), flush buffers
@@ -649,7 +653,8 @@ void AudioFlinger::PlaybackThread::Track::pause()
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("pause mName=%d", mName);
+        thread->mNBLogWriter->logf("pause mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
+                IPCThreadState::self()->getCallingPid());
         if (mState == ACTIVE || mState == RESUMING) {
             mState = PAUSING;
             ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get());
@@ -673,7 +678,8 @@ void AudioFlinger::PlaybackThread::Track::flush()
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("flush mName=%d", mName);
+        thread->mNBLogWriter->logf("flush mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
+                IPCThreadState::self()->getCallingPid());
         if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED &&
                 mState != PAUSING && mState != IDLE && mState != FLUSHED) {
             return;