OSDN Git Service

Temporary additional logging to investigate bug
authorGlenn Kasten <gkasten@google.com>
Wed, 13 Feb 2013 22:46:45 +0000 (14:46 -0800)
committerGlenn Kasten <gkasten@google.com>
Fri, 15 Feb 2013 23:44:50 +0000 (15:44 -0800)
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()
 - increase log buffer sizes yet again
 - enable assertion checking without ALOGV
 - improve a few log messages
 - check for corruption in more places
 - log in all the process hooks
 - add new mixer APIs so we can check for corruption of mixer state
 - fix a build warning

Bug: 6490974
Change-Id: Ib0c4a73dcf606ef9bd898313b3b40ef61ab42f51

include/media/nbaio/NBLog.h
services/audioflinger/AudioFlinger.h
services/audioflinger/AudioMixer.cpp
services/audioflinger/AudioMixer.h
services/audioflinger/FastMixer.cpp
services/audioflinger/StateQueue.h
services/audioflinger/Threads.cpp
services/audioflinger/Threads.h
services/audioflinger/Tracks.cpp

index 8fc417f..107ba66 100644 (file)
@@ -115,7 +115,7 @@ public:
     virtual ~Writer() { }
 
     virtual void    log(const char *string);
-    virtual void    logf(const char *fmt, ...);
+    virtual void    logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
     virtual void    logvf(const char *fmt, va_list ap);
     virtual void    logTimestamp();
     virtual void    logTimestamp(const struct timespec& ts);
@@ -149,7 +149,7 @@ public:
     LockedWriter(size_t size, void *shared);
 
     virtual void    log(const char *string);
-    virtual void    logf(const char *fmt, ...);
+    virtual void    logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
     virtual void    logvf(const char *fmt, va_list ap);
     virtual void    logTimestamp();
     virtual void    logTimestamp(const struct timespec& ts);
index c3f08f6..a25fb80 100644 (file)
@@ -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 = 50 * 1024;
     sp<MemoryDealer>    mLogMemoryDealer;   // == 0 when NBLog is disabled
 public:
 
index 08325ad..2d7894d 100644 (file)
@@ -16,7 +16,7 @@
 */
 
 #define LOG_TAG "AudioMixer"
-//#define LOG_NDEBUG 0
+#define LOG_NDEBUG 0
 
 #include <stdint.h>
 #include <string.h>
@@ -25,6 +25,8 @@
 
 #include <utils/Errors.h>
 #include <utils/Log.h>
+#undef ALOGV
+#define ALOGV(a...) do { } while (0)
 
 #include <cutils/bitops.h>
 #include <cutils/compiler.h>
@@ -98,7 +100,7 @@ effect_descriptor_t AudioMixer::dwnmFxDesc;
 
 AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTracks)
     :   mTrackNames(0), mConfiguredNames((maxNumTracks >= 32 ? 0 : 1 << maxNumTracks) - 1),
-        mSampleRate(sampleRate)
+        mSampleRate(sampleRate), mLog(&mDummyLog)
 {
     // AudioMixer is not yet capable of multi-channel beyond stereo
     COMPILE_TIME_ASSERT_FUNCTION_SCOPE(2 == MAX_NUM_CHANNELS);
@@ -122,6 +124,7 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr
     mState.hook         = process__nop;
     mState.outputTemp   = NULL;
     mState.resampleTemp = NULL;
+    mState.mLog         = &mDummyLog;
     // mState.reserved
 
     // FIXME Most of the following initialization is probably redundant since
@@ -131,6 +134,7 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr
     for (unsigned i=0 ; i < MAX_NUM_TRACKS ; i++) {
         t->resampler = NULL;
         t->downmixerBufferProvider = NULL;
+        t->magic = track_t::kMagic;
         t++;
     }
 
@@ -169,6 +173,12 @@ AudioMixer::~AudioMixer()
     delete [] mState.resampleTemp;
 }
 
+void AudioMixer::setLog(NBLog::Writer *log)
+{
+    mLog = log;
+    mState.mLog = log;
+}
+
 int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
 {
     uint32_t names = (~mTrackNames) & mConfiguredNames;
@@ -209,9 +219,12 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
         t->mainBuffer = NULL;
         t->auxBuffer = NULL;
         t->downmixerBufferProvider = NULL;
+        t->fastIndex = -1;
+        // t->magic unchanged
 
         status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask);
         if (status == OK) {
+            mLog->logf("getTrackName %d", n);
             return TRACK0 + n;
         }
         ALOGE("AudioMixer::getTrackName(0x%x) failed, error preparing track for downmix",
@@ -366,9 +379,11 @@ void AudioMixer::deleteTrackName(int name)
 {
     ALOGV("AudioMixer::deleteTrackName(%d)", name);
     name -= TRACK0;
+    mLog->logf("deleteTrackName %d", name);
     ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
     ALOGV("deleteTrackName(%d)", name);
     track_t& track(mState.tracks[ name ]);
+    track.checkMagic();
     if (track.enabled) {
         track.enabled = false;
         invalidateState(1<<name);
@@ -387,8 +402,10 @@ void AudioMixer::enable(int name)
     name -= TRACK0;
     ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
     track_t& track = mState.tracks[name];
+    track.checkMagic();
 
     if (!track.enabled) {
+        mLog->logf("enable %d", name);
         track.enabled = true;
         ALOGV("enable(%d)", name);
         invalidateState(1 << name);
@@ -400,19 +417,36 @@ void AudioMixer::disable(int name)
     name -= TRACK0;
     ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
     track_t& track = mState.tracks[name];
+    track.checkMagic();
 
     if (track.enabled) {
+        mLog->logf("disable %d", name);
         track.enabled = false;
         ALOGV("disable(%d)", name);
         invalidateState(1 << name);
     }
 }
 
+bool AudioMixer::enabled(int name)
+{
+    name -= TRACK0;
+    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+    track_t& track = mState.tracks[name];
+    track.checkMagic();
+#if 0
+    // can't do this because mState.enabledTracks is updated lazily
+    ALOG_ASSERT(track.enabled == ((mState.enabledTracks & (1 << name)) != 0));
+#endif
+
+    return track.enabled;
+}
+
 void AudioMixer::setParameter(int name, int target, int param, void *value)
 {
     name -= TRACK0;
     ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
     track_t& track = mState.tracks[name];
+    track.checkMagic();
 
     int valueInt = (int)value;
     int32_t *valueBuf = (int32_t *)value;
@@ -455,6 +489,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");
         }
@@ -540,6 +577,7 @@ void AudioMixer::setParameter(int name, int target, int param, void *value)
 
 bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)
 {
+    checkMagic();
     if (value != devSampleRate || resampler != NULL) {
         if (sampleRate != value) {
             sampleRate = value;
@@ -572,6 +610,7 @@ bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)
 inline
 void AudioMixer::track_t::adjustVolumeRamp(bool aux)
 {
+    checkMagic();
     for (uint32_t i=0 ; i<MAX_NUM_CHANNELS ; i++) {
         if (((volumeInc[i]>0) && (((prevVolume[i]+volumeInc[i])>>16) >= volume[i])) ||
             ((volumeInc[i]<0) && (((prevVolume[i]+volumeInc[i])>>16) <= volume[i]))) {
@@ -600,8 +639,10 @@ size_t AudioMixer::getUnreleasedFrames(int name) const
 void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider)
 {
     name -= TRACK0;
+    mLog->logf("set bp %d=%p", name, bufferProvider);
     ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
 
+    mState.tracks[name].checkMagic();
     if (mState.tracks[name].downmixerBufferProvider != NULL) {
         // update required?
         if (mState.tracks[name].downmixerBufferProvider->mTrackBufferProvider != bufferProvider) {
@@ -619,10 +660,27 @@ void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider
     }
 }
 
+AudioBufferProvider* AudioMixer::getBufferProvider(int name)
+{
+    name -= TRACK0;
+    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+    mState.tracks[name].checkMagic();
+    return mState.tracks[name].bufferProvider;
+}
 
+int AudioMixer::getFastIndex(int name)
+{
+    name -= TRACK0;
+    ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+    mState.tracks[name].checkMagic();
+    return mState.tracks[name].fastIndex;
+}
 
 void AudioMixer::process(int64_t pts)
 {
+    if (mState.needsChanged) {
+        mLog->logf("process needs=%#x", mState.needsChanged);
+    }
     mState.hook(&mState, pts);
 }
 
@@ -647,6 +705,7 @@ void AudioMixer::process__validate(state_t* state, int64_t pts)
     }
     state->enabledTracks &= ~disabled;
     state->enabledTracks |=  enabled;
+    state->mLog->logf("process_validate ena=%#x", state->enabledTracks);
 
     // compute everything we need...
     int countActiveTracks = 0;
@@ -1058,6 +1117,7 @@ void AudioMixer::track__16BitsMono(track_t* t, int32_t* out, size_t frameCount,
 void AudioMixer::process__nop(state_t* state, int64_t pts)
 {
     uint32_t e0 = state->enabledTracks;
+    state->mLog->logf("process_nop ena=%#x", e0);
     size_t bufSize = state->frameCount * sizeof(int16_t) * MAX_NUM_CHANNELS;
     while (e0) {
         // process by group of tracks with same output buffer to
@@ -1103,6 +1163,7 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts)
 
     // acquire each track's buffer
     uint32_t enabledTracks = state->enabledTracks;
+    state->mLog->logf("process_gNR ena=%#x", enabledTracks);
     uint32_t e0 = enabledTracks;
     while (e0) {
         const int i = 31 - __builtin_clz(e0);
@@ -1111,8 +1172,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);
@@ -1211,6 +1272,7 @@ void AudioMixer::process__genericResampling(state_t* state, int64_t pts)
     size_t numFrames = state->frameCount;
 
     uint32_t e0 = state->enabledTracks;
+    state->mLog->logf("process_gR ena=%#x", e0);
     while (e0) {
         // process by group of tracks with same output buffer
         // to optimize cache use
@@ -1275,6 +1337,7 @@ void AudioMixer::process__genericResampling(state_t* state, int64_t pts)
 void AudioMixer::process__OneTrack16BitsStereoNoResampling(state_t* state,
                                                            int64_t pts)
 {
+    state->mLog->logf("process_1TSNR ena=%#x", state->enabledTracks);
     // This method is only called when state->enabledTracks has exactly
     // one bit set.  The asserts below would verify this, but are commented out
     // since the whole point of this method is to optimize performance.
@@ -1344,6 +1407,7 @@ void AudioMixer::process__TwoTracks16BitsStereoNoResampling(state_t* state,
 {
     int i;
     uint32_t en = state->enabledTracks;
+    state->mLog->logf("process_2TSNR ena=%#x", en);
 
     i = 31 - __builtin_clz(en);
     const track_t& t0 = state->tracks[i];
index fd21fda..2d00bf5 100644 (file)
@@ -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,13 +108,17 @@ 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);
 
     void        setBufferProvider(int name, AudioBufferProvider* bufferProvider);
+    AudioBufferProvider* getBufferProvider(int name);
     void        process(int64_t pts);
 
     uint32_t    trackNames() const { return mTrackNames; }
+    uint32_t    enabledTrackNames() const { return mState.enabledTracks; }
+    int         getFastIndex(int name);
 
     size_t      getUnreleasedFrames(int name) const;
 
@@ -200,7 +206,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 +219,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 +235,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 +263,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
index 80e37ca..75c3c41 100644 (file)
 // </IMPORTANT_WARNING>
 
 #define LOG_TAG "FastMixer"
-//#define LOG_NDEBUG 0
+#define LOG_NDEBUG 0
 
 #define ATRACE_TAG ATRACE_TAG_AUDIO
 
 #include <sys/atomics.h>
 #include <time.h>
 #include <utils/Log.h>
+#undef ALOGV
+#define ALOGV(a...) do { } while (0)
 #include <utils/Trace.h>
 #include <system/audio.h>
 #ifdef FAST_MIXER_STATISTICS
@@ -93,6 +95,8 @@ bool FastMixer::threadLoop()
     uint32_t warmupCycles = 0;  // counter of number of loop cycles required to warmup
     NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
     NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;
+    bool myEnabled[FastMixerState::kMaxFastTracks];
+    memset(myEnabled, 0, sizeof(myEnabled));
 
     for (;;) {
 
@@ -120,12 +124,16 @@ 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
             dumpState = next->mDumpState != NULL ? next->mDumpState : &dummyDumpState;
             teeSink = next->mTeeSink;
             logWriter = next->mNBLogWriter != NULL ? next->mNBLogWriter : &dummyLogWriter;
+            if (mixer != NULL) {
+                mixer->setLog(logWriter);
+            }
 
             // We want to always have a valid reference to the previous (non-idle) state.
             // However, the state queue only guarantees access to current and previous states.
@@ -300,13 +308,21 @@ bool FastMixer::threadLoop()
                     addedTracks &= ~(1 << i);
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
+                    logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
                     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);
@@ -317,27 +333,41 @@ bool FastMixer::threadLoop()
                         }
                         mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
                                 (void *) fastTrack->mChannelMask);
+                        if (!mixer->enabled(name)) {
+                            logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+                        }
                         mixer->enable(name);
+                        myEnabled[i] = true;
                     }
                     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;
+                        logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
                         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 +390,9 @@ bool FastMixer::threadLoop()
                         generations[i] = fastTrack->mGeneration;
                     }
                 }
+                if (actuallyModifiedTracks) {
+                    logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
+                }
 
                 fastTracksGen = current->mFastTracksGen;
 
@@ -377,6 +410,7 @@ bool FastMixer::threadLoop()
             ALOG_ASSERT(mixBuffer != NULL);
             // for each track, update volume and check for underrun
             unsigned currentTrackMask = current->mTrackMask;
+            logWriter->logf("ctm %#x", currentTrackMask);
             while (currentTrackMask != 0) {
                 i = __builtin_ctz(currentTrackMask);
                 currentTrackMask &= ~(1 << i);
@@ -410,25 +444,76 @@ bool FastMixer::threadLoop()
                         underruns.mBitFields.mEmpty++;
                         underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
                         mixer->disable(name);
+                        myEnabled[i] = false;
                     } else {
                         // allow mixing partial buffer
                         underruns.mBitFields.mPartial++;
                         underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
+                        if (!mixer->enabled(name)) {
+                            logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+                        }
                         mixer->enable(name);
+                        myEnabled[i] = true;
                     }
                 } else {
                     underruns.mBitFields.mFull++;
                     underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
+                    if (!mixer->enabled(name)) {
+                        logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+                    }
                     mixer->enable(name);
+                    myEnabled[i] = true;
                 }
                 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;
             if (outputSink == NULL || (OK != outputSink->getNextWriteTimestamp(&pts)))
                 pts = AudioBufferProvider::kInvalidPTS;
 
+            // validate that mixer state is correct
+            currentTrackMask = current->mTrackMask;
+            unsigned expectedMixerEnabled = 0;
+            while (currentTrackMask != 0) {
+                i = __builtin_ctz(currentTrackMask);
+                currentTrackMask &= ~(1 << i);
+                const FastTrack* fastTrack = &current->mFastTracks[i];
+                int name = fastTrackNames[i];
+                ALOG_ASSERT(name >= 0);
+                bool isEnabled = mixer->enabled(name);
+                if (isEnabled != myEnabled[i]) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("? i=%d name=%d mixena=%d ftena=%d", i, name, isEnabled,
+                            myEnabled[i]);
+                }
+                if (myEnabled[i]) {
+                    expectedMixerEnabled |= 1 << name;
+                }
+                AudioBufferProvider *abp = mixer->getBufferProvider(name);
+                if (abp != fastTrack->mBufferProvider) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("? i=%d name=%d mixbp=%p ftbp=%p", i, name, abp,
+                            fastTrack->mBufferProvider);
+                }
+                int fastIndex = mixer->getFastIndex(name);
+                if (fastIndex != (int) i) {
+                    logWriter->logTimestamp();
+                    logWriter->logf("? i=%d name=%d fastIndex=%d", i, name, fastIndex);
+                }
+            }
+            unsigned mixerEnabled = mixer->enabledTrackNames();
+            if (mixerEnabled != expectedMixerEnabled) {
+                logWriter->logTimestamp();
+                logWriter->logf("? mixena=%#x expected=%#x", mixerEnabled, expectedMixerEnabled);
+            }
+
             // process() is CPU-bound
             mixer->process(pts);
             mixBufferState = MIXED;
@@ -453,7 +538,7 @@ bool FastMixer::threadLoop()
             ATRACE_END();
             dumpState->mWriteSequence++;
             if (framesWritten >= 0) {
-                ALOG_ASSERT(framesWritten <= frameCount);
+                ALOG_ASSERT((size_t) framesWritten <= frameCount);
                 dumpState->mFramesWritten += framesWritten;
                 //if ((size_t) framesWritten == frameCount) {
                 //    didFullWrite = true;
index e33b3c6..313330f 100644 (file)
@@ -174,7 +174,7 @@ public:
 #endif
 
 private:
-    static const unsigned kN = 4;       // values < 4 are not supported by this code
+    static const unsigned kN = 8;       // values < 4 are not supported by this code
     T                 mStates[kN];      // written by mutator, read by observer
 
     // "volatile" is meaningless with SMP, but here it indicates that we're using atomic ops
index ba848d7..58e3cbe 100644 (file)
@@ -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());
@@ -2149,6 +2155,7 @@ AudioFlinger::MixerThread::MixerThread(const sp<AudioFlinger>& audioFlinger, Aud
         FastTrack *fastTrack = &state->mFastTracks[0];
         // wrap the source side of the MonoPipe to make it an AudioBufferProvider
         fastTrack->mBufferProvider = new SourceAudioBufferProvider(new MonoPipeReader(monoPipe));
+        mNBLogWriter->logf("fastTrack0 bp=%p", fastTrack->mBufferProvider);
         fastTrack->mVolumeProvider = NULL;
         fastTrack->mGeneration++;
         state->mFastTracksGen++;
@@ -2553,6 +2560,7 @@ AudioFlinger::PlaybackThread::mixer_state AudioFlinger::MixerThread::prepareTrac
                 // was it previously inactive?
                 if (!(state->mTrackMask & (1 << j))) {
                     ExtendedAudioBufferProvider *eabp = track;
+                    mNBLogWriter->logf("fastTrack j=%d bp=%p", j, eabp);
                     VolumeProvider *vp = track;
                     fastTrack->mBufferProvider = eabp;
                     fastTrack->mVolumeProvider = vp;
@@ -2839,11 +2847,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 +2886,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());
index fa1e336..8e6b69c 100644 (file)
@@ -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 = 8 * 1024;
                 sp<NBLog::Writer>       mNBLogWriter;
 };
 
@@ -546,7 +546,7 @@ private:
     sp<NBAIO_Sink>          mTeeSink;
     sp<NBAIO_Source>        mTeeSource;
     uint32_t                mScreenState;   // cached copy of gScreenState
-    static const size_t     kFastMixerLogSize = 8 * 1024;
+    static const size_t     kFastMixerLogSize = 32 * 1024;
     sp<NBLog::Writer>       mFastMixerNBLogWriter;
 public:
     virtual     bool        hasFastMixer() const = 0;
index 315cbbc..f679751 100644 (file)
@@ -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;