Log slow UID observer in dumpsys

Sample output:
  mUidChangeDispatchCount=322
  Slow UID dispatches:
    com.android.server.usage.UsageStatsService$2: 0 / Max 0ms
    android.app.IUidObserver$Stub$Proxy: 0 / Max 0ms
    android.app.ActivityManager$UidObserver: 0 / Max 0ms
    com.android.server.pm.ShortcutService$3: 0 / Max 0ms
    android.app.IUidObserver$Stub$Proxy: 0 / Max 0ms
    android.app.IUidObserver$Stub$Proxy: 0 / Max 0ms
    com.android.server.net.NetworkPolicyManagerService$3: 0 / Max 0ms
    com.android.server.AlarmManagerService$UidObserver: 0 / Max 0ms
    com.android.server.job.JobSchedulerService$2: 1 / Max 826ms
    android.app.IUidObserver$Stub$Proxy: 1 / Max 44ms
    android.app.IUidObserver$Stub$Proxy: 0 / Max 0ms
    com.android.server.AppStateTracker$UidObserver: 0 / Max 0ms

Bug: 73505782
Test: Boot and observe dumpsys activity.
Change-Id: I17c971a9690a708c253a5e98e21b8c81166d3ed0

diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index 5f8a5ab..460a0b9 100644 (file)
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -608,6 +608,9 @@ public class ActivityManagerService extends IActivityManager.Stub
     // as one line, but close enough for now.
     static final int RESERVED_BYTES_PER_LOGCAT_LINE = 100;
 
+    /** If a UID observer takes more than this long, send a WTF. */
+    private static final int SLOW_UID_OBSERVER_THRESHOLD_MS = 20;
+
     // Access modes for handleIncomingUser.
     static final int ALLOW_NON_FULL = 0;
     static final int ALLOW_NON_FULL_IN_PROFILE = 1;
@@ -780,6 +783,9 @@ public class ActivityManagerService extends IActivityManager.Stub
     @VisibleForTesting
     long mWaitForNetworkTimeoutMs;
 
+    /** Total # of UID change events dispatched, shown in dumpsys. */
+    int mUidChangeDispatchCount;
+
     /**
      * Helper class which strips out priority and proto arguments then calls the dump function with
      * the appropriate arguments. If priority arguments are omitted, function calls the legacy
@@ -1702,6 +1708,15 @@ public class ActivityManagerService extends IActivityManager.Stub
         final int which;
         final int cutpoint;
 
+        /**
+         * Total # of callback calls that took more than {@link #SLOW_UID_OBSERVER_THRESHOLD_MS}.
+         * We show it in dumpsys.
+         */
+        int mSlowDispatchCount;
+
+        /** Max time it took for each dispatch. */
+        int mMaxDispatchTime;
+
         final SparseIntArray lastProcStates;
 
         // Please keep the enum lists in sync
@@ -4721,6 +4736,7 @@ public class ActivityManagerService extends IActivityManager.Stub
                     "*** Delivering " + N + " uid changes");
         }
 
+        mUidChangeDispatchCount += N;
         int i = mUidObservers.beginBroadcast();
         while (i > 0) {
             i--;
@@ -4773,6 +4789,7 @@ public class ActivityManagerService extends IActivityManager.Stub
                     // interested in all proc state changes.
                     continue;
                 }
+                final long start = SystemClock.uptimeMillis();
                 if ((change & UidRecord.CHANGE_IDLE) != 0) {
                     if ((reg.which & ActivityManager.UID_OBSERVER_IDLE) != 0) {
                         if (DEBUG_UID_OBSERVERS) Slog.i(TAG_UID_OBSERVERS,
@@ -4833,6 +4850,13 @@ public class ActivityManagerService extends IActivityManager.Stub
                         }
                     }
                 }
+                final int duration = (int) (SystemClock.uptimeMillis() - start);
+                if (reg.mMaxDispatchTime < duration) {
+                    reg.mMaxDispatchTime = duration;
+                }
+                if (duration >= SLOW_UID_OBSERVER_THRESHOLD_MS) {
+                    reg.mSlowDispatchCount++;
+                }
             }
         } catch (RemoteException e) {
         }
@@ -16793,6 +16817,25 @@ public class ActivityManagerService extends IActivityManager.Stub
                         pw.print(" mLowRamSinceLastIdle=");
                         TimeUtils.formatDuration(getLowRamTimeSinceIdle(now), pw);
                         pw.println();
+                pw.println();
+                pw.print("  mUidChangeDispatchCount=");
+                pw.print(mUidChangeDispatchCount);
+                pw.println();
+
+                pw.println("  Slow UID dispatches:");
+                final int N = mUidObservers.beginBroadcast();
+                for (int i = 0; i < N; i++) {
+                    UidObserverRegistration r =
+                            (UidObserverRegistration) mUidObservers.getBroadcastCookie(i);
+                    pw.print("    ");
+                    pw.print(mUidObservers.getBroadcastItem(i).getClass().getTypeName());
+                    pw.print(": ");
+                    pw.print(r.mSlowDispatchCount);
+                    pw.print(" / Max ");
+                    pw.print(r.mMaxDispatchTime);
+                    pw.println("ms");
+                }
+                mUidObservers.finishBroadcast();
             }
         }
         pw.println("  mForceBackgroundCheck=" + mForceBackgroundCheck);