1 package com.android.server.wm; 2 3 import static android.app.ActivityManager.START_SUCCESS; 4 import static android.app.ActivityManager.START_TASK_TO_FRONT; 5 import static android.app.ActivityManager.processStateAmToProto; 6 import static android.app.WaitResult.LAUNCH_STATE_COLD; 7 import static android.app.WaitResult.LAUNCH_STATE_HOT; 8 import static android.app.WaitResult.LAUNCH_STATE_WARM; 9 import static android.app.WindowConfiguration.WINDOWING_MODE_FREEFORM; 10 import static android.app.WindowConfiguration.WINDOWING_MODE_FULLSCREEN; 11 import static android.app.WindowConfiguration.WINDOWING_MODE_MULTI_WINDOW; 12 import static android.app.WindowConfiguration.WINDOWING_MODE_PINNED; 13 import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_PRIMARY; 14 import static android.app.WindowConfiguration.WINDOWING_MODE_SPLIT_SCREEN_SECONDARY; 15 import static android.app.WindowConfiguration.WINDOWING_MODE_UNDEFINED; 16 17 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.ACTION_ACTIVITY_START; 18 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION; 19 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS; 20 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME; 21 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED; 22 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS; 23 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS; 24 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_IS_EPHEMERAL; 25 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_PROCESS_RUNNING; 26 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN; 27 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN_MS; 28 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS; 29 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS; 30 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_PACKAGE_NAME; 31 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID; 32 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW; 33 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CALLING_UID_PROC_STATE; 34 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME; 35 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_COMING_FROM_PENDING_INTENT; 36 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN; 37 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INTENT_ACTION; 38 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_CUR_PROC_STATE; 39 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES; 40 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES; 41 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES; 42 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_OVERLAY_UI; 43 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_HAS_TOP_UI; 44 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION; 45 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT; 46 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT; 47 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PENDING_UI_CLEAN; 48 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_PROCESS_RECORD_PROCESS_NAME; 49 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID; 50 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW; 51 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_REAL_CALLING_UID_PROC_STATE; 52 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_TARGET_SHORT_COMPONENT_NAME; 53 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_FILTER; 54 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.PACKAGE_OPTIMIZATION_COMPILATION_REASON; 55 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH; 56 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH; 57 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE; 58 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE; 59 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH; 60 import static com.android.server.am.MemoryStatUtil.MemoryStat; 61 import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem; 62 import static com.android.server.wm.ActivityTaskManagerDebugConfig.DEBUG_METRICS; 63 import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_ATM; 64 import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_WITH_CLASS_NAME; 65 import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT; 66 import static com.android.server.wm.EventLogTags.WM_ACTIVITY_LAUNCH_TIME; 67 68 import android.annotation.NonNull; 69 import android.annotation.Nullable; 70 import android.app.WaitResult; 71 import android.app.WindowConfiguration.WindowingMode; 72 import android.content.ComponentName; 73 import android.content.Intent; 74 import android.content.pm.ApplicationInfo; 75 import android.content.pm.dex.ArtManagerInternal; 76 import android.content.pm.dex.PackageOptimizationInfo; 77 import android.metrics.LogMaker; 78 import android.os.Binder; 79 import android.os.Looper; 80 import android.os.SystemClock; 81 import android.os.Trace; 82 import android.util.ArrayMap; 83 import android.util.EventLog; 84 import android.util.Log; 85 import android.util.Slog; 86 import android.util.TimeUtils; 87 import android.util.proto.ProtoOutputStream; 88 89 import com.android.internal.annotations.VisibleForTesting; 90 import com.android.internal.logging.MetricsLogger; 91 import com.android.internal.os.BackgroundThread; 92 import com.android.internal.util.FrameworkStatsLog; 93 import com.android.internal.util.function.pooled.PooledLambda; 94 import com.android.server.LocalServices; 95 96 import java.util.ArrayList; 97 import java.util.LinkedList; 98 import java.util.concurrent.TimeUnit; 99 100 /** 101 * Listens to activity launches, transitions, visibility changes and window drawn callbacks to 102 * determine app launch times and draw delays. Source of truth for activity metrics and provides 103 * data for Tron, logcat, event logs and {@link android.app.WaitResult}. 104 * <p> 105 * A typical sequence of a launch event could be: 106 * {@link #notifyActivityLaunching}, {@link #notifyActivityLaunched}, 107 * {@link #notifyStartingWindowDrawn} (optional), {@link #notifyTransitionStarting} 108 * {@link #notifyWindowsDrawn}. 109 * <p> 110 * Tests: 111 * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests 112 */ 113 class ActivityMetricsLogger { 114 115 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM; 116 117 // Window modes we are interested in logging. If we ever introduce a new type, we need to add 118 // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array. 119 private static final int WINDOW_STATE_STANDARD = 0; 120 private static final int WINDOW_STATE_SIDE_BY_SIDE = 1; 121 private static final int WINDOW_STATE_FREEFORM = 2; 122 private static final int WINDOW_STATE_ASSISTANT = 3; 123 private static final int WINDOW_STATE_MULTI_WINDOW = 4; 124 private static final int WINDOW_STATE_INVALID = -1; 125 126 /** 127 * The flag for {@link #notifyActivityLaunching} to skip associating a new launch with an active 128 * transition, in the case the launch is standalone (e.g. from recents). 129 */ 130 private static final int IGNORE_CALLER = -1; 131 private static final int INVALID_DELAY = -1; 132 private static final int INVALID_TRANSITION_TYPE = -1; 133 134 // Preallocated strings we are sending to tron, so we don't have to allocate a new one every 135 // time we log. 136 private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = { 137 "window_time_0", "window_time_1", "window_time_2", "window_time_3", "window_time_4"}; 138 139 private int mWindowState = WINDOW_STATE_STANDARD; 140 private long mLastLogTimeSecs; 141 private final ActivityStackSupervisor mSupervisor; 142 private final MetricsLogger mMetricsLogger = new MetricsLogger(); 143 144 /** All active transitions. */ 145 private final ArrayList<TransitionInfo> mTransitionInfoList = new ArrayList<>(); 146 /** Map : Last launched activity => {@link TransitionInfo} */ 147 private final ArrayMap<ActivityRecord, TransitionInfo> mLastTransitionInfo = new ArrayMap<>(); 148 149 private ArtManagerInternal mArtManagerInternal; 150 private final StringBuilder mStringBuilder = new StringBuilder(); 151 152 /** 153 * Due to the global single concurrent launch sequence, all calls to this observer must be made 154 * in-order on the same thread to fulfill the "happens-before" guarantee in LaunchObserver. 155 */ 156 private final LaunchObserverRegistryImpl mLaunchObserver; 157 @VisibleForTesting static final int LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE = 512; 158 159 /** 160 * The information created when an intent is incoming but we do not yet know whether it will be 161 * launched successfully. 162 */ 163 static final class LaunchingState { 164 /** The timestamp of {@link #notifyActivityLaunching}. */ 165 private long mCurrentTransitionStartTimeNs; 166 /** Non-null when a {@link TransitionInfo} is created for this state. */ 167 private TransitionInfo mAssociatedTransitionInfo; 168 169 @VisibleForTesting allDrawn()170 boolean allDrawn() { 171 return mAssociatedTransitionInfo != null && mAssociatedTransitionInfo.allDrawn(); 172 } 173 } 174 175 /** The information created when an activity is confirmed to be launched. */ 176 private static final class TransitionInfo { 177 /** 178 * The field to lookup and update an existing transition efficiently between 179 * {@link #notifyActivityLaunching} and {@link #notifyActivityLaunched}. 180 * 181 * @see LaunchingState#mAssociatedTransitionInfo 182 */ 183 final LaunchingState mLaunchingState; 184 /** 185 * The timestamp of the first {@link #notifyActivityLaunching}. It can be used as a key for 186 * observer to identify which callbacks belong to a launch event. 187 */ 188 final long mTransitionStartTimeNs; 189 /** The device uptime in seconds when this transition info is created. */ 190 final int mCurrentTransitionDeviceUptime; 191 /** The type can be cold (new process), warm (new activity), or hot (bring to front). */ 192 final int mTransitionType; 193 /** Whether the process was already running when the transition started. */ 194 final boolean mProcessRunning; 195 /** whether the process of the launching activity didn't have any active activity. */ 196 final boolean mProcessSwitch; 197 /** The activities that should be drawn. */ 198 final LinkedList<ActivityRecord> mPendingDrawActivities = new LinkedList<>(); 199 /** The latest activity to have been launched. */ 200 @NonNull ActivityRecord mLastLaunchedActivity; 201 202 /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyTransitionStarting}. */ 203 int mCurrentTransitionDelayMs; 204 /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyStartingWindowDrawn}. */ 205 int mStartingWindowDelayMs = INVALID_DELAY; 206 /** The time from {@link #mTransitionStartTimeNs} to {@link #notifyBindApplication}. */ 207 int mBindApplicationDelayMs = INVALID_DELAY; 208 /** Elapsed time from when we launch an activity to when its windows are drawn. */ 209 int mWindowsDrawnDelayMs; 210 /** The reason why the transition started (see ActivityManagerInternal.APP_TRANSITION_*). */ 211 int mReason = APP_TRANSITION_TIMEOUT; 212 /** The flag ensures that {@link #mStartingWindowDelayMs} is only set once. */ 213 boolean mLoggedStartingWindowDrawn; 214 /** If the any app transitions have been logged as starting. */ 215 boolean mLoggedTransitionStarting; 216 217 /** Non-null if the application has reported drawn but its window hasn't. */ 218 @Nullable Runnable mPendingFullyDrawn; 219 /** Non-null if the trace is active. */ 220 @Nullable String mLaunchTraceName; 221 222 /** @return Non-null if there will be a window drawn event for the launch. */ 223 @Nullable create(@onNull ActivityRecord r, @NonNull LaunchingState launchingState, boolean processRunning, boolean processSwitch, int startResult)224 static TransitionInfo create(@NonNull ActivityRecord r, 225 @NonNull LaunchingState launchingState, boolean processRunning, 226 boolean processSwitch, int startResult) { 227 int transitionType = INVALID_TRANSITION_TYPE; 228 if (processRunning) { 229 if (startResult == START_SUCCESS) { 230 transitionType = TYPE_TRANSITION_WARM_LAUNCH; 231 } else if (startResult == START_TASK_TO_FRONT) { 232 transitionType = TYPE_TRANSITION_HOT_LAUNCH; 233 } 234 } else if (startResult == START_SUCCESS || startResult == START_TASK_TO_FRONT) { 235 // Task may still exist when cold launching an activity and the start result will be 236 // set to START_TASK_TO_FRONT. Treat this as a COLD launch. 237 transitionType = TYPE_TRANSITION_COLD_LAUNCH; 238 } 239 if (transitionType == INVALID_TRANSITION_TYPE) { 240 // That means the startResult is neither START_SUCCESS nor START_TASK_TO_FRONT. 241 return null; 242 } 243 return new TransitionInfo(r, launchingState, transitionType, processRunning, 244 processSwitch); 245 } 246 247 /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */ TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType, boolean processRunning, boolean processSwitch)248 private TransitionInfo(ActivityRecord r, LaunchingState launchingState, int transitionType, 249 boolean processRunning, boolean processSwitch) { 250 mLaunchingState = launchingState; 251 mTransitionStartTimeNs = launchingState.mCurrentTransitionStartTimeNs; 252 mTransitionType = transitionType; 253 mProcessRunning = processRunning; 254 mProcessSwitch = processSwitch; 255 mCurrentTransitionDeviceUptime = 256 (int) TimeUnit.MILLISECONDS.toSeconds(SystemClock.uptimeMillis()); 257 setLatestLaunchedActivity(r); 258 launchingState.mAssociatedTransitionInfo = this; 259 } 260 261 /** 262 * Remembers the latest launched activity to represent the final transition. This also 263 * tracks the activities that should be drawn, so a consecutive launching sequence can be 264 * coalesced as one event. 265 */ setLatestLaunchedActivity(ActivityRecord r)266 void setLatestLaunchedActivity(ActivityRecord r) { 267 if (mLastLaunchedActivity == r) { 268 return; 269 } 270 mLastLaunchedActivity = r; 271 if (!r.noDisplay) { 272 if (DEBUG_METRICS) Slog.i(TAG, "Add pending draw " + r); 273 mPendingDrawActivities.add(r); 274 } 275 } 276 277 /** @return {@code true} if the activity matches a launched activity in this transition. */ contains(WindowContainer wc)278 boolean contains(WindowContainer wc) { 279 final ActivityRecord r = AppTransitionController.getAppFromContainer(wc); 280 return r != null && (r == mLastLaunchedActivity || mPendingDrawActivities.contains(r)); 281 } 282 283 /** Called when the activity is drawn or won't be drawn. */ removePendingDrawActivity(ActivityRecord r)284 void removePendingDrawActivity(ActivityRecord r) { 285 if (DEBUG_METRICS) Slog.i(TAG, "Remove pending draw " + r); 286 mPendingDrawActivities.remove(r); 287 } 288 allDrawn()289 boolean allDrawn() { 290 return mPendingDrawActivities.isEmpty(); 291 } 292 293 /** 294 * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or 295 * LaunchObserver. 296 */ isInterestingToLoggerAndObserver()297 boolean isInterestingToLoggerAndObserver() { 298 return mProcessSwitch; 299 } 300 calculateCurrentDelay()301 int calculateCurrentDelay() { 302 return calculateDelay(SystemClock.elapsedRealtimeNanos()); 303 } 304 calculateDelay(long timestampNs)305 int calculateDelay(long timestampNs) { 306 // Shouldn't take more than 25 days to launch an app, so int is fine here. 307 return (int) TimeUnit.NANOSECONDS.toMillis(timestampNs - mTransitionStartTimeNs); 308 } 309 310 @Override toString()311 public String toString() { 312 return "TransitionInfo{" + Integer.toHexString(System.identityHashCode(this)) 313 + " a=" + mLastLaunchedActivity + " ua=" + mPendingDrawActivities + "}"; 314 } 315 } 316 317 static final class TransitionInfoSnapshot { 318 final private ApplicationInfo applicationInfo; 319 final private WindowProcessController processRecord; 320 final String packageName; 321 final String launchedActivityName; 322 final private String launchedActivityLaunchedFromPackage; 323 final private String launchedActivityLaunchToken; 324 final private String launchedActivityAppRecordRequiredAbi; 325 final String launchedActivityShortComponentName; 326 final private String processName; 327 final private int reason; 328 final private int startingWindowDelayMs; 329 final private int bindApplicationDelayMs; 330 final int windowsDrawnDelayMs; 331 final int type; 332 final int userId; 333 /** 334 * Elapsed time from when we launch an activity to when the app reported it was 335 * fully drawn. If this is not reported then the value is set to INVALID_DELAY. 336 */ 337 final int windowsFullyDrawnDelayMs; 338 final int activityRecordIdHashCode; 339 TransitionInfoSnapshot(TransitionInfo info)340 private TransitionInfoSnapshot(TransitionInfo info) { 341 this(info, info.mLastLaunchedActivity, INVALID_DELAY); 342 } 343 TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs)344 private TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity, 345 int windowsFullyDrawnDelayMs) { 346 applicationInfo = launchedActivity.info.applicationInfo; 347 packageName = launchedActivity.packageName; 348 launchedActivityName = launchedActivity.info.name; 349 launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage; 350 launchedActivityLaunchToken = launchedActivity.info.launchToken; 351 launchedActivityAppRecordRequiredAbi = launchedActivity.app == null 352 ? null 353 : launchedActivity.app.getRequiredAbi(); 354 reason = info.mReason; 355 startingWindowDelayMs = info.mStartingWindowDelayMs; 356 bindApplicationDelayMs = info.mBindApplicationDelayMs; 357 windowsDrawnDelayMs = info.mWindowsDrawnDelayMs; 358 type = info.mTransitionType; 359 processRecord = launchedActivity.app; 360 processName = launchedActivity.processName; 361 userId = launchedActivity.mUserId; 362 launchedActivityShortComponentName = launchedActivity.shortComponentName; 363 activityRecordIdHashCode = System.identityHashCode(launchedActivity); 364 this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs; 365 } 366 getLaunchState()367 @WaitResult.LaunchState int getLaunchState() { 368 switch (type) { 369 case TYPE_TRANSITION_WARM_LAUNCH: 370 return LAUNCH_STATE_WARM; 371 case TYPE_TRANSITION_HOT_LAUNCH: 372 return LAUNCH_STATE_HOT; 373 case TYPE_TRANSITION_COLD_LAUNCH: 374 return LAUNCH_STATE_COLD; 375 default: 376 return -1; 377 } 378 } 379 } 380 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Looper looper)381 ActivityMetricsLogger(ActivityStackSupervisor supervisor, Looper looper) { 382 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000; 383 mSupervisor = supervisor; 384 mLaunchObserver = new LaunchObserverRegistryImpl(looper); 385 } 386 logWindowState()387 void logWindowState() { 388 final long now = SystemClock.elapsedRealtime() / 1000; 389 if (mWindowState != WINDOW_STATE_INVALID) { 390 // We log even if the window state hasn't changed, because the user might remain in 391 // home/fullscreen move forever and we would like to track this kind of behavior 392 // too. 393 mMetricsLogger.count(TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState], 394 (int) (now - mLastLogTimeSecs)); 395 } 396 mLastLogTimeSecs = now; 397 398 mWindowState = WINDOW_STATE_INVALID; 399 ActivityStack stack = 400 mSupervisor.mRootWindowContainer.getTopDisplayFocusedStack(); 401 if (stack == null) { 402 return; 403 } 404 405 if (stack.isActivityTypeAssistant()) { 406 mWindowState = WINDOW_STATE_ASSISTANT; 407 return; 408 } 409 410 @WindowingMode int windowingMode = stack.getWindowingMode(); 411 if (windowingMode == WINDOWING_MODE_PINNED) { 412 stack = mSupervisor.mRootWindowContainer.findStackBehind(stack); 413 windowingMode = stack.getWindowingMode(); 414 } 415 switch (windowingMode) { 416 case WINDOWING_MODE_FULLSCREEN: 417 mWindowState = WINDOW_STATE_STANDARD; 418 break; 419 case WINDOWING_MODE_SPLIT_SCREEN_PRIMARY: 420 case WINDOWING_MODE_SPLIT_SCREEN_SECONDARY: 421 mWindowState = WINDOW_STATE_SIDE_BY_SIDE; 422 break; 423 case WINDOWING_MODE_FREEFORM: 424 mWindowState = WINDOW_STATE_FREEFORM; 425 break; 426 case WINDOWING_MODE_MULTI_WINDOW: 427 mWindowState = WINDOW_STATE_MULTI_WINDOW; 428 break; 429 default: 430 if (windowingMode != WINDOWING_MODE_UNDEFINED) { 431 throw new IllegalStateException("Unknown windowing mode for stack=" + stack 432 + " windowingMode=" + windowingMode); 433 } 434 } 435 } 436 437 /** @return Non-null {@link TransitionInfo} if the activity is found in an active transition. */ 438 @Nullable getActiveTransitionInfo(WindowContainer wc)439 private TransitionInfo getActiveTransitionInfo(WindowContainer wc) { 440 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { 441 final TransitionInfo info = mTransitionInfoList.get(i); 442 if (info.contains(wc)) { 443 return info; 444 } 445 } 446 return null; 447 } 448 449 /** 450 * This method should be only used by starting recents and starting from recents, or internal 451 * tests. Because it doesn't lookup caller and always creates a new launching state. 452 * 453 * @see #notifyActivityLaunching(Intent, ActivityRecord, int) 454 */ notifyActivityLaunching(Intent intent)455 LaunchingState notifyActivityLaunching(Intent intent) { 456 return notifyActivityLaunching(intent, null /* caller */, IGNORE_CALLER); 457 } 458 459 /** 460 * If the caller is found in an active transition, it will be considered as consecutive launch 461 * and coalesced into the active transition. 462 * 463 * @see #notifyActivityLaunching(Intent, ActivityRecord, int) 464 */ notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller)465 LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller) { 466 return notifyActivityLaunching(intent, caller, Binder.getCallingUid()); 467 } 468 469 /** 470 * Notifies the tracker at the earliest possible point when we are starting to launch an 471 * activity. The caller must ensure that {@link #notifyActivityLaunched} will be called later 472 * with the returned {@link LaunchingState}. 473 */ notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller, int callingUid)474 private LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller, 475 int callingUid) { 476 final long transitionStartTimeNs = SystemClock.elapsedRealtimeNanos(); 477 TransitionInfo existingInfo = null; 478 if (callingUid != IGNORE_CALLER) { 479 // Associate the launching event to an active transition if the caller is found in its 480 // launched activities. 481 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { 482 final TransitionInfo info = mTransitionInfoList.get(i); 483 if (caller != null && info.contains(caller)) { 484 existingInfo = info; 485 break; 486 } 487 if (existingInfo == null && callingUid == info.mLastLaunchedActivity.getUid()) { 488 // Fallback to check the most recent matched uid for the case that the caller is 489 // not an activity. 490 existingInfo = info; 491 } 492 } 493 } 494 if (DEBUG_METRICS) { 495 Slog.i(TAG, "notifyActivityLaunching intent=" + intent 496 + " existingInfo=" + existingInfo); 497 } 498 499 if (existingInfo == null) { 500 // Only notify the observer for a new launching event. 501 launchObserverNotifyIntentStarted(intent, transitionStartTimeNs); 502 final LaunchingState launchingState = new LaunchingState(); 503 launchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs; 504 return launchingState; 505 } 506 existingInfo.mLaunchingState.mCurrentTransitionStartTimeNs = transitionStartTimeNs; 507 return existingInfo.mLaunchingState; 508 } 509 510 /** 511 * Notifies the tracker that the activity is actually launching. 512 * 513 * @param launchingState The launching state to track the new or active transition. 514 * @param resultCode One of the {@link android.app.ActivityManager}.START_* flags, indicating 515 * the result of the launch. 516 * @param launchedActivity The activity that is being launched 517 */ notifyActivityLaunched(@onNull LaunchingState launchingState, int resultCode, @Nullable ActivityRecord launchedActivity)518 void notifyActivityLaunched(@NonNull LaunchingState launchingState, int resultCode, 519 @Nullable ActivityRecord launchedActivity) { 520 if (launchedActivity == null) { 521 // The launch is aborted, e.g. intent not resolved, class not found. 522 abort(null /* info */, "nothing launched"); 523 return; 524 } 525 526 final WindowProcessController processRecord = launchedActivity.app != null 527 ? launchedActivity.app 528 : mSupervisor.mService.getProcessController( 529 launchedActivity.processName, launchedActivity.info.applicationInfo.uid); 530 // Whether the process that will contains the activity is already running. 531 final boolean processRunning = processRecord != null; 532 // We consider this a "process switch" if the process of the activity that gets launched 533 // didn't have an activity that was in started state. In this case, we assume that lot 534 // of caches might be purged so the time until it produces the first frame is very 535 // interesting. 536 final boolean processSwitch = !processRunning 537 || !processRecord.hasStartedActivity(launchedActivity); 538 539 final TransitionInfo info = launchingState.mAssociatedTransitionInfo; 540 if (DEBUG_METRICS) { 541 Slog.i(TAG, "notifyActivityLaunched" + " resultCode=" + resultCode 542 + " launchedActivity=" + launchedActivity + " processRunning=" + processRunning 543 + " processSwitch=" + processSwitch + " info=" + info); 544 } 545 546 if (launchedActivity.mDrawn) { 547 // Launched activity is already visible. We cannot measure windows drawn delay. 548 abort(info, "launched activity already visible"); 549 return; 550 } 551 552 if (info != null 553 && info.mLastLaunchedActivity.mDisplayContent == launchedActivity.mDisplayContent) { 554 // If we are already in an existing transition on the same display, only update the 555 // activity name, but not the other attributes. 556 557 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched update launched activity"); 558 // Coalesce multiple (trampoline) activities from a single sequence together. 559 info.setLatestLaunchedActivity(launchedActivity); 560 return; 561 } 562 563 final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState, 564 processRunning, processSwitch, resultCode); 565 if (newInfo == null) { 566 abort(info, "unrecognized launch"); 567 return; 568 } 569 570 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful"); 571 // A new launch sequence has begun. Start tracking it. 572 mTransitionInfoList.add(newInfo); 573 mLastTransitionInfo.put(launchedActivity, newInfo); 574 startLaunchTrace(newInfo); 575 if (newInfo.isInterestingToLoggerAndObserver()) { 576 launchObserverNotifyActivityLaunched(newInfo); 577 } else { 578 // As abort for no process switch. 579 launchObserverNotifyIntentFailed(); 580 } 581 } 582 583 /** 584 * Notifies the tracker that all windows of the app have been drawn. 585 * 586 * @return Non-null info if the activity was pending to draw, otherwise it might have been set 587 * to invisible (removed from active transition) or it was already drawn. 588 */ 589 @Nullable notifyWindowsDrawn(@onNull ActivityRecord r, long timestampNs)590 TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r, long timestampNs) { 591 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn " + r); 592 593 final TransitionInfo info = getActiveTransitionInfo(r); 594 if (info == null || info.allDrawn()) { 595 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn no activity to be drawn"); 596 return null; 597 } 598 // Always calculate the delay because the caller may need to know the individual drawn time. 599 info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs); 600 info.removePendingDrawActivity(r); 601 final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info); 602 if (info.mLoggedTransitionStarting && info.allDrawn()) { 603 done(false /* abort */, info, "notifyWindowsDrawn - all windows drawn", timestampNs); 604 } 605 return infoSnapshot; 606 } 607 608 /** 609 * Notifies the tracker that the starting window was drawn. 610 */ notifyStartingWindowDrawn(@onNull ActivityRecord r)611 void notifyStartingWindowDrawn(@NonNull ActivityRecord r) { 612 final TransitionInfo info = getActiveTransitionInfo(r); 613 if (info == null || info.mLoggedStartingWindowDrawn) { 614 return; 615 } 616 if (DEBUG_METRICS) Slog.i(TAG, "notifyStartingWindowDrawn " + r); 617 info.mLoggedStartingWindowDrawn = true; 618 info.mStartingWindowDelayMs = info.calculateDelay(SystemClock.elapsedRealtimeNanos()); 619 } 620 621 /** 622 * Notifies the tracker that the app transition is starting. 623 * 624 * @param activityToReason A map from activity to a reason integer, which must be on of 625 * ActivityTaskManagerInternal.APP_TRANSITION_* reasons. 626 */ notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason)627 void notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason) { 628 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting"); 629 630 final long timestampNs = SystemClock.elapsedRealtimeNanos(); 631 for (int index = activityToReason.size() - 1; index >= 0; index--) { 632 final WindowContainer wc = activityToReason.keyAt(index); 633 final TransitionInfo info = getActiveTransitionInfo(wc); 634 if (info == null || info.mLoggedTransitionStarting) { 635 // Ignore any subsequent notifyTransitionStarting. 636 continue; 637 } 638 if (DEBUG_METRICS) { 639 Slog.i(TAG, "notifyTransitionStarting activity=" + wc + " info=" + info); 640 } 641 642 info.mCurrentTransitionDelayMs = info.calculateDelay(timestampNs); 643 info.mReason = activityToReason.valueAt(index); 644 info.mLoggedTransitionStarting = true; 645 if (info.allDrawn()) { 646 done(false /* abort */, info, "notifyTransitionStarting - all windows drawn", 647 timestampNs); 648 } 649 } 650 } 651 652 /** Makes sure that the reference to the removed activity is cleared. */ notifyActivityRemoved(@onNull ActivityRecord r)653 void notifyActivityRemoved(@NonNull ActivityRecord r) { 654 mLastTransitionInfo.remove(r); 655 } 656 657 /** 658 * Notifies the tracker that the visibility of an app is changing. 659 * 660 * @param r the app that is changing its visibility 661 */ notifyVisibilityChanged(@onNull ActivityRecord r)662 void notifyVisibilityChanged(@NonNull ActivityRecord r) { 663 final TransitionInfo info = getActiveTransitionInfo(r); 664 if (info == null) { 665 return; 666 } 667 if (DEBUG_METRICS) { 668 Slog.i(TAG, "notifyVisibilityChanged " + r + " visible=" + r.mVisibleRequested 669 + " state=" + r.getState() + " finishing=" + r.finishing); 670 } 671 if (!r.mVisibleRequested || r.finishing) { 672 info.removePendingDrawActivity(r); 673 } 674 if (info.mLastLaunchedActivity != r) { 675 return; 676 } 677 // The activity and its task are passed separately because the activity may be removed from 678 // the task later. 679 r.mAtmService.mH.sendMessage(PooledLambda.obtainMessage( 680 ActivityMetricsLogger::checkVisibility, this, r.getTask(), r)); 681 } 682 683 /** @return {@code true} if the given task has an activity will be drawn. */ hasActivityToBeDrawn(Task t)684 private static boolean hasActivityToBeDrawn(Task t) { 685 return t.forAllActivities((r) -> r.mVisibleRequested && !r.mDrawn && !r.finishing); 686 } 687 checkVisibility(Task t, ActivityRecord r)688 private void checkVisibility(Task t, ActivityRecord r) { 689 synchronized (mSupervisor.mService.mGlobalLock) { 690 691 final TransitionInfo info = getActiveTransitionInfo(r); 692 693 // If we have an active transition that's waiting on a certain activity that will be 694 // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary. 695 696 // We have no active transitions. 697 if (info == null) { 698 return; 699 } 700 701 // The notified activity whose visibility changed is no longer the launched activity. 702 // We can still wait to get onWindowsDrawn. 703 if (info.mLastLaunchedActivity != r) { 704 return; 705 } 706 707 // If the task of the launched activity contains any activity to be drawn, then the 708 // window drawn event should report later to complete the transition. Otherwise all 709 // activities in this task may be finished, invisible or drawn, so the transition event 710 // should be cancelled. 711 if (hasActivityToBeDrawn(t)) { 712 return; 713 } 714 715 if (DEBUG_METRICS) Slog.i(TAG, "notifyVisibilityChanged to invisible activity=" + r); 716 logAppTransitionCancel(info); 717 abort(info, "notifyVisibilityChanged to invisible"); 718 } 719 } 720 721 /** 722 * Notifies the tracker that we called immediately before we call bindApplication on the client. 723 * 724 * @param appInfo The client into which we'll call bindApplication. 725 */ notifyBindApplication(ApplicationInfo appInfo)726 void notifyBindApplication(ApplicationInfo appInfo) { 727 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { 728 final TransitionInfo info = mTransitionInfoList.get(i); 729 730 // App isn't attached to record yet, so match with info. 731 if (info.mLastLaunchedActivity.info.applicationInfo == appInfo) { 732 info.mBindApplicationDelayMs = info.calculateCurrentDelay(); 733 } 734 } 735 } 736 737 /** Aborts tracking of current launch metrics. */ abort(TransitionInfo info, String cause)738 private void abort(TransitionInfo info, String cause) { 739 done(true /* abort */, info, cause, 0L /* timestampNs */); 740 } 741 742 /** Called when the given transition (info) is no longer active. */ done(boolean abort, @Nullable TransitionInfo info, String cause, long timestampNs)743 private void done(boolean abort, @Nullable TransitionInfo info, String cause, 744 long timestampNs) { 745 if (DEBUG_METRICS) { 746 Slog.i(TAG, "done abort=" + abort + " cause=" + cause + " timestamp=" + timestampNs 747 + " info=" + info); 748 } 749 if (info == null) { 750 launchObserverNotifyIntentFailed(); 751 return; 752 } 753 754 stopLaunchTrace(info); 755 if (abort) { 756 launchObserverNotifyActivityLaunchCancelled(info); 757 } else { 758 if (info.isInterestingToLoggerAndObserver()) { 759 launchObserverNotifyActivityLaunchFinished(info, timestampNs); 760 } 761 logAppTransitionFinished(info); 762 } 763 info.mPendingDrawActivities.clear(); 764 mTransitionInfoList.remove(info); 765 } 766 logAppTransitionCancel(TransitionInfo info)767 private void logAppTransitionCancel(TransitionInfo info) { 768 final int type = info.mTransitionType; 769 final ActivityRecord activity = info.mLastLaunchedActivity; 770 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED); 771 builder.setPackageName(activity.packageName); 772 builder.setType(type); 773 builder.addTaggedData(FIELD_CLASS_NAME, activity.info.name); 774 mMetricsLogger.write(builder); 775 FrameworkStatsLog.write( 776 FrameworkStatsLog.APP_START_CANCELED, 777 activity.info.applicationInfo.uid, 778 activity.packageName, 779 convertAppStartTransitionType(type), 780 activity.info.name); 781 if (DEBUG_METRICS) { 782 Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)", 783 activity.info.applicationInfo.uid, 784 activity.packageName, 785 convertAppStartTransitionType(type), 786 activity.info.name)); 787 } 788 } 789 logAppTransitionFinished(@onNull TransitionInfo info)790 private void logAppTransitionFinished(@NonNull TransitionInfo info) { 791 if (DEBUG_METRICS) Slog.i(TAG, "logging finished transition " + info); 792 793 // Take a snapshot of the transition info before sending it to the handler for logging. 794 // This will avoid any races with other operations that modify the ActivityRecord. 795 final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info); 796 if (info.isInterestingToLoggerAndObserver()) { 797 BackgroundThread.getHandler().post(() -> logAppTransition( 798 info.mCurrentTransitionDeviceUptime, info.mCurrentTransitionDelayMs, 799 infoSnapshot)); 800 } 801 BackgroundThread.getHandler().post(() -> logAppDisplayed(infoSnapshot)); 802 if (info.mPendingFullyDrawn != null) { 803 info.mPendingFullyDrawn.run(); 804 } 805 806 info.mLastLaunchedActivity.info.launchToken = null; 807 } 808 809 // This gets called on a background thread without holding the activity manager lock. logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs, TransitionInfoSnapshot info)810 private void logAppTransition(int currentTransitionDeviceUptime, int currentTransitionDelayMs, 811 TransitionInfoSnapshot info) { 812 final LogMaker builder = new LogMaker(APP_TRANSITION); 813 builder.setPackageName(info.packageName); 814 builder.setType(info.type); 815 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName); 816 final boolean isInstantApp = info.applicationInfo.isInstantApp(); 817 if (info.launchedActivityLaunchedFromPackage != null) { 818 builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME, 819 info.launchedActivityLaunchedFromPackage); 820 } 821 String launchToken = info.launchedActivityLaunchToken; 822 if (launchToken != null) { 823 builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, launchToken); 824 } 825 builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0); 826 builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS, 827 currentTransitionDeviceUptime); 828 builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs); 829 builder.setSubtype(info.reason); 830 if (info.startingWindowDelayMs != INVALID_DELAY) { 831 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS, 832 info.startingWindowDelayMs); 833 } 834 if (info.bindApplicationDelayMs != INVALID_DELAY) { 835 builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS, 836 info.bindApplicationDelayMs); 837 } 838 builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs); 839 final ArtManagerInternal artManagerInternal = getArtManagerInternal(); 840 final PackageOptimizationInfo packageOptimizationInfo = 841 (artManagerInternal == null) || (info.launchedActivityAppRecordRequiredAbi == null) 842 ? PackageOptimizationInfo.createWithNoInfo() 843 : artManagerInternal.getPackageOptimizationInfo( 844 info.applicationInfo, 845 info.launchedActivityAppRecordRequiredAbi, 846 info.launchedActivityName); 847 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON, 848 packageOptimizationInfo.getCompilationReason()); 849 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER, 850 packageOptimizationInfo.getCompilationFilter()); 851 mMetricsLogger.write(builder); 852 FrameworkStatsLog.write( 853 FrameworkStatsLog.APP_START_OCCURRED, 854 info.applicationInfo.uid, 855 info.packageName, 856 convertAppStartTransitionType(info.type), 857 info.launchedActivityName, 858 info.launchedActivityLaunchedFromPackage, 859 isInstantApp, 860 currentTransitionDeviceUptime * 1000, 861 info.reason, 862 currentTransitionDelayMs, 863 info.startingWindowDelayMs, 864 info.bindApplicationDelayMs, 865 info.windowsDrawnDelayMs, 866 launchToken, 867 packageOptimizationInfo.getCompilationReason(), 868 packageOptimizationInfo.getCompilationFilter()); 869 870 if (DEBUG_METRICS) { 871 Slog.i(TAG, String.format("APP_START_OCCURRED(%s, %s, %s, %s, %s)", 872 info.applicationInfo.uid, 873 info.packageName, 874 convertAppStartTransitionType(info.type), 875 info.launchedActivityName, 876 info.launchedActivityLaunchedFromPackage)); 877 } 878 879 880 logAppStartMemoryStateCapture(info); 881 } 882 logAppDisplayed(TransitionInfoSnapshot info)883 private void logAppDisplayed(TransitionInfoSnapshot info) { 884 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) { 885 return; 886 } 887 888 EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME, 889 info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName, 890 info.windowsDrawnDelayMs); 891 892 StringBuilder sb = mStringBuilder; 893 sb.setLength(0); 894 sb.append("Displayed "); 895 sb.append(info.launchedActivityShortComponentName); 896 sb.append(": "); 897 TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb); 898 Log.i(TAG, sb.toString()); 899 } 900 convertAppStartTransitionType(int tronType)901 private int convertAppStartTransitionType(int tronType) { 902 if (tronType == TYPE_TRANSITION_COLD_LAUNCH) { 903 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__COLD; 904 } 905 if (tronType == TYPE_TRANSITION_WARM_LAUNCH) { 906 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__WARM; 907 } 908 if (tronType == TYPE_TRANSITION_HOT_LAUNCH) { 909 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__HOT; 910 } 911 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__UNKNOWN; 912 } 913 914 /** @return the last known window drawn delay of the given activity. */ getLastDrawnDelayMs(ActivityRecord r)915 int getLastDrawnDelayMs(ActivityRecord r) { 916 final TransitionInfo info = mLastTransitionInfo.get(r); 917 return info != null ? info.mWindowsDrawnDelayMs : INVALID_DELAY; 918 } 919 920 /** @see android.app.Activity#reportFullyDrawn */ logAppTransitionReportedDrawn(ActivityRecord r, boolean restoredFromBundle)921 TransitionInfoSnapshot logAppTransitionReportedDrawn(ActivityRecord r, 922 boolean restoredFromBundle) { 923 final TransitionInfo info = mLastTransitionInfo.get(r); 924 if (info == null) { 925 return null; 926 } 927 if (!info.allDrawn() && info.mPendingFullyDrawn == null) { 928 // There are still undrawn activities, postpone reporting fully drawn until all of its 929 // windows are drawn. So that is closer to an usable state. 930 info.mPendingFullyDrawn = () -> { 931 logAppTransitionReportedDrawn(r, restoredFromBundle); 932 info.mPendingFullyDrawn = null; 933 }; 934 return null; 935 } 936 937 final long currentTimestampNs = SystemClock.elapsedRealtimeNanos(); 938 final long startupTimeMs = info.mPendingFullyDrawn != null 939 ? info.mWindowsDrawnDelayMs 940 : TimeUnit.NANOSECONDS.toMillis(currentTimestampNs - info.mTransitionStartTimeNs); 941 final TransitionInfoSnapshot infoSnapshot = 942 new TransitionInfoSnapshot(info, r, (int) startupTimeMs); 943 BackgroundThread.getHandler().post(() -> logAppFullyDrawn(infoSnapshot)); 944 945 if (!info.isInterestingToLoggerAndObserver()) { 946 return infoSnapshot; 947 } 948 949 // Record the handling of the reportFullyDrawn callback in the trace system. This is not 950 // actually used to trace this function, but instead the logical task that this function 951 // fullfils (handling reportFullyDrawn() callbacks). 952 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 953 "ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName); 954 955 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN); 956 builder.setPackageName(r.packageName); 957 builder.addTaggedData(FIELD_CLASS_NAME, r.info.name); 958 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, startupTimeMs); 959 builder.setType(restoredFromBundle 960 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE 961 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE); 962 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING, 963 info.mProcessRunning ? 1 : 0); 964 mMetricsLogger.write(builder); 965 FrameworkStatsLog.write( 966 FrameworkStatsLog.APP_START_FULLY_DRAWN, 967 info.mLastLaunchedActivity.info.applicationInfo.uid, 968 info.mLastLaunchedActivity.packageName, 969 restoredFromBundle 970 ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE 971 : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE, 972 info.mLastLaunchedActivity.info.name, 973 info.mProcessRunning, 974 startupTimeMs); 975 976 // Ends the trace started at the beginning of this function. This is located here to allow 977 // the trace slice to have a noticable duration. 978 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 979 980 // Notify reportFullyDrawn event. 981 launchObserverNotifyReportFullyDrawn(r, currentTimestampNs); 982 983 return infoSnapshot; 984 } 985 logAppFullyDrawn(TransitionInfoSnapshot info)986 private void logAppFullyDrawn(TransitionInfoSnapshot info) { 987 if (info.type != TYPE_TRANSITION_WARM_LAUNCH && info.type != TYPE_TRANSITION_COLD_LAUNCH) { 988 return; 989 } 990 991 StringBuilder sb = mStringBuilder; 992 sb.setLength(0); 993 sb.append("Fully drawn "); 994 sb.append(info.launchedActivityShortComponentName); 995 sb.append(": "); 996 TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb); 997 Log.i(TAG, sb.toString()); 998 } 999 logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp, int callingUid, String callingPackage, int callingUidProcState, boolean callingUidHasAnyVisibleWindow, int realCallingUid, int realCallingUidProcState, boolean realCallingUidHasAnyVisibleWindow, boolean comingFromPendingIntent)1000 void logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp, 1001 int callingUid, String callingPackage, int callingUidProcState, 1002 boolean callingUidHasAnyVisibleWindow, 1003 int realCallingUid, int realCallingUidProcState, 1004 boolean realCallingUidHasAnyVisibleWindow, 1005 boolean comingFromPendingIntent) { 1006 1007 final long nowElapsed = SystemClock.elapsedRealtime(); 1008 final long nowUptime = SystemClock.uptimeMillis(); 1009 final LogMaker builder = new LogMaker(ACTION_ACTIVITY_START); 1010 builder.setTimestamp(System.currentTimeMillis()); 1011 builder.addTaggedData(FIELD_CALLING_UID, callingUid); 1012 builder.addTaggedData(FIELD_CALLING_PACKAGE_NAME, callingPackage); 1013 builder.addTaggedData(FIELD_CALLING_UID_PROC_STATE, 1014 processStateAmToProto(callingUidProcState)); 1015 builder.addTaggedData(FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW, 1016 callingUidHasAnyVisibleWindow ? 1 : 0); 1017 builder.addTaggedData(FIELD_REAL_CALLING_UID, realCallingUid); 1018 builder.addTaggedData(FIELD_REAL_CALLING_UID_PROC_STATE, 1019 processStateAmToProto(realCallingUidProcState)); 1020 builder.addTaggedData(FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW, 1021 realCallingUidHasAnyVisibleWindow ? 1 : 0); 1022 builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0); 1023 if (intent != null) { 1024 builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction()); 1025 ComponentName component = intent.getComponent(); 1026 if (component != null) { 1027 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME, 1028 component.flattenToShortString()); 1029 } 1030 } 1031 if (callerApp != null) { 1032 builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName); 1033 builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE, 1034 processStateAmToProto(callerApp.getCurrentProcState())); 1035 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES, 1036 callerApp.hasClientActivities() ? 1 : 0); 1037 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES, 1038 callerApp.hasForegroundServices() ? 1 : 0); 1039 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES, 1040 callerApp.hasForegroundActivities() ? 1 : 0); 1041 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0); 1042 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI, 1043 callerApp.hasOverlayUi() ? 1 : 0); 1044 builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN, 1045 callerApp.hasPendingUiClean() ? 1 : 0); 1046 if (callerApp.getInteractionEventTime() != 0) { 1047 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT, 1048 (nowElapsed - callerApp.getInteractionEventTime())); 1049 } 1050 if (callerApp.getFgInteractionTime() != 0) { 1051 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION, 1052 (nowElapsed - callerApp.getFgInteractionTime())); 1053 } 1054 if (callerApp.getWhenUnimportant() != 0) { 1055 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT, 1056 (nowUptime - callerApp.getWhenUnimportant())); 1057 } 1058 } 1059 mMetricsLogger.write(builder); 1060 } 1061 logAppStartMemoryStateCapture(TransitionInfoSnapshot info)1062 private void logAppStartMemoryStateCapture(TransitionInfoSnapshot info) { 1063 if (info.processRecord == null) { 1064 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null"); 1065 return; 1066 } 1067 1068 final int pid = info.processRecord.getPid(); 1069 final int uid = info.applicationInfo.uid; 1070 final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid); 1071 if (memoryStat == null) { 1072 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null"); 1073 return; 1074 } 1075 1076 FrameworkStatsLog.write( 1077 FrameworkStatsLog.APP_START_MEMORY_STATE_CAPTURED, 1078 uid, 1079 info.processName, 1080 info.launchedActivityName, 1081 memoryStat.pgfault, 1082 memoryStat.pgmajfault, 1083 memoryStat.rssInBytes, 1084 memoryStat.cacheInBytes, 1085 memoryStat.swapInBytes); 1086 } 1087 getArtManagerInternal()1088 private ArtManagerInternal getArtManagerInternal() { 1089 if (mArtManagerInternal == null) { 1090 // Note that this may be null. 1091 // ArtManagerInternal is registered during PackageManagerService 1092 // initialization which happens after ActivityManagerService. 1093 mArtManagerInternal = LocalServices.getService(ArtManagerInternal.class); 1094 } 1095 return mArtManagerInternal; 1096 } 1097 1098 /** Starts trace for an activity is actually launching. */ startLaunchTrace(@onNull TransitionInfo info)1099 private void startLaunchTrace(@NonNull TransitionInfo info) { 1100 if (DEBUG_METRICS) Slog.i(TAG, "startLaunchTrace " + info); 1101 if (!Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) { 1102 return; 1103 } 1104 info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName; 1105 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName, 1106 (int) info.mTransitionStartTimeNs /* cookie */); 1107 } 1108 1109 /** Stops trace for the launch is completed or cancelled. */ stopLaunchTrace(@onNull TransitionInfo info)1110 private void stopLaunchTrace(@NonNull TransitionInfo info) { 1111 if (DEBUG_METRICS) Slog.i(TAG, "stopLaunchTrace " + info); 1112 if (info.mLaunchTraceName == null) { 1113 return; 1114 } 1115 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName, 1116 (int) info.mTransitionStartTimeNs /* cookie */); 1117 info.mLaunchTraceName = null; 1118 } 1119 getLaunchObserverRegistry()1120 public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() { 1121 return mLaunchObserver; 1122 } 1123 1124 /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */ launchObserverNotifyIntentStarted(Intent intent, long timestampNs)1125 private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) { 1126 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1127 "MetricsLogger:launchObserverNotifyIntentStarted"); 1128 1129 // Beginning a launch is timing sensitive and so should be observed as soon as possible. 1130 mLaunchObserver.onIntentStarted(intent, timestampNs); 1131 1132 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1133 } 1134 1135 /** 1136 * Notify the {@link ActivityMetricsLaunchObserver} that the previous launch sequence has 1137 * aborted due to intent failure (e.g. intent resolve failed or security error, etc) or 1138 * intent being delivered to the top running activity. 1139 */ launchObserverNotifyIntentFailed()1140 private void launchObserverNotifyIntentFailed() { 1141 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1142 "MetricsLogger:launchObserverNotifyIntentFailed"); 1143 1144 mLaunchObserver.onIntentFailed(); 1145 1146 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1147 } 1148 1149 /** 1150 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity 1151 * has started. 1152 */ launchObserverNotifyActivityLaunched(TransitionInfo info)1153 private void launchObserverNotifyActivityLaunched(TransitionInfo info) { 1154 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1155 "MetricsLogger:launchObserverNotifyActivityLaunched"); 1156 1157 @ActivityMetricsLaunchObserver.Temperature int temperature = 1158 convertTransitionTypeToLaunchObserverTemperature(info.mTransitionType); 1159 1160 // Beginning a launch is timing sensitive and so should be observed as soon as possible. 1161 mLaunchObserver.onActivityLaunched(convertActivityRecordToProto(info.mLastLaunchedActivity), 1162 temperature); 1163 1164 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1165 } 1166 1167 /** 1168 * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event. 1169 */ launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs)1170 private void launchObserverNotifyReportFullyDrawn(ActivityRecord r, long timestampNs) { 1171 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1172 "MetricsLogger:launchObserverNotifyReportFullyDrawn"); 1173 mLaunchObserver.onReportFullyDrawn(convertActivityRecordToProto(r), timestampNs); 1174 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1175 } 1176 1177 /** 1178 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is 1179 * cancelled. 1180 */ launchObserverNotifyActivityLaunchCancelled(TransitionInfo info)1181 private void launchObserverNotifyActivityLaunchCancelled(TransitionInfo info) { 1182 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1183 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled"); 1184 1185 final @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] activityRecordProto = 1186 info != null ? convertActivityRecordToProto(info.mLastLaunchedActivity) : null; 1187 1188 mLaunchObserver.onActivityLaunchCancelled(activityRecordProto); 1189 1190 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1191 } 1192 1193 /** 1194 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity 1195 * has fully finished (successfully). 1196 */ launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs)1197 private void launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs) { 1198 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1199 "MetricsLogger:launchObserverNotifyActivityLaunchFinished"); 1200 1201 mLaunchObserver.onActivityLaunchFinished( 1202 convertActivityRecordToProto(info.mLastLaunchedActivity), timestampNs); 1203 1204 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1205 } 1206 1207 @VisibleForTesting 1208 static @ActivityMetricsLaunchObserver.ActivityRecordProto byte[] convertActivityRecordToProto(ActivityRecord record)1209 convertActivityRecordToProto(ActivityRecord record) { 1210 // May take non-negligible amount of time to convert ActivityRecord into a proto, 1211 // so track the time. 1212 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1213 "MetricsLogger:convertActivityRecordToProto"); 1214 1215 // There does not appear to be a way to 'reset' a ProtoOutputBuffer stream, 1216 // so create a new one every time. 1217 final ProtoOutputStream protoOutputStream = 1218 new ProtoOutputStream(LAUNCH_OBSERVER_ACTIVITY_RECORD_PROTO_CHUNK_SIZE); 1219 // Write this data out as the top-most ActivityRecordProto (i.e. it is not a sub-object). 1220 record.dumpDebug(protoOutputStream, WindowTraceLogLevel.ALL); 1221 final byte[] bytes = protoOutputStream.getBytes(); 1222 1223 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1224 1225 return bytes; 1226 } 1227 1228 private static @ActivityMetricsLaunchObserver.Temperature int convertTransitionTypeToLaunchObserverTemperature(int transitionType)1229 convertTransitionTypeToLaunchObserverTemperature(int transitionType) { 1230 switch (transitionType) { 1231 case TYPE_TRANSITION_WARM_LAUNCH: 1232 return ActivityMetricsLaunchObserver.TEMPERATURE_WARM; 1233 case TYPE_TRANSITION_HOT_LAUNCH: 1234 return ActivityMetricsLaunchObserver.TEMPERATURE_HOT; 1235 case TYPE_TRANSITION_COLD_LAUNCH: 1236 return ActivityMetricsLaunchObserver.TEMPERATURE_COLD; 1237 default: 1238 return -1; 1239 } 1240 } 1241 } 1242