Log broadcast dispatch latency during BOOT_COMPLETED
From device boot until BOOT_COMPLETED, log the dispatch latency of a
broadcast, which is the duration between it being enqueued and it being
dispatched, to get an idea of how long the queue is blocked for.
Each time a broadcast is dispatched, we check mLogLatencyMetrics, which
defaults to true when the queue is initialized, and log to statsd.
When the queue is empty, we check if BOOT_COMPLETED is done. If it is,
we stop logging by setting mLogLatencyMetrics to false, since it means
that we have finished all broadcasts that
would have been blocked by BOOT_COMPLETED.
Bug: 120794810
Test: flash, reboot, use stasd_testdrive to verify logging
Change-Id: I40c14744e5247412c0a03032fd5621706758a324
diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto
index 79ef2ca..73ebdc3 100644
--- a/cmds/statsd/src/atoms.proto
+++ b/cmds/statsd/src/atoms.proto
@@ -202,6 +202,7 @@
NfcHceTransactionOccurred nfc_hce_transaction_occurred = 139;
SeStateChanged se_state_changed = 140;
SeOmapiReported se_omapi_reported = 141;
+ BroadcastDispatchLatencyReported broadcast_dispatch_latency_reported = 142;
}
// Pulled events will start at field 10000.
@@ -4452,3 +4453,13 @@
optional string packageName = 3;
}
+
+/**
+ * Logs the dispatch latencey of a broadcast during processing of BOOT_COMPLETED.
+ * The dispatch latencey is the dispatchClockTime - enqueueClockTime.
+ * Logged from:
+ * frameworks/base/services/core/java/com/android/server/am/BroadcastQueue.java
+ */
+message BroadcastDispatchLatencyReported {
+ optional int64 dispatch_latency_millis = 1;
+}
diff --git a/services/core/java/com/android/server/am/BroadcastQueue.java b/services/core/java/com/android/server/am/BroadcastQueue.java
index 65aacdc..353749f 100644
--- a/services/core/java/com/android/server/am/BroadcastQueue.java
+++ b/services/core/java/com/android/server/am/BroadcastQueue.java
@@ -45,6 +45,7 @@
import android.os.UserHandle;
import android.util.EventLog;
import android.util.Slog;
+import android.util.StatsLog;
import android.util.TimeUtils;
import android.util.proto.ProtoOutputStream;
@@ -157,6 +158,9 @@
static final int BROADCAST_INTENT_MSG = ActivityManagerService.FIRST_BROADCAST_QUEUE_MSG;
static final int BROADCAST_TIMEOUT_MSG = ActivityManagerService.FIRST_BROADCAST_QUEUE_MSG + 1;
+ // log latency metrics for ordered broadcasts during BOOT_COMPLETED processing
+ boolean mLogLatencyMetrics = true;
+
final BroadcastHandler mHandler;
private final class BroadcastHandler extends Handler {
@@ -941,6 +945,12 @@
// adjustments.
mService.updateOomAdjLocked();
}
+
+ // when we have no more ordered broadcast on this queue, stop logging
+ if (mService.mUserController.mBootCompleted && mLogLatencyMetrics) {
+ mLogLatencyMetrics = false;
+ }
+
return;
}
r = mOrderedBroadcasts.get(0);
@@ -1036,6 +1046,13 @@
if (recIdx == 0) {
r.dispatchTime = r.receiverTime;
r.dispatchClockTime = System.currentTimeMillis();
+
+ if (mLogLatencyMetrics) {
+ StatsLog.write(
+ StatsLog.BROADCAST_DISPATCH_LATENCY_REPORTED,
+ r.dispatchClockTime - r.enqueueClockTime);
+ }
+
if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER,
createBroadcastTraceTitle(r, BroadcastRecord.DELIVERY_PENDING),
diff --git a/services/core/java/com/android/server/am/UserController.java b/services/core/java/com/android/server/am/UserController.java
index bcce052..c981e68 100644
--- a/services/core/java/com/android/server/am/UserController.java
+++ b/services/core/java/com/android/server/am/UserController.java
@@ -240,6 +240,8 @@
private final LockPatternUtils mLockPatternUtils;
+ volatile boolean mBootCompleted;
+
UserController(ActivityManagerService service) {
this(new Injector(service));
}
@@ -567,6 +569,7 @@
Bundle extras, boolean ordered, boolean sticky, int sendingUser)
throws RemoteException {
Slog.i(UserController.TAG, "Finished processing BOOT_COMPLETED for u" + userId);
+ mBootCompleted = true;
}
}, 0, null, null,
new String[]{android.Manifest.permission.RECEIVE_BOOT_COMPLETED},