ThreadMetrics: Add device-based statistics for audio
Compute summary statistics based on the current device
rather than the entire Audio Thread duration.
Test: adb shell dumpsys media.metrics
Bug: 149850236
Change-Id: Ie6d459b06b4a469401ee9e0c194e45ea5ce380c6
diff --git a/services/audioflinger/AudioFlinger.h b/services/audioflinger/AudioFlinger.h
index 0ed63a4..20f561e 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 "ThreadMetrics.h"
#include "TrackMetrics.h"
#include <powermanager/IPowerManager.h>
diff --git a/services/audioflinger/ThreadMetrics.h b/services/audioflinger/ThreadMetrics.h
new file mode 100644
index 0000000..7989de1
--- /dev/null
+++ b/services/audioflinger/ThreadMetrics.h
@@ -0,0 +1,196 @@
+/*
+ * 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_THREADMETRICS_H
+#define ANDROID_AUDIO_THREADMETRICS_H
+
+#include <mutex>
+
+namespace android {
+
+/**
+ * ThreadMetrics handles the AudioFlinger thread log statistics.
+ *
+ * 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 ThreadMetrics final {
+public:
+ ThreadMetrics(std::string metricsId, bool isOut)
+ : mMetricsId(std::move(metricsId))
+ , mIsOut(isOut)
+ {}
+
+ ~ThreadMetrics() {
+ logEndInterval(); // close any open interval groups
+ std::lock_guard l(mLock);
+ deliverCumulativeMetrics(AMEDIAMETRICS_PROP_EVENT_VALUE_ENDAUDIOINTERVALGROUP);
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
+ .record();
+ }
+
+ // Called under the following circumstances
+ // 1) Upon a createPatch and we are not in standby
+ // 2) We come out of standby
+ void logBeginInterval() {
+ std::lock_guard l(mLock);
+ if (mDevices != mCreatePatchDevices) {
+ deliverCumulativeMetrics(AMEDIAMETRICS_PROP_EVENT_VALUE_ENDAUDIOINTERVALGROUP);
+ mDevices = mCreatePatchDevices; // set after endAudioIntervalGroup
+ resetIntervalGroupMetrics();
+ deliverDeviceMetrics(
+ AMEDIAMETRICS_PROP_EVENT_VALUE_BEGINAUDIOINTERVALGROUP, mDevices.c_str());
+ }
+ if (mIntervalStartTimeNs == 0) {
+ ++mIntervalCount;
+ mIntervalStartTimeNs = systemTime();
+ }
+ }
+
+ void logConstructor(pid_t pid, const char *threadType, int32_t id) const {
+ mediametrics::LogItem(mMetricsId)
+ .setPid(pid)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CTOR)
+ .set(AMEDIAMETRICS_PROP_TYPE, threadType)
+ .set(AMEDIAMETRICS_PROP_THREADID, id)
+ .record();
+ }
+
+ void logCreatePatch(const std::string& devices) {
+ std::lock_guard l(mLock);
+ mCreatePatchDevices = devices;
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_CREATEAUDIOPATCH)
+ .set(AMEDIAMETRICS_PROP_OUTPUTDEVICES, devices)
+ .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 logThrottleMs(double throttleMs) const {
+ mediametrics::LogItem(mMetricsId)
+ // ms units always double
+ .set(AMEDIAMETRICS_PROP_THROTTLEMS, (double)throttleMs)
+ .record();
+ }
+
+ void logLatency(double latencyMs) {
+ mediametrics::LogItem(mMetricsId)
+ .set(AMEDIAMETRICS_PROP_LATENCYMS, latencyMs)
+ .record();
+ std::lock_guard l(mLock);
+ mDeviceLatencyMs.add(latencyMs);
+ }
+
+ // TODO: further implement this.
+ void logUnderrunFrames(size_t count, size_t frames) {
+ std::lock_guard l(mLock);
+ mUnderrunCount = count;
+ mUnderrunFrames = frames;
+ }
+
+ const std::string& getMetricsId() const {
+ return mMetricsId;
+ }
+
+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 (mDeviceLatencyMs.getN() > 0) {
+ item.set(AMEDIAMETRICS_PROP_DEVICELATENCYMS, mDeviceLatencyMs.getMean());
+ }
+ if (mUnderrunCount > 0) {
+ item.set(AMEDIAMETRICS_PROP_UNDERRUN, (int32_t)mUnderrunCount)
+ .set(AMEDIAMETRICS_PROP_UNDERRUNFRAMES, (int64_t)mUnderrunFrames);
+ }
+ item.record();
+ }
+ }
+
+ void resetIntervalGroupMetrics() REQUIRES(mLock) {
+ // mDevices is not reset by clear
+
+ mIntervalCount = 0;
+ mIntervalStartTimeNs = 0;
+ // mCumulativeTimeNs is not reset by clear.
+ mDeviceTimeNs = 0;
+
+ mDeviceLatencyMs.reset();
+
+ mUnderrunCount = 0;
+ mUnderrunFrames = 0;
+ }
+
+ 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);
+ std::string mCreatePatchDevices 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;
+
+ // latency and startup for each interval.
+ audio_utils::Statistics<double> mDeviceLatencyMs GUARDED_BY(mLock);
+
+ // underrun count and frames
+ int64_t mUnderrunCount GUARDED_BY(mLock) = 0;
+ int64_t mUnderrunFrames GUARDED_BY(mLock) = 0;
+};
+
+} // namespace android
+
+#endif // ANDROID_AUDIO_THREADMETRICS_H
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 69bf831..594baf8 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -492,11 +492,13 @@
}
AudioFlinger::ThreadBase::ThreadBase(const sp<AudioFlinger>& audioFlinger, audio_io_handle_t id,
- type_t type, bool systemReady)
+ type_t type, bool systemReady, bool isOut)
: Thread(false /*canCallJava*/),
mType(type),
mAudioFlinger(audioFlinger),
- mMetricsId(std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD) + std::to_string(id)),
+ mThreadMetrics(std::string(AMEDIAMETRICS_KEY_PREFIX_AUDIO_THREAD) + std::to_string(id),
+ isOut),
+ mIsOut(isOut),
// mSampleRate, mFrameCount, mChannelMask, mChannelCount, mFrameSize, mFormat, mBufferSize
// are set by PlaybackThread::readOutputParameters_l() or
// RecordThread::readInputParameters_l()
@@ -508,13 +510,7 @@
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();
-
+ mThreadMetrics.logConstructor(getpid(), threadTypeToString(type), id);
memset(&mPatch, 0, sizeof(struct audio_patch));
}
@@ -531,10 +527,6 @@
}
sendStatistics(true /* force */);
-
- mediametrics::LogItem(mMetricsId)
- .set(AMEDIAMETRICS_PROP_EVENT, AMEDIAMETRICS_PROP_EVENT_VALUE_DTOR)
- .record();
}
status_t AudioFlinger::ThreadBase::readyToRun()
@@ -1835,7 +1827,7 @@
audio_io_handle_t id,
type_t type,
bool systemReady)
- : ThreadBase(audioFlinger, id, type, systemReady),
+ : ThreadBase(audioFlinger, id, type, systemReady, true /* isOut */),
mNormalFrameCount(0), mSinkBuffer(NULL),
mMixerBufferEnabled(AudioFlinger::kEnableExtendedPrecision),
mMixerBuffer(NULL),
@@ -2884,7 +2876,7 @@
}
audio_output_flags_t flags = mOutput->flags;
- mediametrics::LogItem item(mMetricsId);
+ mediametrics::LogItem item(mThreadMetrics.getMetricsId()); // TODO: method in ThreadMetrics?
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)
@@ -3142,7 +3134,10 @@
mNumWrites++;
mInWrite = false;
- mStandby = false;
+ if (mStandby) {
+ mThreadMetrics.logBeginInterval();
+ mStandby = false;
+ }
return bytesWritten;
}
@@ -3681,8 +3676,9 @@
// This is where we go into standby
if (!mStandby) {
LOG_AUDIO_STATE();
+ mThreadMetrics.logEndInterval();
+ mStandby = true;
}
- mStandby = true;
sendStatistics(false /* force */);
}
@@ -3986,10 +3982,7 @@
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();
+ mThreadMetrics.logThrottleMs((double)throttleMs);
usleep(throttleMs * 1000);
// notify of throttle start on verbose log
@@ -4265,10 +4258,10 @@
*handle = AUDIO_PATCH_HANDLE_NONE;
}
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();
+
+ mThreadMetrics.logEndInterval();
+ mThreadMetrics.logCreatePatch(patchSinksAsString);
+ mThreadMetrics.logBeginInterval();
// also dispatch to active AudioTracks for MediaMetrics
for (const auto &track : mActiveTracks) {
track->logEndInterval();
@@ -4816,9 +4809,8 @@
// DeferredOperations handles statistics after setting mixerStatus.
class DeferredOperations {
public:
- DeferredOperations(mixer_state *mixerStatus, const std::string &metricsId)
- : mMixerStatus(mixerStatus)
- , mMetricsId(metricsId) {}
+ explicit DeferredOperations(mixer_state *mixerStatus)
+ : mMixerStatus(mixerStatus) {}
// when leaving scope, tally frames properly.
~DeferredOperations() {
@@ -4841,9 +4833,8 @@
private:
const mixer_state * const mMixerStatus;
- const std::string& __unused mMetricsId;
std::vector<std::pair<sp<Track>, size_t>> mUnderrunFrames;
- } deferredOperations(&mixerStatus, mMetricsId);
+ } deferredOperations(&mixerStatus);
// implicit nested scope for variable capture
bool noFastHapticTrack = true;
@@ -5582,7 +5573,10 @@
status = mOutput->stream->setParameters(keyValuePair);
if (!mStandby && status == INVALID_OPERATION) {
mOutput->standby();
- mStandby = true;
+ if (!mStandby) {
+ mThreadMetrics.logEndInterval();
+ mStandby = true;
+ }
mBytesWritten = 0;
status = mOutput->stream->setParameters(keyValuePair);
}
@@ -6095,7 +6089,10 @@
status = mOutput->stream->setParameters(keyValuePair);
if (!mStandby && status == INVALID_OPERATION) {
mOutput->standby();
- mStandby = true;
+ if (!mStandby) {
+ mThreadMetrics.logEndInterval();
+ mStandby = true;
+ }
mBytesWritten = 0;
status = mOutput->stream->setParameters(keyValuePair);
}
@@ -6690,7 +6687,10 @@
// TODO: Report correction for the other output tracks and show in the dump.
}
- mStandby = false;
+ if (mStandby) {
+ mThreadMetrics.logBeginInterval();
+ mStandby = false;
+ }
return (ssize_t)mSinkBufferSize;
}
@@ -6852,7 +6852,7 @@
audio_io_handle_t id,
bool systemReady
) :
- ThreadBase(audioFlinger, id, RECORD, systemReady),
+ ThreadBase(audioFlinger, id, RECORD, systemReady, false /* isOut */),
mInput(input),
mSource(mInput),
mActiveTracks(&this->mLocalLog),
@@ -7140,7 +7140,10 @@
case TrackBase::STARTING_2:
doBroadcast = true;
- mStandby = false;
+ if (mStandby) {
+ mThreadMetrics.logBeginInterval();
+ mStandby = false;
+ }
activeTrack->mState = TrackBase::ACTIVE;
allStopped = false;
break;
@@ -7581,6 +7584,7 @@
{
if (!mStandby) {
inputStandBy();
+ mThreadMetrics.logEndInterval();
mStandby = true;
}
}
@@ -8553,11 +8557,9 @@
}
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();
+ mThreadMetrics.logEndInterval();
+ mThreadMetrics.logCreatePatch(pathSourcesAsString);
+ mThreadMetrics.logBeginInterval();
// also dispatch to active AudioRecords
for (const auto &track : mActiveTracks) {
track->logEndInterval();
@@ -8669,8 +8671,8 @@
AudioFlinger::MmapThread::MmapThread(
const sp<AudioFlinger>& audioFlinger, audio_io_handle_t id,
- AudioHwDevice *hwDev, sp<StreamHalInterface> stream, bool systemReady)
- : ThreadBase(audioFlinger, id, MMAP, systemReady),
+ AudioHwDevice *hwDev, sp<StreamHalInterface> stream, bool systemReady, bool isOut)
+ : ThreadBase(audioFlinger, id, MMAP, systemReady, isOut),
mSessionId(AUDIO_SESSION_NONE),
mPortId(AUDIO_PORT_HANDLE_NONE),
mHalStream(stream), mHalDevice(hwDev->hwDevice()), mAudioHwDev(hwDev),
@@ -8753,7 +8755,10 @@
ALOGE("%s: error mHalStream->start() = %d for first track", __FUNCTION__, ret);
return ret;
}
- mStandby = false;
+ if (mStandby) {
+ mThreadMetrics.logBeginInterval();
+ mStandby = false;
+ }
return NO_ERROR;
}
@@ -8942,7 +8947,10 @@
return INVALID_OPERATION;
}
mHalStream->standby();
- mStandby = true;
+ if (!mStandby) {
+ mThreadMetrics.logEndInterval();
+ mStandby = true;
+ }
releaseWakeLock();
return NO_ERROR;
}
@@ -8960,7 +8968,8 @@
LOG_ALWAYS_FATAL_IF(result != OK, "Error retrieving buffer size from HAL: %d", result);
mFrameCount = mBufferSize / mFrameSize;
- mediametrics::LogItem item(mMetricsId);
+ // TODO: make a readHalParameters call?
+ mediametrics::LogItem item(mThreadMetrics.getMetricsId());
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)
@@ -9390,7 +9399,7 @@
AudioFlinger::MmapPlaybackThread::MmapPlaybackThread(
const sp<AudioFlinger>& audioFlinger, audio_io_handle_t id,
AudioHwDevice *hwDev, AudioStreamOut *output, bool systemReady)
- : MmapThread(audioFlinger, id, hwDev, output->stream, systemReady),
+ : MmapThread(audioFlinger, id, hwDev, output->stream, systemReady, true /* isOut */),
mStreamType(AUDIO_STREAM_MUSIC),
mStreamVolume(1.0),
mStreamMute(false),
@@ -9601,7 +9610,7 @@
AudioFlinger::MmapCaptureThread::MmapCaptureThread(
const sp<AudioFlinger>& audioFlinger, audio_io_handle_t id,
AudioHwDevice *hwDev, AudioStreamIn *input, bool systemReady)
- : MmapThread(audioFlinger, id, hwDev, input->stream, systemReady),
+ : MmapThread(audioFlinger, id, hwDev, input->stream, systemReady, false /* isOut */),
mInput(input)
{
snprintf(mThreadName, kThreadNameLength, "AudioMmapIn_%X", id);
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index e5a6196..5b8c081 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -37,7 +37,7 @@
static const char *threadTypeToString(type_t type);
ThreadBase(const sp<AudioFlinger>& audioFlinger, audio_io_handle_t id,
- type_t type, bool systemReady);
+ type_t type, bool systemReady, bool isOut);
virtual ~ThreadBase();
virtual status_t readyToRun();
@@ -330,7 +330,7 @@
return mInDeviceTypeAddr;
}
- virtual bool isOutput() const = 0;
+ bool isOutput() const { return mIsOut; }
virtual sp<StreamHalInterface> stream() const = 0;
@@ -524,7 +524,8 @@
Condition mWaitWorkCV;
const sp<AudioFlinger> mAudioFlinger;
- const std::string mMetricsId;
+ ThreadMetrics mThreadMetrics;
+ const bool mIsOut;
// updated by PlaybackThread::readOutputParameters_l() or
// RecordThread::readInputParameters_l()
@@ -911,9 +912,6 @@
// Return the asynchronous signal wait time.
virtual int64_t computeWaitTimeNs_l() const { return INT64_MAX; }
-
- virtual bool isOutput() const override { return true; }
-
// returns true if the track is allowed to be added to the thread.
virtual bool isTrackAllowed_l(
audio_channel_mask_t channelMask __unused,
@@ -1651,7 +1649,6 @@
ThreadBase::acquireWakeLock_l();
mActiveTracks.updatePowerState(this, true /* force */);
}
- virtual bool isOutput() const override { return false; }
void checkBtNrec();
@@ -1760,7 +1757,8 @@
#include "MmapTracks.h"
MmapThread(const sp<AudioFlinger>& audioFlinger, audio_io_handle_t id,
- AudioHwDevice *hwDev, sp<StreamHalInterface> stream, bool systemReady);
+ AudioHwDevice *hwDev, sp<StreamHalInterface> stream, bool systemReady,
+ bool isOut);
virtual ~MmapThread();
virtual void configure(const audio_attributes_t *attr,
@@ -1888,8 +1886,6 @@
virtual void checkSilentMode_l();
void processVolume_l() override;
- virtual bool isOutput() const override { return true; }
-
void updateMetadata_l() override;
virtual void toAudioPortConfig(struct audio_port_config *config);
@@ -1916,7 +1912,6 @@
AudioStreamIn* clearInput();
status_t exitStandby() override;
- virtual bool isOutput() const override { return false; }
void updateMetadata_l() override;
void processVolume_l() override;