TrackMetrics: Add device-based statistics for audio
Compute summary statistics based on the current device
rather than the entire AudioTrack or AudioRecord duration.
Test: adb shell dumpsys media.metrics
Bug: 149850236
Change-Id: Ia3a5707c43c4530f5a6ac90f52901bd2e0bd0bab
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index 6afbd4f..0ed63a4 100644
--- a/services/audioflinger/AudioFlinger.h
+++ b/services/audioflinger/AudioFlinger.h
@@ -88,6 +88,7 @@
#include "SpdifStreamOut.h"
#include "AudioHwDevice.h"
#include "NBAIO_Tee.h"
+#include "TrackMetrics.h"
#include <powermanager/IPowerManager.h>
diff --git a/services/audioflinger/PlaybackTracks.h b/services/audioflinger/PlaybackTracks.h
index 1ff03c4..d8eebf3 100644
--- a/services/audioflinger/PlaybackTracks.h
+++ b/services/audioflinger/PlaybackTracks.h
@@ -171,6 +171,16 @@
void setTeePatches(TeePatches teePatches);
+ void tallyUnderrunFrames(size_t frames) override {
+ if (isOut()) { // we expect this from output tracks only
+ mAudioTrackServerProxy->tallyUnderrunFrames(frames);
+ // Fetch absolute numbers from AudioTrackShared as it counts
+ // contiguous underruns as a one -- we want a consistent number.
+ // TODO: isolate this counting into a class.
+ mTrackMetrics.logUnderruns(mAudioTrackServerProxy->getUnderrunCount(),
+ mAudioTrackServerProxy->getUnderrunFrames());
+ }
+ }
protected:
// for numerous
friend class PlaybackThread;
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 5d9c35a..69bf831 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -220,6 +220,9 @@
{
std::stringstream ss;
for (size_t i = 0; i < patch->num_sinks; ++i) {
+ if (i > 0) {
+ ss << "|";
+ }
ss << "(" << toString(patch->sinks[i].ext.device.type)
<< ", " << patch->sinks[i].ext.device.address << ")";
}
@@ -230,6 +233,9 @@
{
std::stringstream ss;
for (size_t i = 0; i < patch->num_sources; ++i) {
+ if (i > 0) {
+ ss << "|";
+ }
ss << "(" << toString(patch->sources[i].ext.device.type)
<< ", " << patch->sources[i].ext.device.address << ")";
}
@@ -1686,6 +1692,7 @@
#ifdef TEE_SINK
track->dumpTee(-1 /* fd */, "_REMOVE");
#endif
+ track->logEndInterval(); // log to MediaMetrics
return index;
}
@@ -2553,6 +2560,7 @@
chain->incActiveTrackCnt();
}
+ track->logBeginInterval(patchSinksToString(&mPatch)); // log to MediaMetrics
status = NO_ERROR;
}
@@ -4256,10 +4264,16 @@
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())
+ const std::string patchSinksAsString = patchSinksToString(patch);
+ mediametrics::LogItem item(mMetricsId);
+ item.set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_OUTPUTDEVICES, patchSinksAsString.c_str())
.record();
+ // also dispatch to active AudioTracks for MediaMetrics
+ for (const auto &track : mActiveTracks) {
+ track->logEndInterval();
+ track->logBeginInterval(patchSinksAsString);
+ }
if (configChanged) {
sendIoConfigEvent_l(AUDIO_OUTPUT_CONFIG_CHANGED);
@@ -4812,19 +4826,9 @@
// because that is when the underrun occurs.
// We do not distinguish between FastTracks and NormalTracks here.
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);
+ underrun.first->tallyUnderrunFrames(underrun.second);
}
- item.record();
}
}
@@ -4837,7 +4841,7 @@
private:
const mixer_state * const mMixerStatus;
- const std::string& mMetricsId;
+ const std::string& __unused mMetricsId;
std::vector<std::pair<sp<Track>, size_t>> mUnderrunFrames;
} deferredOperations(&mixerStatus, mMetricsId);
// implicit nested scope for variable capture
@@ -7881,6 +7885,9 @@
sendIoConfigEvent_l(
AUDIO_CLIENT_STARTED, recordTrack->creatorPid(), recordTrack->portId());
}
+
+ recordTrack->logBeginInterval(patchSourcesToString(&mPatch)); // log to MediaMetrics
+
// Catch up with current buffer indices if thread is already running.
// This is what makes a new client discard all buffered data. If the track's mRsmpInFront
// was initialized to some value closer to the thread's mRsmpInFront, then the track could
@@ -8545,12 +8552,17 @@
mPatch = *patch;
}
- mediametrics::LogItem(mMetricsId)
- .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
- .set(AMEDIAMETRICS_PROP_INPUTDEVICES, patchSourcesToString(patch).c_str())
+ const std::string pathSourcesAsString = patchSourcesToString(patch);
+ mediametrics::LogItem item(mMetricsId);
+ item.set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_INPUTDEVICES, pathSourcesAsString.c_str())
.set(AMEDIAMETRICS_PROP_SOURCE, toString(mAudioSource).c_str())
.record();
-
+ // also dispatch to active AudioRecords
+ for (const auto &track : mActiveTracks) {
+ track->logEndInterval();
+ track->logBeginInterval(pathSourcesAsString);
+ }
return status;
}
@@ -8861,6 +8873,7 @@
chain->incActiveTrackCnt();
}
+ track->logBeginInterval(patchSinksToString(&mPatch)); // log to MediaMetrics
*handle = portId;
broadcast_l();
@@ -8946,6 +8959,26 @@
result = mHalStream->getBufferSize(&mBufferSize);
LOG_ALWAYS_FATAL_IF(result != OK, "Error retrieving buffer size from HAL: %d", result);
mFrameCount = mBufferSize / mFrameSize;
+
+ 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)mFrameCount)
+ /*
+ .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
+ .record();
}
bool AudioFlinger::MmapThread::threadLoop()
diff --git a/services/audioflinger/TrackBase.h b/services/audioflinger/TrackBase.h
index e39b944..15c66fb 100644
--- a/services/audioflinger/TrackBase.h
+++ b/services/audioflinger/TrackBase.h
@@ -97,10 +97,7 @@
virtual void invalidate() {
if (mIsInvalid) return;
- mediametrics::LogItem(mMetricsId)
- .set(AMEDIAMETRICS_PROP_EVENT,
- AMEDIAMETRICS_PROP_EVENT_VALUE_INVALIDATE)
- .record();
+ mTrackMetrics.logInvalidate();
mIsInvalid = true;
}
bool isInvalid() const { return mIsInvalid; }
@@ -242,6 +239,20 @@
}
}
+ // Called by the PlaybackThread to indicate that the track is becoming active
+ // and a new interval should start with a given device list.
+ void logBeginInterval(const std::string& devices) {
+ mTrackMetrics.logBeginInterval(devices);
+ }
+
+ // Called by the PlaybackThread to indicate the track is no longer active.
+ void logEndInterval() {
+ mTrackMetrics.logEndInterval();
+ }
+
+ // Called to tally underrun frames in playback.
+ virtual void tallyUnderrunFrames(size_t /* frames */) {}
+
protected:
DISALLOW_COPY_AND_ASSIGN(TrackBase);
@@ -367,7 +378,7 @@
int64_t mLogStartTimeNs = 0;
int64_t mLogStartFrames = 0;
- const std::string mMetricsId;
+ TrackMetrics mTrackMetrics;
bool mServerLatencySupported = false;
std::atomic<bool> mServerLatencyFromTrack{}; // latency from track or server timestamp.
diff --git a/services/audioflinger/TrackMetrics.h b/services/audioflinger/TrackMetrics.h
new file mode 100644
index 0000000..399c788
--- /dev/null
+++ b/services/audioflinger/TrackMetrics.h
@@ -0,0 +1,222 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef ANDROID_AUDIO_TRACKMETRICS_H
+#define ANDROID_AUDIO_TRACKMETRICS_H
+
+#include <mutex>
+
+namespace android {
+
+/**
+ * TrackMetrics handles the AudioFlinger track metrics.
+ *
+ * We aggregate metrics for a particular device for proper analysis.
+ * This includes power, performance, and usage metrics.
+ *
+ * This class is thread-safe with a lock for safety. There is no risk of deadlock
+ * as this class only executes external one-way calls in Mediametrics and does not
+ * call any other AudioFlinger class.
+ *
+ * Terminology:
+ * An AudioInterval is a contiguous playback segment.
+ * An AudioIntervalGroup is a group of continuous playback segments on the same device.
+ *
+ * We currently deliver metrics based on an AudioIntervalGroup.
+ */
+class TrackMetrics final {
+public:
+ TrackMetrics(std::string metricsId, bool isOut)
+ : mMetricsId(std::move(metricsId))
+ , mIsOut(isOut)
+ {} // we don't log a constructor item, we wait for more info in logConstructor().
+
+ ~TrackMetrics() {
+ logEndInterval();
+ std::lock_guard l(mLock);
+ deliverCumulativeMetrics(AMEDIAMETRICS_PROP_EVENT_VALUE_ENDAUDIOINTERVALGROUP);
+ // we don't log a destructor item here.
+ }
+
+ // Called under the following circumstances
+ // 1) when we are added to the Thread
+ // 2) when we have a createPatch in the Thread.
+ void logBeginInterval(const std::string& devices) {
+ std::lock_guard l(mLock);
+ if (mDevices != devices) {
+ deliverCumulativeMetrics(AMEDIAMETRICS_PROP_EVENT_VALUE_ENDAUDIOINTERVALGROUP);
+ mDevices = devices;
+ resetIntervalGroupMetrics();
+ deliverDeviceMetrics(
+ AMEDIAMETRICS_PROP_EVENT_VALUE_BEGINAUDIOINTERVALGROUP, devices.c_str());
+ }
+ ++mIntervalCount;
+ mIntervalStartTimeNs = systemTime();
+ }
+
+ void logConstructor(pid_t creatorPid, uid_t creatorUid) const {
+ // Once this item is logged by the server, the client can add properties.
+ // no lock required, all local or const variables.
+ mediametrics::LogItem(mMetricsId)
+ .setPid(creatorPid)
+ .setUid(creatorUid)
+ .set(AMEDIAMETRICS_PROP_ALLOWUID, (int32_t)creatorUid)
+ .set(AMEDIAMETRICS_PROP_EVENT,
+ AMEDIAMETRICS_PROP_PREFIX_SERVER AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .record();
+ }
+
+ // Called when we are removed from the Thread.
+ void logEndInterval() {
+ std::lock_guard l(mLock);
+ if (mIntervalStartTimeNs != 0) {
+ const int64_t elapsedTimeNs = systemTime() - mIntervalStartTimeNs;
+ mIntervalStartTimeNs = 0;
+ mCumulativeTimeNs += elapsedTimeNs;
+ mDeviceTimeNs += elapsedTimeNs;
+ }
+ }
+
+ void logInvalidate() const {
+ // no lock required, all local or const variables.
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT,
+ AMEDIAMETRICS_PROP_EVENT_VALUE_INVALIDATE)
+ .record();
+ }
+
+ void logLatencyAndStartup(double latencyMs, double startupMs) {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_LATENCYMS, latencyMs)
+ .set(AMEDIAMETRICS_PROP_STARTUPMS, startupMs)
+ .record();
+ std::lock_guard l(mLock);
+ mDeviceLatencyMs.add(latencyMs);
+ mDeviceStartupMs.add(startupMs);
+ }
+
+ // may be called multiple times during an interval
+ void logVolume(float volume) {
+ const int64_t timeNs = systemTime();
+ std::lock_guard l(mLock);
+ if (mStartVolumeTimeNs == 0) {
+ mDeviceVolume = mVolume = volume;
+ mLastVolumeChangeTimeNs = mStartVolumeTimeNs = timeNs;
+ return;
+ }
+ mDeviceVolume = (mDeviceVolume * (mLastVolumeChangeTimeNs - mStartVolumeTimeNs) +
+ mVolume * (timeNs - mLastVolumeChangeTimeNs)) / (timeNs - mStartVolumeTimeNs);
+ mVolume = volume;
+ mLastVolumeChangeTimeNs = timeNs;
+ }
+
+ // Use absolute numbers returned by AudioTrackShared.
+ void logUnderruns(size_t count, size_t frames) {
+ std::lock_guard l(mLock);
+ mUnderrunCount = count;
+ mUnderrunFrames = frames;
+ // Consider delivering a message here (also be aware of excessive spam).
+ }
+
+private:
+ // no lock required - all arguments and constants.
+ void deliverDeviceMetrics(const char *eventName, const char *devices) const {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, eventName)
+ .set(mIsOut ? AMEDIAMETRICS_PROP_OUTPUTDEVICES
+ : AMEDIAMETRICS_PROP_INPUTDEVICES, devices)
+ .record();
+ }
+
+ void deliverCumulativeMetrics(const char *eventName) const REQUIRES(mLock) {
+ if (mIntervalCount > 0) {
+ mediametrics::LogItem item(mMetricsId);
+ item.set(AMEDIAMETRICS_PROP_CUMULATIVETIMENS, mCumulativeTimeNs)
+ .set(AMEDIAMETRICS_PROP_DEVICETIMENS, mDeviceTimeNs)
+ .set(AMEDIAMETRICS_PROP_EVENT, eventName)
+ .set(AMEDIAMETRICS_PROP_INTERVALCOUNT, (int32_t)mIntervalCount);
+ if (mIsOut) {
+ item.set(AMEDIAMETRICS_PROP_DEVICEVOLUME, mDeviceVolume);
+ }
+ if (mDeviceLatencyMs.getN() > 0) {
+ item.set(AMEDIAMETRICS_PROP_DEVICELATENCYMS, mDeviceLatencyMs.getMean())
+ .set(AMEDIAMETRICS_PROP_DEVICESTARTUPMS, mDeviceStartupMs.getMean());
+ }
+ if (mUnderrunCount > 0) {
+ item.set(AMEDIAMETRICS_PROP_UNDERRUN,
+ (int32_t)(mUnderrunCount - mUnderrunCountSinceIntervalGroup))
+ .set(AMEDIAMETRICS_PROP_UNDERRUNFRAMES,
+ (int64_t)(mUnderrunFrames - mUnderrunFramesSinceIntervalGroup));
+ }
+ item.record();
+ }
+ }
+
+ void resetIntervalGroupMetrics() REQUIRES(mLock) {
+ // mDevices is not reset by resetIntervalGroupMetrics.
+
+ mIntervalCount = 0;
+ mIntervalStartTimeNs = 0;
+ // mCumulativeTimeNs is not reset by resetIntervalGroupMetrics.
+ mDeviceTimeNs = 0;
+
+ mVolume = 0.f;
+ mDeviceVolume = 0.f;
+ mStartVolumeTimeNs = 0;
+ mLastVolumeChangeTimeNs = 0;
+
+ mDeviceLatencyMs.reset();
+ mDeviceStartupMs.reset();
+
+ mUnderrunCountSinceIntervalGroup = mUnderrunCount;
+ mUnderrunFramesSinceIntervalGroup = mUnderrunFrames;
+ // do not reset mUnderrunCount - it keeps continuously running for tracks.
+ }
+
+ const std::string mMetricsId;
+ const bool mIsOut; // if true, than a playback track, otherwise used for record.
+
+ mutable std::mutex mLock;
+
+ // Devices in the interval group.
+ std::string mDevices GUARDED_BY(mLock);
+
+ // Number of intervals and playing time
+ int32_t mIntervalCount GUARDED_BY(mLock) = 0;
+ int64_t mIntervalStartTimeNs GUARDED_BY(mLock) = 0;
+ int64_t mCumulativeTimeNs GUARDED_BY(mLock) = 0;
+ int64_t mDeviceTimeNs GUARDED_BY(mLock) = 0;
+
+ // Average volume
+ double mVolume GUARDED_BY(mLock) = 0.f;
+ double mDeviceVolume GUARDED_BY(mLock) = 0.f;
+ int64_t mStartVolumeTimeNs GUARDED_BY(mLock) = 0;
+ int64_t mLastVolumeChangeTimeNs GUARDED_BY(mLock) = 0;
+
+ // latency and startup for each interval.
+ audio_utils::Statistics<double> mDeviceLatencyMs GUARDED_BY(mLock);
+ audio_utils::Statistics<double> mDeviceStartupMs GUARDED_BY(mLock);
+
+ // underrun count and frames
+ int64_t mUnderrunCount GUARDED_BY(mLock) = 0;
+ int64_t mUnderrunFrames GUARDED_BY(mLock) = 0;
+ int64_t mUnderrunCountSinceIntervalGroup GUARDED_BY(mLock) = 0;
+ int64_t mUnderrunFramesSinceIntervalGroup GUARDED_BY(mLock) = 0;
+};
+
+} // namespace android
+
+#endif // ANDROID_AUDIO_TRACKMETRICS_H
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 4898d37..58c61c9 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -106,7 +106,7 @@
mThreadIoHandle(thread ? thread->id() : AUDIO_IO_HANDLE_NONE),
mPortId(portId),
mIsInvalid(false),
- mMetricsId(std::move(metricsId)),
+ mTrackMetrics(std::move(metricsId), isOut),
mCreatorPid(creatorPid)
{
const uid_t callingUid = IPCThreadState::self()->getCallingUid();
@@ -602,13 +602,7 @@
}
// Once this item is logged by the server, the client can add properties.
- mediametrics::LogItem(mMetricsId)
- .setPid(creatorPid)
- .setUid(uid)
- .set(AMEDIAMETRICS_PROP_ALLOWUID, (int32_t)uid)
- .set(AMEDIAMETRICS_PROP_EVENT,
- AMEDIAMETRICS_PROP_PREFIX_SERVER AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
- .record();
+ mTrackMetrics.logConstructor(creatorPid, uid);
}
AudioFlinger::PlaybackThread::Track::~Track()
@@ -1249,6 +1243,7 @@
if (mFinalVolume != volume) { // Compare to an epsilon if too many meaningless updates
mFinalVolume = volume;
setMetadataHasChanged();
+ mTrackMetrics.logVolume(volume);
}
}
@@ -1534,10 +1529,7 @@
(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();
+ mTrackMetrics.logLatencyAndStartup(latencyMs, startUpMs);
}
}
}
@@ -2163,12 +2155,7 @@
#endif
// Once this item is logged by the server, the client can add properties.
- mediametrics::LogItem(mMetricsId)
- .setPid(creatorPid)
- .setUid(uid)
- .set(AMEDIAMETRICS_PROP_ALLOWUID, (int32_t)uid)
- .set(AMEDIAMETRICS_PROP_EVENT, "server." AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
- .record();
+ mTrackMetrics.logConstructor(creatorPid, uid);
}
AudioFlinger::RecordThread::RecordTrack::~RecordTrack()
@@ -2725,9 +2712,12 @@
nullptr /* buffer */, (size_t)0 /* bufferSize */,
sessionId, creatorPid, uid, isOut,
ALLOC_NONE,
- TYPE_DEFAULT, portId),
+ TYPE_DEFAULT, portId,
+ std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_MMAP) + std::to_string(portId)),
mPid(pid), mSilenced(false), mSilencedNotified(false)
{
+ // Once this item is logged by the server, the client can add properties.
+ mTrackMetrics.logConstructor(creatorPid, uid);
}
AudioFlinger::MmapThread::MmapTrack::~MmapTrack()