From ab7d72f0804fbb7e91ad9d2a16f826d97e20e5d0 Mon Sep 17 00:00:00 2001 From: Glenn Kasten Date: Wed, 27 Feb 2013 09:05:28 -0800 Subject: 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 --- include/media/nbaio/NBLog.h | 4 ++-- services/audioflinger/AudioMixer.cpp | 7 ++++++- services/audioflinger/AudioMixer.h | 8 +++++++- services/audioflinger/FastMixer.cpp | 24 +++++++----------------- services/audioflinger/Threads.cpp | 13 ------------- services/audioflinger/Threads.h | 4 ++-- services/audioflinger/Tracks.cpp | 4 ---- 7 files changed, 24 insertions(+), 40 deletions(-) diff --git a/include/media/nbaio/NBLog.h b/include/media/nbaio/NBLog.h index 8fc417f..107ba66 100644 --- a/include/media/nbaio/NBLog.h +++ b/include/media/nbaio/NBLog.h @@ -115,7 +115,7 @@ public: virtual ~Writer() { } virtual void log(const char *string); - virtual void logf(const char *fmt, ...); + virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3))); virtual void logvf(const char *fmt, va_list ap); virtual void logTimestamp(); virtual void logTimestamp(const struct timespec& ts); @@ -149,7 +149,7 @@ public: LockedWriter(size_t size, void *shared); virtual void log(const char *string); - virtual void logf(const char *fmt, ...); + virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3))); virtual void logvf(const char *fmt, va_list ap); virtual void logTimestamp(); virtual void logTimestamp(const struct timespec& ts); 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 #include +#include 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 = ¤t->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) { - 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) // destroyTrack_l() must be called with ThreadBase::mLock held void AudioFlinger::PlaybackThread::destroyTrack_l(const sp& 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) void AudioFlinger::PlaybackThread::removeTrack_l(const sp& 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& 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 > > mSuspendedSessions; - static const size_t kLogSize = 512; + static const size_t kLogSize = 4 * 1024; sp mNBLogWriter; }; @@ -546,7 +546,7 @@ private: sp mTeeSink; sp mTeeSource; uint32_t mScreenState; // cached copy of gScreenState - static const size_t kFastMixerLogSize = 8 * 1024; + static const size_t kFastMixerLogSize = 4 * 1024; sp 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 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 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 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 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; -- cgit v1.1