diff options
| -rw-r--r-- | services/core/java/com/android/server/am/BroadcastQueue.java | 67 | ||||
| -rw-r--r-- | services/core/java/com/android/server/am/BroadcastRecord.java | 18 |
2 files changed, 81 insertions, 4 deletions
diff --git a/services/core/java/com/android/server/am/BroadcastQueue.java b/services/core/java/com/android/server/am/BroadcastQueue.java index ea63c080cf68..ade44eac4583 100644 --- a/services/core/java/com/android/server/am/BroadcastQueue.java +++ b/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. diff --git a/services/core/java/com/android/server/am/BroadcastRecord.java b/services/core/java/com/android/server/am/BroadcastRecord.java index 8b1e829ad836..2ee32b6abe96 100644 --- a/services/core/java/com/android/server/am/BroadcastRecord.java +++ b/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); } |