Log a warning if a dispatch on UiThread takes more than

a certain amount of time.

Bug: 34961340
Test: Boot and launch several apps.
Change-Id: I38bd85a1dd9c572242d04f550df4a979f5f3bea5

diff --git a/core/java/android/os/Looper.java b/core/java/android/os/Looper.java
index 63d3e7a..44dbcfb 100644 (file)
--- a/core/java/android/os/Looper.java
+++ b/core/java/android/os/Looper.java
@@ -21,6 +21,7 @@ import android.annotation.Nullable;
 import android.os.LooperProto;
 import android.util.Log;
 import android.util.Printer;
+import android.util.Slog;
 import android.util.proto.ProtoOutputStream;
 
 /**
@@ -76,6 +77,9 @@ 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. */
+    private long mSlowDispatchThresholdMs;
+
      /** 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
@@ -148,17 +152,30 @@ public final class Looper {
                         msg.callback + ": " + msg.what);
             }
 
+            final long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
+
             final long traceTag = me.mTraceTag;
             if (traceTag != 0 && Trace.isTagEnabled(traceTag)) {
                 Trace.traceBegin(traceTag, msg.target.getTraceName(msg));
             }
+            final long start = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
+            final long end;
             try {
                 msg.target.dispatchMessage(msg);
+                end = (slowDispatchThresholdMs == 0) ? 0 : SystemClock.uptimeMillis();
             } 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 (logging != null) {
                 logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
@@ -226,6 +243,11 @@ public final class Looper {
         mTraceTag = traceTag;
     }
 
+    /** {@hide} */
+    public void setSlowDispatchThresholdMs(long slowDispatchThresholdMs) {
+        mSlowDispatchThresholdMs = slowDispatchThresholdMs;
+    }
+
     /**
      * Quits the looper.
      * <p>

diff --git a/services/core/java/com/android/server/UiThread.java b/services/core/java/com/android/server/UiThread.java
index 1bc6250..f1581ad 100644 (file)
--- a/services/core/java/com/android/server/UiThread.java
+++ b/services/core/java/com/android/server/UiThread.java
@@ -17,6 +17,7 @@
 package com.android.server;
 
 import android.os.Handler;
+import android.os.Looper;
 import android.os.Process;
 import android.os.Trace;
 
@@ -26,6 +27,7 @@ import android.os.Trace;
  * on it to avoid UI jank.
  */
 public final class UiThread extends ServiceThread {
+    private static final long SLOW_DISPATCH_THRESHOLD_MS = 100;
     private static UiThread sInstance;
     private static Handler sHandler;
 
@@ -39,7 +41,9 @@ public final class UiThread extends ServiceThread {
         if (sInstance == null) {
             sInstance = new UiThread();
             sInstance.start();
-            sInstance.getLooper().setTraceTag(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+            final Looper looper = sInstance.getLooper();
+            looper.setTraceTag(Trace.TRACE_TAG_ACTIVITY_MANAGER);
+            looper.setSlowDispatchThresholdMs(SLOW_DISPATCH_THRESHOLD_MS);
             sHandler = new Handler(sInstance.getLooper());
         }
     }