Merge "ThreadMetrics: Add device-based statistics for audio" into rvc-dev am: 25b1e25a72 (a36f994f) · Commits · e / os / android_frameworks_av

services/audioflinger/AudioFlinger.h

+1 −0

Original line number	Diff line number	Diff line
		@@ -88,6 +88,7 @@
		#include "SpdifStreamOut.h"
		#include "AudioHwDevice.h"
		#include "NBAIO_Tee.h"
		#include "ThreadMetrics.h"
		#include "TrackMetrics.h"

		#include <powermanager/IPowerManager.h>

services/audioflinger/ThreadMetrics.h

0 → 100644

+196 −0

Original line number	Diff line number	Diff line
		/*
		* 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

services/audioflinger/Threads.cpp

+56 −47

Original line number	Diff line number	Diff line
		@@ -492,11 +492,13 @@ const char *AudioFlinger::ThreadBase::threadTypeToString(AudioFlinger::ThreadBas
		}

		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 @@ AudioFlinger::ThreadBase::ThreadBase(const sp<AudioFlinger>& audioFlinger, audio
		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 @@ AudioFlinger::ThreadBase::~ThreadBase()
		}

		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 @@ AudioFlinger::PlaybackThread::PlaybackThread(const sp<AudioFlinger>& audioFlinge
		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 @@ void AudioFlinger::PlaybackThread::readOutputParameters_l()
		}

		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 @@ ssize_t AudioFlinger::PlaybackThread::threadLoop_write()

		mNumWrites++;
		mInWrite = false;
		if (mStandby) {
		mThreadMetrics.logBeginInterval();
		mStandby = false;
		}
		return bytesWritten;
		}

		@@ -3681,8 +3676,9 @@ bool AudioFlinger::PlaybackThread::threadLoop()
		// This is where we go into standby
		if (!mStandby) {
		LOG_AUDIO_STATE();
		}
		mThreadMetrics.logEndInterval();
		mStandby = true;
		}
		sendStatistics(false /* force */);
		}

		@@ -3986,10 +3982,7 @@ bool AudioFlinger::PlaybackThread::threadLoop()

		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 @@ status_t AudioFlinger::PlaybackThread::createAudioPatch_l(const struct audio_pat
		*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 @@ AudioFlinger::PlaybackThread::mixer_state AudioFlinger::MixerThread::prepareTrac
		// 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 @@ AudioFlinger::PlaybackThread::mixer_state AudioFlinger::MixerThread::prepareTrac

		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 @@ bool AudioFlinger::MixerThread::checkForNewParameter_l(const String8& keyValuePa
		status = mOutput->stream->setParameters(keyValuePair);
		if (!mStandby && status == INVALID_OPERATION) {
		mOutput->standby();
		if (!mStandby) {
		mThreadMetrics.logEndInterval();
		mStandby = true;
		}
		mBytesWritten = 0;
		status = mOutput->stream->setParameters(keyValuePair);
		}
		@@ -6095,7 +6089,10 @@ bool AudioFlinger::DirectOutputThread::checkForNewParameter_l(const String8& key
		status = mOutput->stream->setParameters(keyValuePair);
		if (!mStandby && status == INVALID_OPERATION) {
		mOutput->standby();
		if (!mStandby) {
		mThreadMetrics.logEndInterval();
		mStandby = true;
		}
		mBytesWritten = 0;
		status = mOutput->stream->setParameters(keyValuePair);
		}
		@@ -6690,7 +6687,10 @@ ssize_t AudioFlinger::DuplicatingThread::threadLoop_write()

		// TODO: Report correction for the other output tracks and show in the dump.
		}
		if (mStandby) {
		mThreadMetrics.logBeginInterval();
		mStandby = false;
		}
		return (ssize_t)mSinkBufferSize;
		}

		@@ -6852,7 +6852,7 @@ AudioFlinger::RecordThread::RecordThread(const sp<AudioFlinger>& audioFlinger,
		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 @@ reacquire_wakelock:

		case TrackBase::STARTING_2:
		doBroadcast = true;
		if (mStandby) {
		mThreadMetrics.logBeginInterval();
		mStandby = false;
		}
		activeTrack->mState = TrackBase::ACTIVE;
		allStopped = false;
		break;
		@@ -7581,6 +7584,7 @@ void AudioFlinger::RecordThread::standbyIfNotAlreadyInStandby()
		{
		if (!mStandby) {
		inputStandBy();
		mThreadMetrics.logEndInterval();
		mStandby = true;
		}
		}
		@@ -8553,11 +8557,9 @@ status_t AudioFlinger::RecordThread::createAudioPatch_l(const struct audio_patch
		}

		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 @@ status_t AudioFlinger::MmapThreadHandle::standby()

		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 @@ status_t AudioFlinger::MmapThread::exitStandby()
		ALOGE("%s: error mHalStream->start() = %d for first track", __FUNCTION__, ret);
		return ret;
		}
		if (mStandby) {
		mThreadMetrics.logBeginInterval();
		mStandby = false;
		}
		return NO_ERROR;
		}

		@@ -8942,7 +8947,10 @@ status_t AudioFlinger::MmapThread::standby()
		return INVALID_OPERATION;
		}
		mHalStream->standby();
		if (!mStandby) {
		mThreadMetrics.logEndInterval();
		mStandby = true;
		}
		releaseWakeLock();
		return NO_ERROR;
		}
		@@ -8960,7 +8968,8 @@ void AudioFlinger::MmapThread::readHalParameters_l()
		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 @@ void AudioFlinger::MmapThread::dumpTracks_l(int fd, const Vector<String16>& args
		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 @@ void AudioFlinger::MmapPlaybackThread::dumpInternals_l(int fd, const Vector<Stri
		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);

services/audioflinger/Threads.h

+6 −11

Original line number	Diff line number	Diff line
		@@ -37,7 +37,7 @@ public:
		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 @@ public:
		return mInDeviceTypeAddr;
		}

		virtual bool isOutput() const = 0;
		bool isOutput() const { return mIsOut; }

		virtual sp<StreamHalInterface> stream() const = 0;

		@@ -524,7 +524,8 @@ protected:
		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 @@ public:

		// 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 @@ public:
		ThreadBase::acquireWakeLock_l();
		mActiveTracks.updatePowerState(this, true /* force */);
		}
		virtual bool isOutput() const override { return false; }

		void checkBtNrec();

		@@ -1760,7 +1757,8 @@ class MmapThread : public ThreadBase
		#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 @@ public:
		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 @@ public:
		AudioStreamIn* clearInput();

		status_t exitStandby() override;
		virtual bool isOutput() const override { return false; }

		void updateMetadata_l() override;
		void processVolume_l() override;