From a68e3450ffa7a0905a30d9cab4ec869e4006257f Mon Sep 17 00:00:00 2001 From: Carmen Jackson Date: Tue, 17 Jan 2017 14:01:33 -0800 Subject: [PATCH] Add tracing for broadcast sending and processing. 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 --- .../server/am/ActivityManagerService.java | 9 +--- .../com/android/server/am/BroadcastQueue.java | 51 ++++++++++++++++++- 2 files changed, 50 insertions(+), 10 deletions(-) diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index e7e07fe8594b8..d30438a2f267c 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -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 { diff --git a/services/core/java/com/android/server/am/BroadcastQueue.java b/services/core/java/com/android/server/am/BroadcastQueue.java index ee2467a925c17..68253c78c78cb 100644 --- a/services/core/java/com/android/server/am/BroadcastQueue.java +++ b/services/core/java/com/android/server/am/BroadcastQueue.java @@ -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");