Merge "Use sampling for faster measuring of CPU time"

1 files changed, 204 insertions, 105 deletions

diff --git a/core/java/com/android/internal/os/BinderCallsStats.java b/core/java/com/android/internal/os/BinderCallsStats.java
index 919dc36a140d..ec89d8127e5a 100644
--- a/core/java/com/android/internal/os/BinderCallsStats.java
+++ b/core/java/com/android/internal/os/BinderCallsStats.java
@@ -18,6 +18,7 @@ package com.android.internal.os;
 
 import android.os.Binder;
 import android.os.SystemClock;
+import android.os.UserHandle;
 import android.text.format.DateFormat;
 import android.util.ArrayMap;
 import android.util.SparseArray;
@@ -28,11 +29,12 @@ import com.android.internal.util.Preconditions;
 
 import java.io.PrintWriter;
 import java.util.ArrayList;
-import java.util.HashMap;
+import java.util.Comparator;
 import java.util.List;
 import java.util.Map;
 import java.util.Queue;
 import java.util.concurrent.ConcurrentLinkedQueue;
+import java.util.function.ToDoubleFunction;
 
 /**
  * Collects statistics about CPU time spent per binder call across multiple dimensions, e.g.
@@ -40,6 +42,7 @@ import java.util.concurrent.ConcurrentLinkedQueue;
  */
 public class BinderCallsStats {
     private static final int CALL_SESSIONS_POOL_SIZE = 100;
+    private static final int PERIODIC_SAMPLING_INTERVAL = 10;
     private static final BinderCallsStats sInstance = new BinderCallsStats();
 
     private volatile boolean mDetailedTracking = false;
@@ -48,6 +51,8 @@ public class BinderCallsStats {
     private final Queue<CallSession> mCallSessionsPool = new ConcurrentLinkedQueue<>();
     private final Object mLock = new Object();
     private long mStartTime = System.currentTimeMillis();
+    @GuardedBy("mLock")
+    private UidEntry mSampledEntries = new UidEntry(-1);
 
     private BinderCallsStats() {
     }
@@ -66,40 +71,71 @@ public class BinderCallsStats {
         if (s == null) {
             s = new CallSession();
         }
-        s.mCallStat.className = className;
-        s.mCallStat.msg = code;
-
-        s.mCpuTimeStarted = getThreadTimeMicro();
-        s.mTimeStarted = getElapsedRealtimeNanos() / 1_000;
+        s.callStat.className = className;
+        s.callStat.msg = code;
         s.exceptionThrown = false;
+        s.cpuTimeStarted = -1;
+        s.timeStarted = -1;
+
+        synchronized (mLock) {
+            if (mDetailedTracking) {
+                s.cpuTimeStarted = getThreadTimeMicro();
+                s.timeStarted = getElapsedRealtimeMicro();
+            } else {
+                s.sampledCallStat = mSampledEntries.getOrCreate(s.callStat);
+                if (s.sampledCallStat.callCount % PERIODIC_SAMPLING_INTERVAL == 0) {
+                    s.cpuTimeStarted = getThreadTimeMicro();
+                    s.timeStarted = getElapsedRealtimeMicro();
+                }
+            }
+        }
         return s;
     }
 
     public void callEnded(CallSession s) {
         Preconditions.checkNotNull(s);
-        long duration = mDetailedTracking ? getThreadTimeMicro() - s.mCpuTimeStarted : 1;
-        long latencyDuration =
-            mDetailedTracking ? SystemClock.elapsedRealtimeNanos() / 1_000 - s.mTimeStarted : 1;
-        s.mCallingUId = Binder.getCallingUid();
-
         synchronized (mLock) {
-            UidEntry uidEntry = mUidEntries.get(s.mCallingUId);
+            long duration;
+            long latencyDuration;
+            if (mDetailedTracking) {
+                duration = getThreadTimeMicro() - s.cpuTimeStarted;
+                latencyDuration = getElapsedRealtimeMicro() - s.timeStarted;
+            } else {
+                CallStat cs = s.sampledCallStat;
+                // Non-negative time signals beginning of the new sampling interval
+                if (s.cpuTimeStarted >= 0) {
+                    duration = getThreadTimeMicro() - s.cpuTimeStarted;
+                    latencyDuration = getElapsedRealtimeMicro() - s.timeStarted;
+                } else {
+                    // callCount is always incremented, but time only once per sampling interval
+                    long samplesCount = cs.callCount / PERIODIC_SAMPLING_INTERVAL + 1;
+                    duration = cs.cpuTimeMicros / samplesCount;
+                    latencyDuration = cs.latencyMicros/ samplesCount;
+                }
+            }
+
+            int callingUid = getCallingUid();
+
+            UidEntry uidEntry = mUidEntries.get(callingUid);
             if (uidEntry == null) {
-                uidEntry = new UidEntry(s.mCallingUId);
-                mUidEntries.put(s.mCallingUId, uidEntry);
+                uidEntry = new UidEntry(callingUid);
+                mUidEntries.put(callingUid, uidEntry);
             }
+
             if (mDetailedTracking) {
-                // Find CallDesc entry and update its total time
-                CallStat callStat = uidEntry.mCallStats.get(s.mCallStat);
-                // Only create CallStat if it's a new entry, otherwise update existing instance
-                if (callStat == null) {
-                    callStat = new CallStat(s.mCallStat.className, s.mCallStat.msg);
-                    uidEntry.mCallStats.put(callStat, callStat);
-                }
+                // Find CallStat entry and update its total time
+                CallStat callStat = uidEntry.getOrCreate(s.callStat);
                 callStat.callCount++;
-                callStat.latencyMicros += latencyDuration;
                 callStat.cpuTimeMicros += duration;
+                callStat.latencyMicros += latencyDuration;
                 callStat.exceptionCount += s.exceptionThrown ? 1 : 0;
+            } else {
+                // update sampled timings in the beginning of each interval
+                if (s.cpuTimeStarted >= 0) {
+                    s.sampledCallStat.cpuTimeMicros += duration;
+                    s.sampledCallStat.latencyMicros += latencyDuration;
+                }
+                s.sampledCallStat.callCount++;
             }
 
             uidEntry.cpuTimeMicros += duration;
@@ -122,53 +158,38 @@ public class BinderCallsStats {
         s.exceptionThrown = true;
     }
 
-    public void dump(PrintWriter pw) {
-        Map<Integer, Long> uidTimeMap = new HashMap<>();
-        Map<Integer, Long> uidCallCountMap = new HashMap<>();
+    public void dump(PrintWriter pw, Map<Integer,String> appIdToPkgNameMap, boolean verbose) {
+        synchronized (mLock) {
+            dumpLocked(pw, appIdToPkgNameMap, verbose);
+        }
+    }
+
+    private void dumpLocked(PrintWriter pw, Map<Integer,String> appIdToPkgNameMap, boolean verbose) {
         long totalCallsCount = 0;
-        long totalCpuCallsTime = 0;
-        long totalLatencyCallsTime = 0;
+        long totalCpuTime = 0;
         pw.print("Start time: ");
         pw.println(DateFormat.format("yyyy-MM-dd HH:mm:ss", mStartTime));
-        int uidEntriesSize = mUidEntries.size();
         List<UidEntry> entries = new ArrayList<>();
-        synchronized (mLock) {
-            for (int i = 0; i < uidEntriesSize; i++) {
-                UidEntry e = mUidEntries.valueAt(i);
-                entries.add(e);
-                totalCpuCallsTime += e.cpuTimeMicros;
-                // Update per-uid totals
-                Long totalTimePerUid = uidTimeMap.get(e.uid);
-                uidTimeMap.put(e.uid,
-                        totalTimePerUid == null ? e.cpuTimeMicros : totalTimePerUid + e.cpuTimeMicros);
-                Long totalCallsPerUid = uidCallCountMap.get(e.uid);
-                uidCallCountMap.put(e.uid, totalCallsPerUid == null ? e.callCount
-                        : totalCallsPerUid + e.callCount);
-                totalCallsCount += e.callCount;
-            }
+
+        int uidEntriesSize = mUidEntries.size();
+        for (int i = 0; i < uidEntriesSize; i++) {
+            UidEntry e = mUidEntries.valueAt(i);
+            entries.add(e);
+            totalCpuTime += e.cpuTimeMicros;
+            totalCallsCount += e.callCount;
         }
+
+        entries.sort(Comparator.<UidEntry>comparingDouble(value -> value.cpuTimeMicros).reversed());
+        String datasetSizeDesc = verbose ? "" : "(top 90% by cpu time) ";
+        StringBuilder sb = new StringBuilder();
         if (mDetailedTracking) {
-            pw.println("Raw data (uid,call_desc,cpu_time_micros,latency_time_micros,exception_count,call_count):");
-            entries.sort((o1, o2) -> {
-                if (o1.cpuTimeMicros < o2.cpuTimeMicros) {
-                    return 1;
-                } else if (o1.cpuTimeMicros > o2.cpuTimeMicros) {
-                    return -1;
-                }
-                return 0;
-            });
-            StringBuilder sb = new StringBuilder();
-            for (UidEntry uidEntry : entries) {
-                List<CallStat> callStats = new ArrayList<>(uidEntry.mCallStats.keySet());
-                callStats.sort((o1, o2) -> {
-                    if (o1.cpuTimeMicros < o2.cpuTimeMicros) {
-                        return 1;
-                    } else if (o1.cpuTimeMicros > o2.cpuTimeMicros) {
-                        return -1;
-                    }
-                    return 0;
-                });
-                for (CallStat e : callStats) {
+            pw.println("Per-UID raw data " + datasetSizeDesc
+                    + "(uid, call_desc, cpu_time_micros, latency_time_micros, exception_count, "
+                    + "call_count):");
+            List<UidEntry> topEntries = verbose ? entries
+                    : getHighestValues(entries, value -> value.cpuTimeMicros, 0.9);
+            for (UidEntry uidEntry : topEntries) {
+                for (CallStat e : uidEntry.getCallStatsList()) {
                     sb.setLength(0);
                     sb.append("    ")
                             .append(uidEntry.uid).append(",").append(e)
@@ -180,40 +201,58 @@ public class BinderCallsStats {
                 }
             }
             pw.println();
-            pw.println("Per UID Summary(UID: time, % of total_time, calls_count):");
-            List<Map.Entry<Integer, Long>> uidTotals = new ArrayList<>(uidTimeMap.entrySet());
-            uidTotals.sort((o1, o2) -> o2.getValue().compareTo(o1.getValue()));
-            for (Map.Entry<Integer, Long> uidTotal : uidTotals) {
-                Long callCount = uidCallCountMap.get(uidTotal.getKey());
-                pw.println(String.format("  %7d: %11d %3.0f%% %8d",
-                        uidTotal.getKey(), uidTotal.getValue(),
-                        100d * uidTotal.getValue() / totalCpuCallsTime, callCount));
-            }
-            pw.println();
-            pw.println(String.format("  Summary: total_time=%d, "
-                            + "calls_count=%d, avg_call_time=%.0f",
-                    totalCpuCallsTime, totalCallsCount,
-                    (double)totalCpuCallsTime / totalCallsCount));
         } else {
-            pw.println("Per UID Summary(UID: calls_count, % of total calls_count):");
-            List<Map.Entry<Integer, Long>> uidTotals = new ArrayList<>(uidTimeMap.entrySet());
-            uidTotals.sort((o1, o2) -> o2.getValue().compareTo(o1.getValue()));
-            for (Map.Entry<Integer, Long> uidTotal : uidTotals) {
-                Long callCount = uidCallCountMap.get(uidTotal.getKey());
-                pw.println(String.format("    %7d: %8d %3.0f%%",
-                        uidTotal.getKey(), callCount, 100d * uidTotal.getValue() / totalCpuCallsTime));
+            pw.println("Sampled stats " + datasetSizeDesc
+                    + "(call_desc, cpu_time, call_count, exception_count):");
+            List<CallStat> sampledStatsList = mSampledEntries.getCallStatsList();
+            // Show all if verbose, otherwise 90th percentile
+            if (!verbose) {
+                sampledStatsList = getHighestValues(sampledStatsList,
+                        value -> value.cpuTimeMicros, 0.9);
+            }
+            for (CallStat e : sampledStatsList) {
+                sb.setLength(0);
+                sb.append("    ").append(e)
+                        .append(',').append(e.cpuTimeMicros * PERIODIC_SAMPLING_INTERVAL)
+                        .append(',').append(e.callCount)
+                        .append(',').append(e.exceptionCount);
+                pw.println(sb);
             }
+            pw.println();
+        }
+        pw.println("Per-UID Summary " + datasetSizeDesc
+                + "(cpu_time, % of total cpu_time, call_count, exception_count, package/uid):");
+        List<UidEntry> summaryEntries = verbose ? entries
+                : getHighestValues(entries, value -> value.cpuTimeMicros, 0.9);
+        for (UidEntry entry : summaryEntries) {
+            String uidStr = uidToString(entry.uid, appIdToPkgNameMap);
+            pw.println(String.format("  %10d %3.0f%% %8d %3d %s",
+                    entry.cpuTimeMicros, 100d * entry.cpuTimeMicros / totalCpuTime, entry.callCount,
+                    entry.exceptionCount, uidStr));
         }
+        pw.println();
+        pw.println(String.format("  Summary: total_cpu_time=%d, "
+                        + "calls_count=%d, avg_call_cpu_time=%.0f",
+                totalCpuTime, totalCallsCount, (double)totalCpuTime / totalCallsCount));
+    }
+
+    private static String uidToString(int uid, Map<Integer, String> pkgNameMap) {
+        int appId = UserHandle.getAppId(uid);
+        String pkgName = pkgNameMap == null ? null : pkgNameMap.get(appId);
+        String uidStr = UserHandle.formatUid(uid);
+        return pkgName == null ? uidStr : pkgName + '/' + uidStr;
+    }
+
+    protected long getThreadTimeMicro() {
+        return SystemClock.currentThreadTimeMicro();
     }
 
-    private long getThreadTimeMicro() {
-        // currentThreadTimeMicro is expensive, so we measure cpu time only if detailed tracking is
-        // enabled
-        return mDetailedTracking ? SystemClock.currentThreadTimeMicro() : 0;
+    protected int getCallingUid() {
+        return Binder.getCallingUid();
     }
 
-    private long getElapsedRealtimeNanos() {
-        return mDetailedTracking ? SystemClock.elapsedRealtimeNanos() : 0;
+    private long getElapsedRealtimeMicro() {
+        return SystemClock.elapsedRealtimeNanos() / 1000;
     }
 
     public static BinderCallsStats getInstance() {
@@ -230,18 +269,19 @@ public class BinderCallsStats {
     public void reset() {
         synchronized (mLock) {
             mUidEntries.clear();
+            mSampledEntries.mCallStats.clear();
             mStartTime = System.currentTimeMillis();
         }
     }
 
-
-    private static class CallStat {
-        String className;
-        int msg;
-        long cpuTimeMicros;
-        long latencyMicros;
-        long callCount;
-        long exceptionCount;
+    @VisibleForTesting
+    public static class CallStat {
+        public String className;
+        public int msg;
+        public long cpuTimeMicros;
+        public long latencyMicros;
+        public long callCount;
+        public long exceptionCount;
 
         CallStat() {
         }
@@ -276,17 +316,19 @@ public class BinderCallsStats {
     }
 
     public static class CallSession {
-        int mCallingUId;
-        long mCpuTimeStarted;
-        long mTimeStarted;
+        long cpuTimeStarted;
+        long timeStarted;
         boolean exceptionThrown;
-        CallStat mCallStat = new CallStat();
+        final CallStat callStat = new CallStat();
+        CallStat sampledCallStat;
     }
 
-    private static class UidEntry {
+    @VisibleForTesting
+    public static class UidEntry {
         int uid;
-        long cpuTimeMicros;
-        long callCount;
+        public long cpuTimeMicros;
+        public long callCount;
+        public int exceptionCount;
 
         UidEntry(int uid) {
             this.uid = uid;
@@ -295,6 +337,32 @@ public class BinderCallsStats {
         // Aggregate time spent per each call name: call_desc -> cpu_time_micros
         Map<CallStat, CallStat> mCallStats = new ArrayMap<>();
 
+        CallStat getOrCreate(CallStat callStat) {
+            CallStat mapCallStat = mCallStats.get(callStat);
+            // Only create CallStat if it's a new entry, otherwise update existing instance
+            if (mapCallStat == null) {
+                mapCallStat = new CallStat(callStat.className, callStat.msg);
+                mCallStats.put(mapCallStat, mapCallStat);
+            }
+            return mapCallStat;
+        }
+
+        /**
+         * Returns list of calls sorted by CPU time
+         */
+        public List<CallStat> getCallStatsList() {
+            List<CallStat> callStats = new ArrayList<>(mCallStats.keySet());
+            callStats.sort((o1, o2) -> {
+                if (o1.cpuTimeMicros < o2.cpuTimeMicros) {
+                    return 1;
+                } else if (o1.cpuTimeMicros > o2.cpuTimeMicros) {
+                    return -1;
+                }
+                return 0;
+            });
+            return callStats;
+        }
+
         @Override
         public String toString() {
             return "UidEntry{" +
@@ -320,4 +388,35 @@ public class BinderCallsStats {
         }
     }
 
+    @VisibleForTesting
+    public SparseArray<UidEntry> getUidEntries() {
+        return mUidEntries;
+    }
+
+    @VisibleForTesting
+    public UidEntry getSampledEntries() {
+        return mSampledEntries;
+    }
+
+    @VisibleForTesting
+    public static <T> List<T> getHighestValues(List<T> list, ToDoubleFunction<T> toDouble,
+            double percentile) {
+        List<T> sortedList = new ArrayList<>(list);
+        sortedList.sort(Comparator.comparingDouble(toDouble).reversed());
+        double total = 0;
+        for (T item : list) {
+            total += toDouble.applyAsDouble(item);
+        }
+        List<T> result = new ArrayList<>();
+        double runningSum = 0;
+        for (T item : sortedList) {
+            if (runningSum > percentile * total) {
+                break;
+            }
+            result.add(item);
+            runningSum += toDouble.applyAsDouble(item);
+        }
+        return result;
+    }
+
 }