MediaMetrics: Add AudioFlinger logging
Test: atest mediametrics_tests
Test: mediametrics dumpsys
Bug: 138583596
Change-Id: I2086c5a780744d409052fde4c5ebc1dc92d95ea8
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index d6f0824..5c5c5bb 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -40,6 +40,7 @@
#include <media/audiohal/DevicesFactoryHalInterface.h>
#include <media/audiohal/EffectsFactoryHalInterface.h>
#include <media/AudioParameter.h>
+#include <media/MediaMetricsItem.h>
#include <media/TypeConverter.h>
#include <memunreachable/memunreachable.h>
#include <utils/String16.h>
@@ -198,6 +199,11 @@
std::vector<pid_t> halPids;
mDevicesFactoryHal->getHalPids(&halPids);
TimeCheck::setAudioHalPids(halPids);
+
+ // Notify that we have started (also called when audioserver service restarts)
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
}
void AudioFlinger::onFirstRef()
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index d4e0ae2..a16fa94 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -952,6 +952,8 @@
SimpleLog mRejectedSetParameterLog;
SimpleLog mAppSetParameterLog;
SimpleLog mSystemSetParameterLog;
+
+ static inline constexpr const char *mMetricsId = AMEDIAMETRICS_KEY_AUDIO_FLINGER;
};
#undef INCLUDING_FROM_AUDIOFLINGER_H
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 87b72fb..7b14050 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -24,6 +24,7 @@
#include <math.h>
#include <fcntl.h>
#include <memory>
+#include <sstream>
#include <string>
#include <linux/futex.h>
#include <sys/stat.h>
@@ -212,6 +213,28 @@
// ----------------------------------------------------------------------------
+// TODO: move all toString helpers to audio.h
+// under #ifdef __cplusplus #endif
+static std::string patchSinksToString(const struct audio_patch *patch)
+{
+ std::stringstream ss;
+ for (size_t i = 0; i < patch->num_sinks; ++i) {
+ ss << "(" << toString(patch->sinks[i].ext.device.type)
+ << ", " << patch->sinks[i].ext.device.address << ")";
+ }
+ return ss.str();
+}
+
+static std::string patchSourcesToString(const struct audio_patch *patch)
+{
+ std::stringstream ss;
+ for (size_t i = 0; i < patch->num_sources; ++i) {
+ ss << "(" << toString(patch->sources[i].ext.device.type)
+ << ", " << patch->sources[i].ext.device.address << ")";
+ }
+ return ss.str();
+}
+
static pthread_once_t sFastTrackMultiplierOnce = PTHREAD_ONCE_INIT;
static void sFastTrackMultiplierInit()
@@ -466,6 +489,7 @@
: Thread(false /*canCallJava*/),
mType(type),
mAudioFlinger(audioFlinger),
+ mMetricsId(std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD) + std::to_string(id)),
// mSampleRate, mFrameCount, mChannelMask, mChannelCount, mFrameSize, mFormat, mBufferSize
// are set by PlaybackThread::readOutputParameters_l() or
// RecordThread::readInputParameters_l()
@@ -477,6 +501,13 @@
mSystemReady(systemReady),
mSignalPending(false)
{
+ mediametrics::LogItem(mMetricsId)
+ .setPid(getpid())
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .set(AMEDIAMETRICS_PROP_TYPE, threadTypeToString(type))
+ .set(AMEDIAMETRICS_PROP_THREADID, id)
+ .record();
+
memset(&mPatch, 0, sizeof(struct audio_patch));
}
@@ -493,6 +524,10 @@
}
sendStatistics(true /* force */);
+
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
+ .record();
}
status_t AudioFlinger::ThreadBase::readyToRun()
@@ -2794,6 +2829,30 @@
mAudioFlinger->moveEffectChain_l(effectChains[i]->sessionId(),
this/* srcThread */, this/* dstThread */);
}
+
+ audio_output_flags_t flags = mOutput != nullptr ? mOutput->flags : AUDIO_OUTPUT_FLAG_NONE;
+ mediametrics::LogItem item(mMetricsId);
+ item.set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_READPARAMETERS)
+ .set(AMEDIAMETRICS_PROP_ENCODING, formatToString(mFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_SAMPLERATE, (int32_t)mSampleRate)
+ .set(AMEDIAMETRICS_PROP_CHANNELMASK, (int32_t)mChannelMask)
+ .set(AMEDIAMETRICS_PROP_CHANNELCOUNT, (int32_t)mChannelCount)
+ .set(AMEDIAMETRICS_PROP_FRAMECOUNT, (int32_t)mNormalFrameCount)
+ .set(AMEDIAMETRICS_PROP_FLAGS, toString(flags).c_str())
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAPTIC AMEDIAMETRICS_PROP_CHANNELMASK,
+ (int32_t)mHapticChannelMask)
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAPTIC AMEDIAMETRICS_PROP_CHANNELCOUNT,
+ (int32_t)mHapticChannelCount)
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAL AMEDIAMETRICS_PROP_ENCODING,
+ formatToString(mHALFormat).c_str())
+ .set(AMEDIAMETRICS_PROP_PREFIX_HAL AMEDIAMETRICS_PROP_FRAMECOUNT,
+ (int32_t)mFrameCount) // sic - added HAL
+ ;
+ uint32_t latencyMs;
+ if (mOutput->stream->getLatency(&latencyMs) == NO_ERROR) {
+ item.set(AMEDIAMETRICS_PROP_PREFIX_HAL AMEDIAMETRICS_PROP_LATENCYMS, (double)latencyMs);
+ }
+ item.record();
}
void AudioFlinger::PlaybackThread::updateMetadata_l()
@@ -3870,6 +3929,11 @@
const int32_t throttleMs = (int32_t)mHalfBufferMs - deltaMs;
if ((signed)mHalfBufferMs >= throttleMs && throttleMs > 0) {
+ mediametrics::LogItem(mMetricsId)
+ // ms units always double
+ .set(AMEDIAMETRICS_PROP_THROTTLEMS, (double)throttleMs)
+ .record();
+
usleep(throttleMs * 1000);
// notify of throttle start on verbose log
ALOGV_IF(mThreadThrottleEndMs == mThreadThrottleTimeMs,
@@ -4142,6 +4206,11 @@
status = mOutput->stream->setParameters(param.toString());
*handle = AUDIO_PATCH_HANDLE_NONE;
}
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_OUTPUTDEVICES, patchSinksToString(patch).c_str())
+ .record();
+
if (configChanged) {
sendIoConfigEvent_l(AUDIO_OUTPUT_CONFIG_CHANGED);
}
@@ -4683,19 +4752,29 @@
// DeferredOperations handles statistics after setting mixerStatus.
class DeferredOperations {
public:
- DeferredOperations(mixer_state *mixerStatus)
- : mMixerStatus(mixerStatus) { }
+ DeferredOperations(mixer_state *mixerStatus, const std::string &metricsId)
+ : mMixerStatus(mixerStatus)
+ , mMetricsId(metricsId) {}
// when leaving scope, tally frames properly.
~DeferredOperations() {
// Tally underrun frames only if we are actually mixing (MIXER_TRACKS_READY)
// because that is when the underrun occurs.
// We do not distinguish between FastTracks and NormalTracks here.
- if (*mMixerStatus == MIXER_TRACKS_READY) {
+ if (*mMixerStatus == MIXER_TRACKS_READY && mUnderrunFrames.size() > 0) {
+ mediametrics::LogItem item(mMetricsId);
+
+ item.set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_UNDERRUN);
for (const auto &underrun : mUnderrunFrames) {
underrun.first->mAudioTrackServerProxy->tallyUnderrunFrames(
underrun.second);
+
+ item.set(std::string("[" AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK)
+ + std::to_string(underrun.first->portId())
+ + "]" AMEDIAMETRICS_PROP_UNDERRUN,
+ (int32_t)underrun.second);
}
+ item.record();
}
}
@@ -4708,8 +4787,10 @@
private:
const mixer_state * const mMixerStatus;
+ const std::string& mMetricsId;
std::vector<std::pair<sp<Track>, size_t>> mUnderrunFrames;
- } deferredOperations(&mixerStatus); // implicit nested scope for variable capture
+ } deferredOperations(&mixerStatus, mMetricsId);
+ // implicit nested scope for variable capture
bool noFastHapticTrack = true;
for (size_t i=0 ; i<count ; i++) {
@@ -5187,11 +5268,20 @@
mixerStatus != MIXER_TRACKS_ENABLED) {
mixerStatus = MIXER_TRACKS_READY;
}
+
+ // Enable the next few lines to instrument a test for underrun log handling.
+ // TODO: Remove when we have a better way of testing the underrun log.
+#if 0
+ static int i;
+ if ((++i & 0xf) == 0) {
+ deferredOperations.tallyUnderrunFrames(track, 10 /* underrunFrames */);
+ }
+#endif
} else {
size_t underrunFrames = 0;
if (framesReady < desiredFrames && !track->isStopped() && !track->isPaused()) {
- ALOGV("track(%d) underrun, framesReady(%zu) < framesDesired(%zd)",
- trackId, framesReady, desiredFrames);
+ ALOGV("track(%d) underrun, track state %s framesReady(%zu) < framesDesired(%zd)",
+ trackId, track->getTrackStateAsString(), framesReady, desiredFrames);
underrunFrames = desiredFrames;
}
deferredOperations.tallyUnderrunFrames(track, underrunFrames);
@@ -8404,6 +8494,12 @@
mPatch = *patch;
}
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_INPUTDEVICES, patchSourcesToString(patch).c_str())
+ .set(AMEDIAMETRICS_PROP_SOURCE, toString(mAudioSource).c_str())
+ .record();
+
return status;
}
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index f1adc23..b0eb75d 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -523,6 +523,7 @@
Condition mWaitWorkCV;
const sp<AudioFlinger> mAudioFlinger;
+ const std::string mMetricsId;
// updated by PlaybackThread::readOutputParameters_l() or
// RecordThread::readInputParameters_l()
diff --git a/services/audioflinger/TrackBase.h b/services/audioflinger/TrackBase.h
index 91dbfa4..e39b944 100644
--- a/services/audioflinger/TrackBase.h
+++ b/services/audioflinger/TrackBase.h
@@ -69,7 +69,8 @@
bool isOut,
alloc_type alloc = ALLOC_CBLK,
track_type type = TYPE_DEFAULT,
- audio_port_handle_t portId = AUDIO_PORT_HANDLE_NONE);
+ audio_port_handle_t portId = AUDIO_PORT_HANDLE_NONE,
+ std::string metricsId = {});
virtual ~TrackBase();
virtual status_t initCheck() const;
@@ -94,7 +95,14 @@
bool isPatchTrack() const { return (mType == TYPE_PATCH); }
bool isExternalTrack() const { return !isOutputTrack() && !isPatchTrack(); }
- virtual void invalidate() { mIsInvalid = true; }
+ virtual void invalidate() {
+ if (mIsInvalid) return;
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT,
+ AMEDIAMETRICS_PROP_EVENT_VALUE_INVALIDATE)
+ .record();
+ mIsInvalid = true;
+ }
bool isInvalid() const { return mIsInvalid; }
void terminate() { mTerminated = true; }
@@ -353,6 +361,14 @@
audio_port_handle_t mPortId; // unique ID for this track used by audio policy
bool mIsInvalid; // non-resettable latch, set by invalidate()
+ // It typically takes 5 threadloop mix iterations for latency to stabilize.
+ static inline constexpr int32_t LOG_START_COUNTDOWN = 8;
+ int32_t mLogStartCountdown = 0;
+ int64_t mLogStartTimeNs = 0;
+ int64_t mLogStartFrames = 0;
+
+ const std::string mMetricsId;
+
bool mServerLatencySupported = false;
std::atomic<bool> mServerLatencyFromTrack{}; // latency from track or server timestamp.
std::atomic<double> mServerLatencyMs{}; // last latency pushed from server thread.
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 2437202..23d8329 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -80,7 +80,8 @@
bool isOut,
alloc_type alloc,
track_type type,
- audio_port_handle_t portId)
+ audio_port_handle_t portId,
+ std::string metricsId)
: RefBase(),
mThread(thread),
mClient(client),
@@ -105,6 +106,7 @@
mThreadIoHandle(thread ? thread->id() : AUDIO_IO_HANDLE_NONE),
mPortId(portId),
mIsInvalid(false),
+ mMetricsId(std::move(metricsId)),
mCreatorPid(creatorPid)
{
const uid_t callingUid = IPCThreadState::self()->getCallingUid();
@@ -519,7 +521,9 @@
(sharedBuffer != 0) ? sharedBuffer->size() : bufferSize,
sessionId, creatorPid, uid, true /*isOut*/,
(type == TYPE_PATCH) ? ( buffer == NULL ? ALLOC_LOCAL : ALLOC_NONE) : ALLOC_CBLK,
- type, portId),
+ type,
+ portId,
+ std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_TRACK) + std::to_string(portId)),
mFillingUpStatus(FS_INVALID),
// mRetryCount initialized later when needed
mSharedBuffer(sharedBuffer),
@@ -596,6 +600,14 @@
mExternalVibration = new os::ExternalVibration(
mUid, "" /* pkg */, mAttr, mAudioVibrationController);
}
+
+ // Once this item is logged by the server, the client can add properties.
+ mediametrics::LogItem(mMetricsId)
+ .setPid(creatorPid)
+ .setUid(uid)
+ .set(AMEDIAMETRICS_PROP_EVENT,
+ AMEDIAMETRICS_PROP_PREFIX_SERVER AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
}
AudioFlinger::PlaybackThread::Track::~Track()
@@ -966,6 +978,14 @@
}
}
+ // Audio timing metrics are computed a few mix cycles after starting.
+ {
+ mLogStartCountdown = LOG_START_COUNTDOWN;
+ mLogStartTimeNs = systemTime();
+ mLogStartFrames = mAudioTrackServerProxy->getTimestamp()
+ .mPosition[ExtendedTimestamp::LOCATION_SERVER];
+ }
+
if (status == NO_ERROR || status == ALREADY_EXISTS) {
// for streaming tracks, remove the buffer read stop limit.
mAudioTrackServerProxy->start();
@@ -1497,6 +1517,28 @@
mServerLatencyFromTrack.store(useTrackTimestamp);
mServerLatencyMs.store(latencyMs);
+
+ if (mLogStartCountdown > 0) {
+ if (--mLogStartCountdown == 0) {
+ // startup is the difference in times for the current timestamp and our start
+ double startUpMs =
+ (local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] - mLogStartTimeNs) * 1e-6;
+ // adjust for frames played.
+ startUpMs -= (local.mPosition[ExtendedTimestamp::LOCATION_SERVER] - mLogStartFrames)
+ * 1e3 / mSampleRate;
+ ALOGV("%s: logging localTime:%lld, startTime:%lld"
+ " localPosition:%lld, startPosition:%lld",
+ __func__,
+ (long long)local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER],
+ (long long)mLogStartTimeNs,
+ (long long)local.mPosition[ExtendedTimestamp::LOCATION_SERVER],
+ (long long)mLogStartFrames);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_LATENCYMS, latencyMs)
+ .set(AMEDIAMETRICS_PROP_STARTUPMS, startUpMs)
+ .record();
+ }
+ }
}
binder::Status AudioFlinger::PlaybackThread::Track::AudioVibrationController::mute(
@@ -2071,7 +2113,8 @@
(type == TYPE_DEFAULT) ?
((flags & AUDIO_INPUT_FLAG_FAST) ? ALLOC_PIPE : ALLOC_CBLK) :
((buffer == NULL) ? ALLOC_LOCAL : ALLOC_NONE),
- type, portId),
+ type, portId,
+ std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_RECORD) + std::to_string(portId)),
mOverflow(false),
mFramesToDrop(0),
mResamplerBufferProvider(NULL), // initialize in case of early constructor exit
@@ -2117,6 +2160,13 @@
+ "_" + std::to_string(mId)
+ "_R");
#endif
+
+ // Once this item is logged by the server, the client can add properties.
+ mediametrics::LogItem(mMetricsId)
+ .setPid(creatorPid)
+ .setUid(uid)
+ .set(AMEDIAMETRICS_PROP_EVENT, "server." AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
}
AudioFlinger::RecordThread::RecordTrack::~RecordTrack()