AudioFlinger playback thread CPU measurement in Hz

Log statistics on CPU usage in Hz in addition to wall clock time

Use CPU statistics for all playback threads, not just MIXER
(but they are disabled by default by a compile-time debug macro).

ThreadCpuUsage library:
 - Move statistics out of the library and leave that up to the caller
 - Add API to determine a CPU's frequency

Change-Id: Ia1011123146e641fcf210ef26e78ae2b4d3b64ad

3 files changed, 254 insertions, 55 deletions

diff --git a/include/cpustats/ThreadCpuUsage.h b/include/cpustats/ThreadCpuUsage.h
index 24012a4..9cd93d8 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 ffee039..99b4c83 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 bfa4a49..e3dbe01 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;