Loading core/java/com/android/internal/os/BinderCallsStats.java +204 −105 Original line number Diff line number Diff line Loading @@ -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; Loading @@ -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. Loading @@ -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; Loading @@ -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() { } Loading @@ -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; Loading @@ -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) { int uidEntriesSize = mUidEntries.size(); 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); totalCpuTime += e.cpuTimeMicros; totalCallsCount += e.callCount; } } 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; }); entries.sort(Comparator.<UidEntry>comparingDouble(value -> value.cpuTimeMicros).reversed()); String datasetSizeDesc = verbose ? "" : "(top 90% by cpu time) "; 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) { if (mDetailedTracking) { 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) Loading @@ -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)); } else { 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(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("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 long getThreadTimeMicro() { // currentThreadTimeMicro is expensive, so we measure cpu time only if detailed tracking is // enabled return mDetailedTracking ? SystemClock.currentThreadTimeMicro() : 0; 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; } private long getElapsedRealtimeNanos() { return mDetailedTracking ? SystemClock.elapsedRealtimeNanos() : 0; protected long getThreadTimeMicro() { return SystemClock.currentThreadTimeMicro(); } protected int getCallingUid() { return Binder.getCallingUid(); } private long getElapsedRealtimeMicro() { return SystemClock.elapsedRealtimeNanos() / 1000; } public static BinderCallsStats getInstance() { Loading @@ -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() { } Loading Loading @@ -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; Loading @@ -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{" + Loading @@ -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; } } core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java 0 → 100644 +167 −0 Original line number Diff line number Diff line /* * Copyright (C) 2018 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License */ package com.android.internal.os; import android.os.Binder; import android.platform.test.annotations.Presubmit; import android.support.test.filters.SmallTest; import android.support.test.runner.AndroidJUnit4; import android.util.SparseArray; import org.junit.Assert; import org.junit.Test; import org.junit.runner.RunWith; import java.util.Arrays; import java.util.List; import static org.junit.Assert.assertEquals; @SmallTest @RunWith(AndroidJUnit4.class) @Presubmit public class BinderCallsStatsTest { public static final int TEST_UID = 1; @Test public void testDetailedOff() { TestBinderCallsStats bcs = new TestBinderCallsStats(false); Binder binder = new Binder(); BinderCallsStats.CallSession callSession = bcs.callStarted(binder, 1); bcs.time += 10; bcs.callEnded(callSession); SparseArray<BinderCallsStats.UidEntry> uidEntries = bcs.getUidEntries(); assertEquals(1, uidEntries.size()); BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID); Assert.assertNotNull(uidEntry); assertEquals(1, uidEntry.callCount); assertEquals(10, uidEntry.cpuTimeMicros); assertEquals("Detailed tracking off - no entries should be returned", 0, uidEntry.getCallStatsList().size()); BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries(); List<BinderCallsStats.CallStat> sampledCallStatsList = sampledEntries.getCallStatsList(); assertEquals(1, sampledCallStatsList.size()); assertEquals(1, sampledCallStatsList.get(0).callCount); assertEquals(10, sampledCallStatsList.get(0).cpuTimeMicros); assertEquals(binder.getClass().getName(), sampledCallStatsList.get(0).className); assertEquals(1, sampledCallStatsList.get(0).msg); callSession = bcs.callStarted(binder, 1); bcs.time += 20; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(2, uidEntry.callCount); // When sampling is enabled, cpu time is only measured for the first transaction in the // sampling interval, for others an average duration of previous transactions is used as // approximation assertEquals(20, uidEntry.cpuTimeMicros); sampledCallStatsList = sampledEntries.getCallStatsList(); assertEquals(1, sampledCallStatsList.size()); callSession = bcs.callStarted(binder, 2); bcs.time += 50; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(3, uidEntry.callCount); // This is the first transaction of a new type, so the real CPU time will be measured assertEquals(70, uidEntry.cpuTimeMicros); sampledCallStatsList = sampledEntries.getCallStatsList(); assertEquals(2, sampledCallStatsList.size()); } @Test public void testDetailedOn() { TestBinderCallsStats bcs = new TestBinderCallsStats(true); Binder binder = new Binder(); BinderCallsStats.CallSession callSession = bcs.callStarted(binder, 1); bcs.time += 10; bcs.callEnded(callSession); SparseArray<BinderCallsStats.UidEntry> uidEntries = bcs.getUidEntries(); assertEquals(1, uidEntries.size()); BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID); Assert.assertNotNull(uidEntry); assertEquals(1, uidEntry.callCount); assertEquals(10, uidEntry.cpuTimeMicros); assertEquals(1, uidEntry.getCallStatsList().size()); BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries(); assertEquals("Sampling is not used when detailed tracking on", 0, bcs.getSampledEntries().getCallStatsList().size()); List<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList(); assertEquals(1, callStatsList.get(0).callCount); assertEquals(10, callStatsList.get(0).cpuTimeMicros); assertEquals(binder.getClass().getName(), callStatsList.get(0).className); assertEquals(1, callStatsList.get(0).msg); callSession = bcs.callStarted(binder, 1); bcs.time += 20; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(2, uidEntry.callCount); assertEquals(30, uidEntry.cpuTimeMicros); callStatsList = uidEntry.getCallStatsList(); assertEquals(1, callStatsList.size()); callSession = bcs.callStarted(binder, 2); bcs.time += 50; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(3, uidEntry.callCount); // This is the first transaction of a new type, so the real CPU time will be measured assertEquals(80, uidEntry.cpuTimeMicros); callStatsList = uidEntry.getCallStatsList(); assertEquals(2, callStatsList.size()); } @Test public void testGetHighestValues() { List<Integer> list = Arrays.asList(1, 2, 3, 4); List<Integer> highestValues = BinderCallsStats .getHighestValues(list, value -> value, 0.8); assertEquals(Arrays.asList(4, 3, 2), highestValues); } static class TestBinderCallsStats extends BinderCallsStats { int callingUid = TEST_UID; long time = 1234; TestBinderCallsStats(boolean detailedTracking) { super(detailedTracking); } @Override protected long getThreadTimeMicro() { return time; } @Override protected int getCallingUid() { return callingUid; } } } services/core/java/com/android/server/BinderCallsStatsService.java +28 −3 Original line number Diff line number Diff line Loading @@ -16,15 +16,23 @@ package com.android.server; import android.app.AppGlobals; import android.content.pm.PackageInfo; import android.content.pm.PackageManager; import android.os.Binder; import android.os.RemoteException; import android.os.ServiceManager; import android.os.SystemProperties; import android.os.UserHandle; import android.util.Slog; import com.android.internal.os.BinderCallsStats; import java.io.FileDescriptor; import java.io.PrintWriter; import java.util.HashMap; import java.util.List; import java.util.Map; public class BinderCallsStatsService extends Binder { Loading Loading @@ -54,11 +62,11 @@ public class BinderCallsStatsService extends Binder { @Override protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) { boolean verbose = false; if (args != null) { for (final String arg : args) { if ("-a".equals(arg)) { // We currently dump all information by default continue; verbose = true; } else if ("--reset".equals(arg)) { reset(); pw.println("binder_calls_stats reset."); Loading @@ -84,6 +92,23 @@ public class BinderCallsStatsService extends Binder { } } } BinderCallsStats.getInstance().dump(pw); BinderCallsStats.getInstance().dump(pw, getAppIdToPackagesMap(), verbose); } private Map<Integer, String> getAppIdToPackagesMap() { List<PackageInfo> packages; try { packages = AppGlobals.getPackageManager() .getInstalledPackages(PackageManager.MATCH_UNINSTALLED_PACKAGES, UserHandle.USER_SYSTEM).getList(); } catch (RemoteException e) { throw e.rethrowFromSystemServer(); } Map<Integer,String> map = new HashMap<>(); for (PackageInfo pkg : packages) { map.put(pkg.applicationInfo.uid, pkg.packageName); } return map; } } Loading
core/java/com/android/internal/os/BinderCallsStats.java +204 −105 Original line number Diff line number Diff line Loading @@ -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; Loading @@ -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. Loading @@ -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; Loading @@ -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() { } Loading @@ -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; Loading @@ -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) { int uidEntriesSize = mUidEntries.size(); 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); totalCpuTime += e.cpuTimeMicros; totalCallsCount += e.callCount; } } 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; }); entries.sort(Comparator.<UidEntry>comparingDouble(value -> value.cpuTimeMicros).reversed()); String datasetSizeDesc = verbose ? "" : "(top 90% by cpu time) "; 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) { if (mDetailedTracking) { 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) Loading @@ -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)); } else { 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(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("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 long getThreadTimeMicro() { // currentThreadTimeMicro is expensive, so we measure cpu time only if detailed tracking is // enabled return mDetailedTracking ? SystemClock.currentThreadTimeMicro() : 0; 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; } private long getElapsedRealtimeNanos() { return mDetailedTracking ? SystemClock.elapsedRealtimeNanos() : 0; protected long getThreadTimeMicro() { return SystemClock.currentThreadTimeMicro(); } protected int getCallingUid() { return Binder.getCallingUid(); } private long getElapsedRealtimeMicro() { return SystemClock.elapsedRealtimeNanos() / 1000; } public static BinderCallsStats getInstance() { Loading @@ -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() { } Loading Loading @@ -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; Loading @@ -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{" + Loading @@ -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; } }
core/tests/coretests/src/com/android/internal/os/BinderCallsStatsTest.java 0 → 100644 +167 −0 Original line number Diff line number Diff line /* * Copyright (C) 2018 The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License */ package com.android.internal.os; import android.os.Binder; import android.platform.test.annotations.Presubmit; import android.support.test.filters.SmallTest; import android.support.test.runner.AndroidJUnit4; import android.util.SparseArray; import org.junit.Assert; import org.junit.Test; import org.junit.runner.RunWith; import java.util.Arrays; import java.util.List; import static org.junit.Assert.assertEquals; @SmallTest @RunWith(AndroidJUnit4.class) @Presubmit public class BinderCallsStatsTest { public static final int TEST_UID = 1; @Test public void testDetailedOff() { TestBinderCallsStats bcs = new TestBinderCallsStats(false); Binder binder = new Binder(); BinderCallsStats.CallSession callSession = bcs.callStarted(binder, 1); bcs.time += 10; bcs.callEnded(callSession); SparseArray<BinderCallsStats.UidEntry> uidEntries = bcs.getUidEntries(); assertEquals(1, uidEntries.size()); BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID); Assert.assertNotNull(uidEntry); assertEquals(1, uidEntry.callCount); assertEquals(10, uidEntry.cpuTimeMicros); assertEquals("Detailed tracking off - no entries should be returned", 0, uidEntry.getCallStatsList().size()); BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries(); List<BinderCallsStats.CallStat> sampledCallStatsList = sampledEntries.getCallStatsList(); assertEquals(1, sampledCallStatsList.size()); assertEquals(1, sampledCallStatsList.get(0).callCount); assertEquals(10, sampledCallStatsList.get(0).cpuTimeMicros); assertEquals(binder.getClass().getName(), sampledCallStatsList.get(0).className); assertEquals(1, sampledCallStatsList.get(0).msg); callSession = bcs.callStarted(binder, 1); bcs.time += 20; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(2, uidEntry.callCount); // When sampling is enabled, cpu time is only measured for the first transaction in the // sampling interval, for others an average duration of previous transactions is used as // approximation assertEquals(20, uidEntry.cpuTimeMicros); sampledCallStatsList = sampledEntries.getCallStatsList(); assertEquals(1, sampledCallStatsList.size()); callSession = bcs.callStarted(binder, 2); bcs.time += 50; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(3, uidEntry.callCount); // This is the first transaction of a new type, so the real CPU time will be measured assertEquals(70, uidEntry.cpuTimeMicros); sampledCallStatsList = sampledEntries.getCallStatsList(); assertEquals(2, sampledCallStatsList.size()); } @Test public void testDetailedOn() { TestBinderCallsStats bcs = new TestBinderCallsStats(true); Binder binder = new Binder(); BinderCallsStats.CallSession callSession = bcs.callStarted(binder, 1); bcs.time += 10; bcs.callEnded(callSession); SparseArray<BinderCallsStats.UidEntry> uidEntries = bcs.getUidEntries(); assertEquals(1, uidEntries.size()); BinderCallsStats.UidEntry uidEntry = uidEntries.get(TEST_UID); Assert.assertNotNull(uidEntry); assertEquals(1, uidEntry.callCount); assertEquals(10, uidEntry.cpuTimeMicros); assertEquals(1, uidEntry.getCallStatsList().size()); BinderCallsStats.UidEntry sampledEntries = bcs.getSampledEntries(); assertEquals("Sampling is not used when detailed tracking on", 0, bcs.getSampledEntries().getCallStatsList().size()); List<BinderCallsStats.CallStat> callStatsList = uidEntry.getCallStatsList(); assertEquals(1, callStatsList.get(0).callCount); assertEquals(10, callStatsList.get(0).cpuTimeMicros); assertEquals(binder.getClass().getName(), callStatsList.get(0).className); assertEquals(1, callStatsList.get(0).msg); callSession = bcs.callStarted(binder, 1); bcs.time += 20; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(2, uidEntry.callCount); assertEquals(30, uidEntry.cpuTimeMicros); callStatsList = uidEntry.getCallStatsList(); assertEquals(1, callStatsList.size()); callSession = bcs.callStarted(binder, 2); bcs.time += 50; bcs.callEnded(callSession); uidEntry = bcs.getUidEntries().get(TEST_UID); assertEquals(3, uidEntry.callCount); // This is the first transaction of a new type, so the real CPU time will be measured assertEquals(80, uidEntry.cpuTimeMicros); callStatsList = uidEntry.getCallStatsList(); assertEquals(2, callStatsList.size()); } @Test public void testGetHighestValues() { List<Integer> list = Arrays.asList(1, 2, 3, 4); List<Integer> highestValues = BinderCallsStats .getHighestValues(list, value -> value, 0.8); assertEquals(Arrays.asList(4, 3, 2), highestValues); } static class TestBinderCallsStats extends BinderCallsStats { int callingUid = TEST_UID; long time = 1234; TestBinderCallsStats(boolean detailedTracking) { super(detailedTracking); } @Override protected long getThreadTimeMicro() { return time; } @Override protected int getCallingUid() { return callingUid; } } }
services/core/java/com/android/server/BinderCallsStatsService.java +28 −3 Original line number Diff line number Diff line Loading @@ -16,15 +16,23 @@ package com.android.server; import android.app.AppGlobals; import android.content.pm.PackageInfo; import android.content.pm.PackageManager; import android.os.Binder; import android.os.RemoteException; import android.os.ServiceManager; import android.os.SystemProperties; import android.os.UserHandle; import android.util.Slog; import com.android.internal.os.BinderCallsStats; import java.io.FileDescriptor; import java.io.PrintWriter; import java.util.HashMap; import java.util.List; import java.util.Map; public class BinderCallsStatsService extends Binder { Loading Loading @@ -54,11 +62,11 @@ public class BinderCallsStatsService extends Binder { @Override protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) { boolean verbose = false; if (args != null) { for (final String arg : args) { if ("-a".equals(arg)) { // We currently dump all information by default continue; verbose = true; } else if ("--reset".equals(arg)) { reset(); pw.println("binder_calls_stats reset."); Loading @@ -84,6 +92,23 @@ public class BinderCallsStatsService extends Binder { } } } BinderCallsStats.getInstance().dump(pw); BinderCallsStats.getInstance().dump(pw, getAppIdToPackagesMap(), verbose); } private Map<Integer, String> getAppIdToPackagesMap() { List<PackageInfo> packages; try { packages = AppGlobals.getPackageManager() .getInstalledPackages(PackageManager.MATCH_UNINSTALLED_PACKAGES, UserHandle.USER_SYSTEM).getList(); } catch (RemoteException e) { throw e.rethrowFromSystemServer(); } Map<Integer,String> map = new HashMap<>(); for (PackageInfo pkg : packages) { map.put(pkg.applicationInfo.uid, pkg.packageName); } return map; } }