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

5 files changed, 11 insertions, 41 deletions

diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index 593f131..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 = 20 * 1024;
+    static const size_t kLogMemorySize = 10 * 1024;
     sp<MemoryDealer>    mLogMemoryDealer;   // == 0 when NBLog is disabled
 public:
 
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index 467da39..80e37ca 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -301,11 +301,6 @@ bool FastMixer::threadLoop()
                     const FastTrack* fastTrack = &current->mFastTracks[i];
                     AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
                     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)
@@ -340,11 +335,6 @@ bool FastMixer::threadLoop()
                     if (fastTrack->mGeneration != generations[i]) {
                         AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
                         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);
@@ -433,12 +423,6 @@ bool FastMixer::threadLoop()
                 }
                 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;
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 8cc5f6c..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());
@@ -2876,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 8497788..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 = 4096;
+                static const size_t     kLogSize = 512;
                 sp<NBLog::Writer>       mNBLogWriter;
 };
 
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;