Log slow message delivery on Looper
Sample log:
04-27 15:30:17.306 1000 942 942 W Looper : Dispatch took 222ms on main, h=Handler (com.android.server.job.JobSchedulerService$JobHandler) {42042fc} cb=null msg=7 start=48162 end=48384
04-27 15:30:17.306 1000 942 942 W Looper : Delivery took 235ms on main, h=Handler (com.android.server.job.JobSchedulerService$JobHandler) {42042fc} cb=null msg=4 start=48149 end=48384
04-27 15:30:17.773 1000 942 942 W Looper : Dispatch took 445ms on main, h=Handler (android.app.ActivityThread$H) {5df4c77} cb=android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA@badd538 msg=0 start=48406 end=48851
04-27 15:30:17.828 1000 942 942 W Looper : Drained
04-27 15:30:24.389 1000 942 942 W Looper : Dispatch took 718ms on main, h=Handler (android.hardware.soundtrigger.SoundTriggerModule$NativeEventHandlerDelegate$1) {d7e9947} cb=null msg=4 start=54749 end=55467
04-27 15:30:24.389 1000 942 942 W Looper : Delivery took 621ms on main, h=Handler (com.android.server.media.MediaSessionRecord$MessageHandler) {5851574} cb=null msg=7 start=54846 end=55467
04-27 15:30:24.499 1000 942 942 W Looper : Drained
Bug: 78590632
Test: Boot and check log
Test: setprop log.looper.1000.android.bg 1 and runtime-restart and check log
Change-Id: Ief1fc65b40b8a3d583879f55a76288e3dba6be7d
diff --git a/core/java/android/os/Looper.java b/core/java/android/os/Looper.java
index 848c596..f17e0f0 100644
--- a/core/java/android/os/Looper.java
+++ b/core/java/android/os/Looper.java
@@ -77,10 +77,18 @@
private Printer mLogging;
private long mTraceTag;
- /* If set, the looper will show a warning log if a message dispatch takes longer than time. */
+ /**
+ * If set, the looper will show a warning log if a message dispatch takes longer than this.
+ */
private long mSlowDispatchThresholdMs;
- /** Initialize the current thread as a looper.
+ /**
+ * If set, the looper will show a warning log if a message delivery (actual delivery time -
+ * post time) takes longer than this.
+ */
+ private long mSlowDeliveryThresholdMs;
+
+ /** Initialize the current thread as a looper.
* This gives you a chance to create handlers that then reference
* this looper, before actually starting the loop. Be sure to call
* {@link #loop()} after calling this method, and end it by calling
@@ -138,6 +146,16 @@
Binder.clearCallingIdentity();
final long ident = Binder.clearCallingIdentity();
+ // Allow overriding a threshold with a system prop. e.g.
+ // adb shell 'setprop log.looper.1000.main.slow 1 && stop && start'
+ final int thresholdOverride =
+ SystemProperties.getInt("log.looper."
+ + Process.myUid() + "."
+ + Thread.currentThread().getName()
+ + ".slow", 0);
+
+ boolean slowDeliveryDetected = false;
+
for (;;) {
Message msg = queue.next(); // might block
if (msg == null) {
@@ -152,30 +170,50 @@
msg.callback + ": " + msg.what);
}
- final long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
-
final long traceTag = me.mTraceTag;
+ long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
+ long slowDeliveryThresholdMs = me.mSlowDeliveryThresholdMs;
+ if (thresholdOverride > 0) {
+ slowDispatchThresholdMs = thresholdOverride;
+ slowDeliveryThresholdMs = thresholdOverride;
+ }
+ final boolean logSlowDelivery = (slowDeliveryThresholdMs > 0) && (msg.when > 0);
+ final boolean logSlowDispatch = (slowDispatchThresholdMs > 0);
+
+ final boolean needStartTime = logSlowDelivery || logSlowDispatch;
+ final boolean needEndTime = logSlowDispatch;
+
if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
}
- final long start = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
- final long end;
+
+ final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
+ final long dispatchEnd;
try {
msg.target.dispatchMessage(msg);
- end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
+ dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
}
}
- if (slowDispatchThresholdMs > 0) {
- final long time = end - start;
- if (time > slowDispatchThresholdMs) {
- Slog.w(TAG, "Dispatch took " + time + "ms on "
- + Thread.currentThread().getName() + ", h=" +
- msg.target + " cb=" + msg.callback + " msg=" + msg.what);
+ if (logSlowDelivery) {
+ if (slowDeliveryDetected) {
+ if ((dispatchStart - msg.when) <= 10) {
+ Slog.w(TAG, "Drained");
+ slowDeliveryDetected = false;
+ }
+ } else {
+ if (showSlowLog(slowDeliveryThresholdMs, msg.when, dispatchStart, "delivery",
+ msg)) {
+ // Once we write a slow delivery log, suppress until the queue drains.
+ slowDeliveryDetected = true;
+ }
}
}
+ if (logSlowDispatch) {
+ showSlowLog(slowDispatchThresholdMs, dispatchStart, dispatchEnd, "dispatch", msg);
+ }
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
@@ -196,6 +234,19 @@
}
}
+ private static boolean showSlowLog(long threshold, long measureStart, long measureEnd,
+ String what, Message msg) {
+ final long actualTime = measureEnd - measureStart;
+ if (actualTime < threshold) {
+ return false;
+ }
+ // For slow delivery, the current message isn't really important, but log it anyway.
+ Slog.w(TAG, "Slow " + what + " took " + actualTime + "ms "
+ + Thread.currentThread().getName() + " h="
+ + msg.target.getClass().getName() + " c=" + msg.callback + " m=" + msg.what);
+ return true;
+ }
+
/**
* Return the Looper object associated with the current thread. Returns
* null if the calling thread is not associated with a Looper.
@@ -243,9 +294,13 @@
mTraceTag = traceTag;
}
- /** {@hide} */
- public void setSlowDispatchThresholdMs(long slowDispatchThresholdMs) {
+ /**
+ * Set a thresholds for slow dispatch/delivery log.
+ * {@hide}
+ */
+ public void setSlowLogThresholdMs(long slowDispatchThresholdMs, long slowDeliveryThresholdMs) {
mSlowDispatchThresholdMs = slowDispatchThresholdMs;
+ mSlowDeliveryThresholdMs = slowDeliveryThresholdMs;
}
/**