Merge "Revert "Temporary additional logging to investigate bug""

8 files changed, 24 insertions, 218 deletions

diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index a25fb80..c3f08f6 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 = 50 * 1024;
+    static const size_t kLogMemorySize = 10 * 1024;
     sp<MemoryDealer>    mLogMemoryDealer;   // == 0 when NBLog is disabled
 public:
 
diff --git a/services/audioflinger/AudioMixer.cpp b/services/audioflinger/AudioMixer.cpp
index 2d7894d..08325ad 100644
--- a/services/audioflinger/AudioMixer.cpp
+++ b/services/audioflinger/AudioMixer.cpp
@@ -16,7 +16,7 @@
 */
 
 #define LOG_TAG "AudioMixer"
-#define LOG_NDEBUG 0
+//#define LOG_NDEBUG 0
 
 #include <stdint.h>
 #include <string.h>
@@ -25,8 +25,6 @@
 
 #include <utils/Errors.h>
 #include <utils/Log.h>
-#undef ALOGV
-#define ALOGV(a...) do { } while (0)
 
 #include <cutils/bitops.h>
 #include <cutils/compiler.h>
@@ -100,7 +98,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), mLog(&mDummyLog)
+        mSampleRate(sampleRate)
 {
     // AudioMixer is not yet capable of multi-channel beyond stereo
     COMPILE_TIME_ASSERT_FUNCTION_SCOPE(2 == MAX_NUM_CHANNELS);
@@ -124,7 +122,6 @@ 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
@@ -134,7 +131,6 @@ 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++;
     }
 
@@ -173,12 +169,6 @@ 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;
@@ -219,12 +209,9 @@ 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",
@@ -379,11 +366,9 @@ 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);
@@ -402,10 +387,8 @@ 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);
@@ -417,36 +400,19 @@ 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;
@@ -489,9 +455,6 @@ 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");
         }
@@ -577,7 +540,6 @@ 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;
@@ -610,7 +572,6 @@ 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]))) {
@@ -639,10 +600,8 @@ 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) {
@@ -660,27 +619,10 @@ 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);
 }
 
@@ -705,7 +647,6 @@ 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;
@@ -1117,7 +1058,6 @@ 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
@@ -1163,7 +1103,6 @@ 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);
@@ -1172,8 +1111,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 fastIndex=%d frameCount=%d valid=%#x enabledTracks=%#x",
-                    t.bufferProvider, i, t.fastIndex, t.buffer.frameCount, valid, enabledTracks);
+            ALOGE("invalid bufferProvider=%p name=%d frameCount=%d valid=%#x enabledTracks=%#x",
+                    t.bufferProvider, i, t.buffer.frameCount, valid, enabledTracks);
             // expect to crash
         }
         t.bufferProvider->getNextBuffer(&t.buffer, pts);
@@ -1272,7 +1211,6 @@ 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
@@ -1337,7 +1275,6 @@ 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.
@@ -1407,7 +1344,6 @@ 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];
diff --git a/services/audioflinger/AudioMixer.h b/services/audioflinger/AudioMixer.h
index 2d00bf5..fd21fda 100644
--- a/services/audioflinger/AudioMixer.h
+++ b/services/audioflinger/AudioMixer.h
@@ -28,7 +28,6 @@
 
 #include <audio_effects/effect_downmix.h>
 #include <system/audio.h>
-#include <media/nbaio/NBLog.h>
 
 namespace android {
 
@@ -77,7 +76,6 @@ 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.
@@ -108,17 +106,13 @@ 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;
 
@@ -206,10 +200,7 @@ private:
 
         int32_t     sessionId;
 
-        int32_t     fastIndex;
-        int32_t     magic;
-        static const int kMagic = 0x54637281;
-        //int32_t     padding[1];
+        int32_t     padding[2];
 
         // 16-byte boundary
 
@@ -219,12 +210,6 @@ 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
@@ -235,8 +220,7 @@ private:
         void            (*hook)(state_t* state, int64_t pts);   // one of process__*, never NULL
         int32_t         *outputTemp;
         int32_t         *resampleTemp;
-        NBLog::Writer*  mLog;
-        int32_t         reserved[1];
+        int32_t         reserved[2];
         // FIXME allocate dynamically to save some memory when maxNumTracks < MAX_NUM_TRACKS
         track_t         tracks[MAX_NUM_TRACKS]; __attribute__((aligned(32)));
     };
@@ -263,11 +247,6 @@ 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
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index 75c3c41..80e37ca 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -21,15 +21,13 @@
 // </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
@@ -95,8 +93,6 @@ 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 (;;) {
 
@@ -124,16 +120,12 @@ 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.
@@ -308,21 +300,13 @@ 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);
@@ -333,41 +317,27 @@ 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 (potentially) modified tracks; these use the same slot
+                // finally process 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("pot. mod. %#x", modifiedTracks);
+                    logWriter->logf("modified %#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,
@@ -390,9 +360,6 @@ bool FastMixer::threadLoop()
                         generations[i] = fastTrack->mGeneration;
                     }
                 }
-                if (actuallyModifiedTracks) {
-                    logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
-                }
 
                 fastTracksGen = current->mFastTracksGen;
 
@@ -410,7 +377,6 @@ 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);
@@ -444,76 +410,25 @@ 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;
@@ -538,7 +453,7 @@ bool FastMixer::threadLoop()
             ATRACE_END();
             dumpState->mWriteSequence++;
             if (framesWritten >= 0) {
-                ALOG_ASSERT((size_t) framesWritten <= frameCount);
+                ALOG_ASSERT(framesWritten <= frameCount);
                 dumpState->mFramesWritten += framesWritten;
                 //if ((size_t) framesWritten == frameCount) {
                 //    didFullWrite = true;
diff --git a/services/audioflinger/StateQueue.h b/services/audioflinger/StateQueue.h
index 313330f..e33b3c6 100644
--- a/services/audioflinger/StateQueue.h
+++ b/services/audioflinger/StateQueue.h
@@ -174,7 +174,7 @@ public:
 #endif
 
 private:
-    static const unsigned kN = 8;       // values < 4 are not supported by this code
+    static const unsigned kN = 4;       // 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
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 58e3cbe..ba848d7 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1196,8 +1196,6 @@ 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
@@ -1251,6 +1249,7 @@ Exit:
     if (status) {
         *status = lStatus;
     }
+    mNBLogWriter->logf("createTrack_l");
     return track;
 }
 
@@ -1318,8 +1317,7 @@ 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 mFastIndex=%d caller=%d", track->mName,
-            track->mFastIndex, IPCThreadState::self()->getCallingPid());
+    mNBLogWriter->logf("addTrack_l mName=%d", track->mName);
     status_t status = ALREADY_EXISTS;
 
     // set retry count for buffer fill
@@ -1353,9 +1351,7 @@ 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->logTimestamp();
-    mNBLogWriter->logf("destroyTrack_l mName=%d mFastIndex=%d mClientPid=%d", track->mName,
-            track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1);
+    mNBLogWriter->logf("destroyTrack_l mName=%d", track->mName);
     track->mState = TrackBase::TERMINATED;
     // active tracks are removed by threadLoop()
     if (mActiveTracks.indexOf(track) < 0) {
@@ -1365,9 +1361,7 @@ void AudioFlinger::PlaybackThread::destroyTrack_l(const sp<Track>& track)
 
 void AudioFlinger::PlaybackThread::removeTrack_l(const sp<Track>& track)
 {
-    mNBLogWriter->logTimestamp();
-    mNBLogWriter->logf("removeTrack_l mName=%d mFastIndex=%d clientPid=%d", track->mName,
-            track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1);
+    mNBLogWriter->logf("removeTrack_l mName=%d", track->mName);
     track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
     mTracks.remove(track);
     deleteTrackName_l(track->name());
@@ -2155,7 +2149,6 @@ 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++;
@@ -2560,7 +2553,6 @@ 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;
@@ -2847,19 +2839,11 @@ 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) {
@@ -2886,9 +2870,7 @@ track_is_ready: ;
     if (CC_UNLIKELY(count)) {
         for (size_t i=0 ; i<count ; i++) {
             const sp<Track>& track = tracksToRemove->itemAt(i);
-            mNBLogWriter->logTimestamp();
-            mNBLogWriter->logf("prepareTracks_l remove name=%u mFastIndex=%d", track->name(),
-                    track->mFastIndex);
+            mNBLogWriter->logf("prepareTracks_l remove name=%u", track->name());
             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 8e6b69c..fa1e336 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 = 8 * 1024;
+                static const size_t     kLogSize = 512;
                 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 = 32 * 1024;
+    static const size_t     kFastMixerLogSize = 8 * 1024;
     sp<NBLog::Writer>       mFastMixerNBLogWriter;
 public:
     virtual     bool        hasFastMixer() const = 0;
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index f679751..315cbbc 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -351,7 +351,6 @@ 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,
@@ -361,7 +360,6 @@ 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()
@@ -571,8 +569,7 @@ 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 mFastIndex=%d caller=%d", mName, mFastIndex,
-                IPCThreadState::self()->getCallingPid());
+        thread->mNBLogWriter->logf("start mName=%d", mName);
         track_state state = mState;
         // here the track could be either new, or restarted
         // in both cases "unstop" the track
@@ -615,8 +612,7 @@ void AudioFlinger::PlaybackThread::Track::stop()
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("stop mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
-                IPCThreadState::self()->getCallingPid());
+        thread->mNBLogWriter->logf("stop mName=%d", mName);
         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
@@ -653,8 +649,7 @@ void AudioFlinger::PlaybackThread::Track::pause()
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("pause mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
-                IPCThreadState::self()->getCallingPid());
+        thread->mNBLogWriter->logf("pause mName=%d", mName);
         if (mState == ACTIVE || mState == RESUMING) {
             mState = PAUSING;
             ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get());
@@ -678,8 +673,7 @@ void AudioFlinger::PlaybackThread::Track::flush()
     sp<ThreadBase> thread = mThread.promote();
     if (thread != 0) {
         Mutex::Autolock _l(thread->mLock);
-        thread->mNBLogWriter->logf("flush mName=%d mFastIndex=%d caller=%d", mName, mFastIndex,
-                IPCThreadState::self()->getCallingPid());
+        thread->mNBLogWriter->logf("flush mName=%d", mName);
         if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED &&
                 mState != PAUSING && mState != IDLE && mState != FLUSHED) {
             return;