blob: 73034b020a76d3626d2e55adc693f9afd736a324 [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;
Vishnu Nair132ee832018-09-28 15:00:05 -070059import static com.android.server.am.EventLogTags.AM_ACTIVITY_LAUNCH_TIME;
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;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080066
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -080067import android.app.WaitResult;
Igor Murashkin212d06c2018-10-22 16:34:39 -070068import android.app.WindowConfiguration.WindowingMode;
Michal Karpinski319069b2019-03-27 15:46:50 +000069import android.content.ComponentName;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080070import android.content.Context;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010071import android.content.Intent;
Calin Juravle759fbda2018-02-20 19:52:30 +000072import android.content.pm.ApplicationInfo;
73import android.content.pm.dex.ArtManagerInternal;
74import android.content.pm.dex.PackageOptimizationInfo;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080075import android.metrics.LogMaker;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020076import android.os.Handler;
77import android.os.Looper;
78import android.os.Message;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080079import android.os.SystemClock;
Vishnu Nair132ee832018-09-28 15:00:05 -070080import android.os.Trace;
81import android.util.EventLog;
82import android.util.Log;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020083import android.util.Slog;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080084import android.util.SparseArray;
85import android.util.SparseIntArray;
Olivier Gaillardaed7f122017-12-12 14:26:22 +000086import android.util.StatsLog;
Vishnu Nair132ee832018-09-28 15:00:05 -070087import android.util.TimeUtils;
Igor Murashkinc0b47e42018-11-07 15:54:18 -080088import android.util.proto.ProtoOutputStream;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080089
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -080090import com.android.internal.annotations.VisibleForTesting;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080091import com.android.internal.logging.MetricsLogger;
Ng Zhi An83473542018-02-20 09:02:14 -080092import com.android.internal.os.BackgroundThread;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020093import com.android.internal.os.SomeArgs;
Calin Juravle759fbda2018-02-20 19:52:30 +000094import com.android.server.LocalServices;
Louis Changcdec0802019-11-11 11:45:07 +080095
Yan Wang9eac5ec2019-09-30 15:42:18 -070096import java.util.concurrent.TimeUnit;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080097
98/**
Vishnu Nair132ee832018-09-28 15:00:05 -070099 * Listens to activity launches, transitions, visibility changes and window drawn callbacks to
100 * determine app launch times and draw delays. Source of truth for activity metrics and provides
101 * data for Tron, logcat, event logs and {@link android.app.WaitResult}.
102 *
103 * Tests:
Tadashi G. Takaoka28bc3702019-04-23 11:01:48 +0900104 * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800105 */
106class ActivityMetricsLogger {
Jorim Jaggif9704102016-05-05 19:14:22 -0700107
Wale Ogunwale98875612018-10-12 07:53:02 -0700108 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM;
Jorim Jaggif9704102016-05-05 19:14:22 -0700109
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800110 // Window modes we are interested in logging. If we ever introduce a new type, we need to add
111 // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array.
112 private static final int WINDOW_STATE_STANDARD = 0;
113 private static final int WINDOW_STATE_SIDE_BY_SIDE = 1;
114 private static final int WINDOW_STATE_FREEFORM = 2;
Winson Chung83471632016-12-13 11:02:12 -0800115 private static final int WINDOW_STATE_ASSISTANT = 3;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800116 private static final int WINDOW_STATE_INVALID = -1;
117
Jorim Jaggi275561a2016-02-23 10:11:02 -0500118 private static final long INVALID_START_TIME = -1;
Vishnu Nair132ee832018-09-28 15:00:05 -0700119 private static final int INVALID_DELAY = -1;
120 private static final int INVALID_TRANSITION_TYPE = -1;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500121
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200122 private static final int MSG_CHECK_VISIBILITY = 0;
123
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800124 // Preallocated strings we are sending to tron, so we don't have to allocate a new one every
125 // time we log.
126 private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = {
Winson Chung83471632016-12-13 11:02:12 -0800127 "window_time_0", "window_time_1", "window_time_2", "window_time_3"};
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800128
129 private int mWindowState = WINDOW_STATE_STANDARD;
130 private long mLastLogTimeSecs;
131 private final ActivityStackSupervisor mSupervisor;
132 private final Context mContext;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800133 private final MetricsLogger mMetricsLogger = new MetricsLogger();
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800134
Igor Murashkin212d06c2018-10-22 16:34:39 -0700135 // set to INVALID_START_TIME in reset.
136 // set to valid value in notifyActivityLaunching
Yan Wangd47f90b2019-10-03 19:17:15 -0700137 private long mCurrentTransitionStartTimeNs = INVALID_START_TIME;
138 private long mLastTransitionStartTimeNs = INVALID_START_TIME;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800139
140 private int mCurrentTransitionDeviceUptime;
141 private int mCurrentTransitionDelayMs;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700142
143 /** If the any app transitions have been logged as starting, after the latest reset. */
Jorim Jaggi275561a2016-02-23 10:11:02 -0500144 private boolean mLoggedTransitionStarting;
145
Igor Murashkin212d06c2018-10-22 16:34:39 -0700146 /** Map : @WindowingMode int => WindowingModeTransitionInfo */
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100147 private final SparseArray<WindowingModeTransitionInfo> mWindowingModeTransitionInfo =
148 new SparseArray<>();
Igor Murashkin212d06c2018-10-22 16:34:39 -0700149 /** Map : @WindowingMode int => WindowingModeTransitionInfo */
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100150 private final SparseArray<WindowingModeTransitionInfo> mLastWindowingModeTransitionInfo =
151 new SparseArray<>();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200152 private final H mHandler;
Calin Juravle759fbda2018-02-20 19:52:30 +0000153
154 private ArtManagerInternal mArtManagerInternal;
Vishnu Nair132ee832018-09-28 15:00:05 -0700155 private final StringBuilder mStringBuilder = new StringBuilder();
Calin Juravle759fbda2018-02-20 19:52:30 +0000156
Igor Murashkin212d06c2018-10-22 16:34:39 -0700157 /**
158 * Due to the global single concurrent launch sequence, all calls to this observer must be made
159 * in-order on the same thread to fulfill the "happens-before" guarantee in LaunchObserver.
160 */
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800161 private final LaunchObserverRegistryImpl mLaunchObserver;
162 @VisibleForTesting static final int LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE = 512;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700163
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200164 private final class H extends Handler {
165
166 public H(Looper looper) {
167 super(looper);
168 }
169
170 @Override
171 public void handleMessage(Message msg) {
172 switch (msg.what) {
173 case MSG_CHECK_VISIBILITY:
174 final SomeArgs args = (SomeArgs) msg.obj;
Louis Changcdec0802019-11-11 11:45:07 +0800175 checkVisibility((Task) args.arg1, (ActivityRecord) args.arg2);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200176 break;
177 }
178 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000179 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800180
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100181 private final class WindowingModeTransitionInfo {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700182 /** The latest activity to have been launched. */
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800183 private ActivityRecord launchedActivity;
184 private int startResult;
185 private boolean currentTransitionProcessRunning;
Vishnu Nair132ee832018-09-28 15:00:05 -0700186 /** Elapsed time from when we launch an activity to when its windows are drawn. */
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800187 private int windowsDrawnDelayMs;
Vishnu Nair132ee832018-09-28 15:00:05 -0700188 private int startingWindowDelayMs = INVALID_DELAY;
189 private int bindApplicationDelayMs = INVALID_DELAY;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800190 private int reason = APP_TRANSITION_TIMEOUT;
Riddle Hsu99f2acd2019-10-22 18:41:51 +0800191 // TODO(b/132736359) The number may need to consider the visibility change.
192 private int numUndrawnActivities = 1;
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800193 /** Non-null if the application has reported drawn but its window hasn't. */
194 private Runnable pendingFullyDrawn;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800195 private boolean loggedStartingWindowDrawn;
Vishnu Nair132ee832018-09-28 15:00:05 -0700196 private boolean launchTraceActive;
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800197
198 /**
199 * Remembers the latest launched activity to represent the final transition. This also
200 * increments the number of activities that should be drawn, so a consecutive launching
201 * sequence can be coalesced as one event.
202 */
203 void setLatestLaunchedActivity(ActivityRecord r) {
204 if (launchedActivity == r) {
205 return;
206 }
207 launchedActivity = r;
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800208 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800209 }
210
Vishnu Nair132ee832018-09-28 15:00:05 -0700211 final class WindowingModeTransitionInfoSnapshot {
Calin Juravle759fbda2018-02-20 19:52:30 +0000212 final private ApplicationInfo applicationInfo;
Wale Ogunwalef6733932018-06-27 05:14:34 -0700213 final private WindowProcessController processRecord;
Vishnu Nair132ee832018-09-28 15:00:05 -0700214 final String packageName;
215 final String launchedActivityName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000216 final private String launchedActivityLaunchedFromPackage;
217 final private String launchedActivityLaunchToken;
218 final private String launchedActivityAppRecordRequiredAbi;
Vishnu Nair132ee832018-09-28 15:00:05 -0700219 final String launchedActivityShortComponentName;
Ng Zhi An83473542018-02-20 09:02:14 -0800220 final private String processName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000221 final private int reason;
222 final private int startingWindowDelayMs;
223 final private int bindApplicationDelayMs;
Vishnu Nair132ee832018-09-28 15:00:05 -0700224 final int windowsDrawnDelayMs;
225 final int type;
226 final int userId;
227 /**
228 * Elapsed time from when we launch an activity to when the app reported it was
229 * fully drawn. If this is not reported then the value is set to INVALID_DELAY.
230 */
231 final int windowsFullyDrawnDelayMs;
232 final int activityRecordIdHashCode;
Calin Juravle759fbda2018-02-20 19:52:30 +0000233
234 private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700235 this(info, info.launchedActivity);
236 }
237
238 private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info,
239 ActivityRecord launchedActivity) {
240 this(info, launchedActivity, INVALID_DELAY);
241 }
242
243 private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info,
244 ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs) {
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700245 applicationInfo = launchedActivity.info.applicationInfo;
Vishnu Nair132ee832018-09-28 15:00:05 -0700246 packageName = launchedActivity.packageName;
247 launchedActivityName = launchedActivity.info.name;
248 launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage;
249 launchedActivityLaunchToken = launchedActivity.info.launchToken;
250 launchedActivityAppRecordRequiredAbi = launchedActivity.app == null
Calin Juravle759fbda2018-02-20 19:52:30 +0000251 ? null
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700252 : launchedActivity.app.getRequiredAbi();
Calin Juravle759fbda2018-02-20 19:52:30 +0000253 reason = info.reason;
254 startingWindowDelayMs = info.startingWindowDelayMs;
255 bindApplicationDelayMs = info.bindApplicationDelayMs;
256 windowsDrawnDelayMs = info.windowsDrawnDelayMs;
257 type = getTransitionType(info);
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700258 processRecord = findProcessForActivity(launchedActivity);
259 processName = launchedActivity.processName;
Wale Ogunwale8b19de92018-11-29 19:58:26 -0800260 userId = launchedActivity.mUserId;
Vishnu Nair132ee832018-09-28 15:00:05 -0700261 launchedActivityShortComponentName = launchedActivity.shortComponentName;
262 activityRecordIdHashCode = System.identityHashCode(launchedActivity);
263 this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
Calin Juravle759fbda2018-02-20 19:52:30 +0000264 }
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -0800265
266 @WaitResult.LaunchState int getLaunchState() {
267 switch (type) {
268 case TYPE_TRANSITION_WARM_LAUNCH:
269 return LAUNCH_STATE_WARM;
270 case TYPE_TRANSITION_HOT_LAUNCH:
271 return LAUNCH_STATE_HOT;
272 case TYPE_TRANSITION_COLD_LAUNCH:
273 return LAUNCH_STATE_COLD;
274 default:
275 return -1;
276 }
277 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000278 }
279
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200280 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context, Looper looper) {
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800281 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
282 mSupervisor = supervisor;
283 mContext = context;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200284 mHandler = new H(looper);
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800285 mLaunchObserver = new LaunchObserverRegistryImpl(looper);
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800286 }
287
288 void logWindowState() {
289 final long now = SystemClock.elapsedRealtime() / 1000;
290 if (mWindowState != WINDOW_STATE_INVALID) {
291 // We log even if the window state hasn't changed, because the user might remain in
292 // home/fullscreen move forever and we would like to track this kind of behavior
293 // too.
294 MetricsLogger.count(mContext, TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState],
295 (int) (now - mLastLogTimeSecs));
296 }
297 mLastLogTimeSecs = now;
298
Wale Ogunwale926aade2017-08-29 11:24:37 -0700299 mWindowState = WINDOW_STATE_INVALID;
Wale Ogunwaled32da472018-11-16 07:19:28 -0800300 ActivityStack stack =
301 mSupervisor.mRootActivityContainer.getTopDisplayFocusedStack();
lumarkf6c4a982018-06-15 15:43:12 +0800302 if (stack == null) {
303 return;
304 }
305
Wale Ogunwale926aade2017-08-29 11:24:37 -0700306 if (stack.isActivityTypeAssistant()) {
307 mWindowState = WINDOW_STATE_ASSISTANT;
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800308 return;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800309 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700310
Igor Murashkin212d06c2018-10-22 16:34:39 -0700311 @WindowingMode int windowingMode = stack.getWindowingMode();
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700312 if (windowingMode == WINDOWING_MODE_PINNED) {
Wale Ogunwaled32da472018-11-16 07:19:28 -0800313 stack = mSupervisor.mRootActivityContainer.findStackBehind(stack);
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700314 windowingMode = stack.getWindowingMode();
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800315 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700316 switch (windowingMode) {
317 case WINDOWING_MODE_FULLSCREEN:
318 mWindowState = WINDOW_STATE_STANDARD;
319 break;
320 case WINDOWING_MODE_SPLIT_SCREEN_PRIMARY:
321 case WINDOWING_MODE_SPLIT_SCREEN_SECONDARY:
322 mWindowState = WINDOW_STATE_SIDE_BY_SIDE;
323 break;
Bryce Lee6c605092017-10-12 11:14:49 -0700324 case WINDOWING_MODE_FREEFORM:
Wale Ogunwale926aade2017-08-29 11:24:37 -0700325 mWindowState = WINDOW_STATE_FREEFORM;
326 break;
327 default:
328 if (windowingMode != WINDOWING_MODE_UNDEFINED) {
329 throw new IllegalStateException("Unknown windowing mode for stack=" + stack
330 + " windowingMode=" + windowingMode);
331 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800332 }
333 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500334
335 /**
336 * Notifies the tracker at the earliest possible point when we are starting to launch an
337 * activity.
338 */
Igor Murashkin212d06c2018-10-22 16:34:39 -0700339 void notifyActivityLaunching(Intent intent) {
340 if (DEBUG_METRICS) {
341 Slog.i(TAG, String.format("notifyActivityLaunching: active:%b, intent:%s",
342 isAnyTransitionActive(),
343 intent));
344 }
345
Yan Wangd47f90b2019-10-03 19:17:15 -0700346 if (mCurrentTransitionStartTimeNs == INVALID_START_TIME) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700347
Yan Wangd47f90b2019-10-03 19:17:15 -0700348 mCurrentTransitionStartTimeNs = SystemClock.elapsedRealtimeNanos();
349 mLastTransitionStartTimeNs = mCurrentTransitionStartTimeNs;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700350
Yan Wangd47f90b2019-10-03 19:17:15 -0700351 launchObserverNotifyIntentStarted(intent, mCurrentTransitionStartTimeNs);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800352 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500353 }
354
355 /**
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700356 * Notifies the tracker that the activity is actually launching.
357 *
358 * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the
359 * launch
360 * @param launchedActivity the activity that is being launched
361 */
362 void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity) {
Wale Ogunwalef6733932018-06-27 05:14:34 -0700363 final WindowProcessController processRecord = findProcessForActivity(launchedActivity);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700364 final boolean processRunning = processRecord != null;
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700365
366 // We consider this a "process switch" if the process of the activity that gets launched
367 // didn't have an activity that was in started state. In this case, we assume that lot
368 // of caches might be purged so the time until it produces the first frame is very
369 // interesting.
370 final boolean processSwitch = processRecord == null
Wale Ogunwalef6733932018-06-27 05:14:34 -0700371 || !processRecord.hasStartedActivity(launchedActivity);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700372
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800373 notifyActivityLaunched(resultCode, launchedActivity, processRunning, processSwitch);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700374 }
375
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700376 /**
Jorim Jaggi275561a2016-02-23 10:11:02 -0500377 * Notifies the tracker the the activity is actually launching.
378 *
379 * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the
380 * launch
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800381 * @param launchedActivity the activity being launched
Jorim Jaggi275561a2016-02-23 10:11:02 -0500382 * @param processRunning whether the process that will contains the activity is already running
Jorim Jaggibe67c902016-04-12 00:53:16 -0700383 * @param processSwitch whether the process that will contain the activity didn't have any
384 * activity that was stopped, i.e. the started activity is "switching"
385 * processes
Jorim Jaggi275561a2016-02-23 10:11:02 -0500386 */
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800387 private void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity,
Jorim Jaggibe67c902016-04-12 00:53:16 -0700388 boolean processRunning, boolean processSwitch) {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500389
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200390 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched"
391 + " resultCode=" + resultCode
392 + " launchedActivity=" + launchedActivity
393 + " processRunning=" + processRunning
394 + " processSwitch=" + processSwitch);
395
Igor Murashkin212d06c2018-10-22 16:34:39 -0700396 // If we are already in an existing transition, only update the activity name, but not the
397 // other attributes.
398 final @WindowingMode int windowingMode = launchedActivity != null
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100399 ? launchedActivity.getWindowingMode()
400 : WINDOWING_MODE_UNDEFINED;
Vishnu Nairf8accc52018-10-11 10:19:54 -0700401 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
Yan Wangd47f90b2019-10-03 19:17:15 -0700402 if (mCurrentTransitionStartTimeNs == INVALID_START_TIME) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700403 // No transition is active ignore this launch.
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200404 return;
405 }
406
Vishnu Nair9ba31652018-11-13 14:34:05 -0800407 if (launchedActivity != null && launchedActivity.mDrawn) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700408 // Launched activity is already visible. We cannot measure windows drawn delay.
Riddle Hsu1063b512019-10-22 21:12:23 +0800409 abort(info, "launched activity already visible");
Vishnu Nairf8accc52018-10-11 10:19:54 -0700410 return;
411 }
412
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800413 if (launchedActivity != null && info != null) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700414 // If we are already in an existing transition, only update the activity name, but not
415 // the other attributes.
Igor Murashkin212d06c2018-10-22 16:34:39 -0700416
417 // Coalesce multiple (trampoline) activities from a single sequence together.
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800418 info.setLatestLaunchedActivity(launchedActivity);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500419 return;
420 }
421
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100422 final boolean otherWindowModesLaunching =
423 mWindowingModeTransitionInfo.size() > 0 && info == null;
Jorim Jaggi54cff642018-03-15 15:51:32 +0100424 if ((!isLoggableResultCode(resultCode) || launchedActivity == null || !processSwitch
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100425 || windowingMode == WINDOWING_MODE_UNDEFINED) && !otherWindowModesLaunching) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800426 // Failed to launch or it was not a process switch, so we don't care about the timing.
Riddle Hsu1063b512019-10-22 21:12:23 +0800427 abort(info, "failed to launch or not a process switch");
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800428 return;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100429 } else if (otherWindowModesLaunching) {
430 // Don't log this windowing mode but continue with the other windowing modes.
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800431 return;
432 }
433
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200434 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
435
Igor Murashkin212d06c2018-10-22 16:34:39 -0700436 // A new launch sequence [with the windowingMode] has begun.
437 // Start tracking it.
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100438 final WindowingModeTransitionInfo newInfo = new WindowingModeTransitionInfo();
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800439 newInfo.setLatestLaunchedActivity(launchedActivity);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800440 newInfo.currentTransitionProcessRunning = processRunning;
441 newInfo.startResult = resultCode;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100442 mWindowingModeTransitionInfo.put(windowingMode, newInfo);
443 mLastWindowingModeTransitionInfo.put(windowingMode, newInfo);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800444 mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000);
Vishnu Nair132ee832018-09-28 15:00:05 -0700445 startTraces(newInfo);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700446 launchObserverNotifyActivityLaunched(newInfo);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500447 }
448
449 /**
Jorim Jaggi54cff642018-03-15 15:51:32 +0100450 * @return True if we should start logging an event for an activity start that returned
451 * {@code resultCode} and that we'll indeed get a windows drawn event.
452 */
453 private boolean isLoggableResultCode(int resultCode) {
454 return resultCode == START_SUCCESS || resultCode == START_TASK_TO_FRONT;
455 }
456
457 /**
Jorim Jaggi275561a2016-02-23 10:11:02 -0500458 * Notifies the tracker that all windows of the app have been drawn.
459 */
Igor Murashkin212d06c2018-10-22 16:34:39 -0700460 WindowingModeTransitionInfoSnapshot notifyWindowsDrawn(@WindowingMode int windowingMode,
Yan Wangd47f90b2019-10-03 19:17:15 -0700461 long timestampNs) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100462 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn windowingMode=" + windowingMode);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200463
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100464 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800465 if (info == null || info.numUndrawnActivities == 0) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700466 return null;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500467 }
Yan Wangd47f90b2019-10-03 19:17:15 -0700468 info.windowsDrawnDelayMs = calculateDelay(timestampNs);
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800469 info.numUndrawnActivities--;
Vishnu Nair132ee832018-09-28 15:00:05 -0700470 final WindowingModeTransitionInfoSnapshot infoSnapshot =
471 new WindowingModeTransitionInfoSnapshot(info);
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100472 if (allWindowsDrawn() && mLoggedTransitionStarting) {
Riddle Hsu1063b512019-10-22 21:12:23 +0800473 reset(false /* abort */, info, "notifyWindowsDrawn - all windows drawn", timestampNs);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500474 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700475 return infoSnapshot;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500476 }
477
478 /**
479 * Notifies the tracker that the starting window was drawn.
480 */
Yan Wangb0b20062019-10-30 12:47:09 -0700481 void notifyStartingWindowDrawn(@WindowingMode int windowingMode, long timestampNs) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100482 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800483 if (info == null || info.loggedStartingWindowDrawn) {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500484 return;
485 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800486 info.loggedStartingWindowDrawn = true;
Yan Wangb0b20062019-10-30 12:47:09 -0700487 info.startingWindowDelayMs = calculateDelay(timestampNs);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500488 }
489
490 /**
491 * Notifies the tracker that the app transition is starting.
492 *
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100493 * @param windowingModeToReason A map from windowing mode to a reason integer, which must be on
Vishnu Nair132ee832018-09-28 15:00:05 -0700494 * of ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500495 */
Yan Wangd47f90b2019-10-03 19:17:15 -0700496 void notifyTransitionStarting(SparseIntArray windowingModeToReason, long timestampNs) {
Jorim Jaggid8a57772017-04-14 16:50:42 -0700497 if (!isAnyTransitionActive() || mLoggedTransitionStarting) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700498 // Ignore calls to this made after a reset and prior to notifyActivityLaunching.
499
500 // Ignore any subsequent notifyTransitionStarting until the next reset.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500501 return;
502 }
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200503 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
Yan Wangd47f90b2019-10-03 19:17:15 -0700504 mCurrentTransitionDelayMs = calculateDelay(timestampNs);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500505 mLoggedTransitionStarting = true;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700506
507 WindowingModeTransitionInfo foundInfo = null;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100508 for (int index = windowingModeToReason.size() - 1; index >= 0; index--) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700509 final @WindowingMode int windowingMode = windowingModeToReason.keyAt(index);
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100510 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(
511 windowingMode);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800512 if (info == null) {
513 continue;
514 }
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100515 info.reason = windowingModeToReason.valueAt(index);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700516 foundInfo = info;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800517 }
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100518 if (allWindowsDrawn()) {
Vishnu Naira62534b2018-11-09 09:13:22 -0800519 // abort metrics collection if we cannot find a matching transition.
520 final boolean abortMetrics = foundInfo == null;
Yan Wangd47f90b2019-10-03 19:17:15 -0700521 reset(abortMetrics, foundInfo, "notifyTransitionStarting - all windows drawn",
522 timestampNs /* timestampNs */);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500523 }
524 }
525
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200526 /**
527 * Notifies the tracker that the visibility of an app is changing.
528 *
529 * @param activityRecord the app that is changing its visibility
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200530 */
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200531 void notifyVisibilityChanged(ActivityRecord activityRecord) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100532 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(
533 activityRecord.getWindowingMode());
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200534 if (info == null) {
535 return;
536 }
537 if (info.launchedActivity != activityRecord) {
538 return;
539 }
Louis Changcdec0802019-11-11 11:45:07 +0800540 final Task t = activityRecord.getTask();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200541 final SomeArgs args = SomeArgs.obtain();
542 args.arg1 = t;
543 args.arg2 = activityRecord;
544 mHandler.obtainMessage(MSG_CHECK_VISIBILITY, args).sendToTarget();
545 }
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200546
Riddle Hsu1063b512019-10-22 21:12:23 +0800547 /** @return {@code true} if the given task has an activity will be drawn. */
Louis Changcdec0802019-11-11 11:45:07 +0800548 private static boolean hasActivityToBeDrawn(Task t) {
Wale Ogunwale1a06f152019-10-11 11:26:30 +0200549 for (int i = t.getChildCount() - 1; i >= 0; --i) {
550 final ActivityRecord r = t.getChildAt(i);
Riddle Hsu1063b512019-10-22 21:12:23 +0800551 if (r.visible && !r.mDrawn && !r.finishing) {
Vishnu Nairb1de42d2019-01-28 09:49:51 -0800552 return true;
553 }
554 }
555 return false;
556 }
557
Louis Changcdec0802019-11-11 11:45:07 +0800558 private void checkVisibility(Task t, ActivityRecord r) {
Wale Ogunwalec9e57de2018-05-08 14:28:07 -0700559 synchronized (mSupervisor.mService.mGlobalLock) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200560
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100561 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(
562 r.getWindowingMode());
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200563
564 // If we have an active transition that's waiting on a certain activity that will be
565 // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary.
Vishnu Naird15063b2019-06-11 08:08:25 -0700566
567 // We have no active transitions.
568 if (info == null) {
569 return;
570 }
571
572 // The notified activity whose visibility changed is no longer the launched activity.
573 // We can still wait to get onWindowsDrawn.
574 if (info.launchedActivity != r) {
575 return;
576 }
577
Riddle Hsu1063b512019-10-22 21:12:23 +0800578 // If the task of the launched activity contains any activity to be drawn, then the
579 // window drawn event should report later to complete the transition. Otherwise all
580 // activities in this task may be finished, invisible or drawn, so the transition event
581 // should be cancelled.
582 if (hasActivityToBeDrawn(t)) {
Vishnu Naird15063b2019-06-11 08:08:25 -0700583 return;
584 }
585
586 if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible activity=" + r);
587 logAppTransitionCancel(info);
Riddle Hsu1063b512019-10-22 21:12:23 +0800588 // Abort if this is the only one active transition.
589 if (mWindowingModeTransitionInfo.size() == 1
590 && mWindowingModeTransitionInfo.get(r.getWindowingMode()) != null) {
591 abort(info, "notifyVisibilityChanged to invisible");
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200592 }
593 }
594 }
595
Jorim Jaggi515dd682017-05-05 15:05:07 +0200596 /**
597 * Notifies the tracker that we called immediately before we call bindApplication on the client.
598 *
Wale Ogunwale31913b52018-10-13 08:29:31 -0700599 * @param appInfo The client into which we'll call bindApplication.
Jorim Jaggi515dd682017-05-05 15:05:07 +0200600 */
Wale Ogunwale31913b52018-10-13 08:29:31 -0700601 void notifyBindApplication(ApplicationInfo appInfo) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100602 for (int i = mWindowingModeTransitionInfo.size() - 1; i >= 0; i--) {
603 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.valueAt(i);
Jorim Jaggi515dd682017-05-05 15:05:07 +0200604
605 // App isn't attached to record yet, so match with info.
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700606 if (info.launchedActivity.info.applicationInfo == appInfo) {
Jorim Jaggi515dd682017-05-05 15:05:07 +0200607 info.bindApplicationDelayMs = calculateCurrentDelay();
608 }
609 }
610 }
611
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800612 @VisibleForTesting
613 boolean allWindowsDrawn() {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100614 for (int index = mWindowingModeTransitionInfo.size() - 1; index >= 0; index--) {
Riddle Hsu1c5d72e2019-10-09 20:54:26 +0800615 if (mWindowingModeTransitionInfo.valueAt(index).numUndrawnActivities != 0) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800616 return false;
617 }
618 }
619 return true;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500620 }
621
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800622 private boolean isAnyTransitionActive() {
Yan Wangd47f90b2019-10-03 19:17:15 -0700623 return mCurrentTransitionStartTimeNs != INVALID_START_TIME
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100624 && mWindowingModeTransitionInfo.size() > 0;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800625 }
626
Riddle Hsu1063b512019-10-22 21:12:23 +0800627 /** Aborts tracking of current launch metrics. */
628 private void abort(WindowingModeTransitionInfo info, String cause) {
629 reset(true /* abort */, info, cause, 0L /* timestampNs */);
630 }
631
Yan Wangd47f90b2019-10-03 19:17:15 -0700632 private void reset(boolean abort, WindowingModeTransitionInfo info, String cause,
Riddle Hsu1063b512019-10-22 21:12:23 +0800633 long timestampNs) {
634 final boolean isAnyTransitionActive = isAnyTransitionActive();
Yan Wangd47f90b2019-10-03 19:17:15 -0700635 if (DEBUG_METRICS) {
Riddle Hsu1063b512019-10-22 21:12:23 +0800636 Slog.i(TAG, "reset abort=" + abort + " cause=" + cause + " timestamp=" + timestampNs
637 + " active=" + isAnyTransitionActive);
Yan Wangd47f90b2019-10-03 19:17:15 -0700638 }
Riddle Hsu1063b512019-10-22 21:12:23 +0800639 if (!abort && isAnyTransitionActive) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800640 logAppTransitionMultiEvents();
641 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700642 stopLaunchTrace(info);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700643
644 // Ignore reset-after reset.
Riddle Hsu1063b512019-10-22 21:12:23 +0800645 if (isAnyTransitionActive) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700646 // LaunchObserver callbacks.
647 if (abort) {
648 launchObserverNotifyActivityLaunchCancelled(info);
649 } else {
Yan Wangd47f90b2019-10-03 19:17:15 -0700650 launchObserverNotifyActivityLaunchFinished(info, timestampNs);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700651 }
652 } else {
653 launchObserverNotifyIntentFailed();
654 }
655
Yan Wangd47f90b2019-10-03 19:17:15 -0700656 mCurrentTransitionStartTimeNs = INVALID_START_TIME;
Vishnu Nair132ee832018-09-28 15:00:05 -0700657 mCurrentTransitionDelayMs = INVALID_DELAY;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500658 mLoggedTransitionStarting = false;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100659 mWindowingModeTransitionInfo.clear();
Jorim Jaggi275561a2016-02-23 10:11:02 -0500660 }
661
662 private int calculateCurrentDelay() {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500663 // Shouldn't take more than 25 days to launch an app, so int is fine here.
Yan Wangd47f90b2019-10-03 19:17:15 -0700664 return (int) TimeUnit.NANOSECONDS
665 .toMillis(SystemClock.elapsedRealtimeNanos() - mCurrentTransitionStartTimeNs);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500666 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800667
Yan Wangd47f90b2019-10-03 19:17:15 -0700668 private int calculateDelay(long timestampNs) {
Sudheer Shankac766db02017-06-12 10:37:29 -0700669 // Shouldn't take more than 25 days to launch an app, so int is fine here.
Yan Wangd47f90b2019-10-03 19:17:15 -0700670 return (int) TimeUnit.NANOSECONDS.toMillis(timestampNs -
671 mCurrentTransitionStartTimeNs);
Sudheer Shankac766db02017-06-12 10:37:29 -0700672 }
673
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100674 private void logAppTransitionCancel(WindowingModeTransitionInfo info) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200675 final int type = getTransitionType(info);
Vishnu Nair132ee832018-09-28 15:00:05 -0700676 if (type == INVALID_TRANSITION_TYPE) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200677 return;
678 }
679 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
680 builder.setPackageName(info.launchedActivity.packageName);
681 builder.setType(type);
682 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivity.info.name);
683 mMetricsLogger.write(builder);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000684 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800685 StatsLog.APP_START_CANCELED,
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700686 info.launchedActivity.info.applicationInfo.uid,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000687 info.launchedActivity.packageName,
688 convertAppStartTransitionType(type),
689 info.launchedActivity.info.name);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700690 if (DEBUG_METRICS) {
691 Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)",
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700692 info.launchedActivity.info.applicationInfo.uid,
Igor Murashkin212d06c2018-10-22 16:34:39 -0700693 info.launchedActivity.packageName,
694 convertAppStartTransitionType(type),
695 info.launchedActivity.info.name));
696 }
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200697 }
698
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800699 private void logAppTransitionMultiEvents() {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200700 if (DEBUG_METRICS) Slog.i(TAG, "logging transition events");
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100701 for (int index = mWindowingModeTransitionInfo.size() - 1; index >= 0; index--) {
702 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.valueAt(index);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800703 final int type = getTransitionType(info);
Vishnu Nair132ee832018-09-28 15:00:05 -0700704 if (type == INVALID_TRANSITION_TYPE) {
Vishnu Nair194c64f2019-04-12 13:51:40 -0700705 if (DEBUG_METRICS) {
706 Slog.i(TAG, "invalid transition type"
707 + " processRunning=" + info.currentTransitionProcessRunning
708 + " startResult=" + info.startResult);
709 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800710 return;
711 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000712
713 // Take a snapshot of the transition info before sending it to the handler for logging.
714 // This will avoid any races with other operations that modify the ActivityRecord.
715 final WindowingModeTransitionInfoSnapshot infoSnapshot =
Yan Wangd47f90b2019-10-03 19:17:15 -0700716 new WindowingModeTransitionInfoSnapshot(info);
Ng Zhi An83473542018-02-20 09:02:14 -0800717 final int currentTransitionDeviceUptime = mCurrentTransitionDeviceUptime;
718 final int currentTransitionDelayMs = mCurrentTransitionDelayMs;
719 BackgroundThread.getHandler().post(() -> logAppTransition(
720 currentTransitionDeviceUptime, currentTransitionDelayMs, infoSnapshot));
Vishnu Nair132ee832018-09-28 15:00:05 -0700721 BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800722 if (info.pendingFullyDrawn != null) {
723 info.pendingFullyDrawn.run();
724 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000725
726 info.launchedActivity.info.launchToken = null;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800727 }
728 }
729
Ng Zhi An83473542018-02-20 09:02:14 -0800730 // This gets called on a background thread without holding the activity manager lock.
Calin Juravle759fbda2018-02-20 19:52:30 +0000731 private void logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs,
732 WindowingModeTransitionInfoSnapshot info) {
733 final LogMaker builder = new LogMaker(APP_TRANSITION);
734 builder.setPackageName(info.packageName);
735 builder.setType(info.type);
736 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName);
737 final boolean isInstantApp = info.applicationInfo.isInstantApp();
738 if (info.launchedActivityLaunchedFromPackage != null) {
739 builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME,
740 info.launchedActivityLaunchedFromPackage);
741 }
742 String launchToken = info.launchedActivityLaunchToken;
743 if (launchToken != null) {
744 builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, launchToken);
745 }
746 builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0);
747 builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS,
748 currentTransitionDeviceUptime);
749 builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs);
750 builder.setSubtype(info.reason);
Vishnu Nair132ee832018-09-28 15:00:05 -0700751 if (info.startingWindowDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000752 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
753 info.startingWindowDelayMs);
754 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700755 if (info.bindApplicationDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000756 builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS,
757 info.bindApplicationDelayMs);
758 }
759 builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs);
760 final ArtManagerInternal artManagerInternal = getArtManagerInternal();
761 final PackageOptimizationInfo packageOptimizationInfo =
762 (artManagerInternal == null) || (info.launchedActivityAppRecordRequiredAbi == null)
763 ? PackageOptimizationInfo.createWithNoInfo()
764 : artManagerInternal.getPackageOptimizationInfo(
765 info.applicationInfo,
766 info.launchedActivityAppRecordRequiredAbi);
767 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON,
768 packageOptimizationInfo.getCompilationReason());
769 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER,
770 packageOptimizationInfo.getCompilationFilter());
771 mMetricsLogger.write(builder);
772 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800773 StatsLog.APP_START_OCCURRED,
Calin Juravle759fbda2018-02-20 19:52:30 +0000774 info.applicationInfo.uid,
775 info.packageName,
776 convertAppStartTransitionType(info.type),
777 info.launchedActivityName,
778 info.launchedActivityLaunchedFromPackage,
779 isInstantApp,
780 currentTransitionDeviceUptime * 1000,
781 info.reason,
782 currentTransitionDelayMs,
783 info.startingWindowDelayMs,
784 info.bindApplicationDelayMs,
785 info.windowsDrawnDelayMs,
786 launchToken,
787 packageOptimizationInfo.getCompilationReason(),
788 packageOptimizationInfo.getCompilationFilter());
Igor Murashkin212d06c2018-10-22 16:34:39 -0700789
790 if (DEBUG_METRICS) {
791 Slog.i(TAG, String.format("APP_START_OCCURRED(%s, %s, %s, %s, %s)",
792 info.applicationInfo.uid,
793 info.packageName,
794 convertAppStartTransitionType(info.type),
795 info.launchedActivityName,
796 info.launchedActivityLaunchedFromPackage));
797 }
798
799
Ng Zhi An83473542018-02-20 09:02:14 -0800800 logAppStartMemoryStateCapture(info);
Calin Juravle759fbda2018-02-20 19:52:30 +0000801 }
802
Vishnu Nair132ee832018-09-28 15:00:05 -0700803 private void logAppDisplayed(WindowingModeTransitionInfoSnapshot info) {
804 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
805 return;
806 }
807
808 EventLog.writeEvent(AM_ACTIVITY_LAUNCH_TIME,
809 info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,
810 info.windowsDrawnDelayMs);
811
812 StringBuilder sb = mStringBuilder;
813 sb.setLength(0);
814 sb.append("Displayed ");
815 sb.append(info.launchedActivityShortComponentName);
816 sb.append(": ");
817 TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
818 Log.i(TAG, sb.toString());
819 }
820
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000821 private int convertAppStartTransitionType(int tronType) {
822 if (tronType == TYPE_TRANSITION_COLD_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800823 return StatsLog.APP_START_OCCURRED__TYPE__COLD;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000824 }
825 if (tronType == TYPE_TRANSITION_WARM_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800826 return StatsLog.APP_START_OCCURRED__TYPE__WARM;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000827 }
828 if (tronType == TYPE_TRANSITION_HOT_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800829 return StatsLog.APP_START_OCCURRED__TYPE__HOT;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000830 }
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800831 return StatsLog.APP_START_OCCURRED__TYPE__UNKNOWN;
Riddle Hsuc48c8912019-10-31 13:34:27 +0800832 }
833
834 /** @return the last known window drawn delay of the given windowing mode. */
835 int getLastDrawnDelayMs(@WindowingMode int windowingMode) {
836 final WindowingModeTransitionInfo info = mLastWindowingModeTransitionInfo.get(
837 windowingMode);
838 return info != null ? info.windowsDrawnDelayMs : INVALID_DELAY;
839 }
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000840
Vishnu Nair132ee832018-09-28 15:00:05 -0700841 WindowingModeTransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
842 boolean restoredFromBundle) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100843 final WindowingModeTransitionInfo info = mLastWindowingModeTransitionInfo.get(
844 r.getWindowingMode());
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200845 if (info == null) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700846 return null;
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200847 }
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800848 if (info.numUndrawnActivities > 0 && info.pendingFullyDrawn == null) {
849 // There are still undrawn activities, postpone reporting fully drawn until all of its
850 // windows are drawn. So that is closer to an usable state.
851 info.pendingFullyDrawn = () -> {
852 logAppTransitionReportedDrawn(r, restoredFromBundle);
853 info.pendingFullyDrawn = null;
854 };
855 return null;
856 }
Chris Wailes35c193c2018-10-09 18:12:00 -0700857
858 // Record the handling of the reportFullyDrawn callback in the trace system. This is not
859 // actually used to trace this function, but instead the logical task that this function
860 // fullfils (handling reportFullyDrawn() callbacks).
861 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
862 "ActivityManager:ReportingFullyDrawn " + info.launchedActivity.packageName);
863
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200864 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
865 builder.setPackageName(r.packageName);
866 builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
Riddle Hsuc1f8f9c2019-10-25 16:54:33 +0800867 final long currentTimestampNs = SystemClock.elapsedRealtimeNanos();
868 final long startupTimeMs = info.pendingFullyDrawn != null
869 ? info.windowsDrawnDelayMs
870 : TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - mLastTransitionStartTimeNs);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000871 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200872 builder.setType(restoredFromBundle
873 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
874 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
875 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,
876 info.currentTransitionProcessRunning ? 1 : 0);
877 mMetricsLogger.write(builder);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000878 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800879 StatsLog.APP_START_FULLY_DRAWN,
Andrii Kulianeceebbf2019-06-26 17:36:51 -0700880 info.launchedActivity.info.applicationInfo.uid,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000881 info.launchedActivity.packageName,
882 restoredFromBundle
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800883 ? StatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
884 : StatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000885 info.launchedActivity.info.name,
886 info.currentTransitionProcessRunning,
887 startupTimeMs);
Chris Wailes35c193c2018-10-09 18:12:00 -0700888
889 // Ends the trace started at the beginning of this function. This is located here to allow
890 // the trace slice to have a noticable duration.
891 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
892
Vishnu Nair132ee832018-09-28 15:00:05 -0700893 final WindowingModeTransitionInfoSnapshot infoSnapshot =
894 new WindowingModeTransitionInfoSnapshot(info, r, (int) startupTimeMs);
895 BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));
Yan Wang9eac5ec2019-09-30 15:42:18 -0700896
897 // Notify reportFullyDrawn event.
898 launchObserverNotifyReportFullyDrawn(r, currentTimestampNs);
899
Vishnu Nair132ee832018-09-28 15:00:05 -0700900 return infoSnapshot;
901 }
902
903 private void logAppFullyDrawn(WindowingModeTransitionInfoSnapshot info) {
904 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
905 return;
906 }
907
908 StringBuilder sb = mStringBuilder;
909 sb.setLength(0);
910 sb.append("Fully drawn ");
911 sb.append(info.launchedActivityShortComponentName);
912 sb.append(": ");
913 TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb);
914 Log.i(TAG, sb.toString());
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200915 }
916
Michal Karpinski4fd5b842019-01-28 15:13:32 +0000917 void logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp,
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100918 int callingUid, String callingPackage, int callingUidProcState,
919 boolean callingUidHasAnyVisibleWindow,
920 int realCallingUid, int realCallingUidProcState,
921 boolean realCallingUidHasAnyVisibleWindow,
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100922 boolean comingFromPendingIntent) {
923
924 final long nowElapsed = SystemClock.elapsedRealtime();
925 final long nowUptime = SystemClock.uptimeMillis();
926 final LogMaker builder = new LogMaker(ACTION_ACTIVITY_START);
927 builder.setTimestamp(System.currentTimeMillis());
928 builder.addTaggedData(FIELD_CALLING_UID, callingUid);
929 builder.addTaggedData(FIELD_CALLING_PACKAGE_NAME, callingPackage);
930 builder.addTaggedData(FIELD_CALLING_UID_PROC_STATE,
931 processStateAmToProto(callingUidProcState));
932 builder.addTaggedData(FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
933 callingUidHasAnyVisibleWindow ? 1 : 0);
934 builder.addTaggedData(FIELD_REAL_CALLING_UID, realCallingUid);
935 builder.addTaggedData(FIELD_REAL_CALLING_UID_PROC_STATE,
936 processStateAmToProto(realCallingUidProcState));
937 builder.addTaggedData(FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
938 realCallingUidHasAnyVisibleWindow ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100939 builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0);
Michal Karpinski8596ded2018-11-14 14:43:48 +0000940 if (intent != null) {
941 builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction());
Michal Karpinski319069b2019-03-27 15:46:50 +0000942 ComponentName component = intent.getComponent();
943 if (component != null) {
944 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME,
945 component.flattenToShortString());
946 }
Michal Karpinski8596ded2018-11-14 14:43:48 +0000947 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100948 if (callerApp != null) {
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700949 builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100950 builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700951 processStateAmToProto(callerApp.getCurrentProcState()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100952 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700953 callerApp.hasClientActivities() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100954 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES,
955 callerApp.hasForegroundServices() ? 1 : 0);
956 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700957 callerApp.hasForegroundActivities() ? 1 : 0);
958 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100959 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700960 callerApp.hasOverlayUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100961 builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700962 callerApp.hasPendingUiClean() ? 1 : 0);
963 if (callerApp.getInteractionEventTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100964 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700965 (nowElapsed - callerApp.getInteractionEventTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100966 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700967 if (callerApp.getFgInteractionTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100968 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700969 (nowElapsed - callerApp.getFgInteractionTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100970 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700971 if (callerApp.getWhenUnimportant() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100972 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700973 (nowUptime - callerApp.getWhenUnimportant()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100974 }
975 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100976 mMetricsLogger.write(builder);
977 }
978
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100979 private int getTransitionType(WindowingModeTransitionInfo info) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800980 if (info.currentTransitionProcessRunning) {
981 if (info.startResult == START_SUCCESS) {
982 return TYPE_TRANSITION_WARM_LAUNCH;
983 } else if (info.startResult == START_TASK_TO_FRONT) {
984 return TYPE_TRANSITION_HOT_LAUNCH;
985 }
Vishnu Nair194c64f2019-04-12 13:51:40 -0700986 } else if (info.startResult == START_SUCCESS
987 || (info.startResult == START_TASK_TO_FRONT)) {
Louis Changcdec0802019-11-11 11:45:07 +0800988 // Task may still exist when cold launching an activity and the start
Vishnu Nair194c64f2019-04-12 13:51:40 -0700989 // result will be set to START_TASK_TO_FRONT. Treat this as a COLD launch.
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800990 return TYPE_TRANSITION_COLD_LAUNCH;
991 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700992 return INVALID_TRANSITION_TYPE;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800993 }
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800994
Ng Zhi An83473542018-02-20 09:02:14 -0800995 private void logAppStartMemoryStateCapture(WindowingModeTransitionInfoSnapshot info) {
996 if (info.processRecord == null) {
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800997 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null");
998 return;
999 }
1000
Wale Ogunwalef6733932018-06-27 05:14:34 -07001001 final int pid = info.processRecord.getPid();
Ng Zhi An83473542018-02-20 09:02:14 -08001002 final int uid = info.applicationInfo.uid;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +00001003 final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid);
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001004 if (memoryStat == null) {
1005 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null");
1006 return;
1007 }
1008
1009 StatsLog.write(
1010 StatsLog.APP_START_MEMORY_STATE_CAPTURED,
1011 uid,
Ng Zhi An83473542018-02-20 09:02:14 -08001012 info.processName,
1013 info.launchedActivityName,
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001014 memoryStat.pgfault,
1015 memoryStat.pgmajfault,
1016 memoryStat.rssInBytes,
1017 memoryStat.cacheInBytes,
1018 memoryStat.swapInBytes);
1019 }
1020
Wale Ogunwalef6733932018-06-27 05:14:34 -07001021 private WindowProcessController findProcessForActivity(ActivityRecord launchedActivity) {
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001022 return launchedActivity != null
Wale Ogunwalef6733932018-06-27 05:14:34 -07001023 ? mSupervisor.mService.mProcessNames.get(
Andrii Kulianeceebbf2019-06-26 17:36:51 -07001024 launchedActivity.processName, launchedActivity.info.applicationInfo.uid)
Ng Zhi Anbbefdec2018-01-30 17:12:39 -08001025 : null;
1026 }
Calin Juravle759fbda2018-02-20 19:52:30 +00001027
1028 private ArtManagerInternal getArtManagerInternal() {
1029 if (mArtManagerInternal == null) {
1030 // Note that this may be null.
1031 // ArtManagerInternal is registered during PackageManagerService
1032 // initialization which happens after ActivityManagerService.
1033 mArtManagerInternal = LocalServices.getService(ArtManagerInternal.class);
1034 }
1035 return mArtManagerInternal;
1036 }
Vishnu Nair132ee832018-09-28 15:00:05 -07001037
1038 /**
Chris Wailes35c193c2018-10-09 18:12:00 -07001039 * Starts traces for app launch.
Vishnu Nair132ee832018-09-28 15:00:05 -07001040 *
1041 * @param info
1042 * */
1043 private void startTraces(WindowingModeTransitionInfo info) {
Ioannis Ilkos66e1cd82019-05-03 10:47:30 +01001044 if (!Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER) || info == null
1045 || info.launchTraceActive) {
Vishnu Nair132ee832018-09-28 15:00:05 -07001046 return;
1047 }
Ioannis Ilkos66e1cd82019-05-03 10:47:30 +01001048 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: "
1049 + info.launchedActivity.packageName, 0);
1050 info.launchTraceActive = true;
Vishnu Nair132ee832018-09-28 15:00:05 -07001051 }
1052
1053 private void stopLaunchTrace(WindowingModeTransitionInfo info) {
1054 if (info == null) {
1055 return;
1056 }
1057 if (info.launchTraceActive) {
1058 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: "
1059 + info.launchedActivity.packageName, 0);
1060 info.launchTraceActive = false;
1061 }
1062 }
Igor Murashkin212d06c2018-10-22 16:34:39 -07001063
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001064 public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() {
1065 return mLaunchObserver;
1066 }
1067
Igor Murashkin212d06c2018-10-22 16:34:39 -07001068 /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */
Yan Wangd47f90b2019-10-03 19:17:15 -07001069 private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001070 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1071 "MetricsLogger:launchObserverNotifyIntentStarted");
1072
1073 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
Yan Wangd47f90b2019-10-03 19:17:15 -07001074 mLaunchObserver.onIntentStarted(intent, timestampNs);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001075
1076 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001077 }
1078
1079 /**
1080 * Notify the {@link ActivityMetricsLaunchObserver} that the previous launch sequence has
1081 * aborted due to intent failure (e.g. intent resolve failed or security error, etc) or
1082 * intent being delivered to the top running activity.
1083 */
1084 private void launchObserverNotifyIntentFailed() {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001085 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1086 "MetricsLogger:launchObserverNotifyIntentFailed");
1087
1088 mLaunchObserver.onIntentFailed();
1089
1090 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001091 }
1092
1093 /**
1094 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1095 * has started.
1096 */
1097 private void launchObserverNotifyActivityLaunched(WindowingModeTransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001098 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1099 "MetricsLogger:launchObserverNotifyActivityLaunched");
1100
Igor Murashkin212d06c2018-10-22 16:34:39 -07001101 @ActivityMetricsLaunchObserver.Temperature int temperature =
1102 convertTransitionTypeToLaunchObserverTemperature(getTransitionType(info));
1103
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001104 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
1105 mLaunchObserver.onActivityLaunched(convertActivityRecordToProto(info.launchedActivity),
1106 temperature);
1107
1108 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001109 }
1110
1111 /**
Yan Wang9eac5ec2019-09-30 15:42:18 -07001112 * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event.
1113 */
Yan Wangd47f90b2019-10-03 19:17:15 -07001114 private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) {
Yan Wang9eac5ec2019-09-30 15:42:18 -07001115 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1116 "MetricsLogger:launchObserverNotifyReportFullyDrawn");
Yan Wangd47f90b2019-10-03 19:17:15 -07001117 mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs);
Yan Wang9eac5ec2019-09-30 15:42:18 -07001118 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1119 }
1120
1121 /**
Igor Murashkin212d06c2018-10-22 16:34:39 -07001122 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is
1123 * cancelled.
1124 */
1125 private void launchObserverNotifyActivityLaunchCancelled(WindowingModeTransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001126 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1127 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001128
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001129 final @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] activityRecordProto =
1130 info != null ? convertActivityRecordToProto(info.launchedActivity) : null;
1131
1132 mLaunchObserver.onActivityLaunchCancelled(activityRecordProto);
1133
1134 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001135 }
1136
1137 /**
1138 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1139 * has fully finished (successfully).
1140 */
Yan Wangd47f90b2019-10-03 19:17:15 -07001141 private void launchObserverNotifyActivityLaunchFinished(WindowingModeTransitionInfo info,
1142 long timestampNs) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001143 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1144 "MetricsLogger:launchObserverNotifyActivityLaunchFinished");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001145
Yan Wangd47f90b2019-10-03 19:17:15 -07001146 mLaunchObserver
1147 .onActivityLaunchFinished(convertActivityRecordToProto(info.launchedActivity),
1148 timestampNs);
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001149
1150 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1151 }
1152
1153 @VisibleForTesting
1154 static @ActivityMetricsLaunchObserver.ActivityRecordProto byte[]
1155 convertActivityRecordToProto(ActivityRecord record) {
1156 // May take non-negligible amount of time to convert ActivityRecord into a proto,
1157 // so track the time.
1158 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1159 "MetricsLogger:convertActivityRecordToProto");
1160
1161 // There does not appear to be a way to 'reset' a ProtoOutputBuffer stream,
1162 // so create a new one every time.
1163 final ProtoOutputStream protoOutputStream =
1164 new ProtoOutputStream(LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE);
1165 // Write this data out as the top-most ActivityRecordProto (i.e. it is not a sub-object).
1166 record.writeToProto(protoOutputStream);
1167 final byte[] bytes = protoOutputStream.getBytes();
1168
1169 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1170
1171 return bytes;
Igor Murashkin212d06c2018-10-22 16:34:39 -07001172 }
1173
1174 private static @ActivityMetricsLaunchObserver.Temperature int
1175 convertTransitionTypeToLaunchObserverTemperature(int transitionType) {
1176 switch (transitionType) {
1177 case TYPE_TRANSITION_WARM_LAUNCH:
1178 return ActivityMetricsLaunchObserver.TEMPERATURE_WARM;
1179 case TYPE_TRANSITION_HOT_LAUNCH:
1180 return ActivityMetricsLaunchObserver.TEMPERATURE_HOT;
1181 case TYPE_TRANSITION_COLD_LAUNCH:
1182 return ActivityMetricsLaunchObserver.TEMPERATURE_COLD;
1183 default:
1184 return -1;
1185 }
1186 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -08001187}