commit 712886fd979f58b0de7cefc3bce885ad7f4493b6
author Makoto Onuki <omakoto@google.com> Fri Apr 27 15:22:50 2018 -0700
committer Makoto Onuki <omakoto@google.com> Fri Apr 27 17:15:46 2018 -0700
tree e473baec06ba56a09fa2e3a0a4d7c32f95293c5d
parent 5d8dfe17c814abbdb3268041b2f319697632cfa2

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

services/java/com/android/server/SystemServer.java

diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java
index 74b40ba..1880e9f 100644
--- a/services/java/com/android/server/SystemServer.java
+++ b/services/java/com/android/server/SystemServer.java
@@ -156,6 +156,9 @@
     // 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 @@
                 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");