diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp index 2e7449e92949b..18eb8ca5e361b 100644 --- a/services/audioflinger/AudioFlinger.cpp +++ b/services/audioflinger/AudioFlinger.cpp @@ -63,6 +63,18 @@ // ---------------------------------------------------------------------------- +// Note: the following macro is used for extremely verbose logging message. In +// order to run with LOG_ASSERT turned on, we need to have LOG_NDEBUG set to 0; +// but one side effect of this is to turn all LOGV's as well. Some messages are +// so verbose that we want to suppress them even when we have LOG_ASSERT turned +// on. Do not uncomment the #def below unless you really know what you are +// doing and want to see all of the extremely verbose messages. +//#define VERY_VERY_VERBOSE_LOGGING +#ifdef VERY_VERY_VERBOSE_LOGGING +#define LOGVV LOGV +#else +#define LOGVV(a...) do { } while(0) +#endif namespace android { @@ -3843,6 +3855,7 @@ AudioFlinger::PlaybackThread::TimedTrack::TimedTrack( frameCount, sharedBuffer, sessionId), mQueueHeadInFlight(false), mTrimQueueHeadOnRelease(false), + mFramesPendingInQueue(0), mTimedSilenceBuffer(NULL), mTimedSilenceBufferSize(0), mTimedAudioOutputOnTime(false), @@ -3921,9 +3934,9 @@ void AudioFlinger::PlaybackThread::TimedTrack::trimTimedBufferQueue_l() { } } - size_t trimIndex; - for (trimIndex = 0; trimIndex < mTimedBufferQueue.size(); trimIndex++) { - int64_t frameCount = mTimedBufferQueue[trimIndex].buffer()->size() + size_t trimEnd; + for (trimEnd = 0; trimEnd < mTimedBufferQueue.size(); trimEnd++) { + int64_t frameCount = mTimedBufferQueue[trimEnd].buffer()->size() / mCblk->frameSize; int64_t bufEnd; @@ -3936,7 +3949,7 @@ void AudioFlinger::PlaybackThread::TimedTrack::trimTimedBufferQueue_l() { __PRETTY_FUNCTION__); break; } - bufEnd += mTimedBufferQueue[trimIndex].pts(); + bufEnd += mTimedBufferQueue[trimEnd].pts(); if (bufEnd > mediaTimeNow) break; @@ -3944,17 +3957,55 @@ void AudioFlinger::PlaybackThread::TimedTrack::trimTimedBufferQueue_l() { // Is the buffer we want to use in the middle of a mix operation right // now? If so, don't actually trim it. Just wait for the releaseBuffer // from the mixer which should be coming back shortly. - if (!trimIndex && mQueueHeadInFlight) { + if (!trimEnd && mQueueHeadInFlight) { mTrimQueueHeadOnRelease = true; } } size_t trimStart = mTrimQueueHeadOnRelease ? 1 : 0; - if (trimStart < trimIndex) { - mTimedBufferQueue.removeItemsAt(trimStart, trimIndex); + if (trimStart < trimEnd) { + // Update the bookkeeping for framesReady() + for (size_t i = trimStart; i < trimEnd; ++i) { + updateFramesPendingAfterTrim_l(mTimedBufferQueue[i], "trim"); + } + + // Now actually remove the buffers from the queue. + mTimedBufferQueue.removeItemsAt(trimStart, trimEnd); } } +void AudioFlinger::PlaybackThread::TimedTrack::trimTimedBufferQueueHead_l( + const char* logTag) { + LOG_ASSERT(mTimedBufferQueue.size() > 0, + "%s called (reason \"%s\"), but timed buffer queue has no" + " elements to trim.", __FUNCTION__, logTag); + + updateFramesPendingAfterTrim_l(mTimedBufferQueue[0], logTag); + mTimedBufferQueue.removeAt(0); +} + +void AudioFlinger::PlaybackThread::TimedTrack::updateFramesPendingAfterTrim_l( + const TimedBuffer& buf, + const char* logTag) { + uint32_t bufBytes = buf.buffer()->size(); + uint32_t consumedAlready = buf.position(); + + LOG_ASSERT(consumedAlready <= bufFrames, + "Bad bookkeeping while updating frames pending. Timed buffer is" + " only %u bytes long, but claims to have consumed %u" + " bytes. (update reason: \"%s\")", + bufFrames, consumedAlready, logTag); + + uint32_t bufFrames = (bufBytes - consumedAlready) / mCblk->frameSize; + LOG_ASSERT(mFramesPendingInQueue >= bufFrames, + "Bad bookkeeping while updating frames pending. Should have at" + " least %u queued frames, but we think we have only %u. (update" + " reason: \"%s\")", + bufFrames, mFramesPendingInQueue, logTag); + + mFramesPendingInQueue -= bufFrames; +} + status_t AudioFlinger::PlaybackThread::TimedTrack::queueTimedBuffer( const sp& buffer, int64_t pts) { @@ -3966,6 +4017,8 @@ status_t AudioFlinger::PlaybackThread::TimedTrack::queueTimedBuffer( Mutex::Autolock _l(mTimedBufferQueueLock); + uint32_t bufFrames = buffer->size() / mCblk->frameSize; + mFramesPendingInQueue += bufFrames; mTimedBufferQueue.add(TimedBuffer(buffer, pts)); return NO_ERROR; @@ -3974,7 +4027,7 @@ status_t AudioFlinger::PlaybackThread::TimedTrack::queueTimedBuffer( status_t AudioFlinger::PlaybackThread::TimedTrack::setMediaTimeTransform( const LinearTransform& xform, TimedAudioTrack::TargetTimeline target) { - LOGV("%s az=%lld bz=%lld n=%d d=%u tgt=%d", __PRETTY_FUNCTION__, + LOGVV("setMediaTimeTransform az=%lld bz=%lld n=%d d=%u tgt=%d", xform.a_zero, xform.b_zero, xform.a_to_b_numer, xform.a_to_b_denom, target); @@ -4050,7 +4103,7 @@ status_t AudioFlinger::PlaybackThread::TimedTrack::getNextBuffer( LOGW("timedGetNextBuffer transform failed"); buffer->raw = 0; buffer->frameCount = 0; - mTimedBufferQueue.removeAt(0); + trimTimedBufferQueueHead_l("getNextBuffer; no transform"); return NO_ERROR; } @@ -4079,18 +4132,18 @@ status_t AudioFlinger::PlaybackThread::TimedTrack::getNextBuffer( int64_t sampleDelta; if (llabs(effectivePTS - pts) >= (static_cast(1) << 31)) { LOGV("*** head buffer is too far from PTS: dropped buffer"); - mTimedBufferQueue.removeAt(0); + trimTimedBufferQueueHead_l("getNextBuffer, buf pts too far from mix"); continue; } if (!mLocalTimeToSampleTransform.doForwardTransform( (effectivePTS - pts) << 32, &sampleDelta)) { LOGV("*** too late during sample rate transform: dropped buffer"); - mTimedBufferQueue.removeAt(0); + trimTimedBufferQueueHead_l("getNextBuffer, bad local to sample"); continue; } - LOGV("*** %s head.pts=%lld head.pos=%d pts=%lld sampleDelta=[%d.%08x]", - __PRETTY_FUNCTION__, head.pts(), head.position(), pts, + LOGVV("*** getNextBuffer head.pts=%lld head.pos=%d pts=%lld sampleDelta=[%d.%08x]", + head.pts(), head.position(), pts, static_cast((sampleDelta >= 0 ? 0 : 1) + (sampleDelta >> 32)), static_cast(sampleDelta & 0xFFFFFFFF)); @@ -4110,7 +4163,7 @@ status_t AudioFlinger::PlaybackThread::TimedTrack::getNextBuffer( // with the last output timedYieldSamples_l(buffer); - LOGV("*** on time: head.pos=%d frameCount=%u", head.position(), buffer->frameCount); + LOGVV("*** on time: head.pos=%d frameCount=%u", head.position(), buffer->frameCount); return NO_ERROR; } else if (sampleDelta > 0) { // the gap between the current output position and the proper start of @@ -4130,7 +4183,7 @@ status_t AudioFlinger::PlaybackThread::TimedTrack::getNextBuffer( // all the remaining samples in the head are too late, so // drop it and move on LOGV("*** too late: dropped buffer"); - mTimedBufferQueue.removeAt(0); + trimTimedBufferQueueHead_l("getNextBuffer, dropped late buffer"); continue; } else { // skip over the late samples @@ -4226,9 +4279,16 @@ void AudioFlinger::PlaybackThread::TimedTrack::releaseBuffer( (buffer->frameCount * mCblk->frameSize)); mQueueHeadInFlight = false; + LOG_ASSERT(mFramesPendingInQueue >= buffer->frameCount, + "Bad bookkeeping during releaseBuffer! Should have at" + " least %u queued frames, but we think we have only %u", + buffer->frameCount, mFramesPendingInQueue); + + mFramesPendingInQueue -= buffer->frameCount; + if ((static_cast(head.position()) >= head.buffer()->size()) || mTrimQueueHeadOnRelease) { - mTimedBufferQueue.removeAt(0); + trimTimedBufferQueueHead_l("releaseBuffer"); mTrimQueueHeadOnRelease = false; } } else { @@ -4243,14 +4303,7 @@ done: uint32_t AudioFlinger::PlaybackThread::TimedTrack::framesReady() const { Mutex::Autolock _l(mTimedBufferQueueLock); - - uint32_t frames = 0; - for (size_t i = 0; i < mTimedBufferQueue.size(); i++) { - const TimedBuffer& tb = mTimedBufferQueue[i]; - frames += (tb.buffer()->size() - tb.position()) / mCblk->frameSize; - } - - return frames; + return mFramesPendingInQueue; } AudioFlinger::PlaybackThread::TimedTrack::TimedBuffer::TimedBuffer() diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h index 0eed5f997e58a..289c506eaf388 100644 --- a/services/audioflinger/AudioFlinger.h +++ b/services/audioflinger/AudioFlinger.h @@ -697,32 +697,28 @@ private: TimedBuffer(const sp& buffer, int64_t pts); const sp& buffer() const { return mBuffer; } int64_t pts() const { return mPTS; } - int position() const { return mPosition; } - void setPosition(int pos) { mPosition = pos; } + uint32_t position() const { return mPosition; } + void setPosition(uint32_t pos) { mPosition = pos; } private: sp mBuffer; - int64_t mPTS; - int mPosition; + int64_t mPTS; + uint32_t mPosition; }; + // Mixer facing methods. virtual bool isTimedTrack() const { return true; } - virtual uint32_t framesReady() const; - virtual status_t getNextBuffer(AudioBufferProvider::Buffer* buffer, int64_t pts); virtual void releaseBuffer(AudioBufferProvider::Buffer* buffer); - void timedYieldSamples_l(AudioBufferProvider::Buffer* buffer); - void timedYieldSilence_l(uint32_t numFrames, - AudioBufferProvider::Buffer* buffer); + // Client/App facing methods. status_t allocateTimedBuffer(size_t size, sp* buffer); status_t queueTimedBuffer(const sp& buffer, int64_t pts); status_t setMediaTimeTransform(const LinearTransform& xform, TimedAudioTrack::TargetTimeline target); - void trimTimedBufferQueue_l(); private: TimedTrack(const wp& thread, @@ -735,6 +731,14 @@ private: const sp& sharedBuffer, int sessionId); + void timedYieldSamples_l(AudioBufferProvider::Buffer* buffer); + void timedYieldSilence_l(uint32_t numFrames, + AudioBufferProvider::Buffer* buffer); + void trimTimedBufferQueue_l(); + void trimTimedBufferQueueHead_l(const char* logTag); + void updateFramesPendingAfterTrim_l(const TimedBuffer& buf, + const char* logTag); + uint64_t mLocalTimeFreq; LinearTransform mLocalTimeToSampleTransform; LinearTransform mMediaTimeToSampleTransform; @@ -743,6 +747,7 @@ private: Vector mTimedBufferQueue; bool mQueueHeadInFlight; bool mTrimQueueHeadOnRelease; + uint32_t mFramesPendingInQueue; uint8_t* mTimedSilenceBuffer; uint32_t mTimedSilenceBufferSize;