Merge "Timestamp: Collect and dump statistics"

services/audioflinger/AudioFlinger.h

@@ -63,6 +63,7 @@
 #include <media/VolumeShaper.h>
 
 #include <audio_utils/SimpleLog.h>
+#include <audio_utils/TimestampVerifier.h>
 
 #include "FastCapture.h"
 #include "FastMixer.h"

services/audioflinger/FastMixer.cpp

@@ -336,13 +336,15 @@ void FastMixer::onWork()
 {
     // TODO: pass an ID parameter to indicate which time series we want to write to in NBLog.cpp
     // Or: pass both of these into a single call with a boolean
+    const FastMixerState * const current = (const FastMixerState *) mCurrent;
+    FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;
+
     if (mIsWarm) {
         LOG_HIST_TS();
     } else {
+        dumpState->mTimestampVerifier.discontinuity();
         LOG_AUDIO_STATE();
     }
-    const FastMixerState * const current = (const FastMixerState *) mCurrent;
-    FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;
     const FastMixerState::Command command = mCommand;
     const size_t frameCount = current->mFrameCount;
 
@@ -477,39 +479,47 @@ void FastMixer::onWork()
         mAttemptedWrite = true;
         // FIXME count # of writes blocked excessively, CPU usage, etc. for dump
 
-        ExtendedTimestamp timestamp; // local
-        status_t status = mOutputSink->getTimestamp(timestamp);
-        if (status == NO_ERROR) {
-            const int64_t totalNativeFramesPresented =
-                    timestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL];
-            if (totalNativeFramesPresented <= mTotalNativeFramesWritten) {
-                mNativeFramesWrittenButNotPresented =
-                    mTotalNativeFramesWritten - totalNativeFramesPresented;
-                mTimestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL] =
+        if (mIsWarm) {
+            ExtendedTimestamp timestamp; // local
+            status_t status = mOutputSink->getTimestamp(timestamp);
+            if (status == NO_ERROR) {
+                dumpState->mTimestampVerifier.add(
+                        timestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL],
+                        timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL],
+                        mSampleRate);
+                const int64_t totalNativeFramesPresented =
                         timestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL];
-                mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] =
-                        timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
-                // We don't compensate for server - kernel time difference and
-                // only update latency if we have valid info.
-                dumpState->mLatencyMs =
-                        (double)mNativeFramesWrittenButNotPresented * 1000 / mSampleRate;
+                if (totalNativeFramesPresented <= mTotalNativeFramesWritten) {
+                    mNativeFramesWrittenButNotPresented =
+                        mTotalNativeFramesWritten - totalNativeFramesPresented;
+                    mTimestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL] =
+                            timestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL];
+                    mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] =
+                            timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
+                    // We don't compensate for server - kernel time difference and
+                    // only update latency if we have valid info.
+                    dumpState->mLatencyMs =
+                            (double)mNativeFramesWrittenButNotPresented * 1000 / mSampleRate;
+                } else {
+                    // HAL reported that more frames were presented than were written
+                    mNativeFramesWrittenButNotPresented = 0;
+                    status = INVALID_OPERATION;
+                }
             } else {
-                // HAL reported that more frames were presented than were written
-                mNativeFramesWrittenButNotPresented = 0;
-                status = INVALID_OPERATION;
+                dumpState->mTimestampVerifier.error();
+            }
+            if (status == NO_ERROR) {
+                mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] =
+                        mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
+            } else {
+                // fetch server time if we can't get timestamp
+                mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] =
+                        systemTime(SYSTEM_TIME_MONOTONIC);
+                // clear out kernel cached position as this may get rapidly stale
+                // if we never get a new valid timestamp
+                mTimestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL] = 0;
+                mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] = -1;
             }
-        }
-        if (status == NO_ERROR) {
-            mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] =
-                    mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
-        } else {
-            // fetch server time if we can't get timestamp
-            mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] =
-                    systemTime(SYSTEM_TIME_MONOTONIC);
-            // clear out kernel cached position as this may get rapidly stale
-            // if we never get a new valid timestamp
-            mTimestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL] = 0;
-            mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] = -1;
         }
     }
 }

services/audioflinger/FastMixerDumpState.cpp

@@ -73,6 +73,7 @@ void FastMixerDumpState::dump(int fd) const
                 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
                 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
                 mixPeriodSec * 1e3, mLatencyMs);
+    dprintf(fd, "  FastMixer Timestamp stats: %s\n", mTimestampVerifier.toString().c_str());
 #ifdef FAST_THREAD_STATISTICS
     // find the interval of valid samples
     uint32_t bounds = mBounds;

services/audioflinger/FastMixerDumpState.h

@@ -18,6 +18,7 @@
 #define ANDROID_AUDIO_FAST_MIXER_DUMP_STATE_H
 
 #include <stdint.h>
+#include <audio_utils/TimestampVerifier.h>
 #include "Configuration.h"
 #include "FastThreadDumpState.h"
 #include "FastMixerState.h"
@@ -75,6 +76,9 @@ struct FastMixerDumpState : FastThreadDumpState {
     size_t   mFrameCount;
     uint32_t mTrackMask;        // mask of active tracks
     FastTrackDump   mTracks[FastMixerState::kMaxFastTracks];
+
+    // For timestamp statistics.
+    TimestampVerifier<int64_t /* frame count */, int64_t /* time ns */> mTimestampVerifier;
 };
 
 }   // android

services/audioflinger/Threads.cpp

@@ -853,6 +853,14 @@ void AudioFlinger::ThreadBase::dumpBase(int fd, const Vector<String16>& args __u
     dprintf(fd, "  Input device: %#x (%s)\n", mInDevice, devicesToString(mInDevice).c_str());
     dprintf(fd, "  Audio source: %d (%s)\n", mAudioSource, sourceToString(mAudioSource));
 
+    // Dump timestamp statistics for the Thread types that support it.
+    if (mType == RECORD
+            || mType == MIXER
+            || mType == DUPLICATING
+            || (mType == DIRECT && audio_is_linear_pcm(mHALFormat))) {
+        dprintf(fd, "  Timestamp stats: %s\n", mTimestampVerifier.toString().c_str());
+    }
+
     if (locked) {
         mLock.unlock();
     }
@@ -3205,12 +3213,21 @@ bool AudioFlinger::PlaybackThread::threadLoop()
                 logString = NULL;
             }
 
+            // Collect timestamp statistics for the Playback Thread types that support it.
+            if (mType == MIXER
+                    || mType == DUPLICATING
+                    || (mType == DIRECT && audio_is_linear_pcm(mHALFormat))) { // no indentation
             // Gather the framesReleased counters for all active tracks,
             // and associate with the sink frames written out.  We need
             // this to convert the sink timestamp to the track timestamp.
             bool kernelLocationUpdate = false;
             ExtendedTimestamp timestamp; // use private copy to fetch
-            if (threadloop_getHalTimestamp_l(&timestamp) == OK) {
+            if (mStandby) {
+                mTimestampVerifier.discontinuity();
+            } else if (threadloop_getHalTimestamp_l(&timestamp) == OK) {
+                mTimestampVerifier.add(timestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL],
+                        timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL],
+                        mSampleRate);
                 // We always fetch the timestamp here because often the downstream
                 // sink will block while writing.
 
@@ -3241,7 +3258,10 @@ bool AudioFlinger::PlaybackThread::threadLoop()
                         + mSuspendedFrames; // add frames discarded when suspended
                 mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] =
                         timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
+            } else {
+                mTimestampVerifier.error();
             }
+
             // mFramesWritten for non-offloaded tracks are contiguous
             // even after standby() is called. This is useful for the track frame
             // to sink frame mapping.
@@ -3274,6 +3294,7 @@ bool AudioFlinger::PlaybackThread::threadLoop()
                     }
                 }
             }
+            } // if (mType ... ) { // no indentation
 #if 0
             // logFormat example
             if (z % 100 == 0) {
@@ -6730,8 +6751,9 @@ reacquire_wakelock:
         // Update server timestamp with kernel stats
         if (mPipeSource.get() == nullptr /* don't obtain for FastCapture, could block */) {
             int64_t position, time;
-            int ret = mInput->stream->getCapturePosition(&position, &time);
-            if (ret == NO_ERROR) {
+            if (mStandby) {
+                mTimestampVerifier.discontinuity();
+            } else if (mInput->stream->getCapturePosition(&position, &time) == NO_ERROR) {
                 mTimestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL] = position;
                 mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] = time;
                 // Note: In general record buffers should tend to be empty in
@@ -6739,6 +6761,12 @@ reacquire_wakelock:
                 //
                 // Also, it is not advantageous to call get_presentation_position during the read
                 // as the read obtains a lock, preventing the timestamp call from executing.
+
+                mTimestampVerifier.add(mTimestamp.mPosition[ExtendedTimestamp::LOCATION_KERNEL],
+                        mTimestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL],
+                        mSampleRate);
+            } else {
+                mTimestampVerifier.error();
             }
         }
         // Use this to track timestamp information

services/audioflinger/Threads.h

@@ -499,6 +499,9 @@ protected:
                 sp<NBLog::Writer>       mNBLogWriter;
                 bool                    mSystemReady;
                 ExtendedTimestamp       mTimestamp;
+                TimestampVerifier< // For timestamp statistics.
+                        int64_t /* frame count */, int64_t /* time ns */> mTimestampVerifier;
+
                 // A condition that must be evaluated by the thread loop has changed and
                 // we must not wait for async write callback in the thread loop before evaluating it
                 bool                    mSignalPending;