blob: 189b21fb81a6752cdaa60ae50f8be21942c30c69 [file] [log] [blame]
Wale Ogunwale59507092018-10-29 09:00:30 -07001package com.android.server.wm;
Filip Gruszczynski77d94482015-12-11 13:59:52 -08002
Jorim Jaggi3878ca32017-02-02 17:13:05 -08003import static android.app.ActivityManager.START_SUCCESS;
4import static android.app.ActivityManager.START_TASK_TO_FRONT;
Michal Karpinski201bc0c2018-07-20 15:32:00 +01005import static android.app.ActivityManager.processStateAmToProto;
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -08006import static android.app.WaitResult.LAUNCH_STATE_COLD;
7import static android.app.WaitResult.LAUNCH_STATE_HOT;
8import static android.app.WaitResult.LAUNCH_STATE_WARM;
Bryce Lee6c605092017-10-12 11:14:49 -07009import static android.app.WindowConfiguration.WINDOWING_MODE_FREEFORM;
Wale Ogunwale3382ab12017-07-27 08:55:03 -070010import static android.app.WindowConfiguration.WINDOWING_MODE_FULLSCREEN;
Wale Ogunwale194435b2019-12-23 12:56:51 -080011import static android.app.WindowConfiguration.WINDOWING_MODE_MULTI_WINDOW;
Wale Ogunwale3382ab12017-07-27 08:55:03 -070012import static android.app.WindowConfiguration.WINDOWING_MODE_PINNED;
Vishnu Nair132ee832018-09-28 15:00:05 -070013import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_PRIMARY;
Wale Ogunwale926aade2017-08-29 11:24:37 -070014import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_SECONDARY;
15import static android.app.WindowConfiguration.WINDOWING_MODE_UNDEFINED;
Vishnu Nair132ee832018-09-28 15:00:05 -070016
Michal Karpinski201bc0c2018-07-20 15:32:00 +010017import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.ACTION_ACTIVITY_START;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080018import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION;
Jorim Jaggi515dd682017-05-05 15:05:07 +020019import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS;
Todd Kennedy50d946c12017-03-17 13:55:38 -070020import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020021import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080022import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS;
23import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS;
Todd Kennedy50d946c12017-03-17 13:55:38 -070024import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_IS_EPHEMERAL;
Jorim Jaggi4d27b842017-08-17 17:22:26 +020025import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_PROCESS_RUNNING;
26import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN;
27import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN_MS;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080028import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS;
29import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010030import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_PACKAGE_NAME;
31import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID;
32import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
33import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_PROC_STATE;
Jorim Jaggicdfc04e2017-04-28 19:06:24 +020034import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010035import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_COMING_FROM_PENDING_INTENT;
Todd Kennedy50d946c12017-03-17 13:55:38 -070036import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010037import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INTENT_ACTION;
38import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_CUR_PROC_STATE;
39import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES;
40import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES;
41import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES;
42import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_OVERLAY_UI;
43import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_TOP_UI;
44import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION;
45import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT;
46import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT;
47import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PENDING_UI_CLEAN;
48import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PROCESS_NAME;
49import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010050import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
Vishnu Nair132ee832018-09-28 15:00:05 -070051import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_PROC_STATE;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010052import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_SHORT_COMPONENT_NAME;
Calin Juravle759fbda2018-02-20 19:52:30 +000053import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_FILTER;
Vishnu Nair132ee832018-09-28 15:00:05 -070054import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_REASON;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080055import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH;
56import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH;
Jorim Jaggi4d27b842017-08-17 17:22:26 +020057import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE;
58import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080059import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
Ng Zhi Anbbefdec2018-01-30 17:12:39 -080060import static com.android.server.am.MemoryStatUtil.MemoryStat;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +000061import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem;
Vishnu Naira62534b2018-11-09 09:13:22 -080062import static com.android.server.wm.ActivityTaskManagerDebugConfig.DEBUG_METRICS;
63import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_ATM;
64import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_WITH_CLASS_NAME;
Vishnu Nair132ee832018-09-28 15:00:05 -070065import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT;
Jeff Changd136e772019-11-05 20:33:52 +080066import static com.android.server.wm.EventLogTags.WM_ACTIVITY_LAUNCH_TIME;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080067
Riddle Hsufd66d4d2019-11-14 10:35:55 +080068import android.annotation.NonNull;
69import android.annotation.Nullable;
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -080070import android.app.WaitResult;
Igor Murashkin212d06c2018-10-22 16:34:39 -070071import android.app.WindowConfiguration.WindowingMode;
Michal Karpinski319069b2019-03-27 15:46:50 +000072import android.content.ComponentName;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010073import android.content.Intent;
Calin Juravle759fbda2018-02-20 19:52:30 +000074import android.content.pm.ApplicationInfo;
75import android.content.pm.dex.ArtManagerInternal;
76import android.content.pm.dex.PackageOptimizationInfo;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080077import android.metrics.LogMaker;
Riddle Hsufd66d4d2019-11-14 10:35:55 +080078import android.os.Binder;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020079import android.os.Looper;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080080import android.os.SystemClock;
Vishnu Nair132ee832018-09-28 15:00:05 -070081import android.os.Trace;
Riddle Hsufd66d4d2019-11-14 10:35:55 +080082import android.util.ArrayMap;
Vishnu Nair132ee832018-09-28 15:00:05 -070083import android.util.EventLog;
84import android.util.Log;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020085import android.util.Slog;
Vishnu Nair132ee832018-09-28 15:00:05 -070086import android.util.TimeUtils;
Igor Murashkinc0b47e42018-11-07 15:54:18 -080087import android.util.proto.ProtoOutputStream;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080088
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -080089import com.android.internal.annotations.VisibleForTesting;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080090import com.android.internal.logging.MetricsLogger;
Ng Zhi An83473542018-02-20 09:02:14 -080091import com.android.internal.os.BackgroundThread;
Muhammad Qureshi759f92f2020-01-28 10:41:55 -080092import com.android.internal.util.FrameworkStatsLog;
Riddle Hsufd66d4d2019-11-14 10:35:55 +080093import com.android.internal.util.function.pooled.PooledLambda;
Calin Juravle759fbda2018-02-20 19:52:30 +000094import com.android.server.LocalServices;
Louis Changcdec0802019-11-11 11:45:07 +080095
Riddle Hsufd66d4d2019-11-14 10:35:55 +080096import java.util.ArrayList;
97import java.util.LinkedList;
Yan Wang9eac5ec2019-09-30 15:42:18 -070098import java.util.concurrent.TimeUnit;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080099
100/**
Vishnu Nair132ee832018-09-28 15:00:05 -0700101 * 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}.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800104 * <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>
Vishnu Nair132ee832018-09-28 15:00:05 -0700110 * Tests:
Tadashi G. Takaoka28bc3702019-04-23 11:01:48 +0900111 * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800112 */
113class ActivityMetricsLogger {
Jorim Jaggif9704102016-05-05 19:14:22 -0700114
Wale Ogunwale98875612018-10-12 07:53:02 -0700115 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM;
Jorim Jaggif9704102016-05-05 19:14:22 -0700116
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800117 // 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;
Winson Chung83471632016-12-13 11:02:12 -0800122 private static final int WINDOW_STATE_ASSISTANT = 3;
Wale Ogunwale194435b2019-12-23 12:56:51 -0800123 private static final int WINDOW_STATE_MULTI_WINDOW = 4;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800124 private static final int WINDOW_STATE_INVALID = -1;
125
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800126 /**
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;
Vishnu Nair132ee832018-09-28 15:00:05 -0700131 private static final int INVALID_DELAY = -1;
132 private static final int INVALID_TRANSITION_TYPE = -1;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500133
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800134 // 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 = {
Vishnu Nair511d4732020-03-02 17:35:37 -0800137 "window_time_0", "window_time_1", "window_time_2", "window_time_3", "window_time_4"};
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800138
139 private int mWindowState = WINDOW_STATE_STANDARD;
140 private long mLastLogTimeSecs;
141 private final ActivityStackSupervisor mSupervisor;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800142 private final MetricsLogger mMetricsLogger = new MetricsLogger();
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800143
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800144 /** 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<>();
Calin Juravle759fbda2018-02-20 19:52:30 +0000148
149 private ArtManagerInternal mArtManagerInternal;
Vishnu Nair132ee832018-09-28 15:00:05 -0700150 private final StringBuilder mStringBuilder = new StringBuilder();
Calin Juravle759fbda2018-02-20 19:52:30 +0000151
Igor Murashkin212d06c2018-10-22 16:34:39 -0700152 /**
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 */
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800156 private final LaunchObserverRegistryImpl mLaunchObserver;
157 @VisibleForTesting static final int LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE = 512;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700158
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800159 /**
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;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200168
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800169 @VisibleForTesting
170 boolean allDrawn() {
171 return mAssociatedTransitionInfo != null && mAssociatedTransitionInfo.allDrawn();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200172 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000173 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800174
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800175 /** 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;
Riddle Hsue8d3d192019-11-26 18:56:39 +0800195 /** whether the process of the launching activity didn't have any active activity. */
196 final boolean mProcessSwitch;
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800197 /** The activities that should be drawn. */
198 final LinkedList<ActivityRecord> mPendingDrawActivities = new LinkedList<>();
Igor Murashkin212d06c2018-10-22 16:34:39 -0700199 /** The latest activity to have been launched. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800200 @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;
Vishnu Nair132ee832018-09-28 15:00:05 -0700208 /** Elapsed time from when we launch an activity to when its windows are drawn. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800209 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
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800217 /** Non-null if the application has reported drawn but its window hasn't. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800218 @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
224 static TransitionInfo create(@NonNull ActivityRecord r,
Riddle Hsue8d3d192019-11-26 18:56:39 +0800225 @NonNull LaunchingState launchingState, boolean processRunning,
226 boolean processSwitch, int startResult) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800227 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 }
Riddle Hsue8d3d192019-11-26 18:56:39 +0800243 return new TransitionInfo(r, launchingState, transitionType, processRunning,
244 processSwitch);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800245 }
246
247 /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */
248 private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType,
Riddle Hsue8d3d192019-11-26 18:56:39 +0800249 boolean processRunning, boolean processSwitch) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800250 mLaunchingState = launchingState;
251 mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs;
252 mTransitionType = transitionType;
253 mProcessRunning = processRunning;
Riddle Hsue8d3d192019-11-26 18:56:39 +0800254 mProcessSwitch = processSwitch;
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800255 mCurrentTransitionDeviceUptime =
256 (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis());
257 setLatestLaunchedActivity(r);
258 launchingState.mAssociatedTransitionInfo = this;
259 }
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800260
261 /**
262 * Remembers the latest launched activity to represent the final transition. This also
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800263 * tracks the activities that should be drawn, so a consecutive launching sequence can be
264 * coalesced as one event.
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800265 */
266 void setLatestLaunchedActivity(ActivityRecord r) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800267 if (mLastLaunchedActivity == r) {
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800268 return;
269 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800270 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. */
Evan Rosky55bddd82020-01-29 13:07:18 -0800278 boolean contains(WindowContainer wc) {
279 final ActivityRecord r = AppTransitionController.getAppFromContainer(wc);
280 return r != null && (r == mLastLaunchedActivity || mPendingDrawActivities.contains(r));
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800281 }
282
283 /** Called when the activity is drawn or won't be drawn. */
284 void removePendingDrawActivity(ActivityRecord r) {
285 if (DEBUG_METRICS) Slog.i(TAG, "Remove pending draw " + r);
286 mPendingDrawActivities.remove(r);
287 }
288
289 boolean allDrawn() {
290 return mPendingDrawActivities.isEmpty();
291 }
292
Riddle Hsue8d3d192019-11-26 18:56:39 +0800293 /**
294 * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or
295 * LaunchObserver.
296 */
297 boolean isInterestingToLoggerAndObserver() {
298 return mProcessSwitch;
299 }
300
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800301 int calculateCurrentDelay() {
302 return calculateDelay(SystemClock.elapsedRealtimeNanos());
303 }
304
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
311 public String toString() {
312 return "TransitionInfo{" + Integer.toHexString(System.identityHashCode(this))
313 + " a=" + mLastLaunchedActivity + " ua=" + mPendingDrawActivities + "}";
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800314 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800315 }
316
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800317 static final class TransitionInfoSnapshot {
Calin Juravle759fbda2018-02-20 19:52:30 +0000318 final private ApplicationInfo applicationInfo;
Wale Ogunwalef6733932018-06-27 05:14:34 -0700319 final private WindowProcessController processRecord;
Vishnu Nair132ee832018-09-28 15:00:05 -0700320 final String packageName;
321 final String launchedActivityName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000322 final private String launchedActivityLaunchedFromPackage;
323 final private String launchedActivityLaunchToken;
324 final private String launchedActivityAppRecordRequiredAbi;
Vishnu Nair132ee832018-09-28 15:00:05 -0700325 final String launchedActivityShortComponentName;
Ng Zhi An83473542018-02-20 09:02:14 -0800326 final private String processName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000327 final private int reason;
328 final private int startingWindowDelayMs;
329 final private int bindApplicationDelayMs;
Vishnu Nair132ee832018-09-28 15:00:05 -0700330 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;
Calin Juravle759fbda2018-02-20 19:52:30 +0000339
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800340 private TransitionInfoSnapshot(TransitionInfo info) {
341 this(info, info.mLastLaunchedActivity, INVALID_DELAY);
Vishnu Nair132ee832018-09-28 15:00:05 -0700342 }
343
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800344 private TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity,
345 int windowsFullyDrawnDelayMs) {
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700346 applicationInfo = launchedActivity.info.applicationInfo;
Vishnu Nair132ee832018-09-28 15:00:05 -0700347 packageName = launchedActivity.packageName;
348 launchedActivityName = launchedActivity.info.name;
349 launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage;
350 launchedActivityLaunchToken = launchedActivity.info.launchToken;
351 launchedActivityAppRecordRequiredAbi = launchedActivity.app == null
Calin Juravle759fbda2018-02-20 19:52:30 +0000352 ? null
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700353 : launchedActivity.app.getRequiredAbi();
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800354 reason = info.mReason;
355 startingWindowDelayMs = info.mStartingWindowDelayMs;
356 bindApplicationDelayMs = info.mBindApplicationDelayMs;
357 windowsDrawnDelayMs = info.mWindowsDrawnDelayMs;
358 type = info.mTransitionType;
359 processRecord = launchedActivity.app;
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700360 processName = launchedActivity.processName;
Wale Ogunwale8b19de92018-11-29 19:58:26 -0800361 userId = launchedActivity.mUserId;
Vishnu Nair132ee832018-09-28 15:00:05 -0700362 launchedActivityShortComponentName = launchedActivity.shortComponentName;
363 activityRecordIdHashCode = System.identityHashCode(launchedActivity);
364 this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
Calin Juravle759fbda2018-02-20 19:52:30 +0000365 }
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -0800366
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 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000379 }
380
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800381 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Looper looper) {
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800382 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
383 mSupervisor = supervisor;
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800384 mLaunchObserver = new LaunchObserverRegistryImpl(looper);
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800385 }
386
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.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800393 mMetricsLogger.count(TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState],
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800394 (int) (now - mLastLogTimeSecs));
395 }
396 mLastLogTimeSecs = now;
397
Wale Ogunwale926aade2017-08-29 11:24:37 -0700398 mWindowState = WINDOW_STATE_INVALID;
Wale Ogunwaled32da472018-11-16 07:19:28 -0800399 ActivityStack stack =
Louis Chang149d5c82019-12-30 09:47:39 +0800400 mSupervisor.mRootWindowContainer.getTopDisplayFocusedStack();
lumarkf6c4a982018-06-15 15:43:12 +0800401 if (stack == null) {
402 return;
403 }
404
Wale Ogunwale926aade2017-08-29 11:24:37 -0700405 if (stack.isActivityTypeAssistant()) {
406 mWindowState = WINDOW_STATE_ASSISTANT;
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800407 return;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800408 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700409
Igor Murashkin212d06c2018-10-22 16:34:39 -0700410 @WindowingMode int windowingMode = stack.getWindowingMode();
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700411 if (windowingMode == WINDOWING_MODE_PINNED) {
Louis Chang149d5c82019-12-30 09:47:39 +0800412 stack = mSupervisor.mRootWindowContainer.findStackBehind(stack);
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700413 windowingMode = stack.getWindowingMode();
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800414 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700415 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;
Bryce Lee6c605092017-10-12 11:14:49 -0700423 case WINDOWING_MODE_FREEFORM:
Wale Ogunwale926aade2017-08-29 11:24:37 -0700424 mWindowState = WINDOW_STATE_FREEFORM;
425 break;
Wale Ogunwale194435b2019-12-23 12:56:51 -0800426 case WINDOWING_MODE_MULTI_WINDOW:
427 mWindowState = WINDOW_STATE_MULTI_WINDOW;
428 break;
Wale Ogunwale926aade2017-08-29 11:24:37 -0700429 default:
430 if (windowingMode != WINDOWING_MODE_UNDEFINED) {
431 throw new IllegalStateException("Unknown windowing mode for stack=" + stack
432 + " windowingMode=" + windowingMode);
433 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800434 }
435 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500436
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800437 /** @return Non-null {@link TransitionInfo} if the activity is found in an active transition. */
438 @Nullable
Evan Rosky55bddd82020-01-29 13:07:18 -0800439 private TransitionInfo getActiveTransitionInfo(WindowContainer wc) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800440 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
441 final TransitionInfo info = mTransitionInfoList.get(i);
Evan Rosky55bddd82020-01-29 13:07:18 -0800442 if (info.contains(wc)) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800443 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 */
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 */
465 LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller) {
466 return notifyActivityLaunching(intent, caller, Binder.getCallingUid());
467 }
468
Jorim Jaggi275561a2016-02-23 10:11:02 -0500469 /**
470 * Notifies the tracker at the earliest possible point when we are starting to launch an
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800471 * activity. The caller must ensure that {@link #notifyActivityLaunched} will be called later
472 * with the returned {@link LaunchingState}.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500473 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800474 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 }
Igor Murashkin212d06c2018-10-22 16:34:39 -0700494 if (DEBUG_METRICS) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800495 Slog.i(TAG, "notifyActivityLaunching intent=" + intent
496 + " existingInfo=" + existingInfo);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700497 }
498
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800499 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;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800505 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800506 existingInfo.mLaunchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
507 return existingInfo.mLaunchingState;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500508 }
509
510 /**
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700511 * Notifies the tracker that the activity is actually launching.
512 *
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800513 * @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
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700517 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800518 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 }
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700525
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800526 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;
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700532 // 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.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800536 final boolean processSwitch = !processRunning
Wale Ogunwalef6733932018-06-27 05:14:34 -0700537 || !processRecord.hasStartedActivity(launchedActivity);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700538
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800539 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);
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200544 }
545
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800546 if (launchedActivity.mDrawn) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700547 // Launched activity is already visible. We cannot measure windows drawn delay.
Riddle Hsu1063b512019-10-22 21:12:23 +0800548 abort(info, "launched activity already visible");
Vishnu Nairf8accc52018-10-11 10:19:54 -0700549 return;
550 }
551
Riddle Hsu20cf2bc2019-11-27 18:57:50 +0800552 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.
Igor Murashkin212d06c2018-10-22 16:34:39 -0700556
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800557 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched update launched activity");
Igor Murashkin212d06c2018-10-22 16:34:39 -0700558 // Coalesce multiple (trampoline) activities from a single sequence together.
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800559 info.setLatestLaunchedActivity(launchedActivity);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500560 return;
561 }
562
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800563 final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState,
Riddle Hsue8d3d192019-11-26 18:56:39 +0800564 processRunning, processSwitch, resultCode);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800565 if (newInfo == null) {
566 abort(info, "unrecognized launch");
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800567 return;
568 }
569
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200570 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800571 // A new launch sequence has begun. Start tracking it.
572 mTransitionInfoList.add(newInfo);
573 mLastTransitionInfo.put(launchedActivity, newInfo);
574 startLaunchTrace(newInfo);
Riddle Hsue8d3d192019-11-26 18:56:39 +0800575 if (newInfo.isInterestingToLoggerAndObserver()) {
576 launchObserverNotifyActivityLaunched(newInfo);
577 } else {
578 // As abort for no process switch.
579 launchObserverNotifyIntentFailed();
580 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500581 }
582
583 /**
584 * Notifies the tracker that all windows of the app have been drawn.
Riddle Hsueb628a52020-02-14 00:48:51 +0800585 *
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.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500588 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800589 @Nullable
590 TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r, long timestampNs) {
591 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn " + r);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200592
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800593 final TransitionInfo info = getActiveTransitionInfo(r);
594 if (info == null || info.allDrawn()) {
595 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn no activity to be drawn");
Vishnu Nair132ee832018-09-28 15:00:05 -0700596 return null;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500597 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800598 // 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);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500604 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700605 return infoSnapshot;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500606 }
607
608 /**
609 * Notifies the tracker that the starting window was drawn.
610 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800611 void notifyStartingWindowDrawn(@NonNull ActivityRecord r) {
612 final TransitionInfo info = getActiveTransitionInfo(r);
613 if (info == null || info.mLoggedStartingWindowDrawn) {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500614 return;
615 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800616 if (DEBUG_METRICS) Slog.i(TAG, "notifyStartingWindowDrawn " + r);
617 info.mLoggedStartingWindowDrawn = true;
618 info.mStartingWindowDelayMs = info.calculateDelay(SystemClock.elapsedRealtimeNanos());
Jorim Jaggi275561a2016-02-23 10:11:02 -0500619 }
620
621 /**
622 * Notifies the tracker that the app transition is starting.
623 *
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800624 * @param activityToReason A map from activity to a reason integer, which must be on of
625 * ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500626 */
Evan Rosky55bddd82020-01-29 13:07:18 -0800627 void notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200628 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
Igor Murashkin212d06c2018-10-22 16:34:39 -0700629
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800630 final long timestampNs = SystemClock.elapsedRealtimeNanos();
631 for (int index = activityToReason.size() - 1; index >= 0; index--) {
Evan Rosky55bddd82020-01-29 13:07:18 -0800632 final WindowContainer wc = activityToReason.keyAt(index);
633 final TransitionInfo info = getActiveTransitionInfo(wc);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800634 if (info == null || info.mLoggedTransitionStarting) {
635 // Ignore any subsequent notifyTransitionStarting.
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800636 continue;
637 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800638 if (DEBUG_METRICS) {
Evan Rosky55bddd82020-01-29 13:07:18 -0800639 Slog.i(TAG, "notifyTransitionStarting activity=" + wc + " info=" + info);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800640 }
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 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800649 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800650 }
651
652 /** Makes sure that the reference to the removed activity is cleared. */
653 void notifyActivityRemoved(@NonNull ActivityRecord r) {
654 mLastTransitionInfo.remove(r);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500655 }
656
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200657 /**
658 * Notifies the tracker that the visibility of an app is changing.
659 *
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800660 * @param r the app that is changing its visibility
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200661 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800662 void notifyVisibilityChanged(@NonNull ActivityRecord r) {
663 final TransitionInfo info = getActiveTransitionInfo(r);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200664 if (info == null) {
665 return;
666 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800667 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) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200675 return;
676 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800677 // 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));
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200681 }
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200682
Riddle Hsu1063b512019-10-22 21:12:23 +0800683 /** @return {@code true} if the given task has an activity will be drawn. */
Louis Changcdec0802019-11-11 11:45:07 +0800684 private static boolean hasActivityToBeDrawn(Task t) {
Wale Ogunwalea38654f2019-11-17 20:37:15 -0800685 return t.forAllActivities((r) -> r.mVisibleRequested && !r.mDrawn && !r.finishing);
Vishnu Nairb1de42d2019-01-28 09:49:51 -0800686 }
687
Louis Changcdec0802019-11-11 11:45:07 +0800688 private void checkVisibility(Task t, ActivityRecord r) {
Wale Ogunwalec9e57de2018-05-08 14:28:07 -0700689 synchronized (mSupervisor.mService.mGlobalLock) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200690
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800691 final TransitionInfo info = getActiveTransitionInfo(r);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200692
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.
Vishnu Naird15063b2019-06-11 08:08:25 -0700695
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.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800703 if (info.mLastLaunchedActivity != r) {
Vishnu Naird15063b2019-06-11 08:08:25 -0700704 return;
705 }
706
Riddle Hsu1063b512019-10-22 21:12:23 +0800707 // 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)) {
Vishnu Naird15063b2019-06-11 08:08:25 -0700712 return;
713 }
714
715 if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible activity=" + r);
716 logAppTransitionCancel(info);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800717 abort(info, "notifyVisibilityChanged to invisible");
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200718 }
719 }
720
Jorim Jaggi515dd682017-05-05 15:05:07 +0200721 /**
722 * Notifies the tracker that we called immediately before we call bindApplication on the client.
723 *
Wale Ogunwale31913b52018-10-13 08:29:31 -0700724 * @param appInfo The client into which we'll call bindApplication.
Jorim Jaggi515dd682017-05-05 15:05:07 +0200725 */
Wale Ogunwale31913b52018-10-13 08:29:31 -0700726 void notifyBindApplication(ApplicationInfo appInfo) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800727 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
728 final TransitionInfo info = mTransitionInfoList.get(i);
Jorim Jaggi515dd682017-05-05 15:05:07 +0200729
730 // App isn't attached to record yet, so match with info.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800731 if (info.mLastLaunchedActivity.info.applicationInfo == appInfo) {
732 info.mBindApplicationDelayMs = info.calculateCurrentDelay();
Jorim Jaggi515dd682017-05-05 15:05:07 +0200733 }
734 }
735 }
736
Riddle Hsu1063b512019-10-22 21:12:23 +0800737 /** Aborts tracking of current launch metrics. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800738 private void abort(TransitionInfo info, String cause) {
739 done(true /* abort */, info, cause, 0L /* timestampNs */);
Riddle Hsu1063b512019-10-22 21:12:23 +0800740 }
741
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800742 /** Called when the given transition (info) is no longer active. */
743 private void done(boolean abort, @Nullable TransitionInfo info, String cause,
Riddle Hsu1063b512019-10-22 21:12:23 +0800744 long timestampNs) {
Yan Wangd47f90b2019-10-03 19:17:15 -0700745 if (DEBUG_METRICS) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800746 Slog.i(TAG, "done abort=" + abort + " cause=" + cause + " timestamp=" + timestampNs
747 + " info=" + info);
Yan Wangd47f90b2019-10-03 19:17:15 -0700748 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800749 if (info == null) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700750 launchObserverNotifyIntentFailed();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200751 return;
752 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800753
754 stopLaunchTrace(info);
755 if (abort) {
756 launchObserverNotifyActivityLaunchCancelled(info);
757 } else {
Riddle Hsue8d3d192019-11-26 18:56:39 +0800758 if (info.isInterestingToLoggerAndObserver()) {
759 launchObserverNotifyActivityLaunchFinished(info, timestampNs);
760 }
Yan Wang6f0b47d2020-01-02 16:09:30 -0800761 logAppTransitionFinished(info);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800762 }
763 info.mPendingDrawActivities.clear();
764 mTransitionInfoList.remove(info);
765 }
766
767 private void logAppTransitionCancel(TransitionInfo info) {
768 final int type = info.mTransitionType;
769 final ActivityRecord activity = info.mLastLaunchedActivity;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200770 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800771 builder.setPackageName(activity.packageName);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200772 builder.setType(type);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800773 builder.addTaggedData(FIELD_CLASS_NAME, activity.info.name);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200774 mMetricsLogger.write(builder);
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800775 FrameworkStatsLog.write(
776 FrameworkStatsLog.APP_START_CANCELED,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800777 activity.info.applicationInfo.uid,
778 activity.packageName,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000779 convertAppStartTransitionType(type),
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800780 activity.info.name);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700781 if (DEBUG_METRICS) {
782 Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)",
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800783 activity.info.applicationInfo.uid,
784 activity.packageName,
Igor Murashkin212d06c2018-10-22 16:34:39 -0700785 convertAppStartTransitionType(type),
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800786 activity.info.name));
Igor Murashkin212d06c2018-10-22 16:34:39 -0700787 }
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200788 }
789
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800790 private void logAppTransitionFinished(@NonNull TransitionInfo info) {
791 if (DEBUG_METRICS) Slog.i(TAG, "logging finished transition " + info);
Calin Juravle759fbda2018-02-20 19:52:30 +0000792
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800793 // 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);
Riddle Hsue8d3d192019-11-26 18:56:39 +0800796 if (info.isInterestingToLoggerAndObserver()) {
797 BackgroundThread.getHandler().post(() -> logAppTransition(
798 info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs,
799 infoSnapshot));
800 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800801 BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
802 if (info.mPendingFullyDrawn != null) {
803 info.mPendingFullyDrawn.run();
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800804 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800805
806 info.mLastLaunchedActivity.info.launchToken = null;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800807 }
808
Ng Zhi An83473542018-02-20 09:02:14 -0800809 // This gets called on a background thread without holding the activity manager lock.
Calin Juravle759fbda2018-02-20 19:52:30 +0000810 private void logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800811 TransitionInfoSnapshot info) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000812 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);
Vishnu Nair132ee832018-09-28 15:00:05 -0700830 if (info.startingWindowDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000831 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
832 info.startingWindowDelayMs);
833 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700834 if (info.bindApplicationDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000835 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,
yawanng35a00902020-06-11 06:04:16 +0000845 info.launchedActivityAppRecordRequiredAbi,
846 info.launchedActivityName);
Calin Juravle759fbda2018-02-20 19:52:30 +0000847 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON,
848 packageOptimizationInfo.getCompilationReason());
849 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER,
850 packageOptimizationInfo.getCompilationFilter());
851 mMetricsLogger.write(builder);
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800852 FrameworkStatsLog.write(
853 FrameworkStatsLog.APP_START_OCCURRED,
Calin Juravle759fbda2018-02-20 19:52:30 +0000854 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());
Igor Murashkin212d06c2018-10-22 16:34:39 -0700869
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
Ng Zhi An83473542018-02-20 09:02:14 -0800880 logAppStartMemoryStateCapture(info);
Calin Juravle759fbda2018-02-20 19:52:30 +0000881 }
882
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800883 private void logAppDisplayed(TransitionInfoSnapshot info) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700884 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
885 return;
886 }
887
Jeff Changd136e772019-11-05 20:33:52 +0800888 EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME,
Vishnu Nair132ee832018-09-28 15:00:05 -0700889 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
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000901 private int convertAppStartTransitionType(int tronType) {
902 if (tronType == TYPE_TRANSITION_COLD_LAUNCH) {
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800903 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__COLD;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000904 }
905 if (tronType == TYPE_TRANSITION_WARM_LAUNCH) {
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800906 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__WARM;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000907 }
908 if (tronType == TYPE_TRANSITION_HOT_LAUNCH) {
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800909 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__HOT;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000910 }
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800911 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__UNKNOWN;
Riddle Hsuc48c8912019-10-31 13:34:27 +0800912 }
913
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800914 /** @return the last known window drawn delay of the given activity. */
915 int getLastDrawnDelayMs(ActivityRecord r) {
916 final TransitionInfo info = mLastTransitionInfo.get(r);
917 return info != null ? info.mWindowsDrawnDelayMs : INVALID_DELAY;
Riddle Hsuc48c8912019-10-31 13:34:27 +0800918 }
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000919
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800920 /** @see android.app.Activity#reportFullyDrawn */
921 TransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
Vishnu Nair132ee832018-09-28 15:00:05 -0700922 boolean restoredFromBundle) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800923 final TransitionInfo info = mLastTransitionInfo.get(r);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200924 if (info == null) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700925 return null;
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200926 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800927 if (!info.allDrawn() && info.mPendingFullyDrawn == null) {
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800928 // 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.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800930 info.mPendingFullyDrawn = () -> {
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800931 logAppTransitionReportedDrawn(r, restoredFromBundle);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800932 info.mPendingFullyDrawn = null;
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800933 };
934 return null;
935 }
Chris Wailes35c193c2018-10-09 18:12:00 -0700936
Riddle Hsue8d3d192019-11-26 18:56:39 +0800937 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
Chris Wailes35c193c2018-10-09 18:12:00 -0700949 // 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,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800953 "ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName);
Chris Wailes35c193c2018-10-09 18:12:00 -0700954
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200955 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
956 builder.setPackageName(r.packageName);
957 builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000958 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200959 builder.setType(restoredFromBundle
960 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
961 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
962 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800963 info.mProcessRunning ? 1 : 0);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200964 mMetricsLogger.write(builder);
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800965 FrameworkStatsLog.write(
966 FrameworkStatsLog.APP_START_FULLY_DRAWN,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800967 info.mLastLaunchedActivity.info.applicationInfo.uid,
968 info.mLastLaunchedActivity.packageName,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000969 restoredFromBundle
Muhammad Qureshi759f92f2020-01-28 10:41:55 -0800970 ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
971 : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800972 info.mLastLaunchedActivity.info.name,
973 info.mProcessRunning,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000974 startupTimeMs);
Chris Wailes35c193c2018-10-09 18:12:00 -0700975
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
Yan Wang9eac5ec2019-09-30 15:42:18 -0700980 // Notify reportFullyDrawn event.
981 launchObserverNotifyReportFullyDrawn(r, currentTimestampNs);
982
Vishnu Nair132ee832018-09-28 15:00:05 -0700983 return infoSnapshot;
984 }
985
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800986 private void logAppFullyDrawn(TransitionInfoSnapshot info) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700987 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());
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200998 }
999
Michal Karpinski4fd5b842019-01-28 15:13:32 +00001000 void logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp,
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001001 int callingUid, String callingPackage, int callingUidProcState,
1002 boolean callingUidHasAnyVisibleWindow,
1003 int realCallingUid, int realCallingUidProcState,
1004 boolean realCallingUidHasAnyVisibleWindow,
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001005 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);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001022 builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0);
Michal Karpinski8596ded2018-11-14 14:43:48 +00001023 if (intent != null) {
1024 builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction());
Michal Karpinski319069b2019-03-27 15:46:50 +00001025 ComponentName component = intent.getComponent();
1026 if (component != null) {
1027 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME,
1028 component.flattenToShortString());
1029 }
Michal Karpinski8596ded2018-11-14 14:43:48 +00001030 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001031 if (callerApp != null) {
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001032 builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001033 builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001034 processStateAmToProto(callerApp.getCurrentProcState()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001035 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001036 callerApp.hasClientActivities() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001037 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES,
1038 callerApp.hasForegroundServices() ? 1 : 0);
1039 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001040 callerApp.hasForegroundActivities() ? 1 : 0);
1041 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001042 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001043 callerApp.hasOverlayUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001044 builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001045 callerApp.hasPendingUiClean() ? 1 : 0);
1046 if (callerApp.getInteractionEventTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001047 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001048 (nowElapsed - callerApp.getInteractionEventTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001049 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001050 if (callerApp.getFgInteractionTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001051 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001052 (nowElapsed - callerApp.getFgInteractionTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001053 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001054 if (callerApp.getWhenUnimportant() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001055 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001056 (nowUptime - callerApp.getWhenUnimportant()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001057 }
1058 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001059 mMetricsLogger.write(builder);
1060 }
1061
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001062 private void logAppStartMemoryStateCapture(TransitionInfoSnapshot info) {
Ng Zhi An83473542018-02-20 09:02:14 -08001063 if (info.processRecord == null) {
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001064 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null");
1065 return;
1066 }
1067
Wale Ogunwalef6733932018-06-27 05:14:34 -07001068 final int pid = info.processRecord.getPid();
Ng Zhi An83473542018-02-20 09:02:14 -08001069 final int uid = info.applicationInfo.uid;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +00001070 final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid);
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001071 if (memoryStat == null) {
1072 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null");
1073 return;
1074 }
1075
Muhammad Qureshi759f92f2020-01-28 10:41:55 -08001076 FrameworkStatsLog.write(
1077 FrameworkStatsLog.APP_START_MEMORY_STATE_CAPTURED,
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001078 uid,
Ng Zhi An83473542018-02-20 09:02:14 -08001079 info.processName,
1080 info.launchedActivityName,
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001081 memoryStat.pgfault,
1082 memoryStat.pgmajfault,
1083 memoryStat.rssInBytes,
1084 memoryStat.cacheInBytes,
1085 memoryStat.swapInBytes);
1086 }
1087
Calin Juravle759fbda2018-02-20 19:52:30 +00001088 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 }
Vishnu Nair132ee832018-09-28 15:00:05 -07001097
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001098 /** Starts trace for an activity is actually launching. */
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)) {
Vishnu Nair132ee832018-09-28 15:00:05 -07001102 return;
1103 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001104 info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName;
Riddle Hsue8d3d192019-11-26 18:56:39 +08001105 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
1106 (int) info.mTransitionStartTimeNs /* cookie */);
Vishnu Nair132ee832018-09-28 15:00:05 -07001107 }
1108
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001109 /** Stops trace for the launch is completed or cancelled. */
1110 private void stopLaunchTrace(@NonNull TransitionInfo info) {
1111 if (DEBUG_METRICS) Slog.i(TAG, "stopLaunchTrace " + info);
1112 if (info.mLaunchTraceName == null) {
Vishnu Nair132ee832018-09-28 15:00:05 -07001113 return;
1114 }
Riddle Hsue8d3d192019-11-26 18:56:39 +08001115 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
1116 (int) info.mTransitionStartTimeNs /* cookie */);
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001117 info.mLaunchTraceName = null;
Vishnu Nair132ee832018-09-28 15:00:05 -07001118 }
Igor Murashkin212d06c2018-10-22 16:34:39 -07001119
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001120 public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() {
1121 return mLaunchObserver;
1122 }
1123
Igor Murashkin212d06c2018-10-22 16:34:39 -07001124 /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */
Yan Wangd47f90b2019-10-03 19:17:15 -07001125 private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001126 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.
Yan Wangd47f90b2019-10-03 19:17:15 -07001130 mLaunchObserver.onIntentStarted(intent, timestampNs);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001131
1132 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001133 }
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 */
1140 private void launchObserverNotifyIntentFailed() {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001141 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1142 "MetricsLogger:launchObserverNotifyIntentFailed");
1143
1144 mLaunchObserver.onIntentFailed();
1145
1146 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001147 }
1148
1149 /**
1150 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1151 * has started.
1152 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001153 private void launchObserverNotifyActivityLaunched(TransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001154 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1155 "MetricsLogger:launchObserverNotifyActivityLaunched");
1156
Igor Murashkin212d06c2018-10-22 16:34:39 -07001157 @ActivityMetricsLaunchObserver.Temperature int temperature =
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001158 convertTransitionTypeToLaunchObserverTemperature(info.mTransitionType);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001159
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001160 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001161 mLaunchObserver.onActivityLaunched(convertActivityRecordToProto(info.mLastLaunchedActivity),
1162 temperature);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001163
1164 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001165 }
1166
1167 /**
Yan Wang9eac5ec2019-09-30 15:42:18 -07001168 * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event.
1169 */
Yan Wangd47f90b2019-10-03 19:17:15 -07001170 private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) {
Yan Wang9eac5ec2019-09-30 15:42:18 -07001171 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1172 "MetricsLogger:launchObserverNotifyReportFullyDrawn");
Yan Wangd47f90b2019-10-03 19:17:15 -07001173 mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs);
Yan Wang9eac5ec2019-09-30 15:42:18 -07001174 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1175 }
1176
1177 /**
Igor Murashkin212d06c2018-10-22 16:34:39 -07001178 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is
1179 * cancelled.
1180 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001181 private void launchObserverNotifyActivityLaunchCancelled(TransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001182 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1183 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001184
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001185 final @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] activityRecordProto =
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001186 info != null ? convertActivityRecordToProto(info.mLastLaunchedActivity) : null;
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001187
1188 mLaunchObserver.onActivityLaunchCancelled(activityRecordProto);
1189
1190 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001191 }
1192
1193 /**
1194 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1195 * has fully finished (successfully).
1196 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001197 private void launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001198 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1199 "MetricsLogger:launchObserverNotifyActivityLaunchFinished");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001200
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001201 mLaunchObserver.onActivityLaunchFinished(
1202 convertActivityRecordToProto(info.mLastLaunchedActivity), timestampNs);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001203
1204 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1205 }
1206
1207 @VisibleForTesting
1208 static @ActivityMetricsLaunchObserver.ActivityRecordProto byte[]
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).
Wale Ogunwalef342f062020-01-27 07:34:13 -08001220 record.dumpDebug(protoOutputStream, WindowTraceLogLevel.ALL);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001221 final byte[] bytes = protoOutputStream.getBytes();
1222
1223 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1224
1225 return bytes;
Igor Murashkin212d06c2018-10-22 16:34:39 -07001226 }
1227
1228 private static @ActivityMetricsLaunchObserver.Temperature int
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 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -08001241}