media.log cleanup

Remove almost all of the specific logs, but leave the media.log
logging infrastructure in place for the next time we need it.

Re-apply a few good changes that were reverted earlier:
 - check logf format vs. argument list compatibility
 - distinguish potentially modified and actually modified tracks in FastMixer
 - fix benign bug where sq->end() was called more than once
 - fix a build warning

Bug: 6490974
Change-Id: I02d3e83646c738acaebb415bd0d6b548638b4ef5

6 files changed, 22 insertions, 38 deletions

diff --git a/services/audioflinger/AudioMixer.cpp b/services/audioflinger/AudioMixer.cpp
index 17b6a8a..7d38f80 100644
--- a/services/audioflinger/AudioMixer.cpp
+++ b/services/audioflinger/AudioMixer.cpp
@@ -122,6 +122,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
@@ -169,6 +170,11 @@ AudioMixer::~AudioMixer()
     delete [] mState.resampleTemp;
 }
 
+void AudioMixer::setLog(NBLog::Writer *log)
+{
+    mState.mLog = log;
+}
+
 int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
 {
     uint32_t names = (~mTrackNames) & mConfiguredNames;
@@ -620,7 +626,6 @@ void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider
 }
 
 
-
 void AudioMixer::process(int64_t pts)
 {
     mState.hook(&mState, pts);
diff --git a/services/audioflinger/AudioMixer.h b/services/audioflinger/AudioMixer.h
index fd21fda..43aeb86 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 {
 
@@ -220,7 +221,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 +249,10 @@ private:
 
     const uint32_t  mSampleRate;
 
+    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 80e37ca..2832e96 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -120,12 +120,13 @@ bool FastMixer::threadLoop()
         FastMixerState::Command command = next->mCommand;
         if (next != current) {
 
-            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.
@@ -167,7 +168,6 @@ bool FastMixer::threadLoop()
                 ALOG_ASSERT(coldFutexAddr != NULL);
                 int32_t old = android_atomic_dec(coldFutexAddr);
                 if (old <= 0) {
-                    logWriter->log("wait");
                     __futex_syscall4(coldFutexAddr, FUTEX_WAIT_PRIVATE, old - 1, NULL);
                 }
                 // This may be overly conservative; there could be times that the normal mixer
@@ -186,7 +186,6 @@ bool FastMixer::threadLoop()
             }
             continue;
         case FastMixerState::EXIT:
-            logWriter->log("exit");
             delete mixer;
             delete[] mixBuffer;
             return false;
@@ -264,15 +263,11 @@ bool FastMixer::threadLoop()
             unsigned currentTrackMask = current->mTrackMask;
             dumpState->mTrackMask = currentTrackMask;
             if (current->mFastTracksGen != fastTracksGen) {
-                logWriter->logf("gen %d", current->mFastTracksGen);
                 ALOG_ASSERT(mixBuffer != NULL);
                 int name;
 
                 // process removed tracks first to avoid running out of track names
                 unsigned removedTracks = previousTrackMask & ~currentTrackMask;
-                if (removedTracks) {
-                    logWriter->logf("removed %#x", removedTracks);
-                }
                 while (removedTracks != 0) {
                     i = __builtin_ctz(removedTracks);
                     removedTracks &= ~(1 << i);
@@ -292,9 +287,6 @@ bool FastMixer::threadLoop()
 
                 // now process added tracks
                 unsigned addedTracks = currentTrackMask & ~previousTrackMask;
-                if (addedTracks) {
-                    logWriter->logf("added %#x", addedTracks);
-                }
                 while (addedTracks != 0) {
                     i = __builtin_ctz(addedTracks);
                     addedTracks &= ~(1 << i);
@@ -322,17 +314,15 @@ 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);
-                }
                 while (modifiedTracks != 0) {
                     i = __builtin_ctz(modifiedTracks);
                     modifiedTracks &= ~(1 << i);
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     if (fastTrack->mGeneration != generations[i]) {
+                        // this track was actually modified
                         AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
                         ALOG_ASSERT(bufferProvider != NULL);
                         if (mixer != NULL) {
@@ -453,7 +443,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;
@@ -471,7 +461,7 @@ bool FastMixer::threadLoop()
         struct timespec newTs;
         int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
         if (rc == 0) {
-            logWriter->logTimestamp(newTs);
+            //logWriter->logTimestamp(newTs);
             if (oldTsValid) {
                 time_t sec = newTs.tv_sec - oldTs.tv_sec;
                 long nsec = newTs.tv_nsec - oldTs.tv_nsec;
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 1209ea6..b80ad25 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1249,7 +1249,6 @@ Exit:
     if (status) {
         *status = lStatus;
     }
-    mNBLogWriter->logf("createTrack_l");
     return track;
 }
 
@@ -1317,7 +1316,6 @@ 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);
     status_t status = ALREADY_EXISTS;
 
     // set retry count for buffer fill
@@ -1351,7 +1349,6 @@ 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);
     track->mState = TrackBase::TERMINATED;
     // active tracks are removed by threadLoop()
     if (mActiveTracks.indexOf(track) < 0) {
@@ -1361,7 +1358,6 @@ 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);
     track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE);
     mTracks.remove(track);
     deleteTrackName_l(track->name());
@@ -1934,7 +1930,6 @@ bool AudioFlinger::PlaybackThread::threadLoop()
 
                     threadLoop_standby();
 
-                    mNBLogWriter->log("standby");
                     mStandby = true;
                 }
 
@@ -2030,9 +2025,6 @@ if (mType == MIXER) {
         // since we can't guarantee the destructors won't acquire that
         // same lock.  This will also mutate and push a new fast mixer state.
         threadLoop_removeTracks(tracksToRemove);
-        if (tracksToRemove.size() > 0) {
-            logString = "remove";
-        }
         tracksToRemove.clear();
 
         // FIXME I don't understand the need for this here;
@@ -2839,7 +2831,6 @@ track_is_ready: ;
             block = FastMixerStateQueue::BLOCK_UNTIL_ACKED;
             pauseAudioWatchdog = true;
         }
-        sq->end();
     }
     if (sq != NULL) {
         sq->end(didModify);
@@ -2870,7 +2861,6 @@ 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());
             mActiveTracks.remove(track);
             if (track->mainBuffer() != mMixBuffer) {
                 chain = getEffectChain_l(track->sessionId());
@@ -3247,9 +3237,6 @@ AudioFlinger::PlaybackThread::mixer_state AudioFlinger::DirectOutputThread::prep
     // remove all the tracks that need to be...
     if (CC_UNLIKELY(trackToRemove != 0)) {
         tracksToRemove->add(trackToRemove);
-#if 0
-        mNBLogWriter->logf("prepareTracks_l remove name=%u", trackToRemove->name());
-#endif
         mActiveTracks.remove(trackToRemove);
         if (!mEffectChains.isEmpty()) {
             ALOGV("stopping track on chain %p for session Id: %d", mEffectChains[0].get(),
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index fa1e336..4595b6c 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 = 4 * 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 = 4 * 1024;
     sp<NBLog::Writer>       mFastMixerNBLogWriter;
 public:
     virtual     bool        hasFastMixer() const = 0;
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 724ce38..30fe1f2 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -598,7 +598,6 @@ 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);
         track_state state = mState;
         // here the track could be either new, or restarted
         // in both cases "unstop" the track
@@ -641,7 +640,6 @@ 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);
         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
@@ -678,7 +676,6 @@ 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);
         if (mState == ACTIVE || mState == RESUMING) {
             mState = PAUSING;
             ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get());
@@ -702,7 +699,6 @@ 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);
         if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED &&
                 mState != PAUSING && mState != IDLE && mState != FLUSHED) {
             return;