summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
Diffstat
-rw-r--r--include/media/nbaio/NBLog.h4
-rw-r--r--services/audioflinger/AudioFlinger.h2
-rw-r--r--services/audioflinger/AudioMixer.cpp72
-rw-r--r--services/audioflinger/AudioMixer.h25
-rw-r--r--services/audioflinger/FastMixer.cpp93
-rw-r--r--services/audioflinger/StateQueue.h2
-rw-r--r--services/audioflinger/Threads.cpp30
-rw-r--r--services/audioflinger/Threads.h4
-rw-r--r--services/audioflinger/Tracks.cpp14
9 files changed, 220 insertions, 26 deletions
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 @@ public:
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 @@ public:
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 @@ 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 = 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 @@ effect_descriptor_t AudioMixer::dwnmFxDesc;
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 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr
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 @@ AudioMixer::AudioMixer(size_t frameCount, uint32_t sampleRate, uint32_t maxNumTr
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 @@ AudioMixer::~AudioMixer()
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 @@ int AudioMixer::getTrackName(audio_channel_mask_t channelMask, int sessionId)
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 @@ void AudioMixer::deleteTrackName(int name)
{
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 @@ void AudioMixer::enable(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 (!track.enabled) {
+ mLog->logf("enable %d", name);
track.enabled = true;
ALOGV("enable(%d)", name);
invalidateState(1 << name);
@@ -400,19 +417,36 @@ void AudioMixer::disable(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 (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 @@ 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");
}
@@ -540,6 +577,7 @@ void AudioMixer::setParameter(int name, int target, int param, void *value)
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 @@ bool AudioMixer::track_t::setResampler(uint32_t value, uint32_t devSampleRate)
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 @@ size_t AudioMixer::getUnreleasedFrames(int name) const
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 @@ void AudioMixer::setBufferProvider(int name, AudioBufferProvider* bufferProvider
}
}
+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 @@ void AudioMixer::process__validate(state_t* state, int64_t pts)
}
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::track__16BitsMono(track_t* t, int32_t* out, size_t frameCount,
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 @@ void AudioMixer::process__genericNoResampling(state_t* state, int64_t pts)
// 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 @@ 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);
@@ -1211,6 +1272,7 @@ void AudioMixer::process__genericResampling(state_t* state, int64_t pts)
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__genericResampling(state_t* state, int64_t pts)
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 @@ void AudioMixer::process__TwoTracks16BitsStereoNoResampling(state_t* state,
{
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 @@ 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.
@@ -106,13 +108,17 @@ public:
// 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 @@ private:
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 @@ private:
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 @@ private:
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 @@ private:
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 @@ bool FastMixer::threadLoop()
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 @@ 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
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 @@ bool FastMixer::threadLoop()
addedTracks &= ~(1 << i);
const FastTrack* fastTrack = &current->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 @@ bool FastMixer::threadLoop()
}
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 = &current->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 @@ bool FastMixer::threadLoop()
generations[i] = fastTrack->mGeneration;
}
}
+ if (actuallyModifiedTracks) {
+ logWriter->logf("act. mod. %#x", actuallyModifiedTracks);
+ }
fastTracksGen = current->mFastTracksGen;
@@ -377,6 +410,7 @@ bool FastMixer::threadLoop()
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 @@ bool FastMixer::threadLoop()
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 = &current->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 @@ bool FastMixer::threadLoop()
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 @@ public:
#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 @@ 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());
@@ -2149,6 +2155,7 @@ AudioFlinger::MixerThread::MixerThread(const sp<AudioFlinger>& audioFlinger, Aud
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 @@ AudioFlinger::PlaybackThread::mixer_state AudioFlinger::MixerThread::prepareTrac
// 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 @@ 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 +2886,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..8e6b69c 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 = 8 * 1024;
sp<NBLog::Writer> mNBLogWriter;
};
@@ -546,7 +546,7 @@ private:
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 @@ 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;
generated by cgit v1.1 at 2024-05-15 13:18:38 +0000