AudioFlinger uses media.log service for logging

Change-Id: Ia0f8204334f6b233f644d897762a18c95d936b4b

8 files changed, 112 insertions, 1 deletions

diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index 5f5b041..52fa576 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -59,6 +59,8 @@
 #include <common_time/cc_helper.h>
 //#include <common_time/local_clock.h>
 
+#include <media/IMediaLogService.h>
+
 // ----------------------------------------------------------------------------
 
 // Note: the following macro is used for extremely verbose logging message.  In
@@ -127,6 +129,11 @@ AudioFlinger::AudioFlinger()
       mMode(AUDIO_MODE_INVALID),
       mBtNrecIsOff(false)
 {
+    char value[PROPERTY_VALUE_MAX];
+    bool doLog = (property_get("ro.test_harness", value, "0") > 0) && (atoi(value) == 1);
+    if (doLog) {
+        mLogMemoryDealer = new MemoryDealer(kLogMemorySize, "LogWriters");
+    }
 }
 
 void AudioFlinger::onFirstRef()
@@ -323,6 +330,17 @@ status_t AudioFlinger::dump(int fd, const Vector<String16>& args)
         if (locked) {
             mLock.unlock();
         }
+
+        // append a copy of media.log here by forwarding fd to it, but don't attempt
+        // to lookup the service if it's not running, as it will block for a second
+        if (mLogMemoryDealer != 0) {
+            sp<IBinder> binder = defaultServiceManager()->getService(String16("media.log"));
+            if (binder != 0) {
+                fdprintf(fd, "\nmedia.log:\n");
+                Vector<String16> args;
+                binder->dump(fd, args);
+            }
+        }
     }
     return NO_ERROR;
 }
@@ -340,6 +358,35 @@ sp<AudioFlinger::Client> AudioFlinger::registerPid_l(pid_t pid)
     return client;
 }
 
+sp<NBLog::Writer> AudioFlinger::newWriter_l(size_t size, const char *name)
+{
+    if (mLogMemoryDealer == 0) {
+        return new NBLog::Writer();
+    }
+    sp<IMemory> shared = mLogMemoryDealer->allocate(NBLog::Timeline::sharedSize(size));
+    sp<NBLog::Writer> writer = new NBLog::Writer(size, shared);
+    sp<IBinder> binder = defaultServiceManager()->getService(String16("media.log"));
+    if (binder != 0) {
+        interface_cast<IMediaLogService>(binder)->registerWriter(shared, size, name);
+    }
+    return writer;
+}
+
+void AudioFlinger::unregisterWriter(const sp<NBLog::Writer>& writer)
+{
+    sp<IMemory> iMemory(writer->getIMemory());
+    if (iMemory == 0) {
+        return;
+    }
+    sp<IBinder> binder = defaultServiceManager()->getService(String16("media.log"));
+    if (binder != 0) {
+        interface_cast<IMediaLogService>(binder)->unregisterWriter(iMemory);
+        // Now the media.log remote reference to IMemory is gone.
+        // When our last local reference to IMemory also drops to zero,
+        // the IMemory destructor will deallocate the region from mMemoryDealer.
+    }
+}
+
 // IAudioFlinger interface
 
 
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index a7f5b9e..c3f08f6 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -53,6 +53,8 @@
 
 #include <powermanager/IPowerManager.h>
 
+#include <media/nbaio/NBLog.h>
+
 namespace android {
 
 class audio_track_cblk_t;
@@ -222,6 +224,13 @@ public:
 
     // end of IAudioFlinger interface
 
+    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;
+    sp<MemoryDealer>    mLogMemoryDealer;   // == 0 when NBLog is disabled
+public:
+
     class SyncEvent;
 
     typedef void (*sync_event_callback_t)(const wp<SyncEvent>& event) ;
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index 9283f53..80e37ca 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -92,6 +92,7 @@ bool FastMixer::threadLoop()
     struct timespec measuredWarmupTs = {0, 0};  // how long did it take for warmup to complete
     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;
 
     for (;;) {
 
@@ -119,9 +120,12 @@ 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;
 
             // 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.
@@ -163,6 +167,7 @@ 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
@@ -181,6 +186,7 @@ bool FastMixer::threadLoop()
             }
             continue;
         case FastMixerState::EXIT:
+            logWriter->log("exit");
             delete mixer;
             delete[] mixBuffer;
             return false;
@@ -258,11 +264,15 @@ 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);
@@ -282,6 +292,9 @@ 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);
@@ -312,6 +325,9 @@ bool FastMixer::threadLoop()
                 // 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("modified %#x", modifiedTracks);
+                }
                 while (modifiedTracks != 0) {
                     i = __builtin_ctz(modifiedTracks);
                     modifiedTracks &= ~(1 << i);
@@ -455,6 +471,7 @@ bool FastMixer::threadLoop()
         struct timespec newTs;
         int rc = clock_gettime(CLOCK_MONOTONIC, &newTs);
         if (rc == 0) {
+            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/FastMixerState.cpp b/services/audioflinger/FastMixerState.cpp
index 6305a83..c45c81b 100644
--- a/services/audioflinger/FastMixerState.cpp
+++ b/services/audioflinger/FastMixerState.cpp
@@ -31,7 +31,7 @@ FastTrack::~FastTrack()
 FastMixerState::FastMixerState() :
     mFastTracksGen(0), mTrackMask(0), mOutputSink(NULL), mOutputSinkGen(0),
     mFrameCount(0), mCommand(INITIAL), mColdFutexAddr(NULL), mColdGen(0),
-    mDumpState(NULL), mTeeSink(NULL)
+    mDumpState(NULL), mTeeSink(NULL), mNBLogWriter(NULL)
 {
 }
 
diff --git a/services/audioflinger/FastMixerState.h b/services/audioflinger/FastMixerState.h
index 6e53f21..f6e7903 100644
--- a/services/audioflinger/FastMixerState.h
+++ b/services/audioflinger/FastMixerState.h
@@ -20,6 +20,7 @@
 #include <system/audio.h>
 #include <media/ExtendedAudioBufferProvider.h>
 #include <media/nbaio/NBAIO.h>
+#include <media/nbaio/NBLog.h>
 
 namespace android {
 
@@ -77,6 +78,7 @@ struct FastMixerState {
     // This might be a one-time configuration rather than per-state
     FastMixerDumpState* mDumpState; // if non-NULL, then update dump state periodically
     NBAIO_Sink* mTeeSink;       // if non-NULL, then duplicate write()s to this non-blocking sink
+    NBLog::Writer* mNBLogWriter; // non-blocking logger
 };  // struct FastMixerState
 
 }   // namespace android
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 744a7df..6f748d7 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -936,6 +936,7 @@ AudioFlinger::PlaybackThread::PlaybackThread(const sp<AudioFlinger>& audioFlinge
         mFastTrackAvailMask(((1 << FastMixerState::kMaxFastTracks) - 1) & ~1)
 {
     snprintf(mName, kNameLength, "AudioOut_%X", id);
+    mNBLogWriter = audioFlinger->newWriter_l(kLogSize, mName);
 
     // Assumes constructor is called by AudioFlinger with it's mLock held, but
     // it would be safer to explicitly pass initial masterVolume/masterMute as
@@ -971,6 +972,7 @@ AudioFlinger::PlaybackThread::PlaybackThread(const sp<AudioFlinger>& audioFlinge
 
 AudioFlinger::PlaybackThread::~PlaybackThread()
 {
+    mAudioFlinger->unregisterWriter(mNBLogWriter);
     delete [] mMixBuffer;
 }
 
@@ -1247,6 +1249,7 @@ Exit:
     if (status) {
         *status = lStatus;
     }
+    mNBLogWriter->logf("createTrack_l");
     return track;
 }
 
@@ -1314,6 +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", track->mName);
     status_t status = ALREADY_EXISTS;
 
     // set retry count for buffer fill
@@ -1347,6 +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->logf("destroyTrack_l mName=%d", track->mName);
     track->mState = TrackBase::TERMINATED;
     // active tracks are removed by threadLoop()
     if (mActiveTracks.indexOf(track) < 0) {
@@ -1356,6 +1361,7 @@ 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());
@@ -1892,6 +1898,11 @@ bool AudioFlinger::PlaybackThread::threadLoop()
 
     acquireWakeLock();
 
+    // mNBLogWriter->log can only be called while thread mutex mLock is held.
+    // So if you need to log when mutex is unlocked, set logString to a non-NULL string,
+    // and then that string will be logged at the next convenient opportunity.
+    const char *logString = NULL;
+
     while (!exitPending())
     {
         cpuStats.sample(myName);
@@ -1904,6 +1915,12 @@ bool AudioFlinger::PlaybackThread::threadLoop()
 
             Mutex::Autolock _l(mLock);
 
+            if (logString != NULL) {
+                mNBLogWriter->logTimestamp();
+                mNBLogWriter->log(logString);
+                logString = NULL;
+            }
+
             if (checkForNewParameters_l()) {
                 cacheParameters_l();
             }
@@ -1917,6 +1934,7 @@ bool AudioFlinger::PlaybackThread::threadLoop()
 
                     threadLoop_standby();
 
+                    mNBLogWriter->log("standby");
                     mStandby = true;
                 }
 
@@ -2012,6 +2030,9 @@ 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;
@@ -2143,6 +2164,8 @@ AudioFlinger::MixerThread::MixerThread(const sp<AudioFlinger>& audioFlinger, Aud
         state->mColdGen++;
         state->mDumpState = &mFastMixerDumpState;
         state->mTeeSink = mTeeSink.get();
+        mFastMixerNBLogWriter = audioFlinger->newWriter_l(kFastMixerLogSize, "FastMixer");
+        state->mNBLogWriter = mFastMixerNBLogWriter.get();
         sq->end();
         sq->push(FastMixerStateQueue::BLOCK_UNTIL_PUSHED);
 
@@ -2219,6 +2242,7 @@ AudioFlinger::MixerThread::~MixerThread()
         }
 #endif
     }
+    mAudioFlinger->unregisterWriter(mFastMixerNBLogWriter);
     delete mAudioMixer;
 }
 
@@ -2846,6 +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->logf("prepareTracks_l remove name=%u", track->name());
             mActiveTracks.remove(track);
             if (track->mainBuffer() != mMixBuffer) {
                 chain = getEffectChain_l(track->sessionId());
@@ -3222,6 +3247,9 @@ 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 06a1c8c..5fa7eaf 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -315,6 +315,8 @@ 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;
+                sp<NBLog::Writer>       mNBLogWriter;
 };
 
 // --- PlaybackThread ---
@@ -544,6 +546,8 @@ private:
     sp<NBAIO_Sink>          mTeeSink;
     sp<NBAIO_Source>        mTeeSource;
     uint32_t                mScreenState;   // cached copy of gScreenState
+    static const size_t     kFastMixerLogSize = 8 * 1024;
+    sp<NBLog::Writer>       mFastMixerNBLogWriter;
 public:
     virtual     bool        hasFastMixer() const = 0;
     virtual     FastTrackUnderruns getFastTrackUnderruns(size_t fastIndex) const
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index c5f0ed7..315cbbc 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -569,6 +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", mName);
         track_state state = mState;
         // here the track could be either new, or restarted
         // in both cases "unstop" the track
@@ -611,6 +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", 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
@@ -647,6 +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", mName);
         if (mState == ACTIVE || mState == RESUMING) {
             mState = PAUSING;
             ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get());
@@ -670,6 +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", mName);
         if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED &&
                 mState != PAUSING && mState != IDLE && mState != FLUSHED) {
             return;