diff options
author | Glenn Kasten <gkasten@google.com> | 2013-02-15 23:54:53 +0000 |
---|---|---|
committer | Android (Google) Code Review <android-gerrit@google.com> | 2013-02-15 23:54:53 +0000 |
commit | e96cdab491551ced9d529a2b9587508b92cf7f45 (patch) | |
tree | d353bbce83589cf73dc182802cea372803077378 /services | |
parent | 7aa1237287c43aca1c6bab776573062a66ebd154 (diff) | |
parent | 32584a7d672864b20ab8b83a3cb23c1858e908b7 (diff) | |
download | frameworks_av-e96cdab491551ced9d529a2b9587508b92cf7f45.zip frameworks_av-e96cdab491551ced9d529a2b9587508b92cf7f45.tar.gz frameworks_av-e96cdab491551ced9d529a2b9587508b92cf7f45.tar.bz2 |
Merge "Temporary additional logging to investigate bug"
Diffstat (limited to 'services')
-rw-r--r-- | services/audioflinger/AudioFlinger.h | 2 | ||||
-rw-r--r-- | services/audioflinger/AudioMixer.cpp | 72 | ||||
-rw-r--r-- | services/audioflinger/AudioMixer.h | 25 | ||||
-rw-r--r-- | services/audioflinger/FastMixer.cpp | 93 | ||||
-rw-r--r-- | services/audioflinger/StateQueue.h | 2 | ||||
-rw-r--r-- | services/audioflinger/Threads.cpp | 30 | ||||
-rw-r--r-- | services/audioflinger/Threads.h | 4 | ||||
-rw-r--r-- | services/audioflinger/Tracks.cpp | 14 |
8 files changed, 218 insertions, 24 deletions
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 = ¤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 @@ 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 = ¤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 @@ 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 = ¤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 @@ 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; |