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/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 @@
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 @@
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/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index c3f08f6..a25fb80 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -227,7 +227,7 @@
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 = 50 * 1024;
sp<MemoryDealer> mLogMemoryDealer; // == 0 when NBLog is disabled
public:
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];
diff --git a/services/audioflinger/AudioMixer.h b/services/audioflinger/AudioMixer.h
index fd21fda..2d00bf5 100644
--- a/services/audioflinger/AudioMixer.h
+++ b/services/audioflinger/AudioMixer.h
@@ -28,6 +28,7 @@
#include <audio_effects/effect_downmix.h>
#include <system/audio.h>
+#include <media/nbaio/NBLog.h>
namespace android {
@@ -76,6 +77,7 @@
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.
@@ -106,13 +108,17 @@
// Enable or disable an allocated track by name
void enable(int name);
void disable(int name);
+ bool enabled(int name);
void setParameter(int name, int target, int param, void *value);
void setBufferProvider(int name, AudioBufferProvider* bufferProvider);
+ AudioBufferProvider* getBufferProvider(int name);
void process(int64_t pts);
uint32_t trackNames() const { return mTrackNames; }
+ uint32_t enabledTrackNames() const { return mState.enabledTracks; }
+ int getFastIndex(int name);
size_t getUnreleasedFrames(int name) const;
@@ -200,7 +206,10 @@
int32_t sessionId;
- int32_t padding[2];
+ int32_t fastIndex;
+ int32_t magic;
+ static const int kMagic = 0x54637281;
+ //int32_t padding[1];
// 16-byte boundary
@@ -210,6 +219,12 @@
void adjustVolumeRamp(bool aux);
size_t getUnreleasedFrames() const { return resampler != NULL ?
resampler->getUnreleasedFrames() : 0; };
+ void checkMagic() {
+ if (magic != kMagic) {
+ ALOGE("magic=%#x fastIndex=%d", magic, fastIndex);
+ }
+ }
+
};
// pad to 32-bytes to fill cache line
@@ -220,7 +235,8 @@
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 +263,11 @@
const uint32_t mSampleRate;
+ NBLog::Writer* mLog;
+ 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..75c3c41 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -21,13 +21,15 @@
// </IMPORTANT_WARNING>
#define LOG_TAG "FastMixer"
-//#define LOG_NDEBUG 0
+#define LOG_NDEBUG 0
#define ATRACE_TAG ATRACE_TAG_AUDIO
#include <sys/atomics.h>
#include <time.h>
#include <utils/Log.h>
+#undef ALOGV
+#define ALOGV(a...) do { } while (0)
#include <utils/Trace.h>
#include <system/audio.h>
#ifdef FAST_MIXER_STATISTICS
@@ -93,6 +95,8 @@
uint32_t warmupCycles = 0; // counter of number of loop cycles required to warmup
NBAIO_Sink* teeSink = NULL; // if non-NULL, then duplicate write() to this non-blocking sink
NBLog::Writer dummyLogWriter, *logWriter = &dummyLogWriter;
+ bool myEnabled[FastMixerState::kMaxFastTracks];
+ memset(myEnabled, 0, sizeof(myEnabled));
for (;;) {
@@ -120,12 +124,16 @@
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
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.
@@ -300,13 +308,21 @@
addedTracks &= ~(1 << i);
const FastTrack* fastTrack = ¤t->mFastTracks[i];
AudioBufferProvider *bufferProvider = fastTrack->mBufferProvider;
+ logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
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);
@@ -317,27 +333,41 @@
}
mixer->setParameter(name, AudioMixer::TRACK, AudioMixer::CHANNEL_MASK,
(void *) fastTrack->mChannelMask);
+ if (!mixer->enabled(name)) {
+ logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+ }
mixer->enable(name);
+ myEnabled[i] = true;
}
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;
+ logWriter->logf("bp %d i=%d %p", __LINE__, i, bufferProvider);
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 +390,9 @@
generations[i] = fastTrack->mGeneration;
}
}
+ if (actuallyModifiedTracks) {
+ logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
+ }
fastTracksGen = current->mFastTracksGen;
@@ -377,6 +410,7 @@
ALOG_ASSERT(mixBuffer != NULL);
// for each track, update volume and check for underrun
unsigned currentTrackMask = current->mTrackMask;
+ logWriter->logf("ctm %#x", currentTrackMask);
while (currentTrackMask != 0) {
i = __builtin_ctz(currentTrackMask);
currentTrackMask &= ~(1 << i);
@@ -410,25 +444,76 @@
underruns.mBitFields.mEmpty++;
underruns.mBitFields.mMostRecent = UNDERRUN_EMPTY;
mixer->disable(name);
+ myEnabled[i] = false;
} else {
// allow mixing partial buffer
underruns.mBitFields.mPartial++;
underruns.mBitFields.mMostRecent = UNDERRUN_PARTIAL;
+ if (!mixer->enabled(name)) {
+ logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+ }
mixer->enable(name);
+ myEnabled[i] = true;
}
} else {
underruns.mBitFields.mFull++;
underruns.mBitFields.mMostRecent = UNDERRUN_FULL;
+ if (!mixer->enabled(name)) {
+ logWriter->logf("enable %d i=%d name=%d", __LINE__, i, name);
+ }
mixer->enable(name);
+ myEnabled[i] = true;
}
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;
if (outputSink == NULL || (OK != outputSink->getNextWriteTimestamp(&pts)))
pts = AudioBufferProvider::kInvalidPTS;
+ // validate that mixer state is correct
+ currentTrackMask = current->mTrackMask;
+ unsigned expectedMixerEnabled = 0;
+ while (currentTrackMask != 0) {
+ i = __builtin_ctz(currentTrackMask);
+ currentTrackMask &= ~(1 << i);
+ const FastTrack* fastTrack = ¤t->mFastTracks[i];
+ int name = fastTrackNames[i];
+ ALOG_ASSERT(name >= 0);
+ bool isEnabled = mixer->enabled(name);
+ if (isEnabled != myEnabled[i]) {
+ logWriter->logTimestamp();
+ logWriter->logf("? i=%d name=%d mixena=%d ftena=%d", i, name, isEnabled,
+ myEnabled[i]);
+ }
+ if (myEnabled[i]) {
+ expectedMixerEnabled |= 1 << name;
+ }
+ AudioBufferProvider *abp = mixer->getBufferProvider(name);
+ if (abp != fastTrack->mBufferProvider) {
+ logWriter->logTimestamp();
+ logWriter->logf("? i=%d name=%d mixbp=%p ftbp=%p", i, name, abp,
+ fastTrack->mBufferProvider);
+ }
+ int fastIndex = mixer->getFastIndex(name);
+ if (fastIndex != (int) i) {
+ logWriter->logTimestamp();
+ logWriter->logf("? i=%d name=%d fastIndex=%d", i, name, fastIndex);
+ }
+ }
+ unsigned mixerEnabled = mixer->enabledTrackNames();
+ if (mixerEnabled != expectedMixerEnabled) {
+ logWriter->logTimestamp();
+ logWriter->logf("? mixena=%#x expected=%#x", mixerEnabled, expectedMixerEnabled);
+ }
+
// process() is CPU-bound
mixer->process(pts);
mixBufferState = MIXED;
@@ -453,7 +538,7 @@
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;
diff --git a/services/audioflinger/StateQueue.h b/services/audioflinger/StateQueue.h
index e33b3c6..313330f 100644
--- a/services/audioflinger/StateQueue.h
+++ b/services/audioflinger/StateQueue.h
@@ -174,7 +174,7 @@
#endif
private:
- static const unsigned kN = 4; // values < 4 are not supported by this code
+ static const unsigned kN = 8; // values < 4 are not supported by this code
T mStates[kN]; // written by mutator, read by observer
// "volatile" is meaningless with SMP, but here it indicates that we're using atomic ops
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index ba848d7..58e3cbe 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("fastTrack0 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("fastTrack 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());
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index fa1e336..8e6b69c 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -315,7 +315,7 @@
// 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 = 8 * 1024;
sp<NBLog::Writer> mNBLogWriter;
};
@@ -546,7 +546,7 @@
sp<NBAIO_Sink> mTeeSink;
sp<NBAIO_Source> mTeeSource;
uint32_t mScreenState; // cached copy of gScreenState
- static const size_t kFastMixerLogSize = 8 * 1024;
+ static const size_t kFastMixerLogSize = 32 * 1024;
sp<NBLog::Writer> mFastMixerNBLogWriter;
public:
virtual bool hasFastMixer() const = 0;
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;