diff options
author | Glenn Kasten <gkasten@google.com> | 2013-02-13 14:46:45 -0800 |
---|---|---|
committer | Glenn Kasten <gkasten@google.com> | 2013-02-13 14:51:50 -0800 |
commit | 0ddd56316262ac74a95e9edb595697c163136d6d (patch) | |
tree | 2ed313557a019eeba286e27a3f4ce2e0a45fba17 /services | |
parent | cd27b0798f6abb34e464acc7c7e97e066cd3c6c7 (diff) | |
download | frameworks_av-0ddd56316262ac74a95e9edb595697c163136d6d.zip frameworks_av-0ddd56316262ac74a95e9edb595697c163136d6d.tar.gz frameworks_av-0ddd56316262ac74a95e9edb595697c163136d6d.tar.bz2 |
Temporary additional logging to investigate bug
The bug appears related to continuing to use an invalid buffer provider
in fast mixer after track destruction, so focus the added logs in that area.
Also includes a bug fix: was calling log in an unsafe place
near Threads.cpp AudioFlinger::PlaybackThread::createTrack_l line 1250.
Details:
- include caller pid or client pid where appropriate
- increase log buffer size
- log mFastIndex when AudioMixer sees an invalid bufferProvider.
- log both potentially modified and actually modified tracks in FastMixer.
- fix benign bug where sq->end() was called more than once.
- log StateQueue push() call and return.
Bug: 6490974
Change-Id: Iee7c8f40e20b6000cd8286c0ec6a14fff4a37af1
Diffstat (limited to 'services')
-rw-r--r-- | services/audioflinger/AudioFlinger.h | 2 | ||||
-rw-r--r-- | services/audioflinger/AudioMixer.cpp | 8 | ||||
-rw-r--r-- | services/audioflinger/AudioMixer.h | 4 | ||||
-rw-r--r-- | services/audioflinger/FastMixer.cpp | 30 | ||||
-rw-r--r-- | services/audioflinger/Threads.cpp | 28 | ||||
-rw-r--r-- | services/audioflinger/Threads.h | 2 | ||||
-rw-r--r-- | services/audioflinger/Tracks.cpp | 14 |
7 files changed, 71 insertions, 17 deletions
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h index c3f08f6..593f131 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 = 10 * 1024; + static const size_t kLogMemorySize = 20 * 1024; sp<MemoryDealer> mLogMemoryDealer; // == 0 when NBLog is disabled public: diff --git a/services/audioflinger/AudioMixer.cpp b/services/audioflinger/AudioMixer.cpp index 08325ad..30d645c 100644 --- a/services/audioflinger/AudioMixer.cpp +++ b/services/audioflinger/AudioMixer.cpp @@ -209,6 +209,7 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId) t->mainBuffer = NULL; t->auxBuffer = NULL; t->downmixerBufferProvider = NULL; + t->fastIndex = -1; status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask); if (status == OK) { @@ -455,6 +456,9 @@ void AudioMixer::setParameter(int name, int target, int param, void *value) // for a specific track? or per mixer? /* case DOWNMIX_TYPE: break */ + case FAST_INDEX: + track.fastIndex = valueInt; + break; default: LOG_FATAL("bad param"); } @@ -1111,8 +1115,8 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts) t.buffer.frameCount = state->frameCount; int valid = t.bufferProvider->getValid(); if (valid != AudioBufferProvider::kValid) { - ALOGE("invalid bufferProvider=%p name=%d frameCount=%d valid=%#x enabledTracks=%#x", - t.bufferProvider, i, t.buffer.frameCount, valid, enabledTracks); + ALOGE("invalid bufferProvider=%p name=%d fastIndex=%d frameCount=%d valid=%#x enabledTracks=%#x", + t.bufferProvider, i, t.fastIndex, t.buffer.frameCount, valid, enabledTracks); // expect to crash } t.bufferProvider->getNextBuffer(&t.buffer, pts); diff --git a/services/audioflinger/AudioMixer.h b/services/audioflinger/AudioMixer.h index fd21fda..f757351 100644 --- a/services/audioflinger/AudioMixer.h +++ b/services/audioflinger/AudioMixer.h @@ -76,6 +76,7 @@ public: MAIN_BUFFER = 0x4002, AUX_BUFFER = 0x4003, DOWNMIX_TYPE = 0X4004, + FAST_INDEX = 0x4005, // for debugging only // for target RESAMPLE SAMPLE_RATE = 0x4100, // Configure sample rate conversion on this track name; // parameter 'value' is the new sample rate in Hz. @@ -200,7 +201,8 @@ private: int32_t sessionId; - int32_t padding[2]; + int32_t fastIndex; + int32_t padding[1]; // 16-byte boundary diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp index 80e37ca..b64c8fb 100644 --- a/services/audioflinger/FastMixer.cpp +++ b/services/audioflinger/FastMixer.cpp @@ -120,6 +120,7 @@ bool FastMixer::threadLoop() FastMixerState::Command command = next->mCommand; if (next != current) { + logWriter->logTimestamp(); logWriter->log("next != current"); // As soon as possible of learning of a new dump area, start using it @@ -301,12 +302,19 @@ bool FastMixer::threadLoop() const FastTrack* fastTrack = ¤t->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) name = mixer->getTrackName(AUDIO_CHANNEL_OUT_STEREO, -555); ALOG_ASSERT(name >= 0); fastTrackNames[i] = name; + mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX, + (void *) i); mixer->setBufferProvider(name, bufferProvider); mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::MAIN_BUFFER, (void *) mixBuffer); @@ -322,22 +330,31 @@ 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); + logWriter->logf("pot. mod. %#x", modifiedTracks); } + unsigned actuallyModifiedTracks = 0; while (modifiedTracks != 0) { i = __builtin_ctz(modifiedTracks); modifiedTracks &= ~(1 << i); const FastTrack* fastTrack = ¤t->mFastTracks[i]; if (fastTrack->mGeneration != generations[i]) { + actuallyModifiedTracks |= 1 << 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); + mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::FAST_INDEX, + (void *) i); mixer->setBufferProvider(name, bufferProvider); if (fastTrack->mVolumeProvider == NULL) { mixer->setParameter(name, AudioMixer::VOLUME, AudioMixer::VOLUME0, @@ -360,6 +377,9 @@ bool FastMixer::threadLoop() generations[i] = fastTrack->mGeneration; } } + if (actuallyModifiedTracks) { + logWriter->logf("act. mod. %#x", actuallyModifiedTracks); + } fastTracksGen = current->mFastTracksGen; @@ -423,6 +443,12 @@ 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 ba848d7..554532d 100644 --- a/services/audioflinger/Threads.cpp +++ b/services/audioflinger/Threads.cpp @@ -1196,6 +1196,8 @@ 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 @@ -1249,7 +1251,6 @@ Exit: if (status) { *status = lStatus; } - mNBLogWriter->logf("createTrack_l"); return track; } @@ -1317,7 +1318,8 @@ 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); + mNBLogWriter->logf("addTrack_l mName=%d mFastIndex=%d caller=%d", track->mName, + track->mFastIndex, IPCThreadState::self()->getCallingPid()); status_t status = ALREADY_EXISTS; // set retry count for buffer fill @@ -1351,7 +1353,9 @@ 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); + mNBLogWriter->logTimestamp(); + mNBLogWriter->logf("destroyTrack_l mName=%d mFastIndex=%d mClientPid=%d", track->mName, + track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1); track->mState = TrackBase::TERMINATED; // active tracks are removed by threadLoop() if (mActiveTracks.indexOf(track) < 0) { @@ -1361,7 +1365,9 @@ 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); + mNBLogWriter->logTimestamp(); + mNBLogWriter->logf("removeTrack_l mName=%d mFastIndex=%d clientPid=%d", track->mName, + track->mFastIndex, track->mClient != 0 ? track->mClient->pid() : -1); track->triggerEvents(AudioSystem::SYNC_EVENT_PRESENTATION_COMPLETE); mTracks.remove(track); deleteTrackName_l(track->name()); @@ -2839,11 +2845,19 @@ track_is_ready: ; block = FastMixerStateQueue::BLOCK_UNTIL_ACKED; pauseAudioWatchdog = true; } - sq->end(); } if (sq != NULL) { + unsigned trackMask = state->mTrackMask; sq->end(didModify); + if (didModify) { + mNBLogWriter->logTimestamp(); + mNBLogWriter->logf("push trackMask=%#x block=%d", trackMask, block); + } sq->push(block); + if (didModify) { + mNBLogWriter->logTimestamp(); + mNBLogWriter->log("pushed"); + } } #ifdef AUDIO_WATCHDOG if (pauseAudioWatchdog && mAudioWatchdog != 0) { @@ -2870,7 +2884,9 @@ 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()); + mNBLogWriter->logTimestamp(); + mNBLogWriter->logf("prepareTracks_l remove name=%u mFastIndex=%d", track->name(), + track->mFastIndex); 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 fa1e336..8497788 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 = 4096; sp<NBLog::Writer> mNBLogWriter; }; diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp index 315cbbc..f679751 100644 --- a/services/audioflinger/Tracks.cpp +++ b/services/audioflinger/Tracks.cpp @@ -351,6 +351,7 @@ 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, @@ -360,6 +361,7 @@ 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() @@ -569,7 +571,8 @@ 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); + thread->mNBLogWriter->logf("start mName=%d mFastIndex=%d caller=%d", mName, mFastIndex, + IPCThreadState::self()->getCallingPid()); track_state state = mState; // here the track could be either new, or restarted // in both cases "unstop" the track @@ -612,7 +615,8 @@ 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); + thread->mNBLogWriter->logf("stop mName=%d mFastIndex=%d caller=%d", mName, mFastIndex, + IPCThreadState::self()->getCallingPid()); 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 @@ -649,7 +653,8 @@ 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); + thread->mNBLogWriter->logf("pause mName=%d mFastIndex=%d caller=%d", mName, mFastIndex, + IPCThreadState::self()->getCallingPid()); if (mState == ACTIVE || mState == RESUMING) { mState = PAUSING; ALOGV("ACTIVE/RESUMING => PAUSING (%d) on thread %p", mName, thread.get()); @@ -673,7 +678,8 @@ 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); + thread->mNBLogWriter->logf("flush mName=%d mFastIndex=%d caller=%d", mName, mFastIndex, + IPCThreadState::self()->getCallingPid()); if (mState != STOPPING_1 && mState != STOPPING_2 && mState != STOPPED && mState != PAUSED && mState != PAUSING && mState != IDLE && mState != FLUSHED) { return; |