1 package com.android.server.wm;
2 
3 import static android.app.ActivityManager.START_SUCCESS;
4 import static android.app.ActivityManager.START_TASK_TO_FRONT;
5 import static android.app.ActivityManager.processStateAmToProto;
6 import static android.app.WaitResult.LAUNCH_STATE_COLD;
7 import static android.app.WaitResult.LAUNCH_STATE_HOT;
8 import static android.app.WaitResult.LAUNCH_STATE_WARM;
9 import static android.app.WindowConfiguration.WINDOWING_MODE_FREEFORM;
10 import static android.app.WindowConfiguration.WINDOWING_MODE_FULLSCREEN;
11 import static android.app.WindowConfiguration.WINDOWING_MODE_MULTI_WINDOW;
12 import static android.app.WindowConfiguration.WINDOWING_MODE_PINNED;
13 import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_PRIMARY;
14 import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_SECONDARY;
15 import static android.app.WindowConfiguration.WINDOWING_MODE_UNDEFINED;
16 
17 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.ACTION_ACTIVITY_START;
18 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION;
19 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS;
20 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME;
21 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED;
22 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS;
23 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS;
24 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_IS_EPHEMERAL;
25 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_PROCESS_RUNNING;
26 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN;
27 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN_MS;
28 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS;
29 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS;
30 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_PACKAGE_NAME;
31 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID;
32 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
33 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_PROC_STATE;
34 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME;
35 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_COMING_FROM_PENDING_INTENT;
36 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN;
37 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INTENT_ACTION;
38 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_CUR_PROC_STATE;
39 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES;
40 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES;
41 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES;
42 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_OVERLAY_UI;
43 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_TOP_UI;
44 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION;
45 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT;
46 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT;
47 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PENDING_UI_CLEAN;
48 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PROCESS_NAME;
49 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID;
50 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
51 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_PROC_STATE;
52 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_SHORT_COMPONENT_NAME;
53 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_FILTER;
54 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_REASON;
55 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH;
56 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH;
57 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE;
58 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE;
59 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
60 import static com.android.server.am.MemoryStatUtil.MemoryStat;
61 import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem;
62 import static com.android.server.wm.ActivityTaskManagerDebugConfig.DEBUG_METRICS;
63 import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_ATM;
64 import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_WITH_CLASS_NAME;
65 import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT;
66 import static com.android.server.wm.EventLogTags.WM_ACTIVITY_LAUNCH_TIME;
67 
68 import android.annotation.NonNull;
69 import android.annotation.Nullable;
70 import android.app.WaitResult;
71 import android.app.WindowConfiguration.WindowingMode;
72 import android.content.ComponentName;
73 import android.content.Intent;
74 import android.content.pm.ApplicationInfo;
75 import android.content.pm.dex.ArtManagerInternal;
76 import android.content.pm.dex.PackageOptimizationInfo;
77 import android.metrics.LogMaker;
78 import android.os.Binder;
79 import android.os.Looper;
80 import android.os.SystemClock;
81 import android.os.Trace;
82 import android.util.ArrayMap;
83 import android.util.EventLog;
84 import android.util.Log;
85 import android.util.Slog;
86 import android.util.TimeUtils;
87 import android.util.proto.ProtoOutputStream;
88 
89 import com.android.internal.annotations.VisibleForTesting;
90 import com.android.internal.logging.MetricsLogger;
91 import com.android.internal.os.BackgroundThread;
92 import com.android.internal.util.FrameworkStatsLog;
93 import com.android.internal.util.function.pooled.PooledLambda;
94 import com.android.server.LocalServices;
95 
96 import java.util.ArrayList;
97 import java.util.LinkedList;
98 import java.util.concurrent.TimeUnit;
99 
100 /**
101  * Listens to activity launches, transitions, visibility changes and window drawn callbacks to
102  * determine app launch times and draw delays. Source of truth for activity metrics and provides
103  * data for Tron, logcat, event logs and {@link android.app.WaitResult}.
104  * <p>
105  * A typical sequence of a launch event could be:
106  * {@link #notifyActivityLaunching}, {@link #notifyActivityLaunched},
107  * {@link #notifyStartingWindowDrawn} (optional), {@link #notifyTransitionStarting}
108  * {@link #notifyWindowsDrawn}.
109  * <p>
110  * Tests:
111  * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests
112  */
113 class ActivityMetricsLogger {
114 
115     private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM;
116 
117     // Window modes we are interested in logging. If we ever introduce a new type, we need to add
118     // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array.
119     private static final int WINDOW_STATE_STANDARD = 0;
120     private static final int WINDOW_STATE_SIDE_BY_SIDE = 1;
121     private static final int WINDOW_STATE_FREEFORM = 2;
122     private static final int WINDOW_STATE_ASSISTANT = 3;
123     private static final int WINDOW_STATE_MULTI_WINDOW = 4;
124     private static final int WINDOW_STATE_INVALID = -1;
125 
126     /**
127      * The flag for {@link #notifyActivityLaunching} to skip associating a new launch with an active
128      * transition, in the case the launch is standalone (e.g. from recents).
129      */
130     private static final int IGNORE_CALLER = -1;
131     private static final int INVALID_DELAY = -1;
132     private static final int INVALID_TRANSITION_TYPE = -1;
133 
134     // Preallocated strings we are sending to tron, so we don't have to allocate a new one every
135     // time we log.
136     private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = {
137             "window_time_0", "window_time_1", "window_time_2", "window_time_3", "window_time_4"};
138 
139     private int mWindowState = WINDOW_STATE_STANDARD;
140     private long mLastLogTimeSecs;
141     private final ActivityStackSupervisor mSupervisor;
142     private final MetricsLogger mMetricsLogger = new MetricsLogger();
143 
144     /** All active transitions. */
145     private final ArrayList<TransitionInfo> mTransitionInfoList = new ArrayList<>();
146     /** Map : Last launched activity => {@link TransitionInfo} */
147     private final ArrayMap<ActivityRecord, TransitionInfo> mLastTransitionInfo = new ArrayMap<>();
148 
149     private ArtManagerInternal mArtManagerInternal;
150     private final StringBuilder mStringBuilder = new StringBuilder();
151 
152     /**
153      * Due to the global single concurrent launch sequence, all calls to this observer must be made
154      * in-order on the same thread to fulfill the "happens-before" guarantee in LaunchObserver.
155      */
156     private final LaunchObserverRegistryImpl mLaunchObserver;
157     @VisibleForTesting static final int LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE = 512;
158 
159     /**
160      * The information created when an intent is incoming but we do not yet know whether it will be
161      * launched successfully.
162      */
163     static final class LaunchingState {
164         /** The timestamp of {@link #notifyActivityLaunching}. */
165         private long mCurrentTransitionStartTimeNs;
166         /** Non-null when a {@link TransitionInfo} is created for this state. */
167         private TransitionInfo mAssociatedTransitionInfo;
168 
169         @VisibleForTesting
allDrawn()170         boolean allDrawn() {
171             return mAssociatedTransitionInfo != null && mAssociatedTransitionInfo.allDrawn();
172         }
173     }
174 
175     /** The information created when an activity is confirmed to be launched. */
176     private static final class TransitionInfo {
177         /**
178          * The field to lookup and update an existing transition efficiently between
179          * {@link #notifyActivityLaunching} and {@link #notifyActivityLaunched}.
180          *
181          * @see LaunchingState#mAssociatedTransitionInfo
182          */
183         final LaunchingState mLaunchingState;
184         /**
185          * The timestamp of the first {@link #notifyActivityLaunching}. It can be used as a key for
186          * observer to identify which callbacks belong to a launch event.
187          */
188         final long mTransitionStartTimeNs;
189         /** The device uptime in seconds when this transition info is created. */
190         final int mCurrentTransitionDeviceUptime;
191         /** The type can be cold (new process), warm (new activity), or hot (bring to front). */
192         final int mTransitionType;
193         /** Whether the process was already running when the transition started. */
194         final boolean mProcessRunning;
195         /** whether the process of the launching activity didn't have any active activity. */
196         final boolean mProcessSwitch;
197         /** The activities that should be drawn. */
198         final LinkedList<ActivityRecord> mPendingDrawActivities = new LinkedList<>();
199         /** The latest activity to have been launched. */
200         @NonNull ActivityRecord mLastLaunchedActivity;
201 
202         /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyTransitionStarting}. */
203         int mCurrentTransitionDelayMs;
204         /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyStartingWindowDrawn}. */
205         int mStartingWindowDelayMs = INVALID_DELAY;
206         /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyBindApplication}. */
207         int mBindApplicationDelayMs = INVALID_DELAY;
208         /** Elapsed time from when we launch an activity to when its windows are drawn. */
209         int mWindowsDrawnDelayMs;
210         /** The reason why the transition started (see ActivityManagerInternal.APP_TRANSITION_*). */
211         int mReason = APP_TRANSITION_TIMEOUT;
212         /** The flag ensures that {@link #mStartingWindowDelayMs} is only set once. */
213         boolean mLoggedStartingWindowDrawn;
214         /** If the any app transitions have been logged as starting. */
215         boolean mLoggedTransitionStarting;
216 
217         /** Non-null if the application has reported drawn but its window hasn't. */
218         @Nullable Runnable mPendingFullyDrawn;
219         /** Non-null if the trace is active. */
220         @Nullable String mLaunchTraceName;
221 
222         /** @return Non-null if there will be a window drawn event for the launch. */
223         @Nullable
create(@onNull ActivityRecord r, @NonNull LaunchingState launchingState, boolean processRunning, boolean processSwitch, int startResult)224         static TransitionInfo create(@NonNull ActivityRecord r,
225                 @NonNull LaunchingState launchingState, boolean processRunning,
226                 boolean processSwitch, int startResult) {
227             int transitionType = INVALID_TRANSITION_TYPE;
228             if (processRunning) {
229                 if (startResult == START_SUCCESS) {
230                     transitionType = TYPE_TRANSITION_WARM_LAUNCH;
231                 } else if (startResult == START_TASK_TO_FRONT) {
232                     transitionType = TYPE_TRANSITION_HOT_LAUNCH;
233                 }
234             } else if (startResult == START_SUCCESS || startResult == START_TASK_TO_FRONT) {
235                 // Task may still exist when cold launching an activity and the start result will be
236                 // set to START_TASK_TO_FRONT. Treat this as a COLD launch.
237                 transitionType = TYPE_TRANSITION_COLD_LAUNCH;
238             }
239             if (transitionType == INVALID_TRANSITION_TYPE) {
240                 // That means the startResult is neither START_SUCCESS nor START_TASK_TO_FRONT.
241                 return null;
242             }
243             return new TransitionInfo(r, launchingState, transitionType, processRunning,
244                     processSwitch);
245         }
246 
247         /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */
TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType, boolean processRunning, boolean processSwitch)248         private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType,
249                 boolean processRunning, boolean processSwitch) {
250             mLaunchingState = launchingState;
251             mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs;
252             mTransitionType = transitionType;
253             mProcessRunning = processRunning;
254             mProcessSwitch = processSwitch;
255             mCurrentTransitionDeviceUptime =
256                     (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis());
257             setLatestLaunchedActivity(r);
258             launchingState.mAssociatedTransitionInfo = this;
259         }
260 
261         /**
262          * Remembers the latest launched activity to represent the final transition. This also
263          * tracks the activities that should be drawn, so a consecutive launching sequence can be
264          * coalesced as one event.
265          */
setLatestLaunchedActivity(ActivityRecord r)266         void setLatestLaunchedActivity(ActivityRecord r) {
267             if (mLastLaunchedActivity == r) {
268                 return;
269             }
270             mLastLaunchedActivity = r;
271             if (!r.noDisplay) {
272                 if (DEBUG_METRICS) Slog.i(TAG, "Add pending draw " + r);
273                 mPendingDrawActivities.add(r);
274             }
275         }
276 
277         /** @return {@code true} if the activity matches a launched activity in this transition. */
contains(WindowContainer wc)278         boolean contains(WindowContainer wc) {
279             final ActivityRecord r = AppTransitionController.getAppFromContainer(wc);
280             return r != null && (r == mLastLaunchedActivity || mPendingDrawActivities.contains(r));
281         }
282 
283         /** Called when the activity is drawn or won't be drawn. */
removePendingDrawActivity(ActivityRecord r)284         void removePendingDrawActivity(ActivityRecord r) {
285             if (DEBUG_METRICS) Slog.i(TAG, "Remove pending draw " + r);
286             mPendingDrawActivities.remove(r);
287         }
288 
allDrawn()289         boolean allDrawn() {
290             return mPendingDrawActivities.isEmpty();
291         }
292 
293         /**
294          * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or
295          *         LaunchObserver.
296          */
isInterestingToLoggerAndObserver()297         boolean isInterestingToLoggerAndObserver() {
298             return mProcessSwitch;
299         }
300 
calculateCurrentDelay()301         int calculateCurrentDelay() {
302             return calculateDelay(SystemClock.elapsedRealtimeNanos());
303         }
304 
calculateDelay(long timestampNs)305         int calculateDelay(long timestampNs) {
306             // Shouldn't take more than 25 days to launch an app, so int is fine here.
307             return (int) TimeUnit.NANOSECONDS.toMillis(timestampNs - mTransitionStartTimeNs);
308         }
309 
310         @Override
toString()311         public String toString() {
312             return "TransitionInfo{" + Integer.toHexString(System.identityHashCode(this))
313                     + " a=" + mLastLaunchedActivity + " ua=" + mPendingDrawActivities + "}";
314         }
315     }
316 
317     static final class TransitionInfoSnapshot {
318         final private ApplicationInfo applicationInfo;
319         final private WindowProcessController processRecord;
320         final String packageName;
321         final String launchedActivityName;
322         final private String launchedActivityLaunchedFromPackage;
323         final private String launchedActivityLaunchToken;
324         final private String launchedActivityAppRecordRequiredAbi;
325         final String launchedActivityShortComponentName;
326         final private String processName;
327         final private int reason;
328         final private int startingWindowDelayMs;
329         final private int bindApplicationDelayMs;
330         final int windowsDrawnDelayMs;
331         final int type;
332         final int userId;
333         /**
334          * Elapsed time from when we launch an activity to when the app reported it was
335          * fully drawn. If this is not reported then the value is set to INVALID_DELAY.
336          */
337         final int windowsFullyDrawnDelayMs;
338         final int activityRecordIdHashCode;
339 
TransitionInfoSnapshot(TransitionInfo info)340         private TransitionInfoSnapshot(TransitionInfo info) {
341             this(info, info.mLastLaunchedActivity, INVALID_DELAY);
342         }
343 
TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs)344         private TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity,
345                 int windowsFullyDrawnDelayMs) {
346             applicationInfo = launchedActivity.info.applicationInfo;
347             packageName = launchedActivity.packageName;
348             launchedActivityName = launchedActivity.info.name;
349             launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage;
350             launchedActivityLaunchToken = launchedActivity.info.launchToken;
351             launchedActivityAppRecordRequiredAbi = launchedActivity.app == null
352                     ? null
353                     : launchedActivity.app.getRequiredAbi();
354             reason = info.mReason;
355             startingWindowDelayMs = info.mStartingWindowDelayMs;
356             bindApplicationDelayMs = info.mBindApplicationDelayMs;
357             windowsDrawnDelayMs = info.mWindowsDrawnDelayMs;
358             type = info.mTransitionType;
359             processRecord = launchedActivity.app;
360             processName = launchedActivity.processName;
361             userId = launchedActivity.mUserId;
362             launchedActivityShortComponentName = launchedActivity.shortComponentName;
363             activityRecordIdHashCode = System.identityHashCode(launchedActivity);
364             this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
365         }
366 
getLaunchState()367         @WaitResult.LaunchState int getLaunchState() {
368             switch (type) {
369                 case TYPE_TRANSITION_WARM_LAUNCH:
370                     return LAUNCH_STATE_WARM;
371                 case TYPE_TRANSITION_HOT_LAUNCH:
372                     return LAUNCH_STATE_HOT;
373                 case TYPE_TRANSITION_COLD_LAUNCH:
374                     return LAUNCH_STATE_COLD;
375                 default:
376                     return -1;
377             }
378         }
379     }
380 
ActivityMetricsLogger(ActivityStackSupervisor supervisor, Looper looper)381     ActivityMetricsLogger(ActivityStackSupervisor supervisor, Looper looper) {
382         mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
383         mSupervisor = supervisor;
384         mLaunchObserver = new LaunchObserverRegistryImpl(looper);
385     }
386 
logWindowState()387     void logWindowState() {
388         final long now = SystemClock.elapsedRealtime() / 1000;
389         if (mWindowState != WINDOW_STATE_INVALID) {
390             // We log even if the window state hasn't changed, because the user might remain in
391             // home/fullscreen move forever and we would like to track this kind of behavior
392             // too.
393             mMetricsLogger.count(TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState],
394                     (int) (now - mLastLogTimeSecs));
395         }
396         mLastLogTimeSecs = now;
397 
398         mWindowState = WINDOW_STATE_INVALID;
399         ActivityStack stack =
400                 mSupervisor.mRootWindowContainer.getTopDisplayFocusedStack();
401         if (stack == null) {
402             return;
403         }
404 
405         if (stack.isActivityTypeAssistant()) {
406             mWindowState = WINDOW_STATE_ASSISTANT;
407             return;
408         }
409 
410         @WindowingMode int windowingMode = stack.getWindowingMode();
411         if (windowingMode == WINDOWING_MODE_PINNED) {
412             stack = mSupervisor.mRootWindowContainer.findStackBehind(stack);
413             windowingMode = stack.getWindowingMode();
414         }
415         switch (windowingMode) {
416             case WINDOWING_MODE_FULLSCREEN:
417                 mWindowState = WINDOW_STATE_STANDARD;
418                 break;
419             case WINDOWING_MODE_SPLIT_SCREEN_PRIMARY:
420             case WINDOWING_MODE_SPLIT_SCREEN_SECONDARY:
421                 mWindowState = WINDOW_STATE_SIDE_BY_SIDE;
422                 break;
423             case WINDOWING_MODE_FREEFORM:
424                 mWindowState = WINDOW_STATE_FREEFORM;
425                 break;
426             case WINDOWING_MODE_MULTI_WINDOW:
427                 mWindowState = WINDOW_STATE_MULTI_WINDOW;
428                 break;
429             default:
430                 if (windowingMode != WINDOWING_MODE_UNDEFINED) {
431                     throw new IllegalStateException("Unknown windowing mode for stack=" + stack
432                             + " windowingMode=" + windowingMode);
433                 }
434         }
435     }
436 
437     /** @return Non-null {@link TransitionInfo} if the activity is found in an active transition. */
438     @Nullable
getActiveTransitionInfo(WindowContainer wc)439     private TransitionInfo getActiveTransitionInfo(WindowContainer wc) {
440         for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
441             final TransitionInfo info = mTransitionInfoList.get(i);
442             if (info.contains(wc)) {
443                 return info;
444             }
445         }
446         return null;
447     }
448 
449     /**
450      * This method should be only used by starting recents and starting from recents, or internal
451      * tests. Because it doesn't lookup caller and always creates a new launching state.
452      *
453      * @see #notifyActivityLaunching(Intent, ActivityRecord, int)
454      */
notifyActivityLaunching(Intent intent)455     LaunchingState notifyActivityLaunching(Intent intent) {
456         return notifyActivityLaunching(intent, null /* caller */, IGNORE_CALLER);
457     }
458 
459     /**
460      * If the caller is found in an active transition, it will be considered as consecutive launch
461      * and coalesced into the active transition.
462      *
463      * @see #notifyActivityLaunching(Intent, ActivityRecord, int)
464      */
notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller)465     LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller) {
466         return notifyActivityLaunching(intent, caller, Binder.getCallingUid());
467     }
468 
469     /**
470      * Notifies the tracker at the earliest possible point when we are starting to launch an
471      * activity. The caller must ensure that {@link #notifyActivityLaunched} will be called later
472      * with the returned {@link LaunchingState}.
473      */
notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller, int callingUid)474     private LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller,
475             int callingUid) {
476         final long transitionStartTimeNs = SystemClock.elapsedRealtimeNanos();
477         TransitionInfo existingInfo = null;
478         if (callingUid != IGNORE_CALLER) {
479             // Associate the launching event to an active transition if the caller is found in its
480             // launched activities.
481             for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
482                 final TransitionInfo info = mTransitionInfoList.get(i);
483                 if (caller != null && info.contains(caller)) {
484                     existingInfo = info;
485                     break;
486                 }
487                 if (existingInfo == null && callingUid == info.mLastLaunchedActivity.getUid()) {
488                     // Fallback to check the most recent matched uid for the case that the caller is
489                     // not an activity.
490                     existingInfo = info;
491                 }
492             }
493         }
494         if (DEBUG_METRICS) {
495             Slog.i(TAG, "notifyActivityLaunching intent=" + intent
496                     + " existingInfo=" + existingInfo);
497         }
498 
499         if (existingInfo == null) {
500             // Only notify the observer for a new launching event.
501             launchObserverNotifyIntentStarted(intent, transitionStartTimeNs);
502             final LaunchingState launchingState = new LaunchingState();
503             launchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
504             return launchingState;
505         }
506         existingInfo.mLaunchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
507         return existingInfo.mLaunchingState;
508     }
509 
510     /**
511      * Notifies the tracker that the activity is actually launching.
512      *
513      * @param launchingState The launching state to track the new or active transition.
514      * @param resultCode One of the {@link android.app.ActivityManager}.START_* flags, indicating
515      *                   the result of the launch.
516      * @param launchedActivity The activity that is being launched
517      */
notifyActivityLaunched(@onNull LaunchingState launchingState, int resultCode, @Nullable ActivityRecord launchedActivity)518     void notifyActivityLaunched(@NonNull LaunchingState launchingState, int resultCode,
519             @Nullable ActivityRecord launchedActivity) {
520         if (launchedActivity == null) {
521             // The launch is aborted, e.g. intent not resolved, class not found.
522             abort(null /* info */, "nothing launched");
523             return;
524         }
525 
526         final WindowProcessController processRecord = launchedActivity.app != null
527                 ? launchedActivity.app
528                 : mSupervisor.mService.getProcessController(
529                         launchedActivity.processName, launchedActivity.info.applicationInfo.uid);
530         // Whether the process that will contains the activity is already running.
531         final boolean processRunning = processRecord != null;
532         // We consider this a "process switch" if the process of the activity that gets launched
533         // didn't have an activity that was in started state. In this case, we assume that lot
534         // of caches might be purged so the time until it produces the first frame is very
535         // interesting.
536         final boolean processSwitch = !processRunning
537                 || !processRecord.hasStartedActivity(launchedActivity);
538 
539         final TransitionInfo info = launchingState.mAssociatedTransitionInfo;
540         if (DEBUG_METRICS) {
541             Slog.i(TAG, "notifyActivityLaunched" + " resultCode=" + resultCode
542                     + " launchedActivity=" + launchedActivity + " processRunning=" + processRunning
543                     + " processSwitch=" + processSwitch + " info=" + info);
544         }
545 
546         if (launchedActivity.mDrawn) {
547             // Launched activity is already visible. We cannot measure windows drawn delay.
548             abort(info, "launched activity already visible");
549             return;
550         }
551 
552         if (info != null
553                 && info.mLastLaunchedActivity.mDisplayContent == launchedActivity.mDisplayContent) {
554             // If we are already in an existing transition on the same display, only update the
555             // activity name, but not the other attributes.
556 
557             if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched update launched activity");
558             // Coalesce multiple (trampoline) activities from a single sequence together.
559             info.setLatestLaunchedActivity(launchedActivity);
560             return;
561         }
562 
563         final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState,
564                 processRunning, processSwitch, resultCode);
565         if (newInfo == null) {
566             abort(info, "unrecognized launch");
567             return;
568         }
569 
570         if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
571         // A new launch sequence has begun. Start tracking it.
572         mTransitionInfoList.add(newInfo);
573         mLastTransitionInfo.put(launchedActivity, newInfo);
574         startLaunchTrace(newInfo);
575         if (newInfo.isInterestingToLoggerAndObserver()) {
576             launchObserverNotifyActivityLaunched(newInfo);
577         } else {
578             // As abort for no process switch.
579             launchObserverNotifyIntentFailed();
580         }
581     }
582 
583     /**
584      * Notifies the tracker that all windows of the app have been drawn.
585      *
586      * @return Non-null info if the activity was pending to draw, otherwise it might have been set
587      *         to invisible (removed from active transition) or it was already drawn.
588      */
589     @Nullable
notifyWindowsDrawn(@onNull ActivityRecord r, long timestampNs)590     TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r, long timestampNs) {
591         if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn " + r);
592 
593         final TransitionInfo info = getActiveTransitionInfo(r);
594         if (info == null || info.allDrawn()) {
595             if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn no activity to be drawn");
596             return null;
597         }
598         // Always calculate the delay because the caller may need to know the individual drawn time.
599         info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs);
600         info.removePendingDrawActivity(r);
601         final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
602         if (info.mLoggedTransitionStarting && info.allDrawn()) {
603             done(false /* abort */, info, "notifyWindowsDrawn - all windows drawn", timestampNs);
604         }
605         return infoSnapshot;
606     }
607 
608     /**
609      * Notifies the tracker that the starting window was drawn.
610      */
notifyStartingWindowDrawn(@onNull ActivityRecord r)611     void notifyStartingWindowDrawn(@NonNull ActivityRecord r) {
612         final TransitionInfo info = getActiveTransitionInfo(r);
613         if (info == null || info.mLoggedStartingWindowDrawn) {
614             return;
615         }
616         if (DEBUG_METRICS) Slog.i(TAG, "notifyStartingWindowDrawn " + r);
617         info.mLoggedStartingWindowDrawn = true;
618         info.mStartingWindowDelayMs = info.calculateDelay(SystemClock.elapsedRealtimeNanos());
619     }
620 
621     /**
622      * Notifies the tracker that the app transition is starting.
623      *
624      * @param activityToReason A map from activity to a reason integer, which must be on of
625      *                         ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
626      */
notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason)627     void notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason) {
628         if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
629 
630         final long timestampNs = SystemClock.elapsedRealtimeNanos();
631         for (int index = activityToReason.size() - 1; index >= 0; index--) {
632             final WindowContainer wc = activityToReason.keyAt(index);
633             final TransitionInfo info = getActiveTransitionInfo(wc);
634             if (info == null || info.mLoggedTransitionStarting) {
635                 // Ignore any subsequent notifyTransitionStarting.
636                 continue;
637             }
638             if (DEBUG_METRICS) {
639                 Slog.i(TAG, "notifyTransitionStarting activity=" + wc + " info=" + info);
640             }
641 
642             info.mCurrentTransitionDelayMs = info.calculateDelay(timestampNs);
643             info.mReason = activityToReason.valueAt(index);
644             info.mLoggedTransitionStarting = true;
645             if (info.allDrawn()) {
646                 done(false /* abort */, info, "notifyTransitionStarting - all windows drawn",
647                         timestampNs);
648             }
649         }
650     }
651 
652     /** Makes sure that the reference to the removed activity is cleared. */
notifyActivityRemoved(@onNull ActivityRecord r)653     void notifyActivityRemoved(@NonNull ActivityRecord r) {
654         mLastTransitionInfo.remove(r);
655     }
656 
657     /**
658      * Notifies the tracker that the visibility of an app is changing.
659      *
660      * @param r the app that is changing its visibility
661      */
notifyVisibilityChanged(@onNull ActivityRecord r)662     void notifyVisibilityChanged(@NonNull ActivityRecord r) {
663         final TransitionInfo info = getActiveTransitionInfo(r);
664         if (info == null) {
665             return;
666         }
667         if (DEBUG_METRICS) {
668             Slog.i(TAG, "notifyVisibilityChanged " + r + " visible=" + r.mVisibleRequested
669                     + " state=" + r.getState() + " finishing=" + r.finishing);
670         }
671         if (!r.mVisibleRequested || r.finishing) {
672             info.removePendingDrawActivity(r);
673         }
674         if (info.mLastLaunchedActivity != r) {
675             return;
676         }
677         // The activity and its task are passed separately because the activity may be removed from
678         // the task later.
679         r.mAtmService.mH.sendMessage(PooledLambda.obtainMessage(
680                 ActivityMetricsLogger::checkVisibility, this, r.getTask(), r));
681     }
682 
683     /** @return {@code true} if the given task has an activity will be drawn. */
hasActivityToBeDrawn(Task t)684     private static boolean hasActivityToBeDrawn(Task t) {
685         return t.forAllActivities((r) -> r.mVisibleRequested && !r.mDrawn && !r.finishing);
686     }
687 
checkVisibility(Task t, ActivityRecord r)688     private void checkVisibility(Task t, ActivityRecord r) {
689         synchronized (mSupervisor.mService.mGlobalLock) {
690 
691             final TransitionInfo info = getActiveTransitionInfo(r);
692 
693             // If we have an active transition that's waiting on a certain activity that will be
694             // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary.
695 
696             // We have no active transitions.
697             if (info == null) {
698                 return;
699             }
700 
701             // The notified activity whose visibility changed is no longer the launched activity.
702             // We can still wait to get onWindowsDrawn.
703             if (info.mLastLaunchedActivity != r) {
704                 return;
705             }
706 
707             // If the task of the launched activity contains any activity to be drawn, then the
708             // window drawn event should report later to complete the transition. Otherwise all
709             // activities in this task may be finished, invisible or drawn, so the transition event
710             // should be cancelled.
711             if (hasActivityToBeDrawn(t)) {
712                 return;
713             }
714 
715             if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible activity=" + r);
716             logAppTransitionCancel(info);
717             abort(info, "notifyVisibilityChanged to invisible");
718         }
719     }
720 
721     /**
722      * Notifies the tracker that we called immediately before we call bindApplication on the client.
723      *
724      * @param appInfo The client into which we'll call bindApplication.
725      */
notifyBindApplication(ApplicationInfo appInfo)726     void notifyBindApplication(ApplicationInfo appInfo) {
727         for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
728             final TransitionInfo info = mTransitionInfoList.get(i);
729 
730             // App isn't attached to record yet, so match with info.
731             if (info.mLastLaunchedActivity.info.applicationInfo == appInfo) {
732                 info.mBindApplicationDelayMs = info.calculateCurrentDelay();
733             }
734         }
735     }
736 
737     /** Aborts tracking of current launch metrics. */
abort(TransitionInfo info, String cause)738     private void abort(TransitionInfo info, String cause) {
739         done(true /* abort */, info, cause, 0L /* timestampNs */);
740     }
741 
742     /** Called when the given transition (info) is no longer active. */
done(boolean abort, @Nullable TransitionInfo info, String cause, long timestampNs)743     private void done(boolean abort, @Nullable TransitionInfo info, String cause,
744             long timestampNs) {
745         if (DEBUG_METRICS) {
746             Slog.i(TAG, "done abort=" + abort + " cause=" + cause + " timestamp=" + timestampNs
747                     + " info=" + info);
748         }
749         if (info == null) {
750             launchObserverNotifyIntentFailed();
751             return;
752         }
753 
754         stopLaunchTrace(info);
755         if (abort) {
756             launchObserverNotifyActivityLaunchCancelled(info);
757         } else {
758             if (info.isInterestingToLoggerAndObserver()) {
759                 launchObserverNotifyActivityLaunchFinished(info, timestampNs);
760             }
761             logAppTransitionFinished(info);
762         }
763         info.mPendingDrawActivities.clear();
764         mTransitionInfoList.remove(info);
765     }
766 
logAppTransitionCancel(TransitionInfo info)767     private void logAppTransitionCancel(TransitionInfo info) {
768         final int type = info.mTransitionType;
769         final ActivityRecord activity = info.mLastLaunchedActivity;
770         final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
771         builder.setPackageName(activity.packageName);
772         builder.setType(type);
773         builder.addTaggedData(FIELD_CLASS_NAME, activity.info.name);
774         mMetricsLogger.write(builder);
775         FrameworkStatsLog.write(
776                 FrameworkStatsLog.APP_START_CANCELED,
777                 activity.info.applicationInfo.uid,
778                 activity.packageName,
779                 convertAppStartTransitionType(type),
780                 activity.info.name);
781         if (DEBUG_METRICS) {
782             Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)",
783                     activity.info.applicationInfo.uid,
784                     activity.packageName,
785                     convertAppStartTransitionType(type),
786                     activity.info.name));
787         }
788     }
789 
logAppTransitionFinished(@onNull TransitionInfo info)790     private void logAppTransitionFinished(@NonNull TransitionInfo info) {
791         if (DEBUG_METRICS) Slog.i(TAG, "logging finished transition " + info);
792 
793         // Take a snapshot of the transition info before sending it to the handler for logging.
794         // This will avoid any races with other operations that modify the ActivityRecord.
795         final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
796         if (info.isInterestingToLoggerAndObserver()) {
797             BackgroundThread.getHandler().post(() -> logAppTransition(
798                     info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs,
799                     infoSnapshot));
800         }
801         BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
802         if (info.mPendingFullyDrawn != null) {
803             info.mPendingFullyDrawn.run();
804         }
805 
806         info.mLastLaunchedActivity.info.launchToken = null;
807     }
808 
809     // This gets called on a background thread without holding the activity manager lock.
logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs, TransitionInfoSnapshot info)810     private void logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs,
811             TransitionInfoSnapshot info) {
812         final LogMaker builder = new LogMaker(APP_TRANSITION);
813         builder.setPackageName(info.packageName);
814         builder.setType(info.type);
815         builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName);
816         final boolean isInstantApp = info.applicationInfo.isInstantApp();
817         if (info.launchedActivityLaunchedFromPackage != null) {
818             builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME,
819                     info.launchedActivityLaunchedFromPackage);
820         }
821         String launchToken = info.launchedActivityLaunchToken;
822         if (launchToken != null) {
823             builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, launchToken);
824         }
825         builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0);
826         builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS,
827                 currentTransitionDeviceUptime);
828         builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs);
829         builder.setSubtype(info.reason);
830         if (info.startingWindowDelayMs != INVALID_DELAY) {
831             builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
832                     info.startingWindowDelayMs);
833         }
834         if (info.bindApplicationDelayMs != INVALID_DELAY) {
835             builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS,
836                     info.bindApplicationDelayMs);
837         }
838         builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs);
839         final ArtManagerInternal artManagerInternal = getArtManagerInternal();
840         final PackageOptimizationInfo packageOptimizationInfo =
841                 (artManagerInternal == null) || (info.launchedActivityAppRecordRequiredAbi == null)
842                 ? PackageOptimizationInfo.createWithNoInfo()
843                 : artManagerInternal.getPackageOptimizationInfo(
844                         info.applicationInfo,
845                         info.launchedActivityAppRecordRequiredAbi,
846                         info.launchedActivityName);
847         builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON,
848                 packageOptimizationInfo.getCompilationReason());
849         builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER,
850                 packageOptimizationInfo.getCompilationFilter());
851         mMetricsLogger.write(builder);
852         FrameworkStatsLog.write(
853                 FrameworkStatsLog.APP_START_OCCURRED,
854                 info.applicationInfo.uid,
855                 info.packageName,
856                 convertAppStartTransitionType(info.type),
857                 info.launchedActivityName,
858                 info.launchedActivityLaunchedFromPackage,
859                 isInstantApp,
860                 currentTransitionDeviceUptime * 1000,
861                 info.reason,
862                 currentTransitionDelayMs,
863                 info.startingWindowDelayMs,
864                 info.bindApplicationDelayMs,
865                 info.windowsDrawnDelayMs,
866                 launchToken,
867                 packageOptimizationInfo.getCompilationReason(),
868                 packageOptimizationInfo.getCompilationFilter());
869 
870         if (DEBUG_METRICS) {
871             Slog.i(TAG, String.format("APP_START_OCCURRED(%s, %s, %s, %s, %s)",
872                     info.applicationInfo.uid,
873                     info.packageName,
874                     convertAppStartTransitionType(info.type),
875                     info.launchedActivityName,
876                     info.launchedActivityLaunchedFromPackage));
877         }
878 
879 
880         logAppStartMemoryStateCapture(info);
881     }
882 
logAppDisplayed(TransitionInfoSnapshot info)883     private void logAppDisplayed(TransitionInfoSnapshot info) {
884         if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
885             return;
886         }
887 
888         EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME,
889                 info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,
890                 info.windowsDrawnDelayMs);
891 
892         StringBuilder sb = mStringBuilder;
893         sb.setLength(0);
894         sb.append("Displayed ");
895         sb.append(info.launchedActivityShortComponentName);
896         sb.append(": ");
897         TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
898         Log.i(TAG, sb.toString());
899     }
900 
convertAppStartTransitionType(int tronType)901     private int convertAppStartTransitionType(int tronType) {
902         if (tronType == TYPE_TRANSITION_COLD_LAUNCH) {
903             return FrameworkStatsLog.APP_START_OCCURRED__TYPE__COLD;
904         }
905         if (tronType == TYPE_TRANSITION_WARM_LAUNCH) {
906             return FrameworkStatsLog.APP_START_OCCURRED__TYPE__WARM;
907         }
908         if (tronType == TYPE_TRANSITION_HOT_LAUNCH) {
909             return FrameworkStatsLog.APP_START_OCCURRED__TYPE__HOT;
910         }
911         return FrameworkStatsLog.APP_START_OCCURRED__TYPE__UNKNOWN;
912     }
913 
914     /** @return the last known window drawn delay of the given activity. */
getLastDrawnDelayMs(ActivityRecord r)915     int getLastDrawnDelayMs(ActivityRecord r) {
916         final TransitionInfo info = mLastTransitionInfo.get(r);
917         return info != null ? info.mWindowsDrawnDelayMs : INVALID_DELAY;
918     }
919 
920     /** @see android.app.Activity#reportFullyDrawn */
logAppTransitionReportedDrawn(ActivityRecord r, boolean restoredFromBundle)921     TransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
922             boolean restoredFromBundle) {
923         final TransitionInfo info = mLastTransitionInfo.get(r);
924         if (info == null) {
925             return null;
926         }
927         if (!info.allDrawn() && info.mPendingFullyDrawn == null) {
928             // There are still undrawn activities, postpone reporting fully drawn until all of its
929             // windows are drawn. So that is closer to an usable state.
930             info.mPendingFullyDrawn = () -> {
931                 logAppTransitionReportedDrawn(r, restoredFromBundle);
932                 info.mPendingFullyDrawn = null;
933             };
934             return null;
935         }
936 
937         final long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
938         final long startupTimeMs = info.mPendingFullyDrawn != null
939                 ? info.mWindowsDrawnDelayMs
940                 : TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - info.mTransitionStartTimeNs);
941         final TransitionInfoSnapshot infoSnapshot =
942                 new TransitionInfoSnapshot(info, r, (int) startupTimeMs);
943         BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));
944 
945         if (!info.isInterestingToLoggerAndObserver()) {
946             return infoSnapshot;
947         }
948 
949         // Record the handling of the reportFullyDrawn callback in the trace system. This is not
950         // actually used to trace this function, but instead the logical task that this function
951         // fullfils (handling reportFullyDrawn() callbacks).
952         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
953                 "ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName);
954 
955         final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
956         builder.setPackageName(r.packageName);
957         builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
958         builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
959         builder.setType(restoredFromBundle
960                 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
961                 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
962         builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,
963                 info.mProcessRunning ? 1 : 0);
964         mMetricsLogger.write(builder);
965         FrameworkStatsLog.write(
966                 FrameworkStatsLog.APP_START_FULLY_DRAWN,
967                 info.mLastLaunchedActivity.info.applicationInfo.uid,
968                 info.mLastLaunchedActivity.packageName,
969                 restoredFromBundle
970                         ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
971                         : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
972                 info.mLastLaunchedActivity.info.name,
973                 info.mProcessRunning,
974                 startupTimeMs);
975 
976         // Ends the trace started at the beginning of this function. This is located here to allow
977         // the trace slice to have a noticable duration.
978         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
979 
980         // Notify reportFullyDrawn event.
981         launchObserverNotifyReportFullyDrawn(r, currentTimestampNs);
982 
983         return infoSnapshot;
984     }
985 
logAppFullyDrawn(TransitionInfoSnapshot info)986     private void logAppFullyDrawn(TransitionInfoSnapshot info) {
987         if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
988             return;
989         }
990 
991         StringBuilder sb = mStringBuilder;
992         sb.setLength(0);
993         sb.append("Fully drawn ");
994         sb.append(info.launchedActivityShortComponentName);
995         sb.append(": ");
996         TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb);
997         Log.i(TAG, sb.toString());
998     }
999 
logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp, int callingUid, String callingPackage, int callingUidProcState, boolean callingUidHasAnyVisibleWindow, int realCallingUid, int realCallingUidProcState, boolean realCallingUidHasAnyVisibleWindow, boolean comingFromPendingIntent)1000     void logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp,
1001             int callingUid, String callingPackage, int callingUidProcState,
1002             boolean callingUidHasAnyVisibleWindow,
1003             int realCallingUid, int realCallingUidProcState,
1004             boolean realCallingUidHasAnyVisibleWindow,
1005             boolean comingFromPendingIntent) {
1006 
1007         final long nowElapsed = SystemClock.elapsedRealtime();
1008         final long nowUptime = SystemClock.uptimeMillis();
1009         final LogMaker builder = new LogMaker(ACTION_ACTIVITY_START);
1010         builder.setTimestamp(System.currentTimeMillis());
1011         builder.addTaggedData(FIELD_CALLING_UID, callingUid);
1012         builder.addTaggedData(FIELD_CALLING_PACKAGE_NAME, callingPackage);
1013         builder.addTaggedData(FIELD_CALLING_UID_PROC_STATE,
1014                 processStateAmToProto(callingUidProcState));
1015         builder.addTaggedData(FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
1016                 callingUidHasAnyVisibleWindow ? 1 : 0);
1017         builder.addTaggedData(FIELD_REAL_CALLING_UID, realCallingUid);
1018         builder.addTaggedData(FIELD_REAL_CALLING_UID_PROC_STATE,
1019                 processStateAmToProto(realCallingUidProcState));
1020         builder.addTaggedData(FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
1021                 realCallingUidHasAnyVisibleWindow ? 1 : 0);
1022         builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0);
1023         if (intent != null) {
1024             builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction());
1025             ComponentName component = intent.getComponent();
1026             if (component != null) {
1027                 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME,
1028                         component.flattenToShortString());
1029             }
1030         }
1031         if (callerApp != null) {
1032             builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName);
1033             builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE,
1034                     processStateAmToProto(callerApp.getCurrentProcState()));
1035             builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES,
1036                     callerApp.hasClientActivities() ? 1 : 0);
1037             builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES,
1038                     callerApp.hasForegroundServices() ? 1 : 0);
1039             builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES,
1040                     callerApp.hasForegroundActivities() ? 1 : 0);
1041             builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0);
1042             builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI,
1043                     callerApp.hasOverlayUi() ? 1 : 0);
1044             builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN,
1045                     callerApp.hasPendingUiClean() ? 1 : 0);
1046             if (callerApp.getInteractionEventTime() != 0) {
1047                 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT,
1048                         (nowElapsed - callerApp.getInteractionEventTime()));
1049             }
1050             if (callerApp.getFgInteractionTime() != 0) {
1051                 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION,
1052                         (nowElapsed - callerApp.getFgInteractionTime()));
1053             }
1054             if (callerApp.getWhenUnimportant() != 0) {
1055                 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT,
1056                         (nowUptime - callerApp.getWhenUnimportant()));
1057             }
1058         }
1059         mMetricsLogger.write(builder);
1060     }
1061 
logAppStartMemoryStateCapture(TransitionInfoSnapshot info)1062     private void logAppStartMemoryStateCapture(TransitionInfoSnapshot info) {
1063         if (info.processRecord == null) {
1064             if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null");
1065             return;
1066         }
1067 
1068         final int pid = info.processRecord.getPid();
1069         final int uid = info.applicationInfo.uid;
1070         final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid);
1071         if (memoryStat == null) {
1072             if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null");
1073             return;
1074         }
1075 
1076         FrameworkStatsLog.write(
1077                 FrameworkStatsLog.APP_START_MEMORY_STATE_CAPTURED,
1078                 uid,
1079                 info.processName,
1080                 info.launchedActivityName,
1081                 memoryStat.pgfault,
1082                 memoryStat.pgmajfault,
1083                 memoryStat.rssInBytes,
1084                 memoryStat.cacheInBytes,
1085                 memoryStat.swapInBytes);
1086     }
1087 
getArtManagerInternal()1088     private ArtManagerInternal getArtManagerInternal() {
1089         if (mArtManagerInternal == null) {
1090             // Note that this may be null.
1091             // ArtManagerInternal is registered during PackageManagerService
1092             // initialization which happens after ActivityManagerService.
1093             mArtManagerInternal = LocalServices.getService(ArtManagerInternal.class);
1094         }
1095         return mArtManagerInternal;
1096     }
1097 
1098     /** Starts trace for an activity is actually launching. */
startLaunchTrace(@onNull TransitionInfo info)1099     private void startLaunchTrace(@NonNull TransitionInfo info) {
1100         if (DEBUG_METRICS) Slog.i(TAG, "startLaunchTrace " + info);
1101         if (!Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
1102             return;
1103         }
1104         info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName;
1105         Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
1106                 (int) info.mTransitionStartTimeNs /* cookie */);
1107     }
1108 
1109     /** Stops trace for the launch is completed or cancelled. */
stopLaunchTrace(@onNull TransitionInfo info)1110     private void stopLaunchTrace(@NonNull TransitionInfo info) {
1111         if (DEBUG_METRICS) Slog.i(TAG, "stopLaunchTrace " + info);
1112         if (info.mLaunchTraceName == null) {
1113             return;
1114         }
1115         Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
1116                 (int) info.mTransitionStartTimeNs /* cookie */);
1117         info.mLaunchTraceName = null;
1118     }
1119 
getLaunchObserverRegistry()1120     public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() {
1121         return mLaunchObserver;
1122     }
1123 
1124     /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */
launchObserverNotifyIntentStarted(Intent intent, long timestampNs)1125     private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) {
1126         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1127                 "MetricsLogger:launchObserverNotifyIntentStarted");
1128 
1129         // Beginning a launch is timing sensitive and so should be observed as soon as possible.
1130         mLaunchObserver.onIntentStarted(intent, timestampNs);
1131 
1132         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1133     }
1134 
1135     /**
1136      * Notify the {@link ActivityMetricsLaunchObserver} that the previous launch sequence has
1137      * aborted due to intent failure (e.g. intent resolve failed or security error, etc) or
1138      * intent being delivered to the top running activity.
1139      */
launchObserverNotifyIntentFailed()1140     private void launchObserverNotifyIntentFailed() {
1141        Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1142                 "MetricsLogger:launchObserverNotifyIntentFailed");
1143 
1144         mLaunchObserver.onIntentFailed();
1145 
1146         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1147     }
1148 
1149     /**
1150      * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1151      * has started.
1152      */
launchObserverNotifyActivityLaunched(TransitionInfo info)1153     private void launchObserverNotifyActivityLaunched(TransitionInfo info) {
1154         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1155                 "MetricsLogger:launchObserverNotifyActivityLaunched");
1156 
1157         @ActivityMetricsLaunchObserver.Temperature int temperature =
1158                 convertTransitionTypeToLaunchObserverTemperature(info.mTransitionType);
1159 
1160         // Beginning a launch is timing sensitive and so should be observed as soon as possible.
1161         mLaunchObserver.onActivityLaunched(convertActivityRecordToProto(info.mLastLaunchedActivity),
1162                 temperature);
1163 
1164         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1165     }
1166 
1167     /**
1168      * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event.
1169      */
launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs)1170     private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) {
1171         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1172             "MetricsLogger:launchObserverNotifyReportFullyDrawn");
1173         mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs);
1174         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1175     }
1176 
1177     /**
1178      * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is
1179      * cancelled.
1180      */
launchObserverNotifyActivityLaunchCancelled(TransitionInfo info)1181     private void launchObserverNotifyActivityLaunchCancelled(TransitionInfo info) {
1182         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1183                 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled");
1184 
1185         final @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] activityRecordProto =
1186                 info != null ? convertActivityRecordToProto(info.mLastLaunchedActivity) : null;
1187 
1188         mLaunchObserver.onActivityLaunchCancelled(activityRecordProto);
1189 
1190         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1191     }
1192 
1193     /**
1194      * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1195      * has fully finished (successfully).
1196      */
launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs)1197     private void launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs) {
1198         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1199                 "MetricsLogger:launchObserverNotifyActivityLaunchFinished");
1200 
1201         mLaunchObserver.onActivityLaunchFinished(
1202                 convertActivityRecordToProto(info.mLastLaunchedActivity), timestampNs);
1203 
1204         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1205     }
1206 
1207     @VisibleForTesting
1208     static @ActivityMetricsLaunchObserver.ActivityRecordProto byte[]
convertActivityRecordToProto(ActivityRecord record)1209             convertActivityRecordToProto(ActivityRecord record) {
1210         // May take non-negligible amount of time to convert ActivityRecord into a proto,
1211         // so track the time.
1212         Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1213                 "MetricsLogger:convertActivityRecordToProto");
1214 
1215         // There does not appear to be a way to 'reset' a ProtoOutputBuffer stream,
1216         // so create a new one every time.
1217         final ProtoOutputStream protoOutputStream =
1218                 new ProtoOutputStream(LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE);
1219         // Write this data out as the top-most ActivityRecordProto (i.e. it is not a sub-object).
1220         record.dumpDebug(protoOutputStream, WindowTraceLogLevel.ALL);
1221         final byte[] bytes = protoOutputStream.getBytes();
1222 
1223         Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1224 
1225         return bytes;
1226     }
1227 
1228     private static @ActivityMetricsLaunchObserver.Temperature int
convertTransitionTypeToLaunchObserverTemperature(int transitionType)1229             convertTransitionTypeToLaunchObserverTemperature(int transitionType) {
1230         switch (transitionType) {
1231             case TYPE_TRANSITION_WARM_LAUNCH:
1232                 return ActivityMetricsLaunchObserver.TEMPERATURE_WARM;
1233             case TYPE_TRANSITION_HOT_LAUNCH:
1234                 return ActivityMetricsLaunchObserver.TEMPERATURE_HOT;
1235             case TYPE_TRANSITION_COLD_LAUNCH:
1236                 return ActivityMetricsLaunchObserver.TEMPERATURE_COLD;
1237             default:
1238                 return -1;
1239         }
1240     }
1241 }
1242