1package com.android.server.am; 2 3import static android.app.ActivityManager.START_SUCCESS; 4import static android.app.ActivityManager.START_TASK_TO_FRONT; 5import static android.app.ActivityManager.StackId.ASSISTANT_STACK_ID; 6import static android.app.ActivityManager.StackId.DOCKED_STACK_ID; 7import static android.app.ActivityManager.StackId.FREEFORM_WORKSPACE_STACK_ID; 8import static android.app.ActivityManager.StackId.FULLSCREEN_WORKSPACE_STACK_ID; 9import static android.app.ActivityManager.StackId.INVALID_STACK_ID; 10import static android.app.ActivityManager.StackId.PINNED_STACK_ID; 11import static android.app.ActivityManagerInternal.APP_TRANSITION_TIMEOUT; 12import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION; 13import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS; 14import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME; 15import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED; 16import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS; 17import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS; 18import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_IS_EPHEMERAL; 19import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_PROCESS_RUNNING; 20import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN; 21import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN_MS; 22import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS; 23import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS; 24import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME; 25import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN; 26import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH; 27import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH; 28import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE; 29import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE; 30import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH; 31import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_METRICS; 32import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM; 33import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME; 34import static com.android.server.am.ActivityStack.STACK_INVISIBLE; 35 36import android.app.ActivityManager.StackId; 37import android.content.Context; 38import android.metrics.LogMaker; 39import android.os.Handler; 40import android.os.Looper; 41import android.os.Message; 42import android.os.SystemClock; 43import android.util.Slog; 44import android.util.SparseArray; 45import android.util.SparseIntArray; 46 47import com.android.internal.logging.MetricsLogger; 48import com.android.internal.os.SomeArgs; 49 50import java.util.ArrayList; 51 52/** 53 * Handles logging into Tron. 54 */ 55class ActivityMetricsLogger { 56 57 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_AM; 58 59 // Window modes we are interested in logging. If we ever introduce a new type, we need to add 60 // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array. 61 private static final int WINDOW_STATE_STANDARD = 0; 62 private static final int WINDOW_STATE_SIDE_BY_SIDE = 1; 63 private static final int WINDOW_STATE_FREEFORM = 2; 64 private static final int WINDOW_STATE_ASSISTANT = 3; 65 private static final int WINDOW_STATE_INVALID = -1; 66 67 private static final long INVALID_START_TIME = -1; 68 69 private static final int MSG_CHECK_VISIBILITY = 0; 70 71 // Preallocated strings we are sending to tron, so we don't have to allocate a new one every 72 // time we log. 73 private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = { 74 "window_time_0", "window_time_1", "window_time_2", "window_time_3"}; 75 76 private int mWindowState = WINDOW_STATE_STANDARD; 77 private long mLastLogTimeSecs; 78 private final ActivityStackSupervisor mSupervisor; 79 private final Context mContext; 80 private final MetricsLogger mMetricsLogger = new MetricsLogger(); 81 82 private long mCurrentTransitionStartTime = INVALID_START_TIME; 83 private long mLastTransitionStartTime = INVALID_START_TIME; 84 85 private int mCurrentTransitionDeviceUptime; 86 private int mCurrentTransitionDelayMs; 87 private boolean mLoggedTransitionStarting; 88 89 private final SparseArray<StackTransitionInfo> mStackTransitionInfo = new SparseArray<>(); 90 private final SparseArray<StackTransitionInfo> mLastStackTransitionInfo = new SparseArray<>(); 91 private final H mHandler; 92 private final class H extends Handler { 93 94 public H(Looper looper) { 95 super(looper); 96 } 97 98 @Override 99 public void handleMessage(Message msg) { 100 switch (msg.what) { 101 case MSG_CHECK_VISIBILITY: 102 final SomeArgs args = (SomeArgs) msg.obj; 103 checkVisibility((TaskRecord) args.arg1, (ActivityRecord) args.arg2); 104 break; 105 } 106 } 107 }; 108 109 private final class StackTransitionInfo { 110 private ActivityRecord launchedActivity; 111 private int startResult; 112 private boolean currentTransitionProcessRunning; 113 private int windowsDrawnDelayMs; 114 private int startingWindowDelayMs = -1; 115 private int bindApplicationDelayMs = -1; 116 private int reason = APP_TRANSITION_TIMEOUT; 117 private boolean loggedWindowsDrawn; 118 private boolean loggedStartingWindowDrawn; 119 } 120 121 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context, Looper looper) { 122 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000; 123 mSupervisor = supervisor; 124 mContext = context; 125 mHandler = new H(looper); 126 } 127 128 void logWindowState() { 129 final long now = SystemClock.elapsedRealtime() / 1000; 130 if (mWindowState != WINDOW_STATE_INVALID) { 131 // We log even if the window state hasn't changed, because the user might remain in 132 // home/fullscreen move forever and we would like to track this kind of behavior 133 // too. 134 MetricsLogger.count(mContext, TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState], 135 (int) (now - mLastLogTimeSecs)); 136 } 137 mLastLogTimeSecs = now; 138 139 ActivityStack stack = mSupervisor.getStack(DOCKED_STACK_ID); 140 if (stack != null && stack.shouldBeVisible(null) != STACK_INVISIBLE) { 141 mWindowState = WINDOW_STATE_SIDE_BY_SIDE; 142 return; 143 } 144 mWindowState = WINDOW_STATE_INVALID; 145 stack = mSupervisor.getFocusedStack(); 146 if (stack.mStackId == PINNED_STACK_ID) { 147 stack = mSupervisor.findStackBehind(stack); 148 } 149 if (StackId.isHomeOrRecentsStack(stack.mStackId) 150 || stack.mStackId == FULLSCREEN_WORKSPACE_STACK_ID) { 151 mWindowState = WINDOW_STATE_STANDARD; 152 } else if (stack.mStackId == DOCKED_STACK_ID) { 153 Slog.wtf(TAG, "Docked stack shouldn't be the focused stack, because it reported not" 154 + " being visible."); 155 mWindowState = WINDOW_STATE_INVALID; 156 } else if (stack.mStackId == FREEFORM_WORKSPACE_STACK_ID) { 157 mWindowState = WINDOW_STATE_FREEFORM; 158 } else if (stack.mStackId == ASSISTANT_STACK_ID) { 159 mWindowState = WINDOW_STATE_ASSISTANT; 160 } else if (StackId.isStaticStack(stack.mStackId)) { 161 throw new IllegalStateException("Unknown stack=" + stack); 162 } 163 } 164 165 /** 166 * Notifies the tracker at the earliest possible point when we are starting to launch an 167 * activity. 168 */ 169 void notifyActivityLaunching() { 170 if (!isAnyTransitionActive()) { 171 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunching"); 172 mCurrentTransitionStartTime = SystemClock.uptimeMillis(); 173 mLastTransitionStartTime = mCurrentTransitionStartTime; 174 } 175 } 176 177 /** 178 * Notifies the tracker that the activity is actually launching. 179 * 180 * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the 181 * launch 182 * @param launchedActivity the activity that is being launched 183 */ 184 void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity) { 185 final ProcessRecord processRecord = launchedActivity != null 186 ? mSupervisor.mService.mProcessNames.get(launchedActivity.processName, 187 launchedActivity.appInfo.uid) 188 : null; 189 final boolean processRunning = processRecord != null; 190 191 // We consider this a "process switch" if the process of the activity that gets launched 192 // didn't have an activity that was in started state. In this case, we assume that lot 193 // of caches might be purged so the time until it produces the first frame is very 194 // interesting. 195 final boolean processSwitch = processRecord == null 196 || !hasStartedActivity(processRecord, launchedActivity); 197 198 notifyActivityLaunched(resultCode, launchedActivity, processRunning, processSwitch); 199 } 200 201 private boolean hasStartedActivity(ProcessRecord record, ActivityRecord launchedActivity) { 202 final ArrayList<ActivityRecord> activities = record.activities; 203 for (int i = activities.size() - 1; i >= 0; i--) { 204 final ActivityRecord activity = activities.get(i); 205 if (launchedActivity == activity) { 206 continue; 207 } 208 if (!activity.stopped) { 209 return true; 210 } 211 } 212 return false; 213 } 214 215 /** 216 * Notifies the tracker the the activity is actually launching. 217 * 218 * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the 219 * launch 220 * @param launchedActivity the activity being launched 221 * @param processRunning whether the process that will contains the activity is already running 222 * @param processSwitch whether the process that will contain the activity didn't have any 223 * activity that was stopped, i.e. the started activity is "switching" 224 * processes 225 */ 226 private void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity, 227 boolean processRunning, boolean processSwitch) { 228 229 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched" 230 + " resultCode=" + resultCode 231 + " launchedActivity=" + launchedActivity 232 + " processRunning=" + processRunning 233 + " processSwitch=" + processSwitch); 234 235 // If we are already in an existing transition, only update the activity name, but not the 236 // other attributes. 237 final int stackId = launchedActivity != null && launchedActivity.getStack() != null 238 ? launchedActivity.getStack().mStackId 239 : INVALID_STACK_ID; 240 241 if (mCurrentTransitionStartTime == INVALID_START_TIME) { 242 return; 243 } 244 245 final StackTransitionInfo info = mStackTransitionInfo.get(stackId); 246 if (launchedActivity != null && info != null) { 247 info.launchedActivity = launchedActivity; 248 return; 249 } 250 251 final boolean otherStacksLaunching = mStackTransitionInfo.size() > 0 && info == null; 252 if ((resultCode < 0 || launchedActivity == null || !processSwitch 253 || stackId == INVALID_STACK_ID) && !otherStacksLaunching) { 254 255 // Failed to launch or it was not a process switch, so we don't care about the timing. 256 reset(true /* abort */); 257 return; 258 } else if (otherStacksLaunching) { 259 // Don't log this stack but continue with the other stacks. 260 return; 261 } 262 263 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful"); 264 265 final StackTransitionInfo newInfo = new StackTransitionInfo(); 266 newInfo.launchedActivity = launchedActivity; 267 newInfo.currentTransitionProcessRunning = processRunning; 268 newInfo.startResult = resultCode; 269 mStackTransitionInfo.put(stackId, newInfo); 270 mLastStackTransitionInfo.put(stackId, newInfo); 271 mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000); 272 } 273 274 /** 275 * Notifies the tracker that all windows of the app have been drawn. 276 */ 277 void notifyWindowsDrawn(int stackId, long timestamp) { 278 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn stackId=" + stackId); 279 280 final StackTransitionInfo info = mStackTransitionInfo.get(stackId); 281 if (info == null || info.loggedWindowsDrawn) { 282 return; 283 } 284 info.windowsDrawnDelayMs = calculateDelay(timestamp); 285 info.loggedWindowsDrawn = true; 286 if (allStacksWindowsDrawn() && mLoggedTransitionStarting) { 287 reset(false /* abort */); 288 } 289 } 290 291 /** 292 * Notifies the tracker that the starting window was drawn. 293 */ 294 void notifyStartingWindowDrawn(int stackId, long timestamp) { 295 final StackTransitionInfo info = mStackTransitionInfo.get(stackId); 296 if (info == null || info.loggedStartingWindowDrawn) { 297 return; 298 } 299 info.loggedStartingWindowDrawn = true; 300 info.startingWindowDelayMs = calculateDelay(timestamp); 301 } 302 303 /** 304 * Notifies the tracker that the app transition is starting. 305 * 306 * @param stackIdReasons A map from stack id to a reason integer, which must be on of 307 * ActivityManagerInternal.APP_TRANSITION_* reasons. 308 */ 309 void notifyTransitionStarting(SparseIntArray stackIdReasons, long timestamp) { 310 if (!isAnyTransitionActive() || mLoggedTransitionStarting) { 311 return; 312 } 313 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting"); 314 mCurrentTransitionDelayMs = calculateDelay(timestamp); 315 mLoggedTransitionStarting = true; 316 for (int index = stackIdReasons.size() - 1; index >= 0; index--) { 317 final int stackId = stackIdReasons.keyAt(index); 318 final StackTransitionInfo info = mStackTransitionInfo.get(stackId); 319 if (info == null) { 320 continue; 321 } 322 info.reason = stackIdReasons.valueAt(index); 323 } 324 if (allStacksWindowsDrawn()) { 325 reset(false /* abort */); 326 } 327 } 328 329 /** 330 * Notifies the tracker that the visibility of an app is changing. 331 * 332 * @param activityRecord the app that is changing its visibility 333 */ 334 void notifyVisibilityChanged(ActivityRecord activityRecord) { 335 final StackTransitionInfo info = mStackTransitionInfo.get(activityRecord.getStackId()); 336 if (info == null) { 337 return; 338 } 339 if (info.launchedActivity != activityRecord) { 340 return; 341 } 342 final TaskRecord t = activityRecord.getTask(); 343 final SomeArgs args = SomeArgs.obtain(); 344 args.arg1 = t; 345 args.arg2 = activityRecord; 346 mHandler.obtainMessage(MSG_CHECK_VISIBILITY, args).sendToTarget(); 347 } 348 349 private void checkVisibility(TaskRecord t, ActivityRecord r) { 350 synchronized (mSupervisor.mService) { 351 352 final StackTransitionInfo info = mStackTransitionInfo.get(r.getStackId()); 353 354 // If we have an active transition that's waiting on a certain activity that will be 355 // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary. 356 if (info != null && !t.isVisible()) { 357 if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible" 358 + " activity=" + r); 359 logAppTransitionCancel(info); 360 mStackTransitionInfo.remove(r.getStackId()); 361 if (mStackTransitionInfo.size() == 0) { 362 reset(true /* abort */); 363 } 364 } 365 } 366 } 367 368 /** 369 * Notifies the tracker that we called immediately before we call bindApplication on the client. 370 * 371 * @param app The client into which we'll call bindApplication. 372 */ 373 void notifyBindApplication(ProcessRecord app) { 374 for (int i = mStackTransitionInfo.size() - 1; i >= 0; i--) { 375 final StackTransitionInfo info = mStackTransitionInfo.valueAt(i); 376 377 // App isn't attached to record yet, so match with info. 378 if (info.launchedActivity.appInfo == app.info) { 379 info.bindApplicationDelayMs = calculateCurrentDelay(); 380 } 381 } 382 } 383 384 private boolean allStacksWindowsDrawn() { 385 for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) { 386 if (!mStackTransitionInfo.valueAt(index).loggedWindowsDrawn) { 387 return false; 388 } 389 } 390 return true; 391 } 392 393 private boolean isAnyTransitionActive() { 394 return mCurrentTransitionStartTime != INVALID_START_TIME 395 && mStackTransitionInfo.size() > 0; 396 } 397 398 private void reset(boolean abort) { 399 if (DEBUG_METRICS) Slog.i(TAG, "reset abort=" + abort); 400 if (!abort && isAnyTransitionActive()) { 401 logAppTransitionMultiEvents(); 402 } 403 mCurrentTransitionStartTime = INVALID_START_TIME; 404 mCurrentTransitionDelayMs = -1; 405 mLoggedTransitionStarting = false; 406 mStackTransitionInfo.clear(); 407 } 408 409 private int calculateCurrentDelay() { 410 411 // Shouldn't take more than 25 days to launch an app, so int is fine here. 412 return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime); 413 } 414 415 private int calculateDelay(long timestamp) { 416 // Shouldn't take more than 25 days to launch an app, so int is fine here. 417 return (int) (timestamp - mCurrentTransitionStartTime); 418 } 419 420 private void logAppTransitionCancel(StackTransitionInfo info) { 421 final int type = getTransitionType(info); 422 if (type == -1) { 423 return; 424 } 425 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED); 426 builder.setPackageName(info.launchedActivity.packageName); 427 builder.setType(type); 428 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivity.info.name); 429 mMetricsLogger.write(builder); 430 } 431 432 private void logAppTransitionMultiEvents() { 433 if (DEBUG_METRICS) Slog.i(TAG, "logging transition events"); 434 for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) { 435 final StackTransitionInfo info = mStackTransitionInfo.valueAt(index); 436 final int type = getTransitionType(info); 437 if (type == -1) { 438 return; 439 } 440 final LogMaker builder = new LogMaker(APP_TRANSITION); 441 builder.setPackageName(info.launchedActivity.packageName); 442 builder.setType(type); 443 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivity.info.name); 444 final boolean isInstantApp = info.launchedActivity.info.applicationInfo.isInstantApp(); 445 if (info.launchedActivity.launchedFromPackage != null) { 446 builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME, 447 info.launchedActivity.launchedFromPackage); 448 } 449 if (info.launchedActivity.info.launchToken != null) { 450 builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, 451 info.launchedActivity.info.launchToken); 452 info.launchedActivity.info.launchToken = null; 453 } 454 builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0); 455 builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS, 456 mCurrentTransitionDeviceUptime); 457 builder.addTaggedData(APP_TRANSITION_DELAY_MS, mCurrentTransitionDelayMs); 458 builder.setSubtype(info.reason); 459 if (info.startingWindowDelayMs != -1) { 460 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS, 461 info.startingWindowDelayMs); 462 } 463 if (info.bindApplicationDelayMs != -1) { 464 builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS, 465 info.bindApplicationDelayMs); 466 } 467 builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs); 468 mMetricsLogger.write(builder); 469 } 470 } 471 472 void logAppTransitionReportedDrawn(ActivityRecord r, boolean restoredFromBundle) { 473 final StackTransitionInfo info = mLastStackTransitionInfo.get(r.getStackId()); 474 if (info == null) { 475 return; 476 } 477 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN); 478 builder.setPackageName(r.packageName); 479 builder.addTaggedData(FIELD_CLASS_NAME, r.info.name); 480 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, 481 SystemClock.uptimeMillis() - mLastTransitionStartTime); 482 builder.setType(restoredFromBundle 483 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE 484 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE); 485 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING, 486 info.currentTransitionProcessRunning ? 1 : 0); 487 mMetricsLogger.write(builder); 488 } 489 490 private int getTransitionType(StackTransitionInfo info) { 491 if (info.currentTransitionProcessRunning) { 492 if (info.startResult == START_SUCCESS) { 493 return TYPE_TRANSITION_WARM_LAUNCH; 494 } else if (info.startResult == START_TASK_TO_FRONT) { 495 return TYPE_TRANSITION_HOT_LAUNCH; 496 } 497 } else if (info.startResult == START_SUCCESS) { 498 return TYPE_TRANSITION_COLD_LAUNCH; 499 } 500 return -1; 501 } 502} 503