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/Threads.cpp b/services/audioflinger/Threads.cpp
index ba848d7..a19c5f4 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -1196,6 +1196,8 @@
{ // 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 @@
if (status) {
*status = lStatus;
}
- mNBLogWriter->logf("createTrack_l");
return track;
}
@@ -1317,7 +1318,8 @@
// 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 @@
// 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::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());
@@ -2149,6 +2155,7 @@
FastTrack *fastTrack = &state->mFastTracks[0];
// wrap the source side of the MonoPipe to make it an AudioBufferProvider
fastTrack->mBufferProvider = new SourceAudioBufferProvider(new MonoPipeReader(monoPipe));
+ mNBLogWriter->logf("ft0 bp %p", fastTrack->mBufferProvider);
fastTrack->mVolumeProvider = NULL;
fastTrack->mGeneration++;
state->mFastTracksGen++;
@@ -2553,6 +2560,7 @@
// was it previously inactive?
if (!(state->mTrackMask & (1 << j))) {
ExtendedAudioBufferProvider *eabp = track;
+ mNBLogWriter->logf("j=%d bp %p", j, eabp);
VolumeProvider *vp = track;
fastTrack->mBufferProvider = eabp;
fastTrack->mVolumeProvider = vp;
@@ -2839,11 +2847,19 @@
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 +2886,9 @@
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());