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

5 files changed, 93 insertions, 18 deletions

diff --git a/core/java/android/os/Looper.java b/core/java/android/os/Looper.java
index 848c59610720..f17e0f026fda 100644
--- a/core/java/android/os/Looper.java
+++ b/core/java/android/os/Looper.java
@@ -77,10 +77,18 @@ public final class Looper {
     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 @@ public final class Looper {
         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 @@ public final class Looper {
                         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 @@ public final class Looper {
         }
     }
 
+    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 @@ public final class Looper {
         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;
     }
 
     /**
diff --git a/core/java/com/android/internal/os/BackgroundThread.java b/core/java/com/android/internal/os/BackgroundThread.java
index 7558f8cee233..eada142dd3c6 100644
--- a/core/java/com/android/internal/os/BackgroundThread.java
+++ b/core/java/com/android/internal/os/BackgroundThread.java
@@ -18,12 +18,15 @@ package com.android.internal.os;
 
 import android.os.Handler;
 import android.os.HandlerThread;
+import android.os.Looper;
 import android.os.Trace;
 
 /**
  * Shared singleton background thread for each process.
  */
 public final class BackgroundThread extends HandlerThread {
+    private static final long SLOW_DISPATCH_THRESHOLD_MS = 10_000;
+    private static final long SLOW_DELIVERY_THRESHOLD_MS = 30_000;
     private static BackgroundThread sInstance;
     private static Handler sHandler;
 
@@ -35,7 +38,10 @@ public final class BackgroundThread extends HandlerThread {
         if (sInstance == null) {
             sInstance = new BackgroundThread();
             sInstance.start();
-            sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
+            final Looper looper = sInstance.getLooper();
+            looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
+            looper.setSlowLogThresholdMs(
+                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
             sHandler = new Handler(sInstance.getLooper());
         }
     }
diff --git a/services/core/java/com/android/server/FgThread.java b/services/core/java/com/android/server/FgThread.java
index 021bfaa10230..fe30057fc820 100644
--- a/services/core/java/com/android/server/FgThread.java
+++ b/services/core/java/com/android/server/FgThread.java
@@ -17,6 +17,7 @@
 package com.android.server;
 
 import android.os.Handler;
+import android.os.Looper;
 import android.os.Trace;
 
 /**
@@ -28,6 +29,9 @@ import android.os.Trace;
  * to be delayed for a user-noticeable amount of time.
  */
 public final class FgThread extends ServiceThread {
+    private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
+    private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;
+
     private static FgThread sInstance;
     private static Handler sHandler;
 
@@ -39,7 +43,10 @@ public final class FgThread extends ServiceThread {
         if (sInstance == null) {
             sInstance = new FgThread();
             sInstance.start();
-            sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
+            final Looper looper = sInstance.getLooper();
+            looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
+            looper.setSlowLogThresholdMs(
+                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
             sHandler = new Handler(sInstance.getLooper());
         }
     }
diff --git a/services/core/java/com/android/server/UiThread.java b/services/core/java/com/android/server/UiThread.java
index f81307429ae0..b2fa6846a6d0 100644
--- a/services/core/java/com/android/server/UiThread.java
+++ b/services/core/java/com/android/server/UiThread.java
@@ -28,6 +28,7 @@ import android.os.Trace;
  */
 public final class UiThread extends ServiceThread {
     private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
+    private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;
     private static UiThread sInstance;
     private static Handler sHandler;
 
@@ -48,7 +49,8 @@ public final class UiThread extends ServiceThread {
             sInstance.start();
             final Looper looper = sInstance.getLooper();
             looper.setTraceTag(Trace.TRACE_TAG_SYSTEM_SERVER);
-            looper.setSlowDispatchThresholdMs(SLOW_DISPATCH_THRESHOLD_MS);
+            looper.setSlowLogThresholdMs(
+                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
             sHandler = new Handler(sInstance.getLooper());
         }
     }
diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java
index 74b40ba23518..1880e9fa362c 100644
--- a/services/java/com/android/server/SystemServer.java
+++ b/services/java/com/android/server/SystemServer.java
@@ -156,6 +156,9 @@ public final class SystemServer {
     // give any timezone code room without going into negative time.
     private static final long EARLIEST_SUPPORTED_TIME = 86400 * 1000;
 
+    private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
+    private static final long SLOW_DELIVERY_THRESHOLD_MS = 200;
+
     /*
      * Implementation class names. TODO: Move them to a codegen class or load
      * them from the build system somehow.
@@ -396,6 +399,8 @@ public final class SystemServer {
                 android.os.Process.THREAD_PRIORITY_FOREGROUND);
             android.os.Process.setCanSelfBackground(false);
             Looper.prepareMainLooper();
+            Looper.getMainLooper().setSlowLogThresholdMs(
+                    SLOW_DISPATCH_THRESHOLD_MS, SLOW_DELIVERY_THRESHOLD_MS);
 
             // Initialize native services.
             System.loadLibrary("android_servers");