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.
- increase StateQueue size from 4 to 8 entries
- log mixer->enable(), bufferProvider, and currentTrackMask
- log buffer provider addresses
- increase fast mixer log buffer again
- check logf format vs. argument list compatibility
- add logging to AudioMixer
- add checking of magic field in AudioMixer to detect overwrites
- add bool AudioMixer::enabled()
Bug: 6490974
Change-Id: I1f3f18aa62d9fbd35bc32285b669f5ba40efe28e
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 @@
// 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()
{
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 @@
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 @@
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 @@
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 @@
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;