Merge "AudioFlinger playback thread CPU measurement in Hz"

1 files changed, 82 insertions, 22 deletions

diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index 6802bab..d83d19a 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -61,9 +61,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>
@@ -1949,30 +1953,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,
@@ -1981,7 +2038,12 @@ void CpuStats::sample() {
                     mean / perLoop100,
                     stddev / perLoop100,
                     minimum / perLoop100,
-                    maximum / perLoop100);
+                    maximum / perLoop100,
+                    meanCycles / perLoop1k,
+                    stddevCycles / perLoop1k,
+                    minCycles / perLoop1k,
+                    maxCycles / perLoop1k);
+
         }
     }
 #endif
@@ -2027,16 +2089,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;
 
@@ -2073,9 +2133,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;