diff options
| -rw-r--r-- | include/cpustats/ThreadCpuUsage.h | 78 | ||||
| -rw-r--r-- | libs/cpustats/ThreadCpuUsage.cpp | 127 | ||||
| -rw-r--r-- | services/audioflinger/AudioFlinger.cpp | 104 |
3 files changed, 254 insertions, 55 deletions
diff --git a/include/cpustats/ThreadCpuUsage.h b/include/cpustats/ThreadCpuUsage.h index 24012a47f255..9cd93d807e9d 100644 --- a/include/cpustats/ThreadCpuUsage.h +++ b/include/cpustats/ThreadCpuUsage.h @@ -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 diff --git a/libs/cpustats/ThreadCpuUsage.cpp b/libs/cpustats/ThreadCpuUsage.cpp index ffee039e1ee1..99b4c836394c 100644 --- a/libs/cpustats/ThreadCpuUsage.cpp +++ b/libs/cpustats/ThreadCpuUsage.cpp @@ -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 diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp index bfa4a49d6e7e..e3dbe01583b6 100644 --- a/services/audioflinger/AudioFlinger.cpp +++ b/services/audioflinger/AudioFlinger.cpp @@ -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; |