Merge "Log the duration of executing all receivers of LOCKED_BOOT_COMPLETED or BOOT_COMPLETED broadcast." into tm-dev

services/core/java/com/android/server/am/BroadcastQueue.java

@@ -21,6 +21,9 @@ import static android.os.Process.ZYGOTE_POLICY_FLAG_EMPTY;
 import static android.os.Process.ZYGOTE_POLICY_FLAG_LATENCY_SENSITIVE;
 import static android.text.TextUtils.formatSimple;
 
+import static com.android.internal.util.FrameworkStatsLog.BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED;
+import static com.android.internal.util.FrameworkStatsLog.BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__BOOT_COMPLETED;
+import static com.android.internal.util.FrameworkStatsLog.BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__LOCKED_BOOT_COMPLETED;
 import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST;
 import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST_DEFERRAL;
 import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST_LIGHT;
@@ -29,6 +32,7 @@ import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_PERMISSIONS
 import static com.android.server.am.ActivityManagerDebugConfig.POSTFIX_BROADCAST;
 import static com.android.server.am.ActivityManagerDebugConfig.POSTFIX_MU;
 
+
 import android.annotation.NonNull;
 import android.annotation.Nullable;
 import android.app.ActivityManager;
@@ -51,6 +55,7 @@ import android.content.pm.ApplicationInfo;
 import android.content.pm.PackageManager;
 import android.content.pm.PermissionInfo;
 import android.content.pm.ResolveInfo;
+import android.content.pm.UserInfo;
 import android.os.Bundle;
 import android.os.Handler;
 import android.os.IBinder;
@@ -64,6 +69,7 @@ import android.os.RemoteException;
 import android.os.SystemClock;
 import android.os.Trace;
 import android.os.UserHandle;
+import android.os.UserManager;
 import android.permission.IPermissionManager;
 import android.text.TextUtils;
 import android.util.EventLog;
@@ -75,6 +81,7 @@ import android.util.proto.ProtoOutputStream;
 import com.android.internal.util.ArrayUtils;
 import com.android.internal.util.FrameworkStatsLog;
 import com.android.server.LocalServices;
+import com.android.server.pm.UserManagerInternal;
 
 import java.io.FileDescriptor;
 import java.io.PrintWriter;
@@ -250,12 +257,16 @@ public final class BroadcastQueue {
 
     public void enqueueParallelBroadcastLocked(BroadcastRecord r) {
         r.enqueueClockTime = System.currentTimeMillis();
+        r.enqueueTime = SystemClock.uptimeMillis();
+        r.enqueueRealTime = SystemClock.elapsedRealtime();
         mParallelBroadcasts.add(r);
         enqueueBroadcastHelper(r);
     }
 
     public void enqueueOrderedBroadcastLocked(BroadcastRecord r) {
         r.enqueueClockTime = System.currentTimeMillis();
+        r.enqueueTime = SystemClock.uptimeMillis();
+        r.enqueueRealTime = SystemClock.elapsedRealtime();
         mDispatcher.enqueueOrderedBroadcastLocked(r);
         enqueueBroadcastHelper(r);
     }
@@ -1121,6 +1132,7 @@ public final class BroadcastQueue {
         while (mParallelBroadcasts.size() > 0) {
             r = mParallelBroadcasts.remove(0);
             r.dispatchTime = SystemClock.uptimeMillis();
+            r.dispatchRealTime = SystemClock.elapsedRealtime();
             r.dispatchClockTime = System.currentTimeMillis();
 
             if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
@@ -1292,6 +1304,7 @@ public final class BroadcastQueue {
                             performReceiveLocked(r.callerApp, r.resultTo,
                                     new Intent(r.intent), r.resultCode,
                                     r.resultData, r.resultExtras, false, false, r.userId);
+                            logBootCompletedBroadcastCompletionLatencyIfPossible(r);
                             // Set this to null so that the reference
                             // (local and remote) isn't kept in the mBroadcastHistory.
                             r.resultTo = null;
@@ -1408,6 +1421,7 @@ public final class BroadcastQueue {
         r.receiverTime = SystemClock.uptimeMillis();
         if (recIdx == 0) {
             r.dispatchTime = r.receiverTime;
+            r.dispatchRealTime = SystemClock.elapsedRealtime();
             r.dispatchClockTime = System.currentTimeMillis();
 
             if (mLogLatencyMetrics) {
@@ -1866,6 +1880,59 @@ public final class BroadcastQueue {
         return null;
     }
 
+    private void logBootCompletedBroadcastCompletionLatencyIfPossible(BroadcastRecord r) {
+        // Only log after last receiver.
+        // In case of split BOOT_COMPLETED broadcast, make sure only call this method on the
+        // last BroadcastRecord of the split broadcast which has non-null resultTo.
+        final int numReceivers = (r.receivers != null) ? r.receivers.size() : 0;
+        if (r.nextReceiver < numReceivers) {
+            return;
+        }
+        final String action = r.intent.getAction();
+        int event = 0;
+        if (Intent.ACTION_LOCKED_BOOT_COMPLETED.equals(action)) {
+            event = BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__LOCKED_BOOT_COMPLETED;
+        } else if (Intent.ACTION_BOOT_COMPLETED.equals(action)) {
+            event = BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED__EVENT__BOOT_COMPLETED;
+        }
+        if (event != 0) {
+            final int dispatchLatency = (int)(r.dispatchTime - r.enqueueTime);
+            final int completeLatency = (int)
+                    (SystemClock.uptimeMillis() - r.enqueueTime);
+            final int dispatchRealLatency = (int)(r.dispatchRealTime - r.enqueueRealTime);
+            final int completeRealLatency = (int)
+                    (SystemClock.elapsedRealtime() - r.enqueueRealTime);
+            int userType = FrameworkStatsLog.USER_LIFECYCLE_JOURNEY_REPORTED__USER_TYPE__TYPE_UNKNOWN;
+            // This method is called very infrequently, no performance issue we call
+            // LocalServices.getService() here.
+            final UserManagerInternal umInternal = LocalServices.getService(
+                    UserManagerInternal.class);
+            final UserInfo userInfo = umInternal.getUserInfo(r.userId);
+            if (userInfo != null) {
+                userType = UserManager.getUserTypeForStatsd(userInfo.userType);
+            }
+            Slog.i(TAG_BROADCAST,
+                    "BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED action:"
+                            + action
+                            + " dispatchLatency:" + dispatchLatency
+                            + " completeLatency:" + completeLatency
+                            + " dispatchRealLatency:" + dispatchRealLatency
+                            + " completeRealLatency:" + completeRealLatency
+                            + " receiversSize:" + r.receivers.size()
+                            + " userId:" + r.userId
+                            + " userType:" + (userInfo != null? userInfo.userType : null));
+            FrameworkStatsLog.write(
+                    BOOT_COMPLETED_BROADCAST_COMPLETION_LATENCY_REPORTED,
+                    event,
+                    dispatchLatency,
+                    completeLatency,
+                    dispatchRealLatency,
+                    completeRealLatency,
+                    r.userId,
+                    userType);
+        }
+    }
+
     private void maybeReportBroadcastDispatchedEventLocked(BroadcastRecord r, int targetUid) {
         // STOPSHIP (217251579): Temporarily use temp-allowlist reason to identify
         // push messages and record response events.

services/core/java/com/android/server/am/BroadcastRecord.java

@@ -84,11 +84,14 @@ final class BroadcastRecord extends Binder {
     boolean deferred;
     int splitCount;         // refcount for result callback, when split
     int splitToken;         // identifier for cross-BroadcastRecord refcount
+    long enqueueTime;       // uptimeMillis when the broadcast was enqueued
+    long enqueueRealTime;   // elapsedRealtime when the broadcast was enqueued
     long enqueueClockTime;  // the clock time the broadcast was enqueued
     long dispatchTime;      // when dispatch started on this set of receivers
+    long dispatchRealTime;  // elapsedRealtime when the broadcast was dispatched
     long dispatchClockTime; // the clock time the dispatch started
     long receiverTime;      // when current receiver started for timeouts.
-    long finishTime;        // when we finished the broadcast.
+    long finishTime;        // when we finished the current receiver.
     boolean timeoutExempt;  // true if this broadcast is not subject to receiver timeouts
     int resultCode;         // current result code value.
     String resultData;      // current result data value.
@@ -169,7 +172,7 @@ final class BroadcastRecord extends Binder {
         pw.print(prefix); pw.print("dispatchTime=");
                 TimeUtils.formatDuration(dispatchTime, now, pw);
                 pw.print(" (");
-                TimeUtils.formatDuration(dispatchClockTime-enqueueClockTime, pw);
+                TimeUtils.formatDuration(dispatchTime - enqueueTime, pw);
                 pw.print(" since enq)");
         if (finishTime != 0) {
             pw.print(" finishTime="); TimeUtils.formatDuration(finishTime, now, pw);
@@ -324,8 +327,11 @@ final class BroadcastRecord extends Binder {
         delivery = from.delivery;
         duration = from.duration;
         resultTo = from.resultTo;
+        enqueueTime = from.enqueueTime;
+        enqueueRealTime = from.enqueueRealTime;
         enqueueClockTime = from.enqueueClockTime;
         dispatchTime = from.dispatchTime;
+        dispatchRealTime = from.dispatchRealTime;
         dispatchClockTime = from.dispatchClockTime;
         receiverTime = from.receiverTime;
         finishTime = from.finishTime;
@@ -378,7 +384,9 @@ final class BroadcastRecord extends Binder {
                 requiredPermissions, excludedPermissions, appOp, options, splitReceivers, resultTo,
                 resultCode, resultData, resultExtras, ordered, sticky, initialSticky, userId,
                 allowBackgroundActivityStarts, mBackgroundActivityStartsToken, timeoutExempt);
-
+        split.enqueueTime = this.enqueueTime;
+        split.enqueueRealTime = this.enqueueRealTime;
+        split.enqueueClockTime = this.enqueueClockTime;
         split.splitToken = this.splitToken;
         return split;
     }
@@ -448,9 +456,11 @@ final class BroadcastRecord extends Binder {
             final BroadcastRecord br = new BroadcastRecord(queue, intent, callerApp, callerPackage,
                     callerFeatureId, callingPid, callingUid, callerInstantApp, resolvedType,
                     requiredPermissions, excludedPermissions, appOp, options,
-                    uid2receiverList.valueAt(i), resultTo,
+                    uid2receiverList.valueAt(i), null /* _resultTo */,
                     resultCode, resultData, resultExtras, ordered, sticky, initialSticky, userId,
                     allowBackgroundActivityStarts, mBackgroundActivityStartsToken, timeoutExempt);
+            br.enqueueTime = this.enqueueTime;
+            br.enqueueRealTime = this.enqueueRealTime;
             br.enqueueClockTime = this.enqueueClockTime;
             ret.put(uid2receiverList.keyAt(i), br);
         }