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()
- increase log buffer sizes yet again
- enable assertion checking without ALOGV
- improve a few log messages
- check for corruption in more places
- log in all the process hooks
- add new mixer APIs so we can check for corruption of mixer state
- fix a build warning
Bug: 6490974
Change-Id: Ib0c4a73dcf606ef9bd898313b3b40ef61ab42f51
diff --git a/services/audioflinger/AudioMixer.cpp b/services/audioflinger/AudioMixer.cpp
index 08325ad..2d7894d 100644
--- a/services/audioflinger/AudioMixer.cpp
+++ b/services/audioflinger/AudioMixer.cpp
@@ -16,7 +16,7 @@
*/
#define LOG_TAG "AudioMixer"
-//#define LOG_NDEBUG 0
+#define LOG_NDEBUG 0
#include <stdint.h>
#include <string.h>
@@ -25,6 +25,8 @@
#include <utils/Errors.h>
#include <utils/Log.h>
+#undef ALOGV
+#define ALOGV(a...) do { } while (0)
#include <cutils/bitops.h>
#include <cutils/compiler.h>
@@ -98,7 +100,7 @@
AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTracks)
: mTrackNames(0), mConfiguredNames((maxNumTracks >= 32 ? 0 : 1 << maxNumTracks) - 1),
- mSampleRate(sampleRate)
+ mSampleRate(sampleRate), mLog(&mDummyLog)
{
// AudioMixer is not yet capable of multi-channel beyond stereo
COMPILE_TIME_ASSERT_FUNCTION_SCOPE(2 == MAX_NUM_CHANNELS);
@@ -122,6 +124,7 @@
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
@@ -131,6 +134,7 @@
for (unsigned i=0 ; i < MAX_NUM_TRACKS ; i++) {
t->resampler = NULL;
t->downmixerBufferProvider = NULL;
+ t->magic = track_t::kMagic;
t++;
}
@@ -169,6 +173,12 @@
delete [] mState.resampleTemp;
}
+void AudioMixer::setLog(NBLog::Writer *log)
+{
+ mLog = log;
+ mState.mLog = log;
+}
+
int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
{
uint32_t names = (~mTrackNames) & mConfiguredNames;
@@ -209,9 +219,12 @@
t->mainBuffer = NULL;
t->auxBuffer = NULL;
t->downmixerBufferProvider = NULL;
+ t->fastIndex = -1;
+ // t->magic unchanged
status_t status = initTrackDownmix(&mState.tracks[n], n, channelMask);
if (status == OK) {
+ mLog->logf("getTrackName %d", n);
return TRACK0 + n;
}
ALOGE("AudioMixer::getTrackName(0x%x) failed, error preparing track for downmix",
@@ -366,9 +379,11 @@
{
ALOGV("AudioMixer::deleteTrackName(%d)", name);
name -= TRACK0;
+ mLog->logf("deleteTrackName %d", name);
ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
ALOGV("deleteTrackName(%d)", name);
track_t& track(mState.tracks[ name ]);
+ track.checkMagic();
if (track.enabled) {
track.enabled = false;
invalidateState(1<<name);
@@ -387,8 +402,10 @@
name -= TRACK0;
ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
track_t& track = mState.tracks[name];
+ track.checkMagic();
if (!track.enabled) {
+ mLog->logf("enable %d", name);
track.enabled = true;
ALOGV("enable(%d)", name);
invalidateState(1 << name);
@@ -400,19 +417,36 @@
name -= TRACK0;
ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
track_t& track = mState.tracks[name];
+ track.checkMagic();
if (track.enabled) {
+ mLog->logf("disable %d", name);
track.enabled = false;
ALOGV("disable(%d)", name);
invalidateState(1 << name);
}
}
+bool AudioMixer::enabled(int name)
+{
+ name -= TRACK0;
+ ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+ track_t& track = mState.tracks[name];
+ track.checkMagic();
+#if 0
+ // can't do this because mState.enabledTracks is updated lazily
+ ALOG_ASSERT(track.enabled == ((mState.enabledTracks & (1 << name)) != 0));
+#endif
+
+ return track.enabled;
+}
+
void AudioMixer::setParameter(int name, int target, int param, void *value)
{
name -= TRACK0;
ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
track_t& track = mState.tracks[name];
+ track.checkMagic();
int valueInt = (int)value;
int32_t *valueBuf = (int32_t *)value;
@@ -455,6 +489,9 @@
// for a specific track? or per mixer?
/* case DOWNMIX_TYPE:
break */
+ case FAST_INDEX:
+ track.fastIndex = valueInt;
+ break;
default:
LOG_FATAL("bad param");
}
@@ -540,6 +577,7 @@
bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)
{
+ checkMagic();
if (value != devSampleRate || resampler != NULL) {
if (sampleRate != value) {
sampleRate = value;
@@ -572,6 +610,7 @@
inline
void AudioMixer::track_t::adjustVolumeRamp(bool aux)
{
+ checkMagic();
for (uint32_t i=0 ; i<MAX_NUM_CHANNELS ; i++) {
if (((volumeInc[i]>0) && (((prevVolume[i]+volumeInc[i])>>16) >= volume[i])) ||
((volumeInc[i]<0) && (((prevVolume[i]+volumeInc[i])>>16) <= volume[i]))) {
@@ -600,8 +639,10 @@
void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider)
{
name -= TRACK0;
+ mLog->logf("set bp %d=%p", name, bufferProvider);
ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+ mState.tracks[name].checkMagic();
if (mState.tracks[name].downmixerBufferProvider != NULL) {
// update required?
if (mState.tracks[name].downmixerBufferProvider->mTrackBufferProvider != bufferProvider) {
@@ -619,10 +660,27 @@
}
}
+AudioBufferProvider* AudioMixer::getBufferProvider(int name)
+{
+ name -= TRACK0;
+ ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+ mState.tracks[name].checkMagic();
+ return mState.tracks[name].bufferProvider;
+}
+int AudioMixer::getFastIndex(int name)
+{
+ name -= TRACK0;
+ ALOG_ASSERT(uint32_t(name) < MAX_NUM_TRACKS, "bad track name %d", name);
+ mState.tracks[name].checkMagic();
+ return mState.tracks[name].fastIndex;
+}
void AudioMixer::process(int64_t pts)
{
+ if (mState.needsChanged) {
+ mLog->logf("process needs=%#x", mState.needsChanged);
+ }
mState.hook(&mState, pts);
}
@@ -647,6 +705,7 @@
}
state->enabledTracks &= ~disabled;
state->enabledTracks |= enabled;
+ state->mLog->logf("process_validate ena=%#x", state->enabledTracks);
// compute everything we need...
int countActiveTracks = 0;
@@ -1058,6 +1117,7 @@
void AudioMixer::process__nop(state_t* state, int64_t pts)
{
uint32_t e0 = state->enabledTracks;
+ state->mLog->logf("process_nop ena=%#x", e0);
size_t bufSize = state->frameCount * sizeof(int16_t) * MAX_NUM_CHANNELS;
while (e0) {
// process by group of tracks with same output buffer to
@@ -1103,6 +1163,7 @@
// acquire each track's buffer
uint32_t enabledTracks = state->enabledTracks;
+ state->mLog->logf("process_gNR ena=%#x", enabledTracks);
uint32_t e0 = enabledTracks;
while (e0) {
const int i = 31 - __builtin_clz(e0);
@@ -1111,8 +1172,8 @@
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);
@@ -1211,6 +1272,7 @@
size_t numFrames = state->frameCount;
uint32_t e0 = state->enabledTracks;
+ state->mLog->logf("process_gR ena=%#x", e0);
while (e0) {
// process by group of tracks with same output buffer
// to optimize cache use
@@ -1275,6 +1337,7 @@
void AudioMixer::process__OneTrack16BitsStereoNoResampling(state_t* state,
int64_t pts)
{
+ state->mLog->logf("process_1TSNR ena=%#x", state->enabledTracks);
// This method is only called when state->enabledTracks has exactly
// one bit set. The asserts below would verify this, but are commented out
// since the whole point of this method is to optimize performance.
@@ -1344,6 +1407,7 @@
{
int i;
uint32_t en = state->enabledTracks;
+ state->mLog->logf("process_2TSNR ena=%#x", en);
i = 31 - __builtin_clz(en);
const track_t& t0 = state->tracks[i];