blob: 10231826279827cefcc786265e3c513ac519edcc [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_ACTIVITY_RECORD_FLAGS;
30import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_IS_FULLSCREEN;
31import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_IS_NO_DISPLAY;
32import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_IS_VISIBLE;
33import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_IS_VISIBLE_IGNORING_KEYGUARD;
Vishnu Nair132ee832018-09-28 15:00:05 -070034import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_LAUNCH_MODE;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010035import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_MILLIS_SINCE_LAST_LAUNCH;
36import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_MILLIS_SINCE_LAST_VISIBLE;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010037import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_PROCESS_NAME;
38import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_REAL_ACTIVITY;
39import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_RESULT_TO_PKG_NAME;
40import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_RESULT_TO_SHORT_COMPONENT_NAME;
41import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_SHORT_COMPONENT_NAME;
42import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_ACTIVITY_RECORD_TARGET_ACTIVITY;
43import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_PACKAGE_NAME;
44import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID;
45import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
46import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_PROC_STATE;
Jorim Jaggicdfc04e2017-04-28 19:06:24 +020047import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010048import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_COMING_FROM_PENDING_INTENT;
Todd Kennedy50d946c12017-03-17 13:55:38 -070049import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010050import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INTENT_ACTION;
51import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_CUR_PROC_STATE;
52import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES;
53import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES;
54import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES;
55import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_OVERLAY_UI;
56import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_TOP_UI;
57import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION;
58import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT;
59import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT;
60import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PENDING_UI_CLEAN;
61import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PROCESS_NAME;
62import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010063import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW;
Vishnu Nair132ee832018-09-28 15:00:05 -070064import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_PROC_STATE;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010065import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_PACKAGE_NAME;
66import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_SHORT_COMPONENT_NAME;
67import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_UID;
68import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_UID_HAS_ANY_VISIBLE_WINDOW;
69import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_UID_PROC_STATE;
70import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_WHITELIST_TAG;
Calin Juravle759fbda2018-02-20 19:52:30 +000071import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_FILTER;
Vishnu Nair132ee832018-09-28 15:00:05 -070072import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_REASON;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080073import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH;
74import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH;
Jorim Jaggi4d27b842017-08-17 17:22:26 +020075import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE;
76import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080077import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
Vishnu Nair132ee832018-09-28 15:00:05 -070078import static com.android.server.am.EventLogTags.AM_ACTIVITY_LAUNCH_TIME;
Ng Zhi Anbbefdec2018-01-30 17:12:39 -080079import static com.android.server.am.MemoryStatUtil.MemoryStat;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +000080import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem;
Vishnu Naira62534b2018-11-09 09:13:22 -080081import static com.android.server.wm.ActivityTaskManagerDebugConfig.DEBUG_METRICS;
82import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_ATM;
83import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_WITH_CLASS_NAME;
Vishnu Nair132ee832018-09-28 15:00:05 -070084import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080085
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -080086import android.app.WaitResult;
Igor Murashkin212d06c2018-10-22 16:34:39 -070087import android.app.WindowConfiguration.WindowingMode;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080088import android.content.Context;
Michal Karpinski201bc0c2018-07-20 15:32:00 +010089import android.content.Intent;
Calin Juravle759fbda2018-02-20 19:52:30 +000090import android.content.pm.ApplicationInfo;
91import android.content.pm.dex.ArtManagerInternal;
92import android.content.pm.dex.PackageOptimizationInfo;
Jorim Jaggi3878ca32017-02-02 17:13:05 -080093import android.metrics.LogMaker;
Jorim Jaggi172e99f2017-10-20 14:33:18 +020094import android.os.Handler;
95import android.os.Looper;
96import android.os.Message;
Filip Gruszczynski77d94482015-12-11 13:59:52 -080097import android.os.SystemClock;
Vishnu Nair132ee832018-09-28 15:00:05 -070098import android.os.Trace;
99import android.util.EventLog;
100import android.util.Log;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200101import android.util.Slog;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800102import android.util.SparseArray;
103import android.util.SparseIntArray;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000104import android.util.StatsLog;
Vishnu Nair132ee832018-09-28 15:00:05 -0700105import android.util.TimeUtils;
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800106import android.util.proto.ProtoOutputStream;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800107
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -0800108import com.android.internal.annotations.VisibleForTesting;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800109import com.android.internal.logging.MetricsLogger;
Ng Zhi An83473542018-02-20 09:02:14 -0800110import com.android.internal.os.BackgroundThread;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200111import com.android.internal.os.SomeArgs;
Calin Juravle759fbda2018-02-20 19:52:30 +0000112import com.android.server.LocalServices;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800113
114/**
Vishnu Nair132ee832018-09-28 15:00:05 -0700115 * Listens to activity launches, transitions, visibility changes and window drawn callbacks to
116 * determine app launch times and draw delays. Source of truth for activity metrics and provides
117 * data for Tron, logcat, event logs and {@link android.app.WaitResult}.
118 *
119 * Tests:
Vishnu Nairf8accc52018-10-11 10:19:54 -0700120 * atest CtsActivityManagerDeviceTestCases:ActivityMetricsLoggerTests
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800121 */
122class ActivityMetricsLogger {
Jorim Jaggif9704102016-05-05 19:14:22 -0700123
Wale Ogunwale98875612018-10-12 07:53:02 -0700124 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM;
Jorim Jaggif9704102016-05-05 19:14:22 -0700125
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800126 // Window modes we are interested in logging. If we ever introduce a new type, we need to add
127 // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array.
128 private static final int WINDOW_STATE_STANDARD = 0;
129 private static final int WINDOW_STATE_SIDE_BY_SIDE = 1;
130 private static final int WINDOW_STATE_FREEFORM = 2;
Winson Chung83471632016-12-13 11:02:12 -0800131 private static final int WINDOW_STATE_ASSISTANT = 3;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800132 private static final int WINDOW_STATE_INVALID = -1;
133
Jorim Jaggi275561a2016-02-23 10:11:02 -0500134 private static final long INVALID_START_TIME = -1;
Vishnu Nair132ee832018-09-28 15:00:05 -0700135 private static final int INVALID_DELAY = -1;
136 private static final int INVALID_TRANSITION_TYPE = -1;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500137
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200138 private static final int MSG_CHECK_VISIBILITY = 0;
139
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800140 // Preallocated strings we are sending to tron, so we don't have to allocate a new one every
141 // time we log.
142 private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = {
Winson Chung83471632016-12-13 11:02:12 -0800143 "window_time_0", "window_time_1", "window_time_2", "window_time_3"};
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800144
145 private int mWindowState = WINDOW_STATE_STANDARD;
146 private long mLastLogTimeSecs;
147 private final ActivityStackSupervisor mSupervisor;
148 private final Context mContext;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800149 private final MetricsLogger mMetricsLogger = new MetricsLogger();
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800150
Igor Murashkin212d06c2018-10-22 16:34:39 -0700151 // set to INVALID_START_TIME in reset.
152 // set to valid value in notifyActivityLaunching
Jorim Jaggi275561a2016-02-23 10:11:02 -0500153 private long mCurrentTransitionStartTime = INVALID_START_TIME;
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200154 private long mLastTransitionStartTime = INVALID_START_TIME;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800155
156 private int mCurrentTransitionDeviceUptime;
157 private int mCurrentTransitionDelayMs;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700158
159 /** If the any app transitions have been logged as starting, after the latest reset. */
Jorim Jaggi275561a2016-02-23 10:11:02 -0500160 private boolean mLoggedTransitionStarting;
161
Igor Murashkin212d06c2018-10-22 16:34:39 -0700162 /** Map : @WindowingMode int => WindowingModeTransitionInfo */
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100163 private final SparseArray<WindowingModeTransitionInfo> mWindowingModeTransitionInfo =
164 new SparseArray<>();
Igor Murashkin212d06c2018-10-22 16:34:39 -0700165 /** Map : @WindowingMode int => WindowingModeTransitionInfo */
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100166 private final SparseArray<WindowingModeTransitionInfo> mLastWindowingModeTransitionInfo =
167 new SparseArray<>();
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200168 private final H mHandler;
Calin Juravle759fbda2018-02-20 19:52:30 +0000169
170 private ArtManagerInternal mArtManagerInternal;
Vishnu Nair132ee832018-09-28 15:00:05 -0700171 private final StringBuilder mStringBuilder = new StringBuilder();
Calin Juravle759fbda2018-02-20 19:52:30 +0000172
Igor Murashkin212d06c2018-10-22 16:34:39 -0700173 /**
174 * Due to the global single concurrent launch sequence, all calls to this observer must be made
175 * in-order on the same thread to fulfill the "happens-before" guarantee in LaunchObserver.
176 */
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800177 private final LaunchObserverRegistryImpl mLaunchObserver;
178 @VisibleForTesting static final int LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE = 512;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700179
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200180 private final class H extends Handler {
181
182 public H(Looper looper) {
183 super(looper);
184 }
185
186 @Override
187 public void handleMessage(Message msg) {
188 switch (msg.what) {
189 case MSG_CHECK_VISIBILITY:
190 final SomeArgs args = (SomeArgs) msg.obj;
191 checkVisibility((TaskRecord) args.arg1, (ActivityRecord) args.arg2);
192 break;
193 }
194 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000195 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800196
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100197 private final class WindowingModeTransitionInfo {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700198 /** The latest activity to have been launched. */
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800199 private ActivityRecord launchedActivity;
200 private int startResult;
201 private boolean currentTransitionProcessRunning;
Vishnu Nair132ee832018-09-28 15:00:05 -0700202 /** Elapsed time from when we launch an activity to when its windows are drawn. */
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800203 private int windowsDrawnDelayMs;
Vishnu Nair132ee832018-09-28 15:00:05 -0700204 private int startingWindowDelayMs = INVALID_DELAY;
205 private int bindApplicationDelayMs = INVALID_DELAY;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800206 private int reason = APP_TRANSITION_TIMEOUT;
207 private boolean loggedWindowsDrawn;
208 private boolean loggedStartingWindowDrawn;
Vishnu Nair132ee832018-09-28 15:00:05 -0700209 private boolean launchTraceActive;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800210 }
211
Vishnu Nair132ee832018-09-28 15:00:05 -0700212 final class WindowingModeTransitionInfoSnapshot {
Calin Juravle759fbda2018-02-20 19:52:30 +0000213 final private ApplicationInfo applicationInfo;
Wale Ogunwalef6733932018-06-27 05:14:34 -0700214 final private WindowProcessController processRecord;
Vishnu Nair132ee832018-09-28 15:00:05 -0700215 final String packageName;
216 final String launchedActivityName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000217 final private String launchedActivityLaunchedFromPackage;
218 final private String launchedActivityLaunchToken;
219 final private String launchedActivityAppRecordRequiredAbi;
Vishnu Nair132ee832018-09-28 15:00:05 -0700220 final String launchedActivityShortComponentName;
Ng Zhi An83473542018-02-20 09:02:14 -0800221 final private String processName;
Calin Juravle759fbda2018-02-20 19:52:30 +0000222 final private int reason;
223 final private int startingWindowDelayMs;
224 final private int bindApplicationDelayMs;
Vishnu Nair132ee832018-09-28 15:00:05 -0700225 final int windowsDrawnDelayMs;
226 final int type;
227 final int userId;
228 /**
229 * Elapsed time from when we launch an activity to when the app reported it was
230 * fully drawn. If this is not reported then the value is set to INVALID_DELAY.
231 */
232 final int windowsFullyDrawnDelayMs;
233 final int activityRecordIdHashCode;
Calin Juravle759fbda2018-02-20 19:52:30 +0000234
235 private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700236 this(info, info.launchedActivity);
237 }
238
239 private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info,
240 ActivityRecord launchedActivity) {
241 this(info, launchedActivity, INVALID_DELAY);
242 }
243
244 private WindowingModeTransitionInfoSnapshot(WindowingModeTransitionInfo info,
245 ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs) {
246 applicationInfo = launchedActivity.appInfo;
247 packageName = launchedActivity.packageName;
248 launchedActivityName = launchedActivity.info.name;
249 launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage;
250 launchedActivityLaunchToken = launchedActivity.info.launchToken;
251 launchedActivityAppRecordRequiredAbi = launchedActivity.app == null
Calin Juravle759fbda2018-02-20 19:52:30 +0000252 ? null
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700253 : launchedActivity.app.getRequiredAbi();
Calin Juravle759fbda2018-02-20 19:52:30 +0000254 reason = info.reason;
255 startingWindowDelayMs = info.startingWindowDelayMs;
256 bindApplicationDelayMs = info.bindApplicationDelayMs;
257 windowsDrawnDelayMs = info.windowsDrawnDelayMs;
258 type = getTransitionType(info);
Vishnu Nairaf0ea312018-10-15 16:23:55 -0700259 processRecord = findProcessForActivity(launchedActivity);
260 processName = launchedActivity.processName;
Wale Ogunwale8b19de92018-11-29 19:58:26 -0800261 userId = launchedActivity.mUserId;
Vishnu Nair132ee832018-09-28 15:00:05 -0700262 launchedActivityShortComponentName = launchedActivity.shortComponentName;
263 activityRecordIdHashCode = System.identityHashCode(launchedActivity);
264 this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs;
Calin Juravle759fbda2018-02-20 19:52:30 +0000265 }
Vishnu Nairbb9ab4b2018-12-13 10:29:46 -0800266
267 @WaitResult.LaunchState int getLaunchState() {
268 switch (type) {
269 case TYPE_TRANSITION_WARM_LAUNCH:
270 return LAUNCH_STATE_WARM;
271 case TYPE_TRANSITION_HOT_LAUNCH:
272 return LAUNCH_STATE_HOT;
273 case TYPE_TRANSITION_COLD_LAUNCH:
274 return LAUNCH_STATE_COLD;
275 default:
276 return -1;
277 }
278 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000279 }
280
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200281 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context, Looper looper) {
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800282 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000;
283 mSupervisor = supervisor;
284 mContext = context;
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200285 mHandler = new H(looper);
Igor Murashkinc0b47e42018-11-07 15:54:18 -0800286 mLaunchObserver = new LaunchObserverRegistryImpl(looper);
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800287 }
288
289 void logWindowState() {
290 final long now = SystemClock.elapsedRealtime() / 1000;
291 if (mWindowState != WINDOW_STATE_INVALID) {
292 // We log even if the window state hasn't changed, because the user might remain in
293 // home/fullscreen move forever and we would like to track this kind of behavior
294 // too.
295 MetricsLogger.count(mContext, TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState],
296 (int) (now - mLastLogTimeSecs));
297 }
298 mLastLogTimeSecs = now;
299
Wale Ogunwale926aade2017-08-29 11:24:37 -0700300 mWindowState = WINDOW_STATE_INVALID;
Wale Ogunwaled32da472018-11-16 07:19:28 -0800301 ActivityStack stack =
302 mSupervisor.mRootActivityContainer.getTopDisplayFocusedStack();
lumarkf6c4a982018-06-15 15:43:12 +0800303 if (stack == null) {
304 return;
305 }
306
Wale Ogunwale926aade2017-08-29 11:24:37 -0700307 if (stack.isActivityTypeAssistant()) {
308 mWindowState = WINDOW_STATE_ASSISTANT;
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800309 return;
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800310 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700311
Igor Murashkin212d06c2018-10-22 16:34:39 -0700312 @WindowingMode int windowingMode = stack.getWindowingMode();
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700313 if (windowingMode == WINDOWING_MODE_PINNED) {
Wale Ogunwaled32da472018-11-16 07:19:28 -0800314 stack = mSupervisor.mRootActivityContainer.findStackBehind(stack);
Wale Ogunwale3382ab12017-07-27 08:55:03 -0700315 windowingMode = stack.getWindowingMode();
Filip Gruszczynskicaae14e2015-12-16 14:40:04 -0800316 }
Wale Ogunwale926aade2017-08-29 11:24:37 -0700317 switch (windowingMode) {
318 case WINDOWING_MODE_FULLSCREEN:
319 mWindowState = WINDOW_STATE_STANDARD;
320 break;
321 case WINDOWING_MODE_SPLIT_SCREEN_PRIMARY:
322 case WINDOWING_MODE_SPLIT_SCREEN_SECONDARY:
323 mWindowState = WINDOW_STATE_SIDE_BY_SIDE;
324 break;
Bryce Lee6c605092017-10-12 11:14:49 -0700325 case WINDOWING_MODE_FREEFORM:
Wale Ogunwale926aade2017-08-29 11:24:37 -0700326 mWindowState = WINDOW_STATE_FREEFORM;
327 break;
328 default:
329 if (windowingMode != WINDOWING_MODE_UNDEFINED) {
330 throw new IllegalStateException("Unknown windowing mode for stack=" + stack
331 + " windowingMode=" + windowingMode);
332 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -0800333 }
334 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500335
336 /**
337 * Notifies the tracker at the earliest possible point when we are starting to launch an
338 * activity.
339 */
Igor Murashkin212d06c2018-10-22 16:34:39 -0700340 void notifyActivityLaunching(Intent intent) {
341 if (DEBUG_METRICS) {
342 Slog.i(TAG, String.format("notifyActivityLaunching: active:%b, intent:%s",
343 isAnyTransitionActive(),
344 intent));
345 }
346
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800347 if (!isAnyTransitionActive()) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700348
Alison Cichowlasb7f67ab2017-04-25 18:04:40 -0400349 mCurrentTransitionStartTime = SystemClock.uptimeMillis();
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200350 mLastTransitionStartTime = mCurrentTransitionStartTime;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700351
352 launchObserverNotifyIntentStarted(intent);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800353 }
Jorim Jaggi275561a2016-02-23 10:11:02 -0500354 }
355
356 /**
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700357 * Notifies the tracker that the activity is actually launching.
358 *
359 * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the
360 * launch
361 * @param launchedActivity the activity that is being launched
362 */
363 void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity) {
Wale Ogunwalef6733932018-06-27 05:14:34 -0700364 final WindowProcessController processRecord = findProcessForActivity(launchedActivity);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700365 final boolean processRunning = processRecord != null;
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700366
367 // We consider this a "process switch" if the process of the activity that gets launched
368 // didn't have an activity that was in started state. In this case, we assume that lot
369 // of caches might be purged so the time until it produces the first frame is very
370 // interesting.
371 final boolean processSwitch = processRecord == null
Wale Ogunwalef6733932018-06-27 05:14:34 -0700372 || !processRecord.hasStartedActivity(launchedActivity);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700373
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800374 notifyActivityLaunched(resultCode, launchedActivity, processRunning, processSwitch);
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700375 }
376
Jorim Jaggi1e630c02016-05-16 12:13:13 -0700377 /**
Jorim Jaggi275561a2016-02-23 10:11:02 -0500378 * Notifies the tracker the the activity is actually launching.
379 *
380 * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the
381 * launch
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800382 * @param launchedActivity the activity being launched
Jorim Jaggi275561a2016-02-23 10:11:02 -0500383 * @param processRunning whether the process that will contains the activity is already running
Jorim Jaggibe67c902016-04-12 00:53:16 -0700384 * @param processSwitch whether the process that will contain the activity didn't have any
385 * activity that was stopped, i.e. the started activity is "switching"
386 * processes
Jorim Jaggi275561a2016-02-23 10:11:02 -0500387 */
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800388 private void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity,
Jorim Jaggibe67c902016-04-12 00:53:16 -0700389 boolean processRunning, boolean processSwitch) {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500390
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200391 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched"
392 + " resultCode=" + resultCode
393 + " launchedActivity=" + launchedActivity
394 + " processRunning=" + processRunning
395 + " processSwitch=" + processSwitch);
396
Igor Murashkin212d06c2018-10-22 16:34:39 -0700397 // If we are already in an existing transition, only update the activity name, but not the
398 // other attributes.
399 final @WindowingMode int windowingMode = launchedActivity != null
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100400 ? launchedActivity.getWindowingMode()
401 : WINDOWING_MODE_UNDEFINED;
Vishnu Nairf8accc52018-10-11 10:19:54 -0700402 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200403 if (mCurrentTransitionStartTime == INVALID_START_TIME) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700404 // No transition is active ignore this launch.
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200405 return;
406 }
407
Vishnu Nair9ba31652018-11-13 14:34:05 -0800408 if (launchedActivity != null && launchedActivity.mDrawn) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700409 // Launched activity is already visible. We cannot measure windows drawn delay.
Igor Murashkin212d06c2018-10-22 16:34:39 -0700410 reset(true /* abort */, info, "launched activity already visible");
Vishnu Nairf8accc52018-10-11 10:19:54 -0700411 return;
412 }
413
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800414 if (launchedActivity != null && info != null) {
Vishnu Nairf8accc52018-10-11 10:19:54 -0700415 // If we are already in an existing transition, only update the activity name, but not
416 // the other attributes.
Igor Murashkin212d06c2018-10-22 16:34:39 -0700417
418 // Coalesce multiple (trampoline) activities from a single sequence together.
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800419 info.launchedActivity = launchedActivity;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500420 return;
421 }
422
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100423 final boolean otherWindowModesLaunching =
424 mWindowingModeTransitionInfo.size() > 0 && info == null;
Jorim Jaggi54cff642018-03-15 15:51:32 +0100425 if ((!isLoggableResultCode(resultCode) || launchedActivity == null || !processSwitch
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100426 || windowingMode == WINDOWING_MODE_UNDEFINED) && !otherWindowModesLaunching) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800427 // Failed to launch or it was not a process switch, so we don't care about the timing.
Igor Murashkin212d06c2018-10-22 16:34:39 -0700428 reset(true /* abort */, info, "failed to launch or not a process switch");
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800429 return;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100430 } else if (otherWindowModesLaunching) {
431 // Don't log this windowing mode but continue with the other windowing modes.
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800432 return;
433 }
434
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200435 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful");
436
Igor Murashkin212d06c2018-10-22 16:34:39 -0700437 // A new launch sequence [with the windowingMode] has begun.
438 // Start tracking it.
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100439 final WindowingModeTransitionInfo newInfo = new WindowingModeTransitionInfo();
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800440 newInfo.launchedActivity = launchedActivity;
441 newInfo.currentTransitionProcessRunning = processRunning;
442 newInfo.startResult = resultCode;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100443 mWindowingModeTransitionInfo.put(windowingMode, newInfo);
444 mLastWindowingModeTransitionInfo.put(windowingMode, newInfo);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800445 mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000);
Vishnu Nair132ee832018-09-28 15:00:05 -0700446 startTraces(newInfo);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700447 launchObserverNotifyActivityLaunched(newInfo);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500448 }
449
450 /**
Jorim Jaggi54cff642018-03-15 15:51:32 +0100451 * @return True if we should start logging an event for an activity start that returned
452 * {@code resultCode} and that we'll indeed get a windows drawn event.
453 */
454 private boolean isLoggableResultCode(int resultCode) {
455 return resultCode == START_SUCCESS || resultCode == START_TASK_TO_FRONT;
456 }
457
458 /**
Jorim Jaggi275561a2016-02-23 10:11:02 -0500459 * Notifies the tracker that all windows of the app have been drawn.
460 */
Igor Murashkin212d06c2018-10-22 16:34:39 -0700461 WindowingModeTransitionInfoSnapshot notifyWindowsDrawn(@WindowingMode int windowingMode,
462 long timestamp) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100463 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn windowingMode=" + windowingMode);
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200464
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100465 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800466 if (info == null || info.loggedWindowsDrawn) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700467 return null;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500468 }
Sudheer Shankac766db02017-06-12 10:37:29 -0700469 info.windowsDrawnDelayMs = calculateDelay(timestamp);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800470 info.loggedWindowsDrawn = true;
Vishnu Nair132ee832018-09-28 15:00:05 -0700471 final WindowingModeTransitionInfoSnapshot infoSnapshot =
472 new WindowingModeTransitionInfoSnapshot(info);
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100473 if (allWindowsDrawn() && mLoggedTransitionStarting) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700474 reset(false /* abort */, info, "notifyWindowsDrawn - all windows drawn");
Jorim Jaggi275561a2016-02-23 10:11:02 -0500475 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700476 return infoSnapshot;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500477 }
478
479 /**
480 * Notifies the tracker that the starting window was drawn.
481 */
Igor Murashkin212d06c2018-10-22 16:34:39 -0700482 void notifyStartingWindowDrawn(@WindowingMode int windowingMode, long timestamp) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100483 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(windowingMode);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800484 if (info == null || info.loggedStartingWindowDrawn) {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500485 return;
486 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800487 info.loggedStartingWindowDrawn = true;
Sudheer Shankac766db02017-06-12 10:37:29 -0700488 info.startingWindowDelayMs = calculateDelay(timestamp);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500489 }
490
491 /**
492 * Notifies the tracker that the app transition is starting.
493 *
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100494 * @param windowingModeToReason A map from windowing mode to a reason integer, which must be on
Vishnu Nair132ee832018-09-28 15:00:05 -0700495 * of ActivityTaskManagerInternal.APP_TRANSITION_* reasons.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500496 */
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100497 void notifyTransitionStarting(SparseIntArray windowingModeToReason, long timestamp) {
Jorim Jaggid8a57772017-04-14 16:50:42 -0700498 if (!isAnyTransitionActive() || mLoggedTransitionStarting) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700499 // Ignore calls to this made after a reset and prior to notifyActivityLaunching.
500
501 // Ignore any subsequent notifyTransitionStarting until the next reset.
Jorim Jaggi275561a2016-02-23 10:11:02 -0500502 return;
503 }
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200504 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting");
Sudheer Shankac766db02017-06-12 10:37:29 -0700505 mCurrentTransitionDelayMs = calculateDelay(timestamp);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500506 mLoggedTransitionStarting = true;
Igor Murashkin212d06c2018-10-22 16:34:39 -0700507
508 WindowingModeTransitionInfo foundInfo = null;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100509 for (int index = windowingModeToReason.size() - 1; index >= 0; index--) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700510 final @WindowingMode int windowingMode = windowingModeToReason.keyAt(index);
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100511 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(
512 windowingMode);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800513 if (info == null) {
514 continue;
515 }
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100516 info.reason = windowingModeToReason.valueAt(index);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700517 foundInfo = info;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800518 }
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100519 if (allWindowsDrawn()) {
Vishnu Naira62534b2018-11-09 09:13:22 -0800520 // abort metrics collection if we cannot find a matching transition.
521 final boolean abortMetrics = foundInfo == null;
522 reset(abortMetrics, foundInfo, "notifyTransitionStarting - all windows drawn");
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 }
Wale Ogunwale8b19de92018-11-29 19:58:26 -0800540 final TaskRecord t = activityRecord.getTaskRecord();
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
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200547 private void checkVisibility(TaskRecord t, ActivityRecord r) {
Wale Ogunwalec9e57de2018-05-08 14:28:07 -0700548 synchronized (mSupervisor.mService.mGlobalLock) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200549
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100550 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.get(
551 r.getWindowingMode());
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200552
553 // If we have an active transition that's waiting on a certain activity that will be
554 // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary.
555 if (info != null && !t.isVisible()) {
556 if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible"
557 + " activity=" + r);
558 logAppTransitionCancel(info);
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100559 mWindowingModeTransitionInfo.remove(r.getWindowingMode());
560 if (mWindowingModeTransitionInfo.size() == 0) {
Igor Murashkin212d06c2018-10-22 16:34:39 -0700561 reset(true /* abort */, info, "notifyVisibilityChanged to invisible");
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200562 }
Jorim Jaggicdfc04e2017-04-28 19:06:24 +0200563 }
564 }
565 }
566
Jorim Jaggi515dd682017-05-05 15:05:07 +0200567 /**
568 * Notifies the tracker that we called immediately before we call bindApplication on the client.
569 *
Wale Ogunwale31913b52018-10-13 08:29:31 -0700570 * @param appInfo The client into which we'll call bindApplication.
Jorim Jaggi515dd682017-05-05 15:05:07 +0200571 */
Wale Ogunwale31913b52018-10-13 08:29:31 -0700572 void notifyBindApplication(ApplicationInfo appInfo) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100573 for (int i = mWindowingModeTransitionInfo.size() - 1; i >= 0; i--) {
574 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.valueAt(i);
Jorim Jaggi515dd682017-05-05 15:05:07 +0200575
576 // App isn't attached to record yet, so match with info.
Wale Ogunwale31913b52018-10-13 08:29:31 -0700577 if (info.launchedActivity.appInfo == appInfo) {
Jorim Jaggi515dd682017-05-05 15:05:07 +0200578 info.bindApplicationDelayMs = calculateCurrentDelay();
579 }
580 }
581 }
582
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100583 private boolean allWindowsDrawn() {
584 for (int index = mWindowingModeTransitionInfo.size() - 1; index >= 0; index--) {
585 if (!mWindowingModeTransitionInfo.valueAt(index).loggedWindowsDrawn) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800586 return false;
587 }
588 }
589 return true;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500590 }
591
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800592 private boolean isAnyTransitionActive() {
593 return mCurrentTransitionStartTime != INVALID_START_TIME
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100594 && mWindowingModeTransitionInfo.size() > 0;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800595 }
596
Igor Murashkin212d06c2018-10-22 16:34:39 -0700597 private void reset(boolean abort, WindowingModeTransitionInfo info, String cause) {
598 if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort + ",cause=" + cause);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800599 if (!abort && isAnyTransitionActive()) {
600 logAppTransitionMultiEvents();
601 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700602 stopLaunchTrace(info);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700603
604 // Ignore reset-after reset.
605 if (isAnyTransitionActive()) {
606 // LaunchObserver callbacks.
607 if (abort) {
608 launchObserverNotifyActivityLaunchCancelled(info);
609 } else {
610 launchObserverNotifyActivityLaunchFinished(info);
611 }
612 } else {
613 launchObserverNotifyIntentFailed();
614 }
615
Jorim Jaggi275561a2016-02-23 10:11:02 -0500616 mCurrentTransitionStartTime = INVALID_START_TIME;
Vishnu Nair132ee832018-09-28 15:00:05 -0700617 mCurrentTransitionDelayMs = INVALID_DELAY;
Jorim Jaggi275561a2016-02-23 10:11:02 -0500618 mLoggedTransitionStarting = false;
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100619 mWindowingModeTransitionInfo.clear();
Jorim Jaggi275561a2016-02-23 10:11:02 -0500620 }
621
622 private int calculateCurrentDelay() {
Jorim Jaggi275561a2016-02-23 10:11:02 -0500623 // Shouldn't take more than 25 days to launch an app, so int is fine here.
Alison Cichowlasb7f67ab2017-04-25 18:04:40 -0400624 return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime);
Jorim Jaggi275561a2016-02-23 10:11:02 -0500625 }
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800626
Sudheer Shankac766db02017-06-12 10:37:29 -0700627 private int calculateDelay(long timestamp) {
628 // Shouldn't take more than 25 days to launch an app, so int is fine here.
629 return (int) (timestamp - mCurrentTransitionStartTime);
630 }
631
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100632 private void logAppTransitionCancel(WindowingModeTransitionInfo info) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200633 final int type = getTransitionType(info);
Vishnu Nair132ee832018-09-28 15:00:05 -0700634 if (type == INVALID_TRANSITION_TYPE) {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200635 return;
636 }
637 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED);
638 builder.setPackageName(info.launchedActivity.packageName);
639 builder.setType(type);
640 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivity.info.name);
641 mMetricsLogger.write(builder);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000642 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800643 StatsLog.APP_START_CANCELED,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000644 info.launchedActivity.appInfo.uid,
645 info.launchedActivity.packageName,
646 convertAppStartTransitionType(type),
647 info.launchedActivity.info.name);
Igor Murashkin212d06c2018-10-22 16:34:39 -0700648 if (DEBUG_METRICS) {
649 Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)",
650 info.launchedActivity.appInfo.uid,
651 info.launchedActivity.packageName,
652 convertAppStartTransitionType(type),
653 info.launchedActivity.info.name));
654 }
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200655 }
656
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800657 private void logAppTransitionMultiEvents() {
Jorim Jaggi172e99f2017-10-20 14:33:18 +0200658 if (DEBUG_METRICS) Slog.i(TAG, "logging transition events");
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100659 for (int index = mWindowingModeTransitionInfo.size() - 1; index >= 0; index--) {
660 final WindowingModeTransitionInfo info = mWindowingModeTransitionInfo.valueAt(index);
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800661 final int type = getTransitionType(info);
Vishnu Nair132ee832018-09-28 15:00:05 -0700662 if (type == INVALID_TRANSITION_TYPE) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800663 return;
664 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000665
666 // Take a snapshot of the transition info before sending it to the handler for logging.
667 // This will avoid any races with other operations that modify the ActivityRecord.
668 final WindowingModeTransitionInfoSnapshot infoSnapshot =
669 new WindowingModeTransitionInfoSnapshot(info);
Ng Zhi An83473542018-02-20 09:02:14 -0800670 final int currentTransitionDeviceUptime = mCurrentTransitionDeviceUptime;
671 final int currentTransitionDelayMs = mCurrentTransitionDelayMs;
672 BackgroundThread.getHandler().post(() -> logAppTransition(
673 currentTransitionDeviceUptime, currentTransitionDelayMs, infoSnapshot));
Vishnu Nair132ee832018-09-28 15:00:05 -0700674 BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot));
Calin Juravle759fbda2018-02-20 19:52:30 +0000675
676 info.launchedActivity.info.launchToken = null;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800677 }
678 }
679
Ng Zhi An83473542018-02-20 09:02:14 -0800680 // This gets called on a background thread without holding the activity manager lock.
Calin Juravle759fbda2018-02-20 19:52:30 +0000681 private void logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs,
682 WindowingModeTransitionInfoSnapshot info) {
683 final LogMaker builder = new LogMaker(APP_TRANSITION);
684 builder.setPackageName(info.packageName);
685 builder.setType(info.type);
686 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName);
687 final boolean isInstantApp = info.applicationInfo.isInstantApp();
688 if (info.launchedActivityLaunchedFromPackage != null) {
689 builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME,
690 info.launchedActivityLaunchedFromPackage);
691 }
692 String launchToken = info.launchedActivityLaunchToken;
693 if (launchToken != null) {
694 builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, launchToken);
695 }
696 builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0);
697 builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS,
698 currentTransitionDeviceUptime);
699 builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs);
700 builder.setSubtype(info.reason);
Vishnu Nair132ee832018-09-28 15:00:05 -0700701 if (info.startingWindowDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000702 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS,
703 info.startingWindowDelayMs);
704 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700705 if (info.bindApplicationDelayMs != INVALID_DELAY) {
Calin Juravle759fbda2018-02-20 19:52:30 +0000706 builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS,
707 info.bindApplicationDelayMs);
708 }
709 builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs);
710 final ArtManagerInternal artManagerInternal = getArtManagerInternal();
711 final PackageOptimizationInfo packageOptimizationInfo =
712 (artManagerInternal == null) || (info.launchedActivityAppRecordRequiredAbi == null)
713 ? PackageOptimizationInfo.createWithNoInfo()
714 : artManagerInternal.getPackageOptimizationInfo(
715 info.applicationInfo,
716 info.launchedActivityAppRecordRequiredAbi);
717 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON,
718 packageOptimizationInfo.getCompilationReason());
719 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER,
720 packageOptimizationInfo.getCompilationFilter());
721 mMetricsLogger.write(builder);
722 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800723 StatsLog.APP_START_OCCURRED,
Calin Juravle759fbda2018-02-20 19:52:30 +0000724 info.applicationInfo.uid,
725 info.packageName,
726 convertAppStartTransitionType(info.type),
727 info.launchedActivityName,
728 info.launchedActivityLaunchedFromPackage,
729 isInstantApp,
730 currentTransitionDeviceUptime * 1000,
731 info.reason,
732 currentTransitionDelayMs,
733 info.startingWindowDelayMs,
734 info.bindApplicationDelayMs,
735 info.windowsDrawnDelayMs,
736 launchToken,
737 packageOptimizationInfo.getCompilationReason(),
738 packageOptimizationInfo.getCompilationFilter());
Igor Murashkin212d06c2018-10-22 16:34:39 -0700739
740 if (DEBUG_METRICS) {
741 Slog.i(TAG, String.format("APP_START_OCCURRED(%s, %s, %s, %s, %s)",
742 info.applicationInfo.uid,
743 info.packageName,
744 convertAppStartTransitionType(info.type),
745 info.launchedActivityName,
746 info.launchedActivityLaunchedFromPackage));
747 }
748
749
Ng Zhi An83473542018-02-20 09:02:14 -0800750 logAppStartMemoryStateCapture(info);
Calin Juravle759fbda2018-02-20 19:52:30 +0000751 }
752
Vishnu Nair132ee832018-09-28 15:00:05 -0700753 private void logAppDisplayed(WindowingModeTransitionInfoSnapshot info) {
754 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
755 return;
756 }
757
758 EventLog.writeEvent(AM_ACTIVITY_LAUNCH_TIME,
759 info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName,
760 info.windowsDrawnDelayMs);
761
762 StringBuilder sb = mStringBuilder;
763 sb.setLength(0);
764 sb.append("Displayed ");
765 sb.append(info.launchedActivityShortComponentName);
766 sb.append(": ");
767 TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
768 Log.i(TAG, sb.toString());
769 }
770
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000771 private int convertAppStartTransitionType(int tronType) {
772 if (tronType == TYPE_TRANSITION_COLD_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800773 return StatsLog.APP_START_OCCURRED__TYPE__COLD;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000774 }
775 if (tronType == TYPE_TRANSITION_WARM_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800776 return StatsLog.APP_START_OCCURRED__TYPE__WARM;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000777 }
778 if (tronType == TYPE_TRANSITION_HOT_LAUNCH) {
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800779 return StatsLog.APP_START_OCCURRED__TYPE__HOT;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000780 }
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800781 return StatsLog.APP_START_OCCURRED__TYPE__UNKNOWN;
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000782 }
783
Vishnu Nair132ee832018-09-28 15:00:05 -0700784 WindowingModeTransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r,
785 boolean restoredFromBundle) {
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100786 final WindowingModeTransitionInfo info = mLastWindowingModeTransitionInfo.get(
787 r.getWindowingMode());
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200788 if (info == null) {
Vishnu Nair132ee832018-09-28 15:00:05 -0700789 return null;
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200790 }
Chris Wailes35c193c2018-10-09 18:12:00 -0700791
792 // Record the handling of the reportFullyDrawn callback in the trace system. This is not
793 // actually used to trace this function, but instead the logical task that this function
794 // fullfils (handling reportFullyDrawn() callbacks).
795 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
796 "ActivityManager:ReportingFullyDrawn " + info.launchedActivity.packageName);
797
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200798 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN);
799 builder.setPackageName(r.packageName);
800 builder.addTaggedData(FIELD_CLASS_NAME, r.info.name);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000801 long startupTimeMs = SystemClock.uptimeMillis() - mLastTransitionStartTime;
802 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs);
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200803 builder.setType(restoredFromBundle
804 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE
805 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE);
806 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING,
807 info.currentTransitionProcessRunning ? 1 : 0);
808 mMetricsLogger.write(builder);
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000809 StatsLog.write(
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800810 StatsLog.APP_START_FULLY_DRAWN,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000811 info.launchedActivity.appInfo.uid,
812 info.launchedActivity.packageName,
813 restoredFromBundle
Chenjie Yu5caaa9d2018-03-06 15:48:54 -0800814 ? StatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE
815 : StatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE,
Olivier Gaillardaed7f122017-12-12 14:26:22 +0000816 info.launchedActivity.info.name,
817 info.currentTransitionProcessRunning,
818 startupTimeMs);
Chris Wailes35c193c2018-10-09 18:12:00 -0700819
820 // Ends the trace started at the beginning of this function. This is located here to allow
821 // the trace slice to have a noticable duration.
822 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
823
Vishnu Nair132ee832018-09-28 15:00:05 -0700824 final WindowingModeTransitionInfoSnapshot infoSnapshot =
825 new WindowingModeTransitionInfoSnapshot(info, r, (int) startupTimeMs);
826 BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot));
827 return infoSnapshot;
828 }
829
830 private void logAppFullyDrawn(WindowingModeTransitionInfoSnapshot info) {
831 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) {
832 return;
833 }
834
835 StringBuilder sb = mStringBuilder;
836 sb.setLength(0);
837 sb.append("Fully drawn ");
838 sb.append(info.launchedActivityShortComponentName);
839 sb.append(": ");
840 TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb);
841 Log.i(TAG, sb.toString());
Jorim Jaggi4d27b842017-08-17 17:22:26 +0200842 }
843
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700844 void logActivityStart(Intent intent, WindowProcessController callerApp, ActivityRecord r,
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100845 int callingUid, String callingPackage, int callingUidProcState,
846 boolean callingUidHasAnyVisibleWindow,
847 int realCallingUid, int realCallingUidProcState,
848 boolean realCallingUidHasAnyVisibleWindow,
849 int targetUid, String targetPackage, int targetUidProcState,
850 boolean targetUidHasAnyVisibleWindow, String targetWhitelistTag,
851 boolean comingFromPendingIntent) {
852
853 final long nowElapsed = SystemClock.elapsedRealtime();
854 final long nowUptime = SystemClock.uptimeMillis();
855 final LogMaker builder = new LogMaker(ACTION_ACTIVITY_START);
856 builder.setTimestamp(System.currentTimeMillis());
857 builder.addTaggedData(FIELD_CALLING_UID, callingUid);
858 builder.addTaggedData(FIELD_CALLING_PACKAGE_NAME, callingPackage);
859 builder.addTaggedData(FIELD_CALLING_UID_PROC_STATE,
860 processStateAmToProto(callingUidProcState));
861 builder.addTaggedData(FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
862 callingUidHasAnyVisibleWindow ? 1 : 0);
863 builder.addTaggedData(FIELD_REAL_CALLING_UID, realCallingUid);
864 builder.addTaggedData(FIELD_REAL_CALLING_UID_PROC_STATE,
865 processStateAmToProto(realCallingUidProcState));
866 builder.addTaggedData(FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW,
867 realCallingUidHasAnyVisibleWindow ? 1 : 0);
868 builder.addTaggedData(FIELD_TARGET_UID, targetUid);
869 builder.addTaggedData(FIELD_TARGET_PACKAGE_NAME, targetPackage);
870 builder.addTaggedData(FIELD_TARGET_UID_PROC_STATE,
871 processStateAmToProto(targetUidProcState));
872 builder.addTaggedData(FIELD_TARGET_UID_HAS_ANY_VISIBLE_WINDOW,
873 targetUidHasAnyVisibleWindow ? 1 : 0);
874 builder.addTaggedData(FIELD_TARGET_WHITELIST_TAG, targetWhitelistTag);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100875 builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0);
Michal Karpinski8596ded2018-11-14 14:43:48 +0000876 if (intent != null) {
877 builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction());
878 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100879 if (callerApp != null) {
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700880 builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100881 builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700882 processStateAmToProto(callerApp.getCurrentProcState()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100883 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700884 callerApp.hasClientActivities() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100885 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES,
886 callerApp.hasForegroundServices() ? 1 : 0);
887 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700888 callerApp.hasForegroundActivities() ? 1 : 0);
889 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100890 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700891 callerApp.hasOverlayUi() ? 1 : 0);
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100892 builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700893 callerApp.hasPendingUiClean() ? 1 : 0);
894 if (callerApp.getInteractionEventTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100895 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700896 (nowElapsed - callerApp.getInteractionEventTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100897 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700898 if (callerApp.getFgInteractionTime() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100899 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700900 (nowElapsed - callerApp.getFgInteractionTime()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100901 }
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700902 if (callerApp.getWhenUnimportant() != 0) {
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100903 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT,
Wale Ogunwale342fbe92018-10-09 08:44:10 -0700904 (nowUptime - callerApp.getWhenUnimportant()));
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100905 }
906 }
Michal Karpinski8596ded2018-11-14 14:43:48 +0000907 if (r != null) {
908 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME, r.shortComponentName);
909 builder.addTaggedData(FIELD_ACTIVITY_RECORD_LAUNCH_MODE, r.info.launchMode);
910 builder.addTaggedData(FIELD_ACTIVITY_RECORD_TARGET_ACTIVITY, r.info.targetActivity);
911 builder.addTaggedData(FIELD_ACTIVITY_RECORD_FLAGS, r.info.flags);
912 builder.addTaggedData(FIELD_ACTIVITY_RECORD_REAL_ACTIVITY,
Wale Ogunwale8b19de92018-11-29 19:58:26 -0800913 r.mActivityComponent.toShortString());
Michal Karpinski8596ded2018-11-14 14:43:48 +0000914 builder.addTaggedData(FIELD_ACTIVITY_RECORD_SHORT_COMPONENT_NAME, r.shortComponentName);
915 builder.addTaggedData(FIELD_ACTIVITY_RECORD_PROCESS_NAME, r.processName);
916 builder.addTaggedData(FIELD_ACTIVITY_RECORD_IS_FULLSCREEN, r.fullscreen ? 1 : 0);
917 builder.addTaggedData(FIELD_ACTIVITY_RECORD_IS_NO_DISPLAY, r.noDisplay ? 1 : 0);
918 if (r.lastVisibleTime != 0) {
919 builder.addTaggedData(FIELD_ACTIVITY_RECORD_MILLIS_SINCE_LAST_VISIBLE,
920 (nowUptime - r.lastVisibleTime));
921 }
922 if (r.resultTo != null) {
923 builder.addTaggedData(FIELD_ACTIVITY_RECORD_RESULT_TO_PKG_NAME,
924 r.resultTo.packageName);
925 builder.addTaggedData(FIELD_ACTIVITY_RECORD_RESULT_TO_SHORT_COMPONENT_NAME,
926 r.resultTo.shortComponentName);
927 }
928 builder.addTaggedData(FIELD_ACTIVITY_RECORD_IS_VISIBLE, r.visible ? 1 : 0);
929 builder.addTaggedData(FIELD_ACTIVITY_RECORD_IS_VISIBLE_IGNORING_KEYGUARD,
930 r.visibleIgnoringKeyguard ? 1 : 0);
931 if (r.lastLaunchTime != 0) {
932 builder.addTaggedData(FIELD_ACTIVITY_RECORD_MILLIS_SINCE_LAST_LAUNCH,
933 (nowUptime - r.lastLaunchTime));
934 }
Michal Karpinski201bc0c2018-07-20 15:32:00 +0100935 }
936 mMetricsLogger.write(builder);
937 }
938
Jorim Jaggi9b58f2d2018-02-19 17:48:44 +0100939 private int getTransitionType(WindowingModeTransitionInfo info) {
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800940 if (info.currentTransitionProcessRunning) {
941 if (info.startResult == START_SUCCESS) {
942 return TYPE_TRANSITION_WARM_LAUNCH;
943 } else if (info.startResult == START_TASK_TO_FRONT) {
944 return TYPE_TRANSITION_HOT_LAUNCH;
945 }
946 } else if (info.startResult == START_SUCCESS) {
947 return TYPE_TRANSITION_COLD_LAUNCH;
948 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700949 return INVALID_TRANSITION_TYPE;
Jorim Jaggi3878ca32017-02-02 17:13:05 -0800950 }
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800951
Ng Zhi An83473542018-02-20 09:02:14 -0800952 private void logAppStartMemoryStateCapture(WindowingModeTransitionInfoSnapshot info) {
953 if (info.processRecord == null) {
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800954 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null");
955 return;
956 }
957
Wale Ogunwalef6733932018-06-27 05:14:34 -0700958 final int pid = info.processRecord.getPid();
Ng Zhi An83473542018-02-20 09:02:14 -0800959 final int uid = info.applicationInfo.uid;
Rajeev Kumarbfcd9202018-03-02 22:42:13 +0000960 final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid);
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800961 if (memoryStat == null) {
962 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null");
963 return;
964 }
965
966 StatsLog.write(
967 StatsLog.APP_START_MEMORY_STATE_CAPTURED,
968 uid,
Ng Zhi An83473542018-02-20 09:02:14 -0800969 info.processName,
970 info.launchedActivityName,
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800971 memoryStat.pgfault,
972 memoryStat.pgmajfault,
973 memoryStat.rssInBytes,
974 memoryStat.cacheInBytes,
975 memoryStat.swapInBytes);
976 }
977
Wale Ogunwalef6733932018-06-27 05:14:34 -0700978 private WindowProcessController findProcessForActivity(ActivityRecord launchedActivity) {
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800979 return launchedActivity != null
Wale Ogunwalef6733932018-06-27 05:14:34 -0700980 ? mSupervisor.mService.mProcessNames.get(
Wale Ogunwalec9e57de2018-05-08 14:28:07 -0700981 launchedActivity.processName, launchedActivity.appInfo.uid)
Ng Zhi Anbbefdec2018-01-30 17:12:39 -0800982 : null;
983 }
Calin Juravle759fbda2018-02-20 19:52:30 +0000984
985 private ArtManagerInternal getArtManagerInternal() {
986 if (mArtManagerInternal == null) {
987 // Note that this may be null.
988 // ArtManagerInternal is registered during PackageManagerService
989 // initialization which happens after ActivityManagerService.
990 mArtManagerInternal = LocalServices.getService(ArtManagerInternal.class);
991 }
992 return mArtManagerInternal;
993 }
Vishnu Nair132ee832018-09-28 15:00:05 -0700994
995 /**
Chris Wailes35c193c2018-10-09 18:12:00 -0700996 * Starts traces for app launch.
Vishnu Nair132ee832018-09-28 15:00:05 -0700997 *
998 * @param info
999 * */
1000 private void startTraces(WindowingModeTransitionInfo info) {
1001 if (info == null) {
1002 return;
1003 }
Vishnu Nair132ee832018-09-28 15:00:05 -07001004 int transitionType = getTransitionType(info);
1005 if (!info.launchTraceActive && transitionType == TYPE_TRANSITION_WARM_LAUNCH
1006 || transitionType == TYPE_TRANSITION_COLD_LAUNCH) {
1007 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: "
1008 + info.launchedActivity.packageName, 0);
Vishnu Nair132ee832018-09-28 15:00:05 -07001009 info.launchTraceActive = true;
1010 }
1011 }
1012
1013 private void stopLaunchTrace(WindowingModeTransitionInfo info) {
1014 if (info == null) {
1015 return;
1016 }
1017 if (info.launchTraceActive) {
1018 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, "launching: "
1019 + info.launchedActivity.packageName, 0);
1020 info.launchTraceActive = false;
1021 }
1022 }
Igor Murashkin212d06c2018-10-22 16:34:39 -07001023
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001024 public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() {
1025 return mLaunchObserver;
1026 }
1027
Igor Murashkin212d06c2018-10-22 16:34:39 -07001028 /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */
1029 private void launchObserverNotifyIntentStarted(Intent intent) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001030 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1031 "MetricsLogger:launchObserverNotifyIntentStarted");
1032
1033 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
1034 mLaunchObserver.onIntentStarted(intent);
1035
1036 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001037 }
1038
1039 /**
1040 * Notify the {@link ActivityMetricsLaunchObserver} that the previous launch sequence has
1041 * aborted due to intent failure (e.g. intent resolve failed or security error, etc) or
1042 * intent being delivered to the top running activity.
1043 */
1044 private void launchObserverNotifyIntentFailed() {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001045 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1046 "MetricsLogger:launchObserverNotifyIntentFailed");
1047
1048 mLaunchObserver.onIntentFailed();
1049
1050 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001051 }
1052
1053 /**
1054 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1055 * has started.
1056 */
1057 private void launchObserverNotifyActivityLaunched(WindowingModeTransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001058 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1059 "MetricsLogger:launchObserverNotifyActivityLaunched");
1060
Igor Murashkin212d06c2018-10-22 16:34:39 -07001061 @ActivityMetricsLaunchObserver.Temperature int temperature =
1062 convertTransitionTypeToLaunchObserverTemperature(getTransitionType(info));
1063
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001064 // Beginning a launch is timing sensitive and so should be observed as soon as possible.
1065 mLaunchObserver.onActivityLaunched(convertActivityRecordToProto(info.launchedActivity),
1066 temperature);
1067
1068 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001069 }
1070
1071 /**
1072 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is
1073 * cancelled.
1074 */
1075 private void launchObserverNotifyActivityLaunchCancelled(WindowingModeTransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001076 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1077 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001078
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001079 final @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] activityRecordProto =
1080 info != null ? convertActivityRecordToProto(info.launchedActivity) : null;
1081
1082 mLaunchObserver.onActivityLaunchCancelled(activityRecordProto);
1083
1084 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
Igor Murashkin212d06c2018-10-22 16:34:39 -07001085 }
1086
1087 /**
1088 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity
1089 * has fully finished (successfully).
1090 */
1091 private void launchObserverNotifyActivityLaunchFinished(WindowingModeTransitionInfo info) {
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001092 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1093 "MetricsLogger:launchObserverNotifyActivityLaunchFinished");
Igor Murashkin212d06c2018-10-22 16:34:39 -07001094
Igor Murashkinc0b47e42018-11-07 15:54:18 -08001095 mLaunchObserver.onActivityLaunchFinished(
1096 convertActivityRecordToProto(info.launchedActivity));
1097
1098 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1099 }
1100
1101 @VisibleForTesting
1102 static @ActivityMetricsLaunchObserver.ActivityRecordProto byte[]
1103 convertActivityRecordToProto(ActivityRecord record) {
1104 // May take non-negligible amount of time to convert ActivityRecord into a proto,
1105 // so track the time.
1106 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
1107 "MetricsLogger:convertActivityRecordToProto");
1108
1109 // There does not appear to be a way to 'reset' a ProtoOutputBuffer stream,
1110 // so create a new one every time.
1111 final ProtoOutputStream protoOutputStream =
1112 new ProtoOutputStream(LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE);
1113 // Write this data out as the top-most ActivityRecordProto (i.e. it is not a sub-object).
1114 record.writeToProto(protoOutputStream);
1115 final byte[] bytes = protoOutputStream.getBytes();
1116
1117 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
1118
1119 return bytes;
Igor Murashkin212d06c2018-10-22 16:34:39 -07001120 }
1121
1122 private static @ActivityMetricsLaunchObserver.Temperature int
1123 convertTransitionTypeToLaunchObserverTemperature(int transitionType) {
1124 switch (transitionType) {
1125 case TYPE_TRANSITION_WARM_LAUNCH:
1126 return ActivityMetricsLaunchObserver.TEMPERATURE_WARM;
1127 case TYPE_TRANSITION_HOT_LAUNCH:
1128 return ActivityMetricsLaunchObserver.TEMPERATURE_HOT;
1129 case TYPE_TRANSITION_COLD_LAUNCH:
1130 return ActivityMetricsLaunchObserver.TEMPERATURE_COLD;
1131 default:
1132 return -1;
1133 }
1134 }
Filip Gruszczynski77d94482015-12-11 13:59:52 -08001135}