Timestamp: Collect and dump statistics
Test: Audioflinger dumpsys
Bug: 80502521
Change-Id: I8c7c8b0c2f0f51dc898ed96f6a973e20490022f1
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index a59c13e..0276cad 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/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"
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index caeede9..ad35264 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -336,13 +336,15 @@
{
// 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 @@
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;
+ }
}
}
}
diff --git a/services/audioflinger/FastMixerDumpState.cpp b/services/audioflinger/FastMixerDumpState.cpp
index b3a2520..d60643c 100644
--- a/services/audioflinger/FastMixerDumpState.cpp
+++ b/services/audioflinger/FastMixerDumpState.cpp
@@ -73,6 +73,7 @@
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;
diff --git a/services/audioflinger/FastMixerDumpState.h b/services/audioflinger/FastMixerDumpState.h
index aed6bc5..9b91cbc 100644
--- a/services/audioflinger/FastMixerDumpState.h
+++ b/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 @@
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
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 65bbd8d..c2a2fe0 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -853,6 +853,14 @@
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 @@
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(×tamp) == OK) {
+ if (mStandby) {
+ mTimestampVerifier.discontinuity();
+ } else if (threadloop_getHalTimestamp_l(×tamp) == 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 @@
+ 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 @@
}
}
}
+ } // if (mType ... ) { // no indentation
#if 0
// logFormat example
if (z % 100 == 0) {
@@ -6730,8 +6751,9 @@
// 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 @@
//
// 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
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index b691ca9..064e291 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -499,6 +499,9 @@
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;