TimedAudio: Track of the number of pending frames.

Keep track of the number of frames pending in the timed audio queue so
we can implement framesReady in O(1) time instead of O(N).  This
change partially addresses bug 6020970; the bug will be completely
addressed once this change has been up-integrated into master.

Change-Id: I599eb15ea1f6d715b97b30e65214fb6fadd169df
Signed-off-by: John Grossman <johngro@google.com>

Author: johngro

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,25 +3949,63 @@ void AudioFlinger::PlaybackThread::TimedTrack::trimTimedBufferQueue_l() {
                  __PRETTY_FUNCTION__);
             break;
         }
-        bufEnd += mTimedBufferQueue[trimIndex].pts();
+        bufEnd += mTimedBufferQueue[trimEnd].pts();
 
         if (bufEnd > mediaTimeNow)
             break;
 
         // 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<IMemory>& 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<int64_t>(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<int32_t>((sampleDelta >= 0 ? 0 : 1) + (sampleDelta >> 32)),
              static_cast<uint32_t>(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<size_t>(head.position()) >= head.buffer()->size())
             || mTrimQueueHeadOnRelease) {
-            mTimedBufferQueue.removeAt(0);
+            trimTimedBufferQueueHead_l("releaseBuffer");
             mTrimQueueHeadOnRelease = false;
         }
     } else {
@@ -4243,14 +4303,7 @@ void AudioFlinger::PlaybackThread::TimedTrack::releaseBuffer(
 
 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()

services/audioflinger/AudioFlinger.h

@@ -697,32 +697,28 @@ class AudioFlinger :
                 TimedBuffer(const sp<IMemory>& buffer, int64_t pts);
                 const sp<IMemory>& 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<IMemory> 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<IMemory>* buffer);
             status_t    queueTimedBuffer(const sp<IMemory>& buffer,
                                          int64_t pts);
             status_t    setMediaTimeTransform(const LinearTransform& xform,
                                               TimedAudioTrack::TargetTimeline target);
-            void        trimTimedBufferQueue_l();
 
           private:
             TimedTrack(const wp<ThreadBase>& thread,
@@ -735,6 +731,14 @@ class AudioFlinger :
                        const sp<IMemory>& 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 @@ class AudioFlinger :
             Vector<TimedBuffer> mTimedBufferQueue;
             bool                mQueueHeadInFlight;
             bool                mTrimQueueHeadOnRelease;
+            uint32_t            mFramesPendingInQueue;
 
             uint8_t*            mTimedSilenceBuffer;
             uint32_t            mTimedSilenceBufferSize;