AudioFlinger playback thread CPU measurement in Hz (f57e2bce) · Commits · e / os / android_frameworks_base

include/cpustats/ThreadCpuUsage.h

+52 −26

Original line number	Diff line number	Diff line
		@@ -17,16 +17,17 @@
		#ifndef _THREAD_CPU_USAGE_H
		#define _THREAD_CPU_USAGE_H

		#include <cpustats/CentralTendencyStatistics.h>
		#include <fcntl.h>
		#include <pthread.h>

		// Track CPU usage for the current thread, and maintain statistics on
		// the CPU usage. Units are in per-thread CPU ns, as reported by
		namespace android {

		// Track CPU usage for the current thread.
		// Units are in per-thread CPU ns, as reported by
		// clock_gettime(CLOCK_THREAD_CPUTIME_ID). Simple usage: for cyclic
		// threads where you want to measure the execution time of the whole
		// cycle, just call sampleAndEnable() at the start of each cycle.
		// Then call statistics() to get the results, and resetStatistics()
		// to start a new set of measurements.
		// For acyclic threads, or for cyclic threads where you want to measure
		// For acyclic threads, or for cyclic threads where you want to measure/track
		// only part of each cycle, call enable(), disable(), and/or setEnabled()
		// to demarcate the region(s) of interest, and then call sample() periodically.
		// This class is not thread-safe for concurrent calls from multiple threads;
		@@ -44,13 +45,17 @@ public:
		// mPreviousTs
		// mMonotonicTs
		mMonotonicKnown(false)
		// mStatistics
		{ }
		{
		(void) pthread_once(&sOnceControl, &init);
		for (int i = 0; i < sKernelMax; ++i) {
		mCurrentkHz[i] = (uint32_t) ~0; // unknown
		}
		}

		~ThreadCpuUsage() { }

		// Return whether currently tracking CPU usage by current thread
		bool isEnabled() { return mIsEnabled; }
		bool isEnabled() const { return mIsEnabled; }

		// Enable tracking of CPU usage by current thread;
		// any CPU used from this point forward will be tracked.
		@@ -66,39 +71,52 @@ public:
		// This method is intended to be used for safe nested enable/disabling.
		bool setEnabled(bool isEnabled);

		// Add a sample point for central tendency statistics, and also
		// enable tracking if needed. If tracking has never been enabled, then
		// enables tracking but does not add a sample (it is not possible to add
		// a sample the first time because no previous). Otherwise if tracking is
		// enabled, then adds a sample for tracked CPU ns since the previous
		// Add a sample point, and also enable tracking if needed.
		// If tracking has never been enabled, then this call enables tracking but
		// does _not_ add a sample -- it is not possible to add a sample the
		// first time because there is no previous point to subtract from.
		// Otherwise, if tracking is enabled,
		// then adds a sample for tracked CPU ns since the previous
		// sample, or since the first call to sampleAndEnable(), enable(), or
		// setEnabled(true). If there was a previous sample but tracking is
		// now disabled, then adds a sample for the tracked CPU ns accumulated
		// up until the most recent disable(), resets this accumulator, and then
		// enables tracking. Calling this method rather than enable() followed
		// by sample() avoids a race condition for the first sample.
		void sampleAndEnable();
		// Returns true if the sample 'ns' is valid, or false if invalid.
		// Note that 'ns' is an output parameter passed by reference.
		// The caller does not need to initialize this variable.
		// The units are CPU nanoseconds consumed by current thread.
		bool sampleAndEnable(double& ns);

		// Add a sample point for central tendency statistics, but do not
		// Add a sample point, but do not
		// change the tracking enabled status. If tracking has either never been
		// enabled, or has never been enabled since the last sample, then log a warning
		// and don't add sample. Otherwise, adds a sample for tracked CPU ns since
		// the previous sample or since the first call to sampleAndEnable(),
		// enable(), or setEnabled(true) if no previous sample.
		void sample();
		// Returns true if the sample is valid, or false if invalid.
		// Note that 'ns' is an output parameter passed by reference.
		// The caller does not need to initialize this variable.
		// The units are CPU nanoseconds consumed by current thread.
		bool sample(double& ns);

		// Return the elapsed delta wall clock ns since initial enable or statistics reset,
		// Return the elapsed delta wall clock ns since initial enable or reset,
		// as reported by clock_gettime(CLOCK_MONOTONIC).
		long long elapsed() const;

		// Reset statistics and elapsed. Has no effect on tracking or accumulator.
		void resetStatistics();
		// Reset elapsed wall clock. Has no effect on tracking or accumulator.
		void resetElapsed();

		// Return a const reference to the central tendency statistics.
		// Note that only the const methods can be called on this object.
		const CentralTendencyStatistics& statistics() const {
		return mStatistics;
		}
		// Return current clock frequency for specified CPU, in kHz.
		// You can get your CPU number using sched_getcpu(2). Note that, unless CPU affinity
		// has been configured appropriately, the CPU number can change.
		// Also note that, unless the CPU governor has been configured appropriately,
		// the CPU frequency can change. And even if the CPU frequency is locked down
		// to a particular value, that the frequency might still be adjusted
		// to prevent thermal overload. Therefore you should poll for your thread's
		// current CPU number and clock frequency periodically.
		uint32_t getCpukHz(int cpuNum);

		private:
		bool mIsEnabled; // whether tracking is currently enabled
		@@ -107,7 +125,15 @@ private:
		struct timespec mPreviousTs; // most recent thread CPU time, valid only if mIsEnabled is true
		struct timespec mMonotonicTs; // most recent monotonic time
		bool mMonotonicKnown; // whether mMonotonicTs has been set
		CentralTendencyStatistics mStatistics;

		static const int MAX_CPU = 8;
		static int sScalingFds[MAX_CPU];// file descriptor per CPU for reading scaling_cur_freq
		uint32_t mCurrentkHz[MAX_CPU]; // current CPU frequency in kHz, not static to avoid a race
		static pthread_once_t sOnceControl;
		static int sKernelMax; // like MAX_CPU, but determined at runtime == cpu/kernel_max + 1
		static void init();
		};

		} // namespace android

		#endif // _THREAD_CPU_USAGE_H

libs/cpustats/ThreadCpuUsage.cpp

+120 −7

Original line number	Diff line number	Diff line
		@@ -14,18 +14,26 @@
		* limitations under the License.
		*/

		#define LOG_TAG "ThreadCpuUsage"
		//#define LOG_NDEBUG 0

		#include <errno.h>
		#include <stdlib.h>
		#include <time.h>

		#include <utils/Debug.h>
		#include <utils/Log.h>

		#include <cpustats/ThreadCpuUsage.h>

		namespace android {

		bool ThreadCpuUsage::setEnabled(bool isEnabled)
		{
		bool wasEnabled = mIsEnabled;
		// only do something if there is a change
		if (isEnabled != wasEnabled) {
		ALOGV("setEnabled(%d)", isEnabled);
		int rc;
		// enabling
		if (isEnabled) {
		@@ -65,20 +73,28 @@ bool ThreadCpuUsage::setEnabled(bool isEnabled)
		return wasEnabled;
		}

		void ThreadCpuUsage::sampleAndEnable()
		bool ThreadCpuUsage::sampleAndEnable(double& ns)
		{
		bool ret;
		bool wasEverEnabled = mWasEverEnabled;
		if (enable()) {
		// already enabled, so add a new sample relative to previous
		sample();
		return sample(ns);
		} else if (wasEverEnabled) {
		// was disabled, but add sample for accumulated time while enabled
		mStatistics.sample((double) mAccumulator);
		ns = (double) mAccumulator;
		mAccumulator = 0;
		ALOGV("sampleAndEnable %.0f", ns);
		return true;
		} else {
		// first time called
		ns = 0.0;
		ALOGV("sampleAndEnable false");
		return false;
		}
		}

		void ThreadCpuUsage::sample()
		bool ThreadCpuUsage::sample(double &ns)
		{
		if (mWasEverEnabled) {
		if (mIsEnabled) {
		@@ -87,6 +103,8 @@ void ThreadCpuUsage::sample()
		rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts);
		if (rc) {
		ALOGE("clock_gettime(CLOCK_THREAD_CPUTIME_ID) errno=%d", errno);
		ns = 0.0;
		return false;
		} else {
		long long delta = (ts.tv_sec - mPreviousTs.tv_sec) * 1000000000LL +
		(ts.tv_nsec - mPreviousTs.tv_nsec);
		@@ -96,10 +114,14 @@ void ThreadCpuUsage::sample()
		} else {
		mWasEverEnabled = false;
		}
		mStatistics.sample((double) mAccumulator);
		ns = (double) mAccumulator;
		ALOGV("sample %.0f", ns);
		mAccumulator = 0;
		return true;
		} else {
		ALOGW("Can't add sample because measurements have never been enabled");
		ns = 0.0;
		return false;
		}
		}

		@@ -122,12 +144,13 @@ long long ThreadCpuUsage::elapsed() const
		ALOGW("Can't compute elapsed time because measurements have never been enabled");
		elapsed = 0;
		}
		ALOGV("elapsed %lld", elapsed);
		return elapsed;
		}

		void ThreadCpuUsage::resetStatistics()
		void ThreadCpuUsage::resetElapsed()
		{
		mStatistics.reset();
		ALOGV("resetElapsed");
		if (mMonotonicKnown) {
		int rc;
		rc = clock_gettime(CLOCK_MONOTONIC, &mMonotonicTs);
		@@ -137,3 +160,93 @@ void ThreadCpuUsage::resetStatistics()
		}
		}
		}

		/static/
		int ThreadCpuUsage::sScalingFds[ThreadCpuUsage::MAX_CPU];
		pthread_once_t ThreadCpuUsage::sOnceControl = PTHREAD_ONCE_INIT;
		int ThreadCpuUsage::sKernelMax;

		/static/
		void ThreadCpuUsage::init()
		{
		// read the number of CPUs
		sKernelMax = 1;
		int fd = open("/sys/devices/system/cpu/kernel_max", O_RDONLY);
		if (fd >= 0) {
		#define KERNEL_MAX_SIZE 12
		char kernelMax[KERNEL_MAX_SIZE];
		ssize_t actual = read(fd, kernelMax, sizeof(kernelMax));
		if (actual >= 2 && kernelMax[actual-1] == '\n') {
		sKernelMax = atoi(kernelMax);
		if (sKernelMax >= MAX_CPU - 1) {
		ALOGW("kernel_max %d but MAX_CPU %d", sKernelMax, MAX_CPU);
		sKernelMax = MAX_CPU;
		} else if (sKernelMax < 0) {
		ALOGW("kernel_max invalid %d", sKernelMax);
		sKernelMax = 1;
		} else {
		++sKernelMax;
		ALOGV("number of CPUs %d", sKernelMax);
		}
		} else {
		ALOGW("Can't read number of CPUs");
		}
		(void) close(fd);
		} else {
		ALOGW("Can't open number of CPUs");
		}

		// open fd to each frequency per CPU
		#define FREQ_SIZE 64
		char freq_path[FREQ_SIZE];
		#define FREQ_DIGIT 27
		COMPILE_TIME_ASSERT_FUNCTION_SCOPE(MAX_CPU <= 10);
		strlcpy(freq_path, "/sys/devices/system/cpu/cpu?/cpufreq/scaling_cur_freq", sizeof(freq_path));
		int i;
		for (i = 0; i < MAX_CPU; ++i) {
		sScalingFds[i] = -1;
		}
		for (i = 0; i < sKernelMax; ++i) {
		freq_path[FREQ_DIGIT] = i + '0';
		fd = open(freq_path, O_RDONLY);
		if (fd >= 0) {
		// keep this fd until process exit
		sScalingFds[i] = fd;
		} else {
		ALOGW("Can't open CPU %d", i);
		}
		}
		}

		uint32_t ThreadCpuUsage::getCpukHz(int cpuNum)
		{
		if (cpuNum < 0 \|\| cpuNum >= MAX_CPU) {
		ALOGW("getCpukHz called with invalid CPU %d", cpuNum);
		return 0;
		}
		int fd = sScalingFds[cpuNum];
		if (fd < 0) {
		ALOGW("getCpukHz called for unopened CPU %d", cpuNum);
		return 0;
		}
		#define KHZ_SIZE 12
		char kHz[KHZ_SIZE]; // kHz base 10
		ssize_t actual = pread(fd, kHz, sizeof(kHz), (off_t) 0);
		uint32_t ret;
		if (actual >= 2 && kHz[actual-1] == '\n') {
		ret = atoi(kHz);
		} else {
		ret = 0;
		}
		if (ret != mCurrentkHz[cpuNum]) {
		if (ret > 0) {
		ALOGV("CPU %d frequency %u kHz", cpuNum, ret);
		} else {
		ALOGW("Can't read CPU %d frequency", cpuNum);
		}
		mCurrentkHz[cpuNum] = ret;
		}
		return ret;
		}

		} // namespace android

services/audioflinger/AudioFlinger.cpp

+82 −22

Original line number	Diff line number	Diff line
		@@ -57,9 +57,13 @@

		#include <audio_utils/primitives.h>

		#include <cpustats/ThreadCpuUsage.h>
		#include <powermanager/PowerManager.h>

		// #define DEBUG_CPU_USAGE 10 // log statistics every n wall clock seconds
		#ifdef DEBUG_CPU_USAGE
		#include <cpustats/CentralTendencyStatistics.h>
		#include <cpustats/ThreadCpuUsage.h>
		#endif

		#include <common_time/cc_helper.h>
		#include <common_time/local_clock.h>
		@@ -1939,30 +1943,83 @@ AudioFlinger::MixerThread::~MixerThread()

		class CpuStats {
		public:
		void sample();
		CpuStats();
		void sample(const String8 &title);
		#ifdef DEBUG_CPU_USAGE
		private:
		ThreadCpuUsage mCpu;
		ThreadCpuUsage mCpuUsage; // instantaneous thread CPU usage in wall clock ns
		CentralTendencyStatistics mWcStats; // statistics on thread CPU usage in wall clock ns

		CentralTendencyStatistics mHzStats; // statistics on thread CPU usage in cycles

		int mCpuNum; // thread's current CPU number
		int mCpukHz; // frequency of thread's current CPU in kHz
		#endif
		};

		void CpuStats::sample() {
		CpuStats::CpuStats()
		#ifdef DEBUG_CPU_USAGE
		const CentralTendencyStatistics& stats = mCpu.statistics();
		mCpu.sampleAndEnable();
		unsigned n = stats.n();
		// mCpu.elapsed() is expensive, so don't call it every loop
		: mCpuNum(-1), mCpukHz(-1)
		#endif
		{
		}

		void CpuStats::sample(const String8 &title) {
		#ifdef DEBUG_CPU_USAGE
		// get current thread's delta CPU time in wall clock ns
		double wcNs;
		bool valid = mCpuUsage.sampleAndEnable(wcNs);

		// record sample for wall clock statistics
		if (valid) {
		mWcStats.sample(wcNs);
		}

		// get the current CPU number
		int cpuNum = sched_getcpu();

		// get the current CPU frequency in kHz
		int cpukHz = mCpuUsage.getCpukHz(cpuNum);

		// check if either CPU number or frequency changed
		if (cpuNum != mCpuNum \|\| cpukHz != mCpukHz) {
		mCpuNum = cpuNum;
		mCpukHz = cpukHz;
		// ignore sample for purposes of cycles
		valid = false;
		}

		// if no change in CPU number or frequency, then record sample for cycle statistics
		if (valid && mCpukHz > 0) {
		double cycles = wcNs * cpukHz * 0.000001;
		mHzStats.sample(cycles);
		}

		unsigned n = mWcStats.n();
		// mCpuUsage.elapsed() is expensive, so don't call it every loop
		if ((n & 127) == 1) {
		long long elapsed = mCpu.elapsed();
		long long elapsed = mCpuUsage.elapsed();
		if (elapsed >= DEBUG_CPU_USAGE * 1000000000LL) {
		double perLoop = elapsed / (double) n;
		double perLoop100 = perLoop * 0.01;
		double mean = stats.mean();
		double stddev = stats.stddev();
		double minimum = stats.minimum();
		double maximum = stats.maximum();
		mCpu.resetStatistics();
		ALOGI("CPU usage over past %.1f secs (%u mixer loops at %.1f mean ms per loop):\n us per mix loop: mean=%.0f stddev=%.0f min=%.0f max=%.0f\n %% of wall: mean=%.1f stddev=%.1f min=%.1f max=%.1f",
		double perLoop1k = perLoop * 0.001;
		double mean = mWcStats.mean();
		double stddev = mWcStats.stddev();
		double minimum = mWcStats.minimum();
		double maximum = mWcStats.maximum();
		double meanCycles = mHzStats.mean();
		double stddevCycles = mHzStats.stddev();
		double minCycles = mHzStats.minimum();
		double maxCycles = mHzStats.maximum();
		mCpuUsage.resetElapsed();
		mWcStats.reset();
		mHzStats.reset();
		ALOGD("CPU usage for %s over past %.1f secs\n"
		" (%u mixer loops at %.1f mean ms per loop):\n"
		" us per mix loop: mean=%.0f stddev=%.0f min=%.0f max=%.0f\n"
		" %% of wall: mean=%.1f stddev=%.1f min=%.1f max=%.1f\n"
		" MHz: mean=%.1f, stddev=%.1f, min=%.1f max=%.1f",
		title.string(),
		elapsed * .000000001, n, perLoop * .000001,
		mean * .001,
		stddev * .001,
		@@ -1971,7 +2028,12 @@ void CpuStats::sample() {
		mean / perLoop100,
		stddev / perLoop100,
		minimum / perLoop100,
		maximum / perLoop100);
		maximum / perLoop100,
		meanCycles / perLoop1k,
		stddevCycles / perLoop1k,
		minCycles / perLoop1k,
		maxCycles / perLoop1k);

		}
		}
		#endif
		@@ -2017,16 +2079,14 @@ if (mType == MIXER) {
		sleepTimeShift = 0;
		}

		// MIXER
		CpuStats cpuStats;
		const String8 myName(String8::format("thread %p type %d TID %d", this, mType, gettid()));

		acquireWakeLock();

		while (!exitPending())
		{
		if (mType == MIXER) {
		cpuStats.sample();
		}
		cpuStats.sample(myName);

		Vector< sp<EffectChain> > effectChains;

		@@ -2063,9 +2123,9 @@ if (mType == MIXER) {

		releaseWakeLock_l();
		// wait until we have something to do...
		ALOGV("Thread %p type %d TID %d going to sleep", this, mType, gettid());
		ALOGV("%s going to sleep", myName.string());
		mWaitWorkCV.wait(mLock);
		ALOGV("Thread %p type %d TID %d waking up", this, mType, gettid());
		ALOGV("%s waking up", myName.string());
		acquireWakeLock_l();

		mPrevMixerStatus = MIXER_IDLE;