Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Enabled aggregated per-uid stats collection by default

Browse Source 
Enabled collection of number of calls per-uid. It has relatively small
overhead. Memory impact is minimal and cpu overhead is also small -
250 ns vs 1500 ns with detailed tracking

Detailed tracking is disabled by default. Controlled by
persist.sys.binder_calls_detailed_tracking

Added commands to reset and enable/disable detailed stats:
dumpsys binder_calls_stats --reset
dumpsys binder_calls_stats --enable-detailed-tracking
dumpsys binder_calls_stats --disable-detailed-tracking

Test: manual
Bug: 75318418
Change-Id: I7c1280c025001b6d2b46e4a37bad841712b6da2f
This commit is contained in:
Fyodor Kupolov
2018-04-18 17:26:43 -07:00
parent 5e12ebfffd
commit 3f3af617ae
3 changed files with 120 additions and 73 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
apct-tests/perftests/core/src/android/os/BinderCallsStatsPerfTest.java
View File

@@ -69,7 +69,6 @@ public class BinderCallsStatsPerfTest {
final BenchmarkState state = mPerfStatusReporter.getBenchmarkState();
Binder b = new Binder();
mBinderCallsStats = new BinderCallsStats(false);
assertNull(mBinderCallsStats.callStarted(b, 0));
while (state.keepRunning()) {
BinderCallsStats.CallSession s = mBinderCallsStats.callStarted(b, 0);
mBinderCallsStats.callEnded(s);

142
core/java/com/android/internal/os/BinderCallsStats.java
View File

@@ -21,6 +21,7 @@ import android.os.SystemClock;
import android.util.ArrayMap;
import android.util.SparseArray;
import com.android.internal.annotations.GuardedBy;
import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.util.Preconditions;
@@ -40,23 +41,21 @@ public class BinderCallsStats {
private static final int CALL_SESSIONS_POOL_SIZE = 100;
private static final BinderCallsStats sInstance = new BinderCallsStats();
private volatile boolean mTrackingEnabled = false;
private volatile boolean mDetailedTracking = false;
@GuardedBy("mLock")
private final SparseArray<UidEntry> mUidEntries = new SparseArray<>();
private final Queue<CallSession> mCallSessionsPool = new ConcurrentLinkedQueue<>();
private final Object mLock = new Object();
private BinderCallsStats() {
}
@VisibleForTesting
public BinderCallsStats(boolean trackingEnabled) {
mTrackingEnabled = trackingEnabled;
public BinderCallsStats(boolean detailedTracking) {
mDetailedTracking = detailedTracking;
}
public CallSession callStarted(Binder binder, int code) {
if (!mTrackingEnabled) {
return null;
}
return callStarted(binder.getClass().getName(), code);
}
@@ -73,32 +72,31 @@ public class BinderCallsStats {
}
public void callEnded(CallSession s) {
if (!mTrackingEnabled) {
return;
}
Preconditions.checkNotNull(s);
final long cpuTimeNow = getThreadTimeMicro();
final long duration = cpuTimeNow - s.mStarted;
long duration = mDetailedTracking ? getThreadTimeMicro() - s.mStarted : 1;
s.mCallingUId = Binder.getCallingUid();
synchronized (mUidEntries) {
synchronized (mLock) {
UidEntry uidEntry = mUidEntries.get(s.mCallingUId);
if (uidEntry == null) {
uidEntry = new UidEntry(s.mCallingUId);
mUidEntries.put(s.mCallingUId, uidEntry);
}
// 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);
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);
}
callStat.callCount++;
callStat.time += duration;
}
uidEntry.time += duration;
uidEntry.callCount++;
callStat.callCount++;
callStat.time += duration;
}
if (mCallSessionsPool.size() < CALL_SESSIONS_POOL_SIZE) {
mCallSessionsPool.add(s);
@@ -112,7 +110,7 @@ public class BinderCallsStats {
long totalCallsTime = 0;
int uidEntriesSize = mUidEntries.size();
List<UidEntry> entries = new ArrayList<>();
synchronized (mUidEntries) {
synchronized (mLock) {
for (int i = 0; i < uidEntriesSize; i++) {
UidEntry e = mUidEntries.valueAt(i);
entries.add(e);
@@ -127,20 +125,10 @@ public class BinderCallsStats {
totalCallsCount += e.callCount;
}
}
pw.println("Binder call stats:");
pw.println(" Raw data (uid,call_desc,time):");
entries.sort((o1, o2) -> {
if (o1.time < o2.time) {
return 1;
} else if (o1.time > o2.time) {
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 (mDetailedTracking) {
pw.println("Binder call stats:");
pw.println(" Raw data (uid,call_desc,time):");
entries.sort((o1, o2) -> {
if (o1.time < o2.time) {
return 1;
} else if (o1.time > o2.time) {
@@ -148,44 +136,72 @@ public class BinderCallsStats {
}
return 0;
});
for (CallStat e : callStats) {
sb.setLength(0);
sb.append(" ")
.append(uidEntry.uid).append(",").append(e).append(',').append(e.time);
pw.println(sb);
StringBuilder sb = new StringBuilder();
for (UidEntry uidEntry : entries) {
List<CallStat> callStats = new ArrayList<>(uidEntry.mCallStats.keySet());
callStats.sort((o1, o2) -> {
if (o1.time < o2.time) {
return 1;
} else if (o1.time > o2.time) {
return -1;
}
return 0;
});
for (CallStat e : callStats) {
sb.setLength(0);
sb.append(" ")
.append(uidEntry.uid).append(",").append(e).append(',').append(e.time);
pw.println(sb);
}
}
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() / totalCallsTime, callCount));
}
pw.println();
pw.println(String.format(" Summary: total_time=%d, "
+ "calls_count=%d, avg_call_time=%.0f",
totalCallsTime, totalCallsCount,
(double)totalCallsTime / 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() / totalCallsTime));
}
}
pw.println();
pw.println(" Per UID Summary(UID: time, total_time_percentage, 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(" %5d: %11d %3.0f%% %8d",
uidTotal.getKey(), uidTotal.getValue(),
100d * uidTotal.getValue() / totalCallsTime, callCount));
}
pw.println();
pw.println(String.format(" Summary: total_time=%d, "
+ "calls_count=%d, avg_call_time=%.0f",
totalCallsTime, totalCallsCount,
(double)totalCallsTime / totalCallsCount));
}
private static 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;
}
public static BinderCallsStats getInstance() {
return sInstance;
}
public void setTrackingEnabled(boolean enabled) {
mTrackingEnabled = enabled;
public void setDetailedTracking(boolean enabled) {
if (enabled != mDetailedTracking) {
reset();
mDetailedTracking = enabled;
}
}
public boolean isTrackingEnabled() {
return mTrackingEnabled;
public void reset() {
synchronized (mLock) {
mUidEntries.clear();
}
}
private static class CallStat {
@@ -210,7 +226,7 @@ public class BinderCallsStats {
CallStat callStat = (CallStat) o;
return msg == callStat.msg && (className == callStat.className);
return msg == callStat.msg && (className.equals(callStat.className));
}
@Override

50
services/core/java/com/android/server/BinderCallsStatsService.java
View File

@@ -30,26 +30,58 @@ public class BinderCallsStatsService extends Binder {
private static final String TAG = "BinderCallsStatsService";
private static final String PERSIST_SYS_BINDER_CPU_STATS_TRACKING
= "persist.sys.binder_cpu_stats_tracking";
private static final String PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING
= "persist.sys.binder_calls_detailed_tracking";
public static void start() {
BinderCallsStatsService service = new BinderCallsStatsService();
ServiceManager.addService("binder_calls_stats", service);
// TODO Enable by default on eng/userdebug builds
boolean trackingEnabledDefault = false;
boolean trackingEnabled = SystemProperties.getBoolean(PERSIST_SYS_BINDER_CPU_STATS_TRACKING,
trackingEnabledDefault);
boolean detailedTrackingEnabled = SystemProperties.getBoolean(
PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, false);
if (trackingEnabled) {
if (detailedTrackingEnabled) {
Slog.i(TAG, "Enabled CPU usage tracking for binder calls. Controlled by "
+ PERSIST_SYS_BINDER_CPU_STATS_TRACKING);
BinderCallsStats.getInstance().setTrackingEnabled(true);
+ PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING
+ " or via dumpsys binder_calls_stats --enable-detailed-tracking");
BinderCallsStats.getInstance().setDetailedTracking(true);
}
}
public static void reset() {
Slog.i(TAG, "Resetting stats");
BinderCallsStats.getInstance().reset();
}
@Override
protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
if (args != null) {
for (final String arg : args) {
if ("--reset".equals(arg)) {
reset();
pw.println("binder_calls_stats reset.");
return;
} else if ("--enable-detailed-tracking".equals(arg)) {
SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, "1");
BinderCallsStats.getInstance().setDetailedTracking(true);
pw.println("Detailed tracking enabled");
return;
} else if ("--disable-detailed-tracking".equals(arg)) {
SystemProperties.set(PERSIST_SYS_BINDER_CALLS_DETAILED_TRACKING, "");
BinderCallsStats.getInstance().setDetailedTracking(false);
pw.println("Detailed tracking disabled");
return;
} else if ("-h".equals(arg)) {
pw.println("binder_calls_stats commands:");
pw.println(" --reset: Reset stats");
pw.println(" --enable-detailed-tracking: Enables detailed tracking");
pw.println(" --disable-detailed-tracking: Disables detailed tracking");
return;
} else {
pw.println("Unknown option: " + arg);
return;
}
}
}
BinderCallsStats.getInstance().dump(pw);
}
}