From bea51c0677144b160a906642a4204c07b02155a7 Mon Sep 17 00:00:00 2001 From: Jing Ji Date: Mon, 8 Aug 2022 18:38:14 -0700 Subject: [PATCH] Log the delay of broadcast dispatch/receive/handling into Westworld. Bug: 234527537 Test: statsd_testdrive 475 Change-Id: I542f5e3cd1defac537256aa232d5f4ddc3235730 Merged-In: I542f5e3cd1defac537256aa232d5f4ddc3235730 --- .../server/am/ActivityManagerService.java | 4 +- .../com/android/server/am/BroadcastQueue.java | 66 +++++++++++++------ .../android/server/am/BroadcastRecord.java | 2 + 3 files changed, 51 insertions(+), 21 deletions(-) diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index 07a5fb5d0f0f5..3780169967583 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -14255,10 +14255,12 @@ public class ActivityManagerService extends IActivityManager.Stub if (oldRecord.resultTo != null) { final BroadcastQueue oldQueue = broadcastQueueForIntent(oldRecord.intent); try { + oldRecord.mIsReceiverAppRunning = true; oldQueue.performReceiveLocked(oldRecord.callerApp, oldRecord.resultTo, oldRecord.intent, Activity.RESULT_CANCELED, null, null, - false, false, oldRecord.userId, oldRecord.callingUid, callingUid); + false, false, oldRecord.userId, oldRecord.callingUid, callingUid, + SystemClock.uptimeMillis() - oldRecord.enqueueTime, 0); } catch (RemoteException e) { Slog.w(TAG, "Failure [" + queue.mQueueName + "] sending broadcast result of " diff --git a/services/core/java/com/android/server/am/BroadcastQueue.java b/services/core/java/com/android/server/am/BroadcastQueue.java index 43d0de9855fe9..5a9231dcffdad 100644 --- a/services/core/java/com/android/server/am/BroadcastQueue.java +++ b/services/core/java/com/android/server/am/BroadcastQueue.java @@ -321,7 +321,7 @@ public final class BroadcastQueue { } private final void processCurBroadcastLocked(BroadcastRecord r, - ProcessRecord app, int receiverType, int processTemperature) throws RemoteException { + ProcessRecord app) throws RemoteException { if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST, "Process cur broadcast " + r + " for app " + app); final IApplicationThread thread = app.getThread(); @@ -367,10 +367,6 @@ public final class BroadcastQueue { if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST, "Process cur broadcast " + r + " DELIVERED for app " + app); started = true; - FrameworkStatsLog.write(BROADCAST_DELIVERY_EVENT_REPORTED, app.uid, - r.callingUid == -1 ? Process.SYSTEM_UID : r.callingUid, - ActivityManagerService.getShortAction(r.intent.getAction()), - receiverType, processTemperature); } finally { if (!started) { if (DEBUG_BROADCAST) Slog.v(TAG_BROADCAST, @@ -407,9 +403,8 @@ public final class BroadcastQueue { } try { mPendingBroadcast = null; - processCurBroadcastLocked(br, app, - BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__MANIFEST, - BROADCAST_DELIVERY_EVENT_REPORTED__PROC_START_TYPE__PROCESS_START_TYPE_COLD); + br.mIsReceiverAppRunning = false; + processCurBroadcastLocked(br, app); didSomething = true; } catch (Exception e) { Slog.w(TAG, "Exception in new application when starting receiver " @@ -517,6 +512,22 @@ public final class BroadcastQueue { final long finishTime = SystemClock.uptimeMillis(); final long elapsed = finishTime - r.receiverTime; r.state = BroadcastRecord.IDLE; + final int curIndex = r.nextReceiver - 1; + if (curIndex >= 0 && curIndex < r.receivers.size() && r.curApp != null) { + final Object curReceiver = r.receivers.get(curIndex); + FrameworkStatsLog.write(BROADCAST_DELIVERY_EVENT_REPORTED, r.curApp.uid, + r.callingUid == -1 ? Process.SYSTEM_UID : r.callingUid, + ActivityManagerService.getShortAction(r.intent.getAction()), + curReceiver instanceof BroadcastFilter + ? BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__RUNTIME + : BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__MANIFEST, + r.mIsReceiverAppRunning + ? BROADCAST_DELIVERY_EVENT_REPORTED__PROC_START_TYPE__PROCESS_START_TYPE_WARM + : BROADCAST_DELIVERY_EVENT_REPORTED__PROC_START_TYPE__PROCESS_START_TYPE_COLD, + r.dispatchTime - r.enqueueTime, + r.receiverTime - r.dispatchTime, + finishTime - r.receiverTime); + } if (state == BroadcastRecord.IDLE) { Slog.w(TAG_BROADCAST, "finishReceiver [" + mQueueName + "] called but state is IDLE"); } @@ -640,7 +651,8 @@ public final class BroadcastQueue { void performReceiveLocked(ProcessRecord app, IIntentReceiver receiver, Intent intent, int resultCode, String data, Bundle extras, boolean ordered, boolean sticky, int sendingUser, - int receiverUid, int callingUid) throws RemoteException { + int receiverUid, int callingUid, long dispatchDelay, + long receiveDelay) throws RemoteException { // Send the intent to the receiver asynchronously using one-way binder calls. if (app != null) { final IApplicationThread thread = app.getThread(); @@ -674,12 +686,15 @@ public final class BroadcastQueue { receiver.performReceive(intent, resultCode, data, extras, ordered, sticky, sendingUser); } - FrameworkStatsLog.write(BROADCAST_DELIVERY_EVENT_REPORTED, - receiverUid == -1 ? Process.SYSTEM_UID : receiverUid, - callingUid == -1 ? Process.SYSTEM_UID : callingUid, - ActivityManagerService.getShortAction(intent.getAction()), - BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__RUNTIME, - BROADCAST_DELIVERY_EVENT_REPORTED__PROC_START_TYPE__PROCESS_START_TYPE_WARM); + if (!ordered) { + FrameworkStatsLog.write(BROADCAST_DELIVERY_EVENT_REPORTED, + receiverUid == -1 ? Process.SYSTEM_UID : receiverUid, + callingUid == -1 ? Process.SYSTEM_UID : callingUid, + ActivityManagerService.getShortAction(intent.getAction()), + BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__RUNTIME, + BROADCAST_DELIVERY_EVENT_REPORTED__PROC_START_TYPE__PROCESS_START_TYPE_WARM, + dispatchDelay, receiveDelay, 0 /* finish_delay */); + } } private void deliverToRegisteredReceiverLocked(BroadcastRecord r, @@ -983,7 +998,9 @@ public final class BroadcastQueue { performReceiveLocked(filter.receiverList.app, filter.receiverList.receiver, new Intent(r.intent), r.resultCode, r.resultData, r.resultExtras, r.ordered, r.initialSticky, r.userId, - filter.receiverList.uid, r.callingUid); + filter.receiverList.uid, r.callingUid, + r.dispatchTime - r.enqueueTime, + r.receiverTime - r.dispatchTime); // parallel broadcasts are fire-and-forget, not bookended by a call to // finishReceiverLocked(), so we manage their activity-start token here if (filter.receiverList.app != null @@ -1166,6 +1183,7 @@ public final class BroadcastQueue { r.dispatchTime = SystemClock.uptimeMillis(); r.dispatchRealTime = SystemClock.elapsedRealtime(); r.dispatchClockTime = System.currentTimeMillis(); + r.mIsReceiverAppRunning = true; if (Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) { Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, @@ -1333,10 +1351,18 @@ public final class BroadcastQueue { Slog.i(TAG_BROADCAST, "Finishing broadcast [" + mQueueName + "] " + r.intent.getAction() + " app=" + r.callerApp); } + if (r.dispatchTime == 0) { + // The dispatch time here could be 0, in case it's a parallel + // broadcast but it has a result receiver. Set it to now. + r.dispatchTime = now; + } + r.mIsReceiverAppRunning = true; performReceiveLocked(r.callerApp, r.resultTo, new Intent(r.intent), r.resultCode, r.resultData, r.resultExtras, false, false, r.userId, - r.callingUid, r.callingUid); + r.callingUid, r.callingUid, + r.dispatchTime - r.enqueueTime, + now - r.dispatchTime); logBootCompletedBroadcastCompletionLatencyIfPossible(r); // Set this to null so that the reference // (local and remote) isn't kept in the mBroadcastHistory. @@ -1493,6 +1519,7 @@ public final class BroadcastQueue { "Delivering ordered [" + mQueueName + "] to registered " + filter + ": " + r); + r.mIsReceiverAppRunning = true; deliverToRegisteredReceiverLocked(r, filter, r.ordered, recIdx); if (r.receiver == null || !r.ordered) { // The receiver has already finished, so schedule to @@ -1856,9 +1883,8 @@ public final class BroadcastQueue { app.addPackage(info.activityInfo.packageName, info.activityInfo.applicationInfo.longVersionCode, mService.mProcessStats); maybeAddAllowBackgroundActivityStartsToken(app, r); - processCurBroadcastLocked(r, app, - BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__MANIFEST, - BROADCAST_DELIVERY_EVENT_REPORTED__PROC_START_TYPE__PROCESS_START_TYPE_WARM); + r.mIsReceiverAppRunning = true; + processCurBroadcastLocked(r, app); return; } catch (RemoteException e) { Slog.w(TAG, "Exception when sending broadcast to " diff --git a/services/core/java/com/android/server/am/BroadcastRecord.java b/services/core/java/com/android/server/am/BroadcastRecord.java index ae91d75ef0ce8..ce4528bca8871 100644 --- a/services/core/java/com/android/server/am/BroadcastRecord.java +++ b/services/core/java/com/android/server/am/BroadcastRecord.java @@ -135,6 +135,8 @@ final class BroadcastRecord extends Binder { ComponentName curComponent; // the receiver class that is currently running. ActivityInfo curReceiver; // info about the receiver that is currently running. + boolean mIsReceiverAppRunning; // Was the receiver's app already running. + // Private refcount-management bookkeeping; start > 0 static AtomicInteger sNextToken = new AtomicInteger(1);