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