AudioFlinger: Add latency measurements from timestamp

Replaces main and aux buf from track dump.

Bug: 80272001
Test: adb shell dumpsys media.audio_flinger
Change-Id: I5d6565410e652ec7fc6701b171d299dea9f7bc3e

include/private/media/AudioTrackShared.h

@@ -538,6 +538,10 @@ public:
         mTimestampMutator.push(timestamp);
     }
 
+    virtual ExtendedTimestamp getTimestamp() const {
+        return mTimestampMutator.last();
+    }
+
     // Flushes the shared ring buffer if the client had requested it using mStreaming.mFlush.
     // If flush occurs then:
     //   cblk->u.mStreaming.mFront, ServerProxy::mFlush and ServerProxy::mFlushed will be modified

media/libaudioclient/include/media/AudioTimestamp.h

@@ -135,6 +135,21 @@ struct alignas(8) /* bug 29096183, bug 29108507 */ ExtendedTimestamp {
         return INVALID_OPERATION;
     }
 
+    double getOutputServerLatencyMs(uint32_t sampleRate) const {
+        return getLatencyMs(sampleRate, LOCATION_SERVER, LOCATION_KERNEL);
+    }
+
+    double getLatencyMs(uint32_t sampleRate, Location location1, Location location2) const {
+        if (mTimeNs[location1] > 0 && mTimeNs[location2] > 0) {
+            const int64_t frameDifference =
+                    mPosition[location1] - mPosition[location2];
+            const int64_t timeDifferenceNs =
+                    mTimeNs[location1] - mTimeNs[location2];
+            return ((double)frameDifference * 1e9 / sampleRate - timeDifferenceNs) * 1e-6;
+        }
+        return 0.;
+    }
+
     // convert fields to a printable string
     std::string toString() {
         std::stringstream ss;

services/audioflinger/FastMixer.cpp

@@ -489,6 +489,10 @@ void FastMixer::onWork()
                         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;

services/audioflinger/FastMixerDumpState.cpp

@@ -68,11 +68,11 @@ void FastMixerDumpState::dump(int fd) const
     dprintf(fd, "  FastMixer command=%s writeSequence=%u framesWritten=%u\n"
                 "            numTracks=%u writeErrors=%u underruns=%u overruns=%u\n"
                 "            sampleRate=%u frameCount=%zu measuredWarmup=%.3g ms, warmupCycles=%u\n"
-                "            mixPeriod=%.2f ms\n",
+                "            mixPeriod=%.2f ms latency=%.2f ms\n",
                 FastMixerState::commandToString(mCommand), mWriteSequence, mFramesWritten,
                 mNumTracks, mWriteErrors, mUnderruns, mOverruns,
                 mSampleRate, mFrameCount, measuredWarmupMs, mWarmupCycles,
-                mixPeriodSec * 1e3);
+                mixPeriodSec * 1e3, mLatencyMs);
 #ifdef FAST_THREAD_STATISTICS
     // find the interval of valid samples
     uint32_t bounds = mBounds;

services/audioflinger/FastMixerDumpState.h

@@ -66,6 +66,7 @@ struct FastMixerDumpState : FastThreadDumpState {
 
     void dump(int fd) const;    // should only be called on a stable copy, not the original
 
+    double   mLatencyMs = 0.;   // measured latency, default of 0 if no valid timestamp read.
     uint32_t mWriteSequence;    // incremented before and after each write()
     uint32_t mFramesWritten;    // total number of frames written successfully
     uint32_t mNumTracks;        // total number of active fast tracks

services/audioflinger/PlaybackTracks.h

@@ -41,7 +41,7 @@ public:
     virtual             ~Track();
     virtual status_t    initCheck() const;
 
-    static  void        appendDumpHeader(String8& result);
+            void        appendDumpHeader(String8& result);
             void        appendDump(String8& result, bool active);
     virtual status_t    start(AudioSystem::sync_event_t event =
                                     AudioSystem::SYNC_EVENT_NONE,
@@ -75,6 +75,7 @@ public:
             bool        isOffloadedOrDirect() const { return (mFlags
                             & (AUDIO_OUTPUT_FLAG_COMPRESS_OFFLOAD
                                     | AUDIO_OUTPUT_FLAG_DIRECT)) != 0; }
+            bool        isStatic() const { return  mSharedBuffer.get() != nullptr; }
 
             status_t    setParameters(const String8& keyValuePairs);
             status_t    attachAuxEffect(int EffectId);
@@ -93,6 +94,11 @@ public:
 
     virtual bool        isFastTrack() const { return (mFlags & AUDIO_OUTPUT_FLAG_FAST) != 0; }
 
+    virtual double bufferLatencyMs() {
+        return isStatic() ? 0.
+                : (double)mAudioTrackServerProxy->framesReadySafe() * 1000 / sampleRate();
+    }
+
 // implement volume handling.
     media::VolumeShaper::Status applyVolumeShaper(
                                 const sp<media::VolumeShaper::Configuration>& configuration,
@@ -194,6 +200,7 @@ protected:
 
     sp<media::VolumeHandler>  mVolumeHandler; // handles multiple VolumeShaper configs and operations
 
+    bool               mDumpLatency = false; // true if track supports latency dumps.
 private:
     // The following fields are only for fast tracks, and should be in a subclass
     int                 mFastIndex; // index within FastMixerState::mFastTracks[];

services/audioflinger/Threads.cpp

@@ -1784,7 +1784,7 @@ void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>& ar
     if (numtracks) {
         dprintf(fd, " of which %zu are active\n", numactive);
         result.append(prefix);
-        Track::appendDumpHeader(result);
+        mTracks[0]->appendDumpHeader(result);
         for (size_t i = 0; i < numtracks; ++i) {
             sp<Track> track = mTracks[i];
             if (track != 0) {
@@ -1804,7 +1804,7 @@ void AudioFlinger::PlaybackThread::dumpTracks(int fd, const Vector<String16>& ar
         result.append("  The following tracks are in the active list but"
                 " not in the track list\n");
         result.append(prefix);
-        Track::appendDumpHeader(result);
+        mActiveTracks[0]->appendDumpHeader(result);
         for (size_t i = 0; i < numactive; ++i) {
             sp<Track> track = mActiveTracks[i];
             if (mTracks.indexOf(track) < 0) {
@@ -5054,6 +5054,10 @@ void AudioFlinger::MixerThread::dumpInternals(int fd, const Vector<String16>& ar
     dprintf(fd, "  Thread throttle time (msecs): %u\n", mThreadThrottleTimeMs);
     dprintf(fd, "  AudioMixer tracks: %s\n", mAudioMixer->trackNames().c_str());
     dprintf(fd, "  Master mono: %s\n", mMasterMono ? "on" : "off");
+    const double latencyMs = mTimestamp.getOutputServerLatencyMs(mSampleRate);
+    if (latencyMs > 0.) {
+        dprintf(fd, "  NormalMixer latency ms: %.2lf\n", latencyMs);
+    }
 
     if (hasFastMixer()) {
         dprintf(fd, "  FastMixer thread %p tid=%d", mFastMixer.get(), mFastMixer->getTid());

services/audioflinger/Tracks.cpp

@@ -435,6 +435,7 @@ AudioFlinger::PlaybackThread::Track::Track(
     }
     mName = TRACK_NAME_PENDING;
 
+    mDumpLatency = thread->type() == ThreadBase::MIXER;
 #ifdef TEE_SINK
     mTee.setId(std::string("_") + std::to_string(mThreadIoHandle)
             + "_" + std::to_string(mId) +
@@ -489,13 +490,14 @@ void AudioFlinger::PlaybackThread::Track::destroy()
     }
 }
 
-/*static*/ void AudioFlinger::PlaybackThread::Track::appendDumpHeader(String8& result)
+void AudioFlinger::PlaybackThread::Track::appendDumpHeader(String8& result)
 {
-    result.append("T Name Active Client Session S  Flags "
+    result.appendFormat("T Name Active Client Session S  Flags "
                   "  Format Chn mask  SRate "
                   "ST  L dB  R dB  VS dB "
-                  "  Server FrmCnt  FrmRdy F Underruns  Flushed "
-                  "Main Buf  Aux Buf\n");
+                  "  Server FrmCnt  FrmRdy F Underruns  Flushed"
+                  "%s\n",
+                  mDumpLatency ? " Latency" : "");
 }
 
 void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool active)
@@ -504,7 +506,7 @@ void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool activ
     switch (mType) {
     case TYPE_DEFAULT:
     case TYPE_OUTPUT:
-        if (mSharedBuffer.get() != nullptr) {
+        if (isStatic()) {
             trackType = 'S'; // static
         } else {
             trackType = ' '; // normal
@@ -582,8 +584,7 @@ void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool activ
     result.appendFormat("%7s %6u %7u %2s 0x%03X "
                            "%08X %08X %6u "
                            "%2u %5.2g %5.2g %5.2g%c "
-                           "%08X %6zu%c %6zu %c %9u%c %7u "
-                           "%08zX %08zX\n",
+                           "%08X %6zu%c %6zu %c %9u%c %7u",
             active ? "yes" : "no",
             (mClient == 0) ? getpid() : mClient->pid(),
             mSessionId,
@@ -607,11 +608,19 @@ void AudioFlinger::PlaybackThread::Track::appendDump(String8& result, bool activ
             fillingStatus,
             mAudioTrackServerProxy->getUnderrunFrames(),
             nowInUnderrun,
-            (unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000,
-
-            (size_t)mMainBuffer, // use %zX as %p appends 0x
-            (size_t)mAuxBuffer   // use %zX as %p appends 0x
+            (unsigned)mAudioTrackServerProxy->framesFlushed() % 10000000
             );
+    if (mDumpLatency) {
+        double latencyMs =
+                mAudioTrackServerProxy->getTimestamp().getOutputServerLatencyMs(mSampleRate);
+        if (latencyMs > 0.) {
+            latencyMs += bufferLatencyMs();
+            result.appendFormat(" %7.3f", latencyMs);
+        } else {
+            result.appendFormat(" Unknown");
+        }
+    }
+    result.append("\n");
 }
 
 uint32_t AudioFlinger::PlaybackThread::Track::sampleRate() const {