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

Add tracing for broadcast sending and processing.

Browse Source 
This change instruments BroadcastQueue using asyncTrace to give us
visibility into broadcasts from a trace. There's one traced section for
the time the broadcasts spend in the queue, and another one for the time
it takes to dispatch the broadcast.

My previous solution for this bug was incomplete, so this change also
cleans up that solution (which instrumented a callsite). Last, there's a
couple minor changes to logs (fixing a typo and making a log clearer).

Bug: 33645477
Test: https://screenshot.googleplex.com/2F6SWiCtEUD

Change-Id: I27e38cd70fee144986405bae302eb04045dff06d
This commit is contained in:
Carmen Jackson
2017-01-17 14:01:33 -08:00
parent 274907e729
commit a68e3450ff
2 changed files with 50 additions and 10 deletions
Download Patch File Download Diff File Expand all files Collapse all files

9
services/core/java/com/android/server/am/ActivityManagerService.java
View File

@@ -18652,7 +18652,7 @@ public class ActivityManagerService extends IActivityManager.Stub
final boolean replacePending =
(intent.getFlags()&Intent.FLAG_RECEIVER_REPLACE_PENDING) != 0;
if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST, "Enqueing broadcast: " + intent.getAction()
if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST, "Enqueueing broadcast: " + intent.getAction()
+ " replacePending=" + replacePending);
int NR = registeredReceivers != null ? registeredReceivers.size() : 0;
@@ -18960,14 +18960,7 @@ public class ActivityManagerService extends IActivityManager.Stub
}
if (doNext) {
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
String.format("ProcessBroadcast from %s (%s) %s", r.callerPackage,
r.callerApp == null ? "caller unknown" : r.callerApp.toShortString(),
r.intent == null ? "" : r.intent.toString()));
}
r.queue.processNextBroadcast(false);
Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
}
trimApplications();
} finally {

51
services/core/java/com/android/server/am/BroadcastQueue.java
View File

@@ -16,6 +16,7 @@
package com.android.server.am;
import android.os.Trace;
import java.io.FileDescriptor;
import java.io.PrintWriter;
import java.text.SimpleDateFormat;
@@ -216,12 +217,26 @@ public final class BroadcastQueue {
public void enqueueParallelBroadcastLocked(BroadcastRecord r) {
mParallelBroadcasts.add(r);
r.enqueueClockTime = System.currentTimeMillis();
enqueueBroadcastHelper(r);
}
public void enqueueOrderedBroadcastLocked(BroadcastRecord r) {
mOrderedBroadcasts.add(r);
enqueueBroadcastHelper(r);
}
/**
* Don't call this method directly; call enqueueParallelBroadcastLocked or
* enqueueOrderedBroadcastLocked.
*/
private void enqueueBroadcastHelper(BroadcastRecord r) {
r.enqueueClockTime = System.currentTimeMillis();
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_PENDING),
System.identityHashCode(r));
}
}
public final boolean replaceParallelBroadcastLocked(BroadcastRecord r) {
@@ -751,7 +766,7 @@ public final class BroadcastQueue {
if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST, "processNextBroadcast ["
+ mQueueName + "]: "
+ mParallelBroadcasts.size() + " broadcasts, "
+ mParallelBroadcasts.size() + " parallel broadcasts, "
+ mOrderedBroadcasts.size() + " ordered broadcasts");
mService.updateCpuStats();
@@ -765,6 +780,16 @@ public final class BroadcastQueue {
r = mParallelBroadcasts.remove(0);
r.dispatchTime = SystemClock.uptimeMillis();
r.dispatchClockTime = System.currentTimeMillis();
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_PENDING),
System.identityHashCode(r));
Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_DELIVERED),
System.identityHashCode(r));
}
final int N = r.receivers.size();
if (DEBUG_BROADCAST_LIGHT) Slog.v(TAG_BROADCAST, "Processing parallel broadcast ["
+ mQueueName + "] " + r);
@@ -915,6 +940,14 @@ public final class BroadcastQueue {
if (recIdx == 0) {
r.dispatchTime = r.receiverTime;
r.dispatchClockTime = System.currentTimeMillis();
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_PENDING),
System.identityHashCode(r));
Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_DELIVERED),
System.identityHashCode(r));
}
if (DEBUG_BROADCAST_LIGHT) Slog.v(TAG_BROADCAST, "Processing ordered broadcast ["
+ mQueueName + "] " + r);
}
@@ -1398,6 +1431,12 @@ public final class BroadcastQueue {
}
r.finishTime = SystemClock.uptimeMillis();
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_DELIVERED),
System.identityHashCode(r));
}
mBroadcastHistory[mHistoryNext] = r;
mHistoryNext = ringAdvance(mHistoryNext, 1, MAX_BROADCAST_HISTORY);
@@ -1456,6 +1495,14 @@ public final class BroadcastQueue {
}
}
private String createBroadcastTraceTitle(BroadcastRecord record, int state) {
return String.format("Broadcast %s from %s (%s) %s",
state == BroadcastRecord.DELIVERY_PENDING ? "in queue" : "dispatched",
record.callerPackage == null ? "" : record.callerPackage,
record.callerApp == null ? "process unknown" : record.callerApp.toShortString(),
record.intent == null ? "" : record.intent.getAction());
}
final boolean dumpLocked(FileDescriptor fd, PrintWriter pw, String[] args,
int opti, boolean dumpAll, String dumpPackage, boolean needSep) {
SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");