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.
 - increase StateQueue size from 4 to 8 entries
 - log mixer->enable(), bufferProvider, and currentTrackMask
 - log buffer provider addresses
 - increase fast mixer log buffer again
 - check logf format vs. argument list compatibility
 - add logging to AudioMixer
 - add checking of magic field in AudioMixer to detect overwrites
 - add bool AudioMixer::enabled()

Bug: 6490974
Change-Id: I1f3f18aa62d9fbd35bc32285b669f5ba40efe28e

1 files changed, 20 insertions, 2 deletions

diff --git a/services/audioflinger/AudioMixer.h b/services/audioflinger/AudioMixer.h
index fd21fda..f0ccd8e 100644
--- a/services/audioflinger/AudioMixer.h
+++ b/services/audioflinger/AudioMixer.h
@@ -28,6 +28,7 @@
 
 #include <audio_effects/effect_downmix.h>
 #include <system/audio.h>
+#include <media/nbaio/NBLog.h>
 
 namespace android {
 
@@ -76,6 +77,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.
@@ -106,6 +108,7 @@ public:
     // Enable or disable an allocated track by name
     void        enable(int name);
     void        disable(int name);
+    bool        enabled(int name);
 
     void        setParameter(int name, int target, int param, void *value);
 
@@ -200,7 +203,10 @@ private:
 
         int32_t     sessionId;
 
-        int32_t     padding[2];
+        int32_t     fastIndex;
+        int32_t     magic;
+        static const int kMagic = 0x54637281;
+        //int32_t     padding[1];
 
         // 16-byte boundary
 
@@ -210,6 +216,12 @@ private:
         void        adjustVolumeRamp(bool aux);
         size_t      getUnreleasedFrames() const { return resampler != NULL ?
                                                     resampler->getUnreleasedFrames() : 0; };
+        void        checkMagic() {
+            if (magic != kMagic) {
+                ALOGE("magic=%#x fastIndex=%d", magic, fastIndex);
+            }
+        }
+
     };
 
     // pad to 32-bytes to fill cache line
@@ -220,7 +232,8 @@ private:
         void            (*hook)(state_t* state, int64_t pts);   // one of process__*, never NULL
         int32_t         *outputTemp;
         int32_t         *resampleTemp;
-        int32_t         reserved[2];
+        NBLog::Writer*  mLog;
+        int32_t         reserved[1];
         // FIXME allocate dynamically to save some memory when maxNumTracks < MAX_NUM_TRACKS
         track_t         tracks[MAX_NUM_TRACKS]; __attribute__((aligned(32)));
     };
@@ -247,6 +260,11 @@ private:
 
     const uint32_t  mSampleRate;
 
+    NBLog::Writer*  mLog;
+    NBLog::Writer   mDummyLog;
+public:
+    void            setLog(NBLog::Writer* log);
+private:
     state_t         mState __attribute__((aligned(32)));
 
     // effect descriptor for the downmixer used by the mixer