From 011aa652a9349750dd6bca1dcb1b82f19e07504e Mon Sep 17 00:00:00 2001
From: Glenn Kasten <gkasten@google.com>
Date: Fri, 18 Jan 2013 15:09:48 -0800
Subject: AudioFlinger uses media.log service for logging

Change-Id: Ia0f8204334f6b233f644d897762a18c95d936b4b
---
 services/audioflinger/Threads.cpp | 28 ++++++++++++++++++++++++++++
 1 file changed, 28 insertions(+)

(limited to 'services/audioflinger/Threads.cpp')

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(),
-- 
cgit v1.1