Merge "AudioFlinger playback thread CPU measurement in Hz" (81fe4fbd) · Commits · e / os / android_frameworks_base

include/cpustats/ThreadCpuUsage.h

+52 −26

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

	~ThreadCpuUsage() { }		~ThreadCpuUsage() { }

	// Return whether currently tracking CPU usage by current thread		// 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;		// Enable tracking of CPU usage by current thread;
	// any CPU used from this point forward will be tracked.		// 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.		// This method is intended to be used for safe nested enable/disabling.
	bool setEnabled(bool isEnabled);		bool setEnabled(bool isEnabled);

	// Add a sample point for central tendency statistics, and also		// Add a sample point, and also enable tracking if needed.
	// enable tracking if needed. If tracking has never been enabled, then		// If tracking has never been enabled, then this call enables tracking but
	// enables tracking but does not add a sample (it is not possible to add		// does _not_ add a sample -- it is not possible to add a sample the
	// a sample the first time because no previous). Otherwise if tracking is		// first time because there is no previous point to subtract from.
	// enabled, then adds a sample for tracked CPU ns since the previous		// 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		// sample, or since the first call to sampleAndEnable(), enable(), or
	// setEnabled(true). If there was a previous sample but tracking is		// setEnabled(true). If there was a previous sample but tracking is
	// now disabled, then adds a sample for the tracked CPU ns accumulated		// now disabled, then adds a sample for the tracked CPU ns accumulated
	// up until the most recent disable(), resets this accumulator, and then		// up until the most recent disable(), resets this accumulator, and then
	// enables tracking. Calling this method rather than enable() followed		// enables tracking. Calling this method rather than enable() followed
	// by sample() avoids a race condition for the first sample.		// 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		// 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		// 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		// and don't add sample. Otherwise, adds a sample for tracked CPU ns since
	// the previous sample or since the first call to sampleAndEnable(),		// the previous sample or since the first call to sampleAndEnable(),
	// enable(), or setEnabled(true) if no previous sample.		// 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).		// as reported by clock_gettime(CLOCK_MONOTONIC).
	long long elapsed() const;		long long elapsed() const;

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

	// Return a const reference to the central tendency statistics.		// Return current clock frequency for specified CPU, in kHz.
	// Note that only the const methods can be called on this object.		// You can get your CPU number using sched_getcpu(2). Note that, unless CPU affinity
	const CentralTendencyStatistics& statistics() const {		// has been configured appropriately, the CPU number can change.
	return mStatistics;		// 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:		private:
	bool mIsEnabled; // whether tracking is currently enabled		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 mPreviousTs; // most recent thread CPU time, valid only if mIsEnabled is true
	struct timespec mMonotonicTs; // most recent monotonic time		struct timespec mMonotonicTs; // most recent monotonic time
	bool mMonotonicKnown; // whether mMonotonicTs has been set		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		#endif // _THREAD_CPU_USAGE_H

libs/cpustats/ThreadCpuUsage.cpp

+120 −7

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

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

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

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

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

			namespace android {

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

	void ThreadCpuUsage::sampleAndEnable()		bool ThreadCpuUsage::sampleAndEnable(double& ns)
	{		{
			bool ret;
	bool wasEverEnabled = mWasEverEnabled;		bool wasEverEnabled = mWasEverEnabled;
	if (enable()) {		if (enable()) {
	// already enabled, so add a new sample relative to previous		// already enabled, so add a new sample relative to previous
	sample();		return sample(ns);
	} else if (wasEverEnabled) {		} else if (wasEverEnabled) {
	// was disabled, but add sample for accumulated time while enabled		// was disabled, but add sample for accumulated time while enabled
	mStatistics.sample((double) mAccumulator);		ns = (double) mAccumulator;
	mAccumulator = 0;		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 (mWasEverEnabled) {
	if (mIsEnabled) {		if (mIsEnabled) {
	@@ -87,6 +103,8 @@ void ThreadCpuUsage::sample()
	rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts);		rc = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts);
	if (rc) {		if (rc) {
	ALOGE("clock_gettime(CLOCK_THREAD_CPUTIME_ID) errno=%d", errno);		ALOGE("clock_gettime(CLOCK_THREAD_CPUTIME_ID) errno=%d", errno);
			ns = 0.0;
			return false;
	} else {		} else {
	long long delta = (ts.tv_sec - mPreviousTs.tv_sec) * 1000000000LL +		long long delta = (ts.tv_sec - mPreviousTs.tv_sec) * 1000000000LL +
	(ts.tv_nsec - mPreviousTs.tv_nsec);		(ts.tv_nsec - mPreviousTs.tv_nsec);
	@@ -96,10 +114,14 @@ void ThreadCpuUsage::sample()
	} else {		} else {
	mWasEverEnabled = false;		mWasEverEnabled = false;
	}		}
	mStatistics.sample((double) mAccumulator);		ns = (double) mAccumulator;
			ALOGV("sample %.0f", ns);
	mAccumulator = 0;		mAccumulator = 0;
			return true;
	} else {		} else {
	ALOGW("Can't add sample because measurements have never been enabled");		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");		ALOGW("Can't compute elapsed time because measurements have never been enabled");
	elapsed = 0;		elapsed = 0;
	}		}
			ALOGV("elapsed %lld", elapsed);
	return elapsed;		return elapsed;
	}		}

	void ThreadCpuUsage::resetStatistics()		void ThreadCpuUsage::resetElapsed()
	{		{
	mStatistics.reset();		ALOGV("resetElapsed");
	if (mMonotonicKnown) {		if (mMonotonicKnown) {
	int rc;		int rc;
	rc = clock_gettime(CLOCK_MONOTONIC, &mMonotonicTs);		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	Original line	Diff line number	Diff line
	@@ -61,9 +61,13 @@

	#include <audio_utils/primitives.h>		#include <audio_utils/primitives.h>

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

	// #define DEBUG_CPU_USAGE 10 // log statistics every n wall clock seconds		// #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/cc_helper.h>
	#include <common_time/local_clock.h>		#include <common_time/local_clock.h>
	@@ -1949,30 +1953,83 @@ AudioFlinger::MixerThread::~MixerThread()

	class CpuStats {		class CpuStats {
	public:		public:
	void sample();		CpuStats();
			void sample(const String8 &title);
	#ifdef DEBUG_CPU_USAGE		#ifdef DEBUG_CPU_USAGE
	private:		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		#endif
	};		};

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

			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) {		if ((n & 127) == 1) {
	long long elapsed = mCpu.elapsed();		long long elapsed = mCpuUsage.elapsed();
	if (elapsed >= DEBUG_CPU_USAGE * 1000000000LL) {		if (elapsed >= DEBUG_CPU_USAGE * 1000000000LL) {
	double perLoop = elapsed / (double) n;		double perLoop = elapsed / (double) n;
	double perLoop100 = perLoop * 0.01;		double perLoop100 = perLoop * 0.01;
	double mean = stats.mean();		double perLoop1k = perLoop * 0.001;
	double stddev = stats.stddev();		double mean = mWcStats.mean();
	double minimum = stats.minimum();		double stddev = mWcStats.stddev();
	double maximum = stats.maximum();		double minimum = mWcStats.minimum();
	mCpu.resetStatistics();		double maximum = mWcStats.maximum();
	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 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,		elapsed * .000000001, n, perLoop * .000001,
	mean * .001,		mean * .001,
	stddev * .001,		stddev * .001,
	@@ -1981,7 +2038,12 @@ void CpuStats::sample() {
	mean / perLoop100,		mean / perLoop100,
	stddev / perLoop100,		stddev / perLoop100,
	minimum / perLoop100,		minimum / perLoop100,
	maximum / perLoop100);		maximum / perLoop100,
			meanCycles / perLoop1k,
			stddevCycles / perLoop1k,
			minCycles / perLoop1k,
			maxCycles / perLoop1k);

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

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

	acquireWakeLock();		acquireWakeLock();

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

	Vector< sp<EffectChain> > effectChains;		Vector< sp<EffectChain> > effectChains;

	@@ -2073,9 +2133,9 @@ if (mType == MIXER) {

	releaseWakeLock_l();		releaseWakeLock_l();
	// wait until we have something to do...		// 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);		mWaitWorkCV.wait(mLock);
	ALOGV("Thread %p type %d TID %d waking up", this, mType, gettid());		ALOGV("%s waking up", myName.string());
	acquireWakeLock_l();		acquireWakeLock_l();

	mPrevMixerStatus = MIXER_IDLE;		mPrevMixerStatus = MIXER_IDLE;