blob: 1c010c7d3171903197efea59c52a13b88486d031 [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;
11import static android.app.WindowConfiguration.WINDOWING_MODE_PINNED;
Vishnu Nair132ee832018-09-28 15:00:05 -070012import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_PRIMARY;
Wale Ogunwale926aade2017-08-29 11:24:37 -070013import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_SECONDARY;
14import static android.app.WindowConfiguration.WINDOWING_MODE_UNDEFINED;
Vishnu Nair132ee832018-09-28 15:00:05 -070015
Michal Karpinski201bc0c2018-07-20 15:32:00 +010016import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.ACTION_ACTIVITY_START;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080017import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION;
Jorim Jaggi515dd682017-05-05 15:05:07 +020018import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS;
Todd Kennedy50d946c12017-03-17 13:55:38 -070019import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020020import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080021import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS;
22import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS;
Todd Kennedy50d946c12017-03-17 13:55:38 -070023import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_IS_EPHEMERAL;
Jorim Jaggi4d27b842017-08-17 17:22:26 +020024import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_PROCESS_RUNNING;
25import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN;
26import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN_MS;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080027import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS;
28import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010029import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_PACKAGE_NAME;
30import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID;
31import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
32import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_PROC_STATE;
Jorim Jaggicdfc04e2017-04-28 19:06:24 +020033import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010034import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_COMING_FROM_PENDING_INTENT;
Todd Kennedy50d946c12017-03-17 13:55:38 -070035import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010036import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INTENT_ACTION;
37import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_CUR_PROC_STATE;
38import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES;
39import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES;
40import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES;
41import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_OVERLAY_UI;
42import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_TOP_UI;
43import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION;
44import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT;
45import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT;
46import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PENDING_UI_CLEAN;
47import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PROCESS_NAME;
48import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010049import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
Vishnu Nair132ee832018-09-28 15:00:05 -070050import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_PROC_STATE;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010051import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_SHORT_COMPONENT_NAME;
Calin Juravle759fbda2018-02-20 19:52:30 +000052import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_FILTER;
Vishnu Nair132ee832018-09-28 15:00:05 -070053import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_REASON;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080054import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH;
55import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH;
Jorim Jaggi4d27b842017-08-17 17:22:26 +020056import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE;
57import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080058import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
Ng Zhi Anbbefdec2018-01-30 17:12:39 -080059import static com.android.server.am.MemoryStatUtil.MemoryStat;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +000060import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem;
Vishnu Naira62534b2018-11-09 09:13:22 -080061import static com.android.server.wm.ActivityTaskManagerDebugConfig.DEBUG_METRICS;
62import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_ATM;
63import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_WITH_CLASS_NAME;
Vishnu Nair132ee832018-09-28 15:00:05 -070064import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT;
Jeff Changd136e772019-11-05 20:33:52 +080065import static com.android.server.wm.EventLogTags.WM_ACTIVITY_LAUNCH_TIME;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080066
Riddle Hsufd66d4d2019-11-14 10:35:55 +080067import android.annotation.NonNull;
68import android.annotation.Nullable;
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -080069import android.app.WaitResult;
Igor Murashkin212d06c2018-10-22 16:34:39 -070070import android.app.WindowConfiguration.WindowingMode;
Michal Karpinski319069b2019-03-27 15:46:50 +000071import android.content.ComponentName;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010072import android.content.Intent;
Calin Juravle759fbda2018-02-20 19:52:30 +000073import android.content.pm.ApplicationInfo;
74import android.content.pm.dex.ArtManagerInternal;
75import android.content.pm.dex.PackageOptimizationInfo;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080076import android.metrics.LogMaker;
Riddle Hsufd66d4d2019-11-14 10:35:55 +080077import android.os.Binder;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020078import android.os.Looper;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080079import android.os.SystemClock;
Vishnu Nair132ee832018-09-28 15:00:05 -070080import android.os.Trace;
Riddle Hsufd66d4d2019-11-14 10:35:55 +080081import android.util.ArrayMap;
Vishnu Nair132ee832018-09-28 15:00:05 -070082import android.util.EventLog;
83import android.util.Log;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020084import android.util.Slog;
Olivier Gaillardaed7f122017-12-12 14:26:22 +000085import android.util.StatsLog;
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;
Riddle Hsufd66d4d2019-11-14 10:35:55 +080092import com.android.internal.util.function.pooled.PooledLambda;
Calin Juravle759fbda2018-02-20 19:52:30 +000093import com.android.server.LocalServices;
Louis Changcdec0802019-11-11 11:45:07 +080094
Riddle Hsufd66d4d2019-11-14 10:35:55 +080095import java.util.ArrayList;
96import java.util.LinkedList;
Yan Wang9eac5ec2019-09-30 15:42:18 -070097import java.util.concurrent.TimeUnit;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080098
99/**
Vishnu Nair132ee832018-09-28 15:00:05 -0700100 * Listens to activity launches, transitions, visibility changes and window drawn callbacks to
101 * determine app launch times and draw delays. Source of truth for activity metrics and provides
102 * data for Tron, logcat, event logs and {@link android.app.WaitResult}.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800103 * <p>
104 * A typical sequence of a launch event could be:
105 * {@link #notifyActivityLaunching}, {@link #notifyActivityLaunched},
106 * {@link #notifyStartingWindowDrawn} (optional), {@link #notifyTransitionStarting}
107 * {@link #notifyWindowsDrawn}.
108 * <p>
Vishnu Nair132ee832018-09-28 15:00:05 -0700109 * Tests:
Tadashi G. Takaoka28bc3702019-04-23 11:01:48 +0900110 * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800111 */
112class ActivityMetricsLogger {
Jorim Jaggif9704102016-05-05 19:14:22 -0700113
Wale Ogunwale98875612018-10-12 07:53:02 -0700114 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM;
Jorim Jaggif9704102016-05-05 19:14:22 -0700115
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800116 // Window modes we are interested in logging. If we ever introduce a new type, we need to add
117 // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array.
118 private static final int WINDOW_STATE_STANDARD = 0;
119 private static final int WINDOW_STATE_SIDE_BY_SIDE = 1;
120 private static final int WINDOW_STATE_FREEFORM = 2;
Winson Chung83471632016-12-13 11:02:12 -0800121 private static final int WINDOW_STATE_ASSISTANT = 3;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800122 private static final int WINDOW_STATE_INVALID = -1;
123
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800124 /**
125 * The flag for {@link #notifyActivityLaunching} to skip associating a new launch with an active
126 * transition, in the case the launch is standalone (e.g. from recents).
127 */
128 private static final int IGNORE_CALLER = -1;
Vishnu Nair132ee832018-09-28 15:00:05 -0700129 private static final int INVALID_DELAY = -1;
130 private static final int INVALID_TRANSITION_TYPE = -1;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500131
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800132 // Preallocated strings we are sending to tron, so we don't have to allocate a new one every
133 // time we log.
134 private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = {
Winson Chung83471632016-12-13 11:02:12 -0800135 "window_time_0", "window_time_1", "window_time_2", "window_time_3"};
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800136
137 private int mWindowState = WINDOW_STATE_STANDARD;
138 private long mLastLogTimeSecs;
139 private final ActivityStackSupervisor mSupervisor;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800140 private final MetricsLogger mMetricsLogger = new MetricsLogger();
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800141
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800142 /** All active transitions. */
143 private final ArrayList<TransitionInfo> mTransitionInfoList = new ArrayList<>();
144 /** Map : Last launched activity => {@link TransitionInfo} */
145 private final ArrayMap<ActivityRecord, TransitionInfo> mLastTransitionInfo = new ArrayMap<>();
Calin Juravle759fbda2018-02-20 19:52:30 +0000146
147 private ArtManagerInternal mArtManagerInternal;
Vishnu Nair132ee832018-09-28 15:00:05 -0700148 private final StringBuilder mStringBuilder = new StringBuilder();
Calin Juravle759fbda2018-02-20 19:52:30 +0000149
Igor Murashkin212d06c2018-10-22 16:34:39 -0700150 /**
151 * Due to the global single concurrent launch sequence, all calls to this observer must be made
152 * in-order on the same thread to fulfill the "happens-before" guarantee in LaunchObserver.
153 */
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800154 private final LaunchObserverRegistryImpl mLaunchObserver;
155 @VisibleForTesting static final int LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE = 512;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700156
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800157 /**
158 * The information created when an intent is incoming but we do not yet know whether it will be
159 * launched successfully.
160 */
161 static final class LaunchingState {
162 /** The timestamp of {@link #notifyActivityLaunching}. */
163 private long mCurrentTransitionStartTimeNs;
164 /** Non-null when a {@link TransitionInfo} is created for this state. */
165 private TransitionInfo mAssociatedTransitionInfo;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200166
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800167 @VisibleForTesting
168 boolean allDrawn() {
169 return mAssociatedTransitionInfo != null && mAssociatedTransitionInfo.allDrawn();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200170 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000171 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800172
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800173 /** The information created when an activity is confirmed to be launched. */
174 private static final class TransitionInfo {
175 /**
176 * The field to lookup and update an existing transition efficiently between
177 * {@link #notifyActivityLaunching} and {@link #notifyActivityLaunched}.
178 *
179 * @see LaunchingState#mAssociatedTransitionInfo
180 */
181 final LaunchingState mLaunchingState;
182 /**
183 * The timestamp of the first {@link #notifyActivityLaunching}. It can be used as a key for
184 * observer to identify which callbacks belong to a launch event.
185 */
186 final long mTransitionStartTimeNs;
187 /** The device uptime in seconds when this transition info is created. */
188 final int mCurrentTransitionDeviceUptime;
189 /** The type can be cold (new process), warm (new activity), or hot (bring to front). */
190 final int mTransitionType;
191 /** Whether the process was already running when the transition started. */
192 final boolean mProcessRunning;
Riddle Hsue8d3d192019-11-26 18:56:39 +0800193 /** whether the process of the launching activity didn't have any active activity. */
194 final boolean mProcessSwitch;
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800195 /** The activities that should be drawn. */
196 final LinkedList<ActivityRecord> mPendingDrawActivities = new LinkedList<>();
Igor Murashkin212d06c2018-10-22 16:34:39 -0700197 /** The latest activity to have been launched. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800198 @NonNull ActivityRecord mLastLaunchedActivity;
199
200 /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyTransitionStarting}. */
201 int mCurrentTransitionDelayMs;
202 /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyStartingWindowDrawn}. */
203 int mStartingWindowDelayMs = INVALID_DELAY;
204 /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyBindApplication}. */
205 int mBindApplicationDelayMs = INVALID_DELAY;
Vishnu Nair132ee832018-09-28 15:00:05 -0700206 /** Elapsed time from when we launch an activity to when its windows are drawn. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800207 int mWindowsDrawnDelayMs;
208 /** The reason why the transition started (see ActivityManagerInternal.APP_TRANSITION_*). */
209 int mReason = APP_TRANSITION_TIMEOUT;
210 /** The flag ensures that {@link #mStartingWindowDelayMs} is only set once. */
211 boolean mLoggedStartingWindowDrawn;
212 /** If the any app transitions have been logged as starting. */
213 boolean mLoggedTransitionStarting;
214
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800215 /** Non-null if the application has reported drawn but its window hasn't. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800216 @Nullable Runnable mPendingFullyDrawn;
217 /** Non-null if the trace is active. */
218 @Nullable String mLaunchTraceName;
219
220 /** @return Non-null if there will be a window drawn event for the launch. */
221 @Nullable
222 static TransitionInfo create(@NonNull ActivityRecord r,
Riddle Hsue8d3d192019-11-26 18:56:39 +0800223 @NonNull LaunchingState launchingState, boolean processRunning,
224 boolean processSwitch, int startResult) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800225 int transitionType = INVALID_TRANSITION_TYPE;
226 if (processRunning) {
227 if (startResult == START_SUCCESS) {
228 transitionType = TYPE_TRANSITION_WARM_LAUNCH;
229 } else if (startResult == START_TASK_TO_FRONT) {
230 transitionType = TYPE_TRANSITION_HOT_LAUNCH;
231 }
232 } else if (startResult == START_SUCCESS || startResult == START_TASK_TO_FRONT) {
233 // Task may still exist when cold launching an activity and the start result will be
234 // set to START_TASK_TO_FRONT. Treat this as a COLD launch.
235 transitionType = TYPE_TRANSITION_COLD_LAUNCH;
236 }
237 if (transitionType == INVALID_TRANSITION_TYPE) {
238 // That means the startResult is neither START_SUCCESS nor START_TASK_TO_FRONT.
239 return null;
240 }
Riddle Hsue8d3d192019-11-26 18:56:39 +0800241 return new TransitionInfo(r, launchingState, transitionType, processRunning,
242 processSwitch);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800243 }
244
245 /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */
246 private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType,
Riddle Hsue8d3d192019-11-26 18:56:39 +0800247 boolean processRunning, boolean processSwitch) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800248 mLaunchingState = launchingState;
249 mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs;
250 mTransitionType = transitionType;
251 mProcessRunning = processRunning;
Riddle Hsue8d3d192019-11-26 18:56:39 +0800252 mProcessSwitch = processSwitch;
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800253 mCurrentTransitionDeviceUptime =
254 (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis());
255 setLatestLaunchedActivity(r);
256 launchingState.mAssociatedTransitionInfo = this;
257 }
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800258
259 /**
260 * Remembers the latest launched activity to represent the final transition. This also
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800261 * tracks the activities that should be drawn, so a consecutive launching sequence can be
262 * coalesced as one event.
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800263 */
264 void setLatestLaunchedActivity(ActivityRecord r) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800265 if (mLastLaunchedActivity == r) {
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800266 return;
267 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800268 mLastLaunchedActivity = r;
269 if (!r.noDisplay) {
270 if (DEBUG_METRICS) Slog.i(TAG, "Add pending draw " + r);
271 mPendingDrawActivities.add(r);
272 }
273 }
274
275 /** @return {@code true} if the activity matches a launched activity in this transition. */
276 boolean contains(ActivityRecord r) {
277 return r == mLastLaunchedActivity || mPendingDrawActivities.contains(r);
278 }
279
280 /** Called when the activity is drawn or won't be drawn. */
281 void removePendingDrawActivity(ActivityRecord r) {
282 if (DEBUG_METRICS) Slog.i(TAG, "Remove pending draw " + r);
283 mPendingDrawActivities.remove(r);
284 }
285
286 boolean allDrawn() {
287 return mPendingDrawActivities.isEmpty();
288 }
289
Riddle Hsue8d3d192019-11-26 18:56:39 +0800290 /**
291 * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or
292 * LaunchObserver.
293 */
294 boolean isInterestingToLoggerAndObserver() {
295 return mProcessSwitch;
296 }
297
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800298 int calculateCurrentDelay() {
299 return calculateDelay(SystemClock.elapsedRealtimeNanos());
300 }
301
302 int calculateDelay(long timestampNs) {
303 // Shouldn't take more than 25 days to launch an app, so int is fine here.
304 return (int) TimeUnit.NANOSECONDS.toMillis(timestampNs - mTransitionStartTimeNs);
305 }
306
307 @Override
308 public String toString() {
309 return "TransitionInfo{" + Integer.toHexString(System.identityHashCode(this))
310 + " a=" + mLastLaunchedActivity + " ua=" + mPendingDrawActivities + "}";
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800311 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800312 }
313
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800314 static final class TransitionInfoSnapshot {
Calin Juravle759fbda2018-02-20 19:52:30 +0000315 final private ApplicationInfo applicationInfo;
Wale Ogunwalef6733932018-06-27 05:14:34 -0700316 final private WindowProcessController processRecord;
Vishnu Nair132ee832018-09-28 15:00:05 -0700317 final String packageName;
318 final String launchedActivityName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000319 final private String launchedActivityLaunchedFromPackage;
320 final private String launchedActivityLaunchToken;
321 final private String launchedActivityAppRecordRequiredAbi;
Vishnu Nair132ee832018-09-28 15:00:05 -0700322 final String launchedActivityShortComponentName;
Ng Zhi An83473542018-02-20 09:02:14 -0800323 final private String processName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000324 final private int reason;
325 final private int startingWindowDelayMs;
326 final private int bindApplicationDelayMs;
Vishnu Nair132ee832018-09-28 15:00:05 -0700327 final int windowsDrawnDelayMs;
328 final int type;
329 final int userId;
330 /**
331 * Elapsed time from when we launch an activity to when the app reported it was
332 * fully drawn. If this is not reported then the value is set to INVALID_DELAY.
333 */
334 final int windowsFullyDrawnDelayMs;
335 final int activityRecordIdHashCode;
Calin Juravle759fbda2018-02-20 19:52:30 +0000336
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800337 private TransitionInfoSnapshot(TransitionInfo info) {
338 this(info, info.mLastLaunchedActivity, INVALID_DELAY);
Vishnu Nair132ee832018-09-28 15:00:05 -0700339 }
340
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800341 private TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity,
342 int windowsFullyDrawnDelayMs) {
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700343 applicationInfo = launchedActivity.info.applicationInfo;
Vishnu Nair132ee832018-09-28 15:00:05 -0700344 packageName = launchedActivity.packageName;
345 launchedActivityName = launchedActivity.info.name;
346 launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage;
347 launchedActivityLaunchToken = launchedActivity.info.launchToken;
348 launchedActivityAppRecordRequiredAbi = launchedActivity.app == null
Calin Juravle759fbda2018-02-20 19:52:30 +0000349 ? null
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700350 : launchedActivity.app.getRequiredAbi();
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800351 reason = info.mReason;
352 startingWindowDelayMs = info.mStartingWindowDelayMs;
353 bindApplicationDelayMs = info.mBindApplicationDelayMs;
354 windowsDrawnDelayMs = info.mWindowsDrawnDelayMs;
355 type = info.mTransitionType;
356 processRecord = launchedActivity.app;
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700357 processName = launchedActivity.processName;
Wale Ogunwale8b19de92018-11-29 19:58:26 -0800358 userId = launchedActivity.mUserId;
Vishnu Nair132ee832018-09-28 15:00:05 -0700359 launchedActivityShortComponentName = launchedActivity.shortComponentName;
360 activityRecordIdHashCode = System.identityHashCode(launchedActivity);
361 this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
Calin Juravle759fbda2018-02-20 19:52:30 +0000362 }
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -0800363
364 @WaitResult.LaunchState int getLaunchState() {
365 switch (type) {
366 case TYPE_TRANSITION_WARM_LAUNCH:
367 return LAUNCH_STATE_WARM;
368 case TYPE_TRANSITION_HOT_LAUNCH:
369 return LAUNCH_STATE_HOT;
370 case TYPE_TRANSITION_COLD_LAUNCH:
371 return LAUNCH_STATE_COLD;
372 default:
373 return -1;
374 }
375 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000376 }
377
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800378 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Looper looper) {
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800379 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
380 mSupervisor = supervisor;
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800381 mLaunchObserver = new LaunchObserverRegistryImpl(looper);
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800382 }
383
384 void logWindowState() {
385 final long now = SystemClock.elapsedRealtime() / 1000;
386 if (mWindowState != WINDOW_STATE_INVALID) {
387 // We log even if the window state hasn't changed, because the user might remain in
388 // home/fullscreen move forever and we would like to track this kind of behavior
389 // too.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800390 mMetricsLogger.count(TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState],
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800391 (int) (now - mLastLogTimeSecs));
392 }
393 mLastLogTimeSecs = now;
394
Wale Ogunwale926aade2017-08-29 11:24:37 -0700395 mWindowState = WINDOW_STATE_INVALID;
Wale Ogunwaled32da472018-11-16 07:19:28 -0800396 ActivityStack stack =
397 mSupervisor.mRootActivityContainer.getTopDisplayFocusedStack();
lumarkf6c4a982018-06-15 15:43:12 +0800398 if (stack == null) {
399 return;
400 }
401
Wale Ogunwale926aade2017-08-29 11:24:37 -0700402 if (stack.isActivityTypeAssistant()) {
403 mWindowState = WINDOW_STATE_ASSISTANT;
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800404 return;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800405 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700406
Igor Murashkin212d06c2018-10-22 16:34:39 -0700407 @WindowingMode int windowingMode = stack.getWindowingMode();
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700408 if (windowingMode == WINDOWING_MODE_PINNED) {
Wale Ogunwaled32da472018-11-16 07:19:28 -0800409 stack = mSupervisor.mRootActivityContainer.findStackBehind(stack);
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700410 windowingMode = stack.getWindowingMode();
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800411 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700412 switch (windowingMode) {
413 case WINDOWING_MODE_FULLSCREEN:
414 mWindowState = WINDOW_STATE_STANDARD;
415 break;
416 case WINDOWING_MODE_SPLIT_SCREEN_PRIMARY:
417 case WINDOWING_MODE_SPLIT_SCREEN_SECONDARY:
418 mWindowState = WINDOW_STATE_SIDE_BY_SIDE;
419 break;
Bryce Lee6c605092017-10-12 11:14:49 -0700420 case WINDOWING_MODE_FREEFORM:
Wale Ogunwale926aade2017-08-29 11:24:37 -0700421 mWindowState = WINDOW_STATE_FREEFORM;
422 break;
423 default:
424 if (windowingMode != WINDOWING_MODE_UNDEFINED) {
425 throw new IllegalStateException("Unknown windowing mode for stack=" + stack
426 + " windowingMode=" + windowingMode);
427 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800428 }
429 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500430
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800431 /** @return Non-null {@link TransitionInfo} if the activity is found in an active transition. */
432 @Nullable
433 private TransitionInfo getActiveTransitionInfo(ActivityRecord r) {
434 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
435 final TransitionInfo info = mTransitionInfoList.get(i);
436 if (info.contains(r)) {
437 return info;
438 }
439 }
440 return null;
441 }
442
443 /**
444 * This method should be only used by starting recents and starting from recents, or internal
445 * tests. Because it doesn't lookup caller and always creates a new launching state.
446 *
447 * @see #notifyActivityLaunching(Intent, ActivityRecord, int)
448 */
449 LaunchingState notifyActivityLaunching(Intent intent) {
450 return notifyActivityLaunching(intent, null /* caller */, IGNORE_CALLER);
451 }
452
453 /**
454 * If the caller is found in an active transition, it will be considered as consecutive launch
455 * and coalesced into the active transition.
456 *
457 * @see #notifyActivityLaunching(Intent, ActivityRecord, int)
458 */
459 LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller) {
460 return notifyActivityLaunching(intent, caller, Binder.getCallingUid());
461 }
462
Jorim Jaggi275561a2016-02-23 10:11:02 -0500463 /**
464 * Notifies the tracker at the earliest possible point when we are starting to launch an
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800465 * activity. The caller must ensure that {@link #notifyActivityLaunched} will be called later
466 * with the returned {@link LaunchingState}.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500467 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800468 private LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller,
469 int callingUid) {
470 final long transitionStartTimeNs = SystemClock.elapsedRealtimeNanos();
471 TransitionInfo existingInfo = null;
472 if (callingUid != IGNORE_CALLER) {
473 // Associate the launching event to an active transition if the caller is found in its
474 // launched activities.
475 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
476 final TransitionInfo info = mTransitionInfoList.get(i);
477 if (caller != null && info.contains(caller)) {
478 existingInfo = info;
479 break;
480 }
481 if (existingInfo == null && callingUid == info.mLastLaunchedActivity.getUid()) {
482 // Fallback to check the most recent matched uid for the case that the caller is
483 // not an activity.
484 existingInfo = info;
485 }
486 }
487 }
Igor Murashkin212d06c2018-10-22 16:34:39 -0700488 if (DEBUG_METRICS) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800489 Slog.i(TAG, "notifyActivityLaunching intent=" + intent
490 + " existingInfo=" + existingInfo);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700491 }
492
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800493 if (existingInfo == null) {
494 // Only notify the observer for a new launching event.
495 launchObserverNotifyIntentStarted(intent, transitionStartTimeNs);
496 final LaunchingState launchingState = new LaunchingState();
497 launchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
498 return launchingState;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800499 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800500 existingInfo.mLaunchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs;
501 return existingInfo.mLaunchingState;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500502 }
503
504 /**
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700505 * Notifies the tracker that the activity is actually launching.
506 *
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800507 * @param launchingState The launching state to track the new or active transition.
508 * @param resultCode One of the {@link android.app.ActivityManager}.START_* flags, indicating
509 * the result of the launch.
510 * @param launchedActivity The activity that is being launched
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700511 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800512 void notifyActivityLaunched(@NonNull LaunchingState launchingState, int resultCode,
513 @Nullable ActivityRecord launchedActivity) {
514 if (launchedActivity == null) {
515 // The launch is aborted, e.g. intent not resolved, class not found.
516 abort(null /* info */, "nothing launched");
517 return;
518 }
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700519
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800520 final WindowProcessController processRecord = launchedActivity.app != null
521 ? launchedActivity.app
522 : mSupervisor.mService.getProcessController(
523 launchedActivity.processName, launchedActivity.info.applicationInfo.uid);
524 // Whether the process that will contains the activity is already running.
525 final boolean processRunning = processRecord != null;
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700526 // We consider this a "process switch" if the process of the activity that gets launched
527 // didn't have an activity that was in started state. In this case, we assume that lot
528 // of caches might be purged so the time until it produces the first frame is very
529 // interesting.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800530 final boolean processSwitch = !processRunning
Wale Ogunwalef6733932018-06-27 05:14:34 -0700531 || !processRecord.hasStartedActivity(launchedActivity);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700532
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800533 final TransitionInfo info = launchingState.mAssociatedTransitionInfo;
534 if (DEBUG_METRICS) {
535 Slog.i(TAG, "notifyActivityLaunched" + " resultCode=" + resultCode
536 + " launchedActivity=" + launchedActivity + " processRunning=" + processRunning
537 + " processSwitch=" + processSwitch + " info=" + info);
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200538 }
539
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800540 if (launchedActivity.mDrawn) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700541 // Launched activity is already visible. We cannot measure windows drawn delay.
Riddle Hsu1063b512019-10-22 21:12:23 +0800542 abort(info, "launched activity already visible");
Vishnu Nairf8accc52018-10-11 10:19:54 -0700543 return;
544 }
545
Riddle Hsu20cf2bc2019-11-27 18:57:50 +0800546 if (info != null
547 && info.mLastLaunchedActivity.mDisplayContent == launchedActivity.mDisplayContent) {
548 // If we are already in an existing transition on the same display, only update the
549 // activity name, but not the other attributes.
Igor Murashkin212d06c2018-10-22 16:34:39 -0700550
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800551 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched update launched activity");
Igor Murashkin212d06c2018-10-22 16:34:39 -0700552 // Coalesce multiple (trampoline) activities from a single sequence together.
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800553 info.setLatestLaunchedActivity(launchedActivity);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500554 return;
555 }
556
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800557 final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState,
Riddle Hsue8d3d192019-11-26 18:56:39 +0800558 processRunning, processSwitch, resultCode);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800559 if (newInfo == null) {
560 abort(info, "unrecognized launch");
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800561 return;
562 }
563
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200564 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800565 // A new launch sequence has begun. Start tracking it.
566 mTransitionInfoList.add(newInfo);
567 mLastTransitionInfo.put(launchedActivity, newInfo);
568 startLaunchTrace(newInfo);
Riddle Hsue8d3d192019-11-26 18:56:39 +0800569 if (newInfo.isInterestingToLoggerAndObserver()) {
570 launchObserverNotifyActivityLaunched(newInfo);
571 } else {
572 // As abort for no process switch.
573 launchObserverNotifyIntentFailed();
574 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500575 }
576
577 /**
578 * Notifies the tracker that all windows of the app have been drawn.
579 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800580 @Nullable
581 TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r, long timestampNs) {
582 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn " + r);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200583
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800584 final TransitionInfo info = getActiveTransitionInfo(r);
585 if (info == null || info.allDrawn()) {
586 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn no activity to be drawn");
Vishnu Nair132ee832018-09-28 15:00:05 -0700587 return null;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500588 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800589 // Always calculate the delay because the caller may need to know the individual drawn time.
590 info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs);
591 info.removePendingDrawActivity(r);
592 final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
593 if (info.mLoggedTransitionStarting && info.allDrawn()) {
594 done(false /* abort */, info, "notifyWindowsDrawn - all windows drawn", timestampNs);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500595 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700596 return infoSnapshot;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500597 }
598
599 /**
600 * Notifies the tracker that the starting window was drawn.
601 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800602 void notifyStartingWindowDrawn(@NonNull ActivityRecord r) {
603 final TransitionInfo info = getActiveTransitionInfo(r);
604 if (info == null || info.mLoggedStartingWindowDrawn) {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500605 return;
606 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800607 if (DEBUG_METRICS) Slog.i(TAG, "notifyStartingWindowDrawn " + r);
608 info.mLoggedStartingWindowDrawn = true;
609 info.mStartingWindowDelayMs = info.calculateDelay(SystemClock.elapsedRealtimeNanos());
Jorim Jaggi275561a2016-02-23 10:11:02 -0500610 }
611
612 /**
613 * Notifies the tracker that the app transition is starting.
614 *
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800615 * @param activityToReason A map from activity to a reason integer, which must be on of
616 * ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500617 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800618 void notifyTransitionStarting(ArrayMap<ActivityRecord, Integer> activityToReason) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200619 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
Igor Murashkin212d06c2018-10-22 16:34:39 -0700620
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800621 final long timestampNs = SystemClock.elapsedRealtimeNanos();
622 for (int index = activityToReason.size() - 1; index >= 0; index--) {
623 final ActivityRecord r = activityToReason.keyAt(index);
624 final TransitionInfo info = getActiveTransitionInfo(r);
625 if (info == null || info.mLoggedTransitionStarting) {
626 // Ignore any subsequent notifyTransitionStarting.
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800627 continue;
628 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800629 if (DEBUG_METRICS) {
630 Slog.i(TAG, "notifyTransitionStarting activity=" + r + " info=" + info);
631 }
632
633 info.mCurrentTransitionDelayMs = info.calculateDelay(timestampNs);
634 info.mReason = activityToReason.valueAt(index);
635 info.mLoggedTransitionStarting = true;
636 if (info.allDrawn()) {
637 done(false /* abort */, info, "notifyTransitionStarting - all windows drawn",
638 timestampNs);
639 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800640 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800641 }
642
643 /** Makes sure that the reference to the removed activity is cleared. */
644 void notifyActivityRemoved(@NonNull ActivityRecord r) {
645 mLastTransitionInfo.remove(r);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500646 }
647
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200648 /**
649 * Notifies the tracker that the visibility of an app is changing.
650 *
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800651 * @param r the app that is changing its visibility
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200652 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800653 void notifyVisibilityChanged(@NonNull ActivityRecord r) {
654 final TransitionInfo info = getActiveTransitionInfo(r);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200655 if (info == null) {
656 return;
657 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800658 if (DEBUG_METRICS) {
659 Slog.i(TAG, "notifyVisibilityChanged " + r + " visible=" + r.mVisibleRequested
660 + " state=" + r.getState() + " finishing=" + r.finishing);
661 }
662 if (!r.mVisibleRequested || r.finishing) {
663 info.removePendingDrawActivity(r);
664 }
665 if (info.mLastLaunchedActivity != r) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200666 return;
667 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800668 // The activity and its task are passed separately because the activity may be removed from
669 // the task later.
670 r.mAtmService.mH.sendMessage(PooledLambda.obtainMessage(
671 ActivityMetricsLogger::checkVisibility, this, r.getTask(), r));
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200672 }
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200673
Riddle Hsu1063b512019-10-22 21:12:23 +0800674 /** @return {@code true} if the given task has an activity will be drawn. */
Louis Changcdec0802019-11-11 11:45:07 +0800675 private static boolean hasActivityToBeDrawn(Task t) {
Wale Ogunwalea38654f2019-11-17 20:37:15 -0800676 return t.forAllActivities((r) -> r.mVisibleRequested && !r.mDrawn && !r.finishing);
Vishnu Nairb1de42d2019-01-28 09:49:51 -0800677 }
678
Louis Changcdec0802019-11-11 11:45:07 +0800679 private void checkVisibility(Task t, ActivityRecord r) {
Wale Ogunwalec9e57de2018-05-08 14:28:07 -0700680 synchronized (mSupervisor.mService.mGlobalLock) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200681
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800682 final TransitionInfo info = getActiveTransitionInfo(r);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200683
684 // If we have an active transition that's waiting on a certain activity that will be
685 // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary.
Vishnu Naird15063b2019-06-11 08:08:25 -0700686
687 // We have no active transitions.
688 if (info == null) {
689 return;
690 }
691
692 // The notified activity whose visibility changed is no longer the launched activity.
693 // We can still wait to get onWindowsDrawn.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800694 if (info.mLastLaunchedActivity != r) {
Vishnu Naird15063b2019-06-11 08:08:25 -0700695 return;
696 }
697
Riddle Hsu1063b512019-10-22 21:12:23 +0800698 // If the task of the launched activity contains any activity to be drawn, then the
699 // window drawn event should report later to complete the transition. Otherwise all
700 // activities in this task may be finished, invisible or drawn, so the transition event
701 // should be cancelled.
702 if (hasActivityToBeDrawn(t)) {
Vishnu Naird15063b2019-06-11 08:08:25 -0700703 return;
704 }
705
706 if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible activity=" + r);
707 logAppTransitionCancel(info);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800708 abort(info, "notifyVisibilityChanged to invisible");
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200709 }
710 }
711
Jorim Jaggi515dd682017-05-05 15:05:07 +0200712 /**
713 * Notifies the tracker that we called immediately before we call bindApplication on the client.
714 *
Wale Ogunwale31913b52018-10-13 08:29:31 -0700715 * @param appInfo The client into which we'll call bindApplication.
Jorim Jaggi515dd682017-05-05 15:05:07 +0200716 */
Wale Ogunwale31913b52018-10-13 08:29:31 -0700717 void notifyBindApplication(ApplicationInfo appInfo) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800718 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) {
719 final TransitionInfo info = mTransitionInfoList.get(i);
Jorim Jaggi515dd682017-05-05 15:05:07 +0200720
721 // App isn't attached to record yet, so match with info.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800722 if (info.mLastLaunchedActivity.info.applicationInfo == appInfo) {
723 info.mBindApplicationDelayMs = info.calculateCurrentDelay();
Jorim Jaggi515dd682017-05-05 15:05:07 +0200724 }
725 }
726 }
727
Riddle Hsu1063b512019-10-22 21:12:23 +0800728 /** Aborts tracking of current launch metrics. */
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800729 private void abort(TransitionInfo info, String cause) {
730 done(true /* abort */, info, cause, 0L /* timestampNs */);
Riddle Hsu1063b512019-10-22 21:12:23 +0800731 }
732
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800733 /** Called when the given transition (info) is no longer active. */
734 private void done(boolean abort, @Nullable TransitionInfo info, String cause,
Riddle Hsu1063b512019-10-22 21:12:23 +0800735 long timestampNs) {
Yan Wangd47f90b2019-10-03 19:17:15 -0700736 if (DEBUG_METRICS) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800737 Slog.i(TAG, "done abort=" + abort + " cause=" + cause + " timestamp=" + timestampNs
738 + " info=" + info);
Yan Wangd47f90b2019-10-03 19:17:15 -0700739 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800740 if (info == null) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700741 launchObserverNotifyIntentFailed();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200742 return;
743 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800744
745 stopLaunchTrace(info);
746 if (abort) {
747 launchObserverNotifyActivityLaunchCancelled(info);
748 } else {
749 logAppTransitionFinished(info);
Riddle Hsue8d3d192019-11-26 18:56:39 +0800750 if (info.isInterestingToLoggerAndObserver()) {
751 launchObserverNotifyActivityLaunchFinished(info, timestampNs);
752 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800753 }
754 info.mPendingDrawActivities.clear();
755 mTransitionInfoList.remove(info);
756 }
757
758 private void logAppTransitionCancel(TransitionInfo info) {
759 final int type = info.mTransitionType;
760 final ActivityRecord activity = info.mLastLaunchedActivity;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200761 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800762 builder.setPackageName(activity.packageName);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200763 builder.setType(type);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800764 builder.addTaggedData(FIELD_CLASS_NAME, activity.info.name);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200765 mMetricsLogger.write(builder);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000766 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800767 StatsLog.APP_START_CANCELED,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800768 activity.info.applicationInfo.uid,
769 activity.packageName,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000770 convertAppStartTransitionType(type),
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800771 activity.info.name);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700772 if (DEBUG_METRICS) {
773 Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)",
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800774 activity.info.applicationInfo.uid,
775 activity.packageName,
Igor Murashkin212d06c2018-10-22 16:34:39 -0700776 convertAppStartTransitionType(type),
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800777 activity.info.name));
Igor Murashkin212d06c2018-10-22 16:34:39 -0700778 }
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200779 }
780
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800781 private void logAppTransitionFinished(@NonNull TransitionInfo info) {
782 if (DEBUG_METRICS) Slog.i(TAG, "logging finished transition " + info);
Calin Juravle759fbda2018-02-20 19:52:30 +0000783
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800784 // Take a snapshot of the transition info before sending it to the handler for logging.
785 // This will avoid any races with other operations that modify the ActivityRecord.
786 final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info);
Riddle Hsue8d3d192019-11-26 18:56:39 +0800787 if (info.isInterestingToLoggerAndObserver()) {
788 BackgroundThread.getHandler().post(() -> logAppTransition(
789 info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs,
790 infoSnapshot));
791 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800792 BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
793 if (info.mPendingFullyDrawn != null) {
794 info.mPendingFullyDrawn.run();
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800795 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800796
797 info.mLastLaunchedActivity.info.launchToken = null;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800798 }
799
Ng Zhi An83473542018-02-20 09:02:14 -0800800 // This gets called on a background thread without holding the activity manager lock.
Calin Juravle759fbda2018-02-20 19:52:30 +0000801 private void logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800802 TransitionInfoSnapshot info) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000803 final LogMaker builder = new LogMaker(APP_TRANSITION);
804 builder.setPackageName(info.packageName);
805 builder.setType(info.type);
806 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName);
807 final boolean isInstantApp = info.applicationInfo.isInstantApp();
808 if (info.launchedActivityLaunchedFromPackage != null) {
809 builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME,
810 info.launchedActivityLaunchedFromPackage);
811 }
812 String launchToken = info.launchedActivityLaunchToken;
813 if (launchToken != null) {
814 builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, launchToken);
815 }
816 builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0);
817 builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS,
818 currentTransitionDeviceUptime);
819 builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs);
820 builder.setSubtype(info.reason);
Vishnu Nair132ee832018-09-28 15:00:05 -0700821 if (info.startingWindowDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000822 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
823 info.startingWindowDelayMs);
824 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700825 if (info.bindApplicationDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000826 builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS,
827 info.bindApplicationDelayMs);
828 }
829 builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs);
830 final ArtManagerInternal artManagerInternal = getArtManagerInternal();
831 final PackageOptimizationInfo packageOptimizationInfo =
832 (artManagerInternal == null) || (info.launchedActivityAppRecordRequiredAbi == null)
833 ? PackageOptimizationInfo.createWithNoInfo()
834 : artManagerInternal.getPackageOptimizationInfo(
835 info.applicationInfo,
836 info.launchedActivityAppRecordRequiredAbi);
837 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON,
838 packageOptimizationInfo.getCompilationReason());
839 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER,
840 packageOptimizationInfo.getCompilationFilter());
841 mMetricsLogger.write(builder);
842 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800843 StatsLog.APP_START_OCCURRED,
Calin Juravle759fbda2018-02-20 19:52:30 +0000844 info.applicationInfo.uid,
845 info.packageName,
846 convertAppStartTransitionType(info.type),
847 info.launchedActivityName,
848 info.launchedActivityLaunchedFromPackage,
849 isInstantApp,
850 currentTransitionDeviceUptime * 1000,
851 info.reason,
852 currentTransitionDelayMs,
853 info.startingWindowDelayMs,
854 info.bindApplicationDelayMs,
855 info.windowsDrawnDelayMs,
856 launchToken,
857 packageOptimizationInfo.getCompilationReason(),
858 packageOptimizationInfo.getCompilationFilter());
Igor Murashkin212d06c2018-10-22 16:34:39 -0700859
860 if (DEBUG_METRICS) {
861 Slog.i(TAG, String.format("APP_START_OCCURRED(%s, %s, %s, %s, %s)",
862 info.applicationInfo.uid,
863 info.packageName,
864 convertAppStartTransitionType(info.type),
865 info.launchedActivityName,
866 info.launchedActivityLaunchedFromPackage));
867 }
868
869
Ng Zhi An83473542018-02-20 09:02:14 -0800870 logAppStartMemoryStateCapture(info);
Calin Juravle759fbda2018-02-20 19:52:30 +0000871 }
872
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800873 private void logAppDisplayed(TransitionInfoSnapshot info) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700874 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
875 return;
876 }
877
Jeff Changd136e772019-11-05 20:33:52 +0800878 EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME,
Vishnu Nair132ee832018-09-28 15:00:05 -0700879 info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,
880 info.windowsDrawnDelayMs);
881
882 StringBuilder sb = mStringBuilder;
883 sb.setLength(0);
884 sb.append("Displayed ");
885 sb.append(info.launchedActivityShortComponentName);
886 sb.append(": ");
887 TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
888 Log.i(TAG, sb.toString());
889 }
890
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000891 private int convertAppStartTransitionType(int tronType) {
892 if (tronType == TYPE_TRANSITION_COLD_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800893 return StatsLog.APP_START_OCCURRED__TYPE__COLD;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000894 }
895 if (tronType == TYPE_TRANSITION_WARM_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800896 return StatsLog.APP_START_OCCURRED__TYPE__WARM;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000897 }
898 if (tronType == TYPE_TRANSITION_HOT_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800899 return StatsLog.APP_START_OCCURRED__TYPE__HOT;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000900 }
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800901 return StatsLog.APP_START_OCCURRED__TYPE__UNKNOWN;
Riddle Hsuc48c8912019-10-31 13:34:27 +0800902 }
903
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800904 /** @return the last known window drawn delay of the given activity. */
905 int getLastDrawnDelayMs(ActivityRecord r) {
906 final TransitionInfo info = mLastTransitionInfo.get(r);
907 return info != null ? info.mWindowsDrawnDelayMs : INVALID_DELAY;
Riddle Hsuc48c8912019-10-31 13:34:27 +0800908 }
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000909
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800910 /** @see android.app.Activity#reportFullyDrawn */
911 TransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
Vishnu Nair132ee832018-09-28 15:00:05 -0700912 boolean restoredFromBundle) {
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800913 final TransitionInfo info = mLastTransitionInfo.get(r);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200914 if (info == null) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700915 return null;
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200916 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800917 if (!info.allDrawn() && info.mPendingFullyDrawn == null) {
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800918 // There are still undrawn activities, postpone reporting fully drawn until all of its
919 // windows are drawn. So that is closer to an usable state.
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800920 info.mPendingFullyDrawn = () -> {
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800921 logAppTransitionReportedDrawn(r, restoredFromBundle);
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800922 info.mPendingFullyDrawn = null;
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800923 };
924 return null;
925 }
Chris Wailes35c193c2018-10-09 18:12:00 -0700926
Riddle Hsue8d3d192019-11-26 18:56:39 +0800927 final long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
928 final long startupTimeMs = info.mPendingFullyDrawn != null
929 ? info.mWindowsDrawnDelayMs
930 : TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - info.mTransitionStartTimeNs);
931 final TransitionInfoSnapshot infoSnapshot =
932 new TransitionInfoSnapshot(info, r, (int) startupTimeMs);
933 BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));
934
935 if (!info.isInterestingToLoggerAndObserver()) {
936 return infoSnapshot;
937 }
938
Chris Wailes35c193c2018-10-09 18:12:00 -0700939 // Record the handling of the reportFullyDrawn callback in the trace system. This is not
940 // actually used to trace this function, but instead the logical task that this function
941 // fullfils (handling reportFullyDrawn() callbacks).
942 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800943 "ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName);
Chris Wailes35c193c2018-10-09 18:12:00 -0700944
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200945 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
946 builder.setPackageName(r.packageName);
947 builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000948 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200949 builder.setType(restoredFromBundle
950 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
951 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
952 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800953 info.mProcessRunning ? 1 : 0);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200954 mMetricsLogger.write(builder);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000955 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800956 StatsLog.APP_START_FULLY_DRAWN,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800957 info.mLastLaunchedActivity.info.applicationInfo.uid,
958 info.mLastLaunchedActivity.packageName,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000959 restoredFromBundle
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800960 ? StatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
961 : StatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800962 info.mLastLaunchedActivity.info.name,
963 info.mProcessRunning,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000964 startupTimeMs);
Chris Wailes35c193c2018-10-09 18:12:00 -0700965
966 // Ends the trace started at the beginning of this function. This is located here to allow
967 // the trace slice to have a noticable duration.
968 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
969
Yan Wang9eac5ec2019-09-30 15:42:18 -0700970 // Notify reportFullyDrawn event.
971 launchObserverNotifyReportFullyDrawn(r, currentTimestampNs);
972
Vishnu Nair132ee832018-09-28 15:00:05 -0700973 return infoSnapshot;
974 }
975
Riddle Hsufd66d4d2019-11-14 10:35:55 +0800976 private void logAppFullyDrawn(TransitionInfoSnapshot info) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700977 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
978 return;
979 }
980
981 StringBuilder sb = mStringBuilder;
982 sb.setLength(0);
983 sb.append("Fully drawn ");
984 sb.append(info.launchedActivityShortComponentName);
985 sb.append(": ");
986 TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb);
987 Log.i(TAG, sb.toString());
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200988 }
989
Michal Karpinski4fd5b842019-01-28 15:13:32 +0000990 void logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp,
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100991 int callingUid, String callingPackage, int callingUidProcState,
992 boolean callingUidHasAnyVisibleWindow,
993 int realCallingUid, int realCallingUidProcState,
994 boolean realCallingUidHasAnyVisibleWindow,
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100995 boolean comingFromPendingIntent) {
996
997 final long nowElapsed = SystemClock.elapsedRealtime();
998 final long nowUptime = SystemClock.uptimeMillis();
999 final LogMaker builder = new LogMaker(ACTION_ACTIVITY_START);
1000 builder.setTimestamp(System.currentTimeMillis());
1001 builder.addTaggedData(FIELD_CALLING_UID, callingUid);
1002 builder.addTaggedData(FIELD_CALLING_PACKAGE_NAME, callingPackage);
1003 builder.addTaggedData(FIELD_CALLING_UID_PROC_STATE,
1004 processStateAmToProto(callingUidProcState));
1005 builder.addTaggedData(FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
1006 callingUidHasAnyVisibleWindow ? 1 : 0);
1007 builder.addTaggedData(FIELD_REAL_CALLING_UID, realCallingUid);
1008 builder.addTaggedData(FIELD_REAL_CALLING_UID_PROC_STATE,
1009 processStateAmToProto(realCallingUidProcState));
1010 builder.addTaggedData(FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
1011 realCallingUidHasAnyVisibleWindow ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001012 builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0);
Michal Karpinski8596ded2018-11-14 14:43:48 +00001013 if (intent != null) {
1014 builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction());
Michal Karpinski319069b2019-03-27 15:46:50 +00001015 ComponentName component = intent.getComponent();
1016 if (component != null) {
1017 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME,
1018 component.flattenToShortString());
1019 }
Michal Karpinski8596ded2018-11-14 14:43:48 +00001020 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001021 if (callerApp != null) {
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001022 builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001023 builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001024 processStateAmToProto(callerApp.getCurrentProcState()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001025 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001026 callerApp.hasClientActivities() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001027 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES,
1028 callerApp.hasForegroundServices() ? 1 : 0);
1029 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001030 callerApp.hasForegroundActivities() ? 1 : 0);
1031 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001032 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001033 callerApp.hasOverlayUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001034 builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001035 callerApp.hasPendingUiClean() ? 1 : 0);
1036 if (callerApp.getInteractionEventTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001037 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001038 (nowElapsed - callerApp.getInteractionEventTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001039 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001040 if (callerApp.getFgInteractionTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001041 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001042 (nowElapsed - callerApp.getFgInteractionTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001043 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001044 if (callerApp.getWhenUnimportant() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001045 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -07001046 (nowUptime - callerApp.getWhenUnimportant()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001047 }
1048 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +01001049 mMetricsLogger.write(builder);
1050 }
1051
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001052 private void logAppStartMemoryStateCapture(TransitionInfoSnapshot info) {
Ng Zhi An83473542018-02-20 09:02:14 -08001053 if (info.processRecord == null) {
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001054 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null");
1055 return;
1056 }
1057
Wale Ogunwalef6733932018-06-27 05:14:34 -07001058 final int pid = info.processRecord.getPid();
Ng Zhi An83473542018-02-20 09:02:14 -08001059 final int uid = info.applicationInfo.uid;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +00001060 final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid);
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001061 if (memoryStat == null) {
1062 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null");
1063 return;
1064 }
1065
1066 StatsLog.write(
1067 StatsLog.APP_START_MEMORY_STATE_CAPTURED,
1068 uid,
Ng Zhi An83473542018-02-20 09:02:14 -08001069 info.processName,
1070 info.launchedActivityName,
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001071 memoryStat.pgfault,
1072 memoryStat.pgmajfault,
1073 memoryStat.rssInBytes,
1074 memoryStat.cacheInBytes,
1075 memoryStat.swapInBytes);
1076 }
1077
Calin Juravle759fbda2018-02-20 19:52:30 +00001078 private ArtManagerInternal getArtManagerInternal() {
1079 if (mArtManagerInternal == null) {
1080 // Note that this may be null.
1081 // ArtManagerInternal is registered during PackageManagerService
1082 // initialization which happens after ActivityManagerService.
1083 mArtManagerInternal = LocalServices.getService(ArtManagerInternal.class);
1084 }
1085 return mArtManagerInternal;
1086 }
Vishnu Nair132ee832018-09-28 15:00:05 -07001087
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001088 /** Starts trace for an activity is actually launching. */
1089 private void startLaunchTrace(@NonNull TransitionInfo info) {
1090 if (DEBUG_METRICS) Slog.i(TAG, "startLaunchTrace " + info);
1091 if (!Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) {
Vishnu Nair132ee832018-09-28 15:00:05 -07001092 return;
1093 }
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001094 info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName;
Riddle Hsue8d3d192019-11-26 18:56:39 +08001095 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
1096 (int) info.mTransitionStartTimeNs /* cookie */);
Vishnu Nair132ee832018-09-28 15:00:05 -07001097 }
1098
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001099 /** Stops trace for the launch is completed or cancelled. */
1100 private void stopLaunchTrace(@NonNull TransitionInfo info) {
1101 if (DEBUG_METRICS) Slog.i(TAG, "stopLaunchTrace " + info);
1102 if (info.mLaunchTraceName == null) {
Vishnu Nair132ee832018-09-28 15:00:05 -07001103 return;
1104 }
Riddle Hsue8d3d192019-11-26 18:56:39 +08001105 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName,
1106 (int) info.mTransitionStartTimeNs /* cookie */);
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001107 info.mLaunchTraceName = null;
Vishnu Nair132ee832018-09-28 15:00:05 -07001108 }
Igor Murashkin212d06c2018-10-22 16:34:39 -07001109
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001110 public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() {
1111 return mLaunchObserver;
1112 }
1113
Igor Murashkin212d06c2018-10-22 16:34:39 -07001114 /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */
Yan Wangd47f90b2019-10-03 19:17:15 -07001115 private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001116 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1117 "MetricsLogger:launchObserverNotifyIntentStarted");
1118
1119 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
Yan Wangd47f90b2019-10-03 19:17:15 -07001120 mLaunchObserver.onIntentStarted(intent, timestampNs);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001121
1122 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001123 }
1124
1125 /**
1126 * Notify the {@link ActivityMetricsLaunchObserver} that the previous launch sequence has
1127 * aborted due to intent failure (e.g. intent resolve failed or security error, etc) or
1128 * intent being delivered to the top running activity.
1129 */
1130 private void launchObserverNotifyIntentFailed() {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001131 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1132 "MetricsLogger:launchObserverNotifyIntentFailed");
1133
1134 mLaunchObserver.onIntentFailed();
1135
1136 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001137 }
1138
1139 /**
1140 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1141 * has started.
1142 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001143 private void launchObserverNotifyActivityLaunched(TransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001144 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1145 "MetricsLogger:launchObserverNotifyActivityLaunched");
1146
Igor Murashkin212d06c2018-10-22 16:34:39 -07001147 @ActivityMetricsLaunchObserver.Temperature int temperature =
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001148 convertTransitionTypeToLaunchObserverTemperature(info.mTransitionType);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001149
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001150 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001151 mLaunchObserver.onActivityLaunched(convertActivityRecordToProto(info.mLastLaunchedActivity),
1152 temperature);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001153
1154 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001155 }
1156
1157 /**
Yan Wang9eac5ec2019-09-30 15:42:18 -07001158 * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event.
1159 */
Yan Wangd47f90b2019-10-03 19:17:15 -07001160 private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) {
Yan Wang9eac5ec2019-09-30 15:42:18 -07001161 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1162 "MetricsLogger:launchObserverNotifyReportFullyDrawn");
Yan Wangd47f90b2019-10-03 19:17:15 -07001163 mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs);
Yan Wang9eac5ec2019-09-30 15:42:18 -07001164 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1165 }
1166
1167 /**
Igor Murashkin212d06c2018-10-22 16:34:39 -07001168 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is
1169 * cancelled.
1170 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001171 private void launchObserverNotifyActivityLaunchCancelled(TransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001172 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1173 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001174
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001175 final @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] activityRecordProto =
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001176 info != null ? convertActivityRecordToProto(info.mLastLaunchedActivity) : null;
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001177
1178 mLaunchObserver.onActivityLaunchCancelled(activityRecordProto);
1179
1180 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001181 }
1182
1183 /**
1184 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1185 * has fully finished (successfully).
1186 */
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001187 private void launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001188 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1189 "MetricsLogger:launchObserverNotifyActivityLaunchFinished");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001190
Riddle Hsufd66d4d2019-11-14 10:35:55 +08001191 mLaunchObserver.onActivityLaunchFinished(
1192 convertActivityRecordToProto(info.mLastLaunchedActivity), timestampNs);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001193
1194 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1195 }
1196
1197 @VisibleForTesting
1198 static @ActivityMetricsLaunchObserver.ActivityRecordProto byte[]
1199 convertActivityRecordToProto(ActivityRecord record) {
1200 // May take non-negligible amount of time to convert ActivityRecord into a proto,
1201 // so track the time.
1202 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1203 "MetricsLogger:convertActivityRecordToProto");
1204
1205 // There does not appear to be a way to 'reset' a ProtoOutputBuffer stream,
1206 // so create a new one every time.
1207 final ProtoOutputStream protoOutputStream =
1208 new ProtoOutputStream(LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE);
1209 // Write this data out as the top-most ActivityRecordProto (i.e. it is not a sub-object).
Jeffrey Huangcb782852019-12-05 11:28:11 -08001210 record.dumpDebug(protoOutputStream);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001211 final byte[] bytes = protoOutputStream.getBytes();
1212
1213 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1214
1215 return bytes;
Igor Murashkin212d06c2018-10-22 16:34:39 -07001216 }
1217
1218 private static @ActivityMetricsLaunchObserver.Temperature int
1219 convertTransitionTypeToLaunchObserverTemperature(int transitionType) {
1220 switch (transitionType) {
1221 case TYPE_TRANSITION_WARM_LAUNCH:
1222 return ActivityMetricsLaunchObserver.TEMPERATURE_WARM;
1223 case TYPE_TRANSITION_HOT_LAUNCH:
1224 return ActivityMetricsLaunchObserver.TEMPERATURE_HOT;
1225 case TYPE_TRANSITION_COLD_LAUNCH:
1226 return ActivityMetricsLaunchObserver.TEMPERATURE_COLD;
1227 default:
1228 return -1;
1229 }
1230 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -08001231}