1 package com.android.server.wm; 2 3 import static android.app.ActivityManager.PROCESS_STATE_NONEXISTENT; 4 import static android.app.ActivityManager.START_SUCCESS; 5 import static android.app.ActivityManager.START_TASK_TO_FRONT; 6 import static android.app.ActivityManager.processStateAmToProto; 7 import static android.app.WaitResult.INVALID_DELAY; 8 import static android.app.WaitResult.LAUNCH_STATE_COLD; 9 import static android.app.WaitResult.LAUNCH_STATE_HOT; 10 import static android.app.WaitResult.LAUNCH_STATE_RELAUNCH; 11 import static android.app.WaitResult.LAUNCH_STATE_WARM; 12 import static android.app.WindowConfiguration.WINDOWING_MODE_FREEFORM; 13 import static android.app.WindowConfiguration.WINDOWING_MODE_FULLSCREEN; 14 import static android.app.WindowConfiguration.WINDOWING_MODE_MULTI_WINDOW; 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.internal.util.FrameworkStatsLog.APP_COMPAT_STATE_CHANGED__LETTERBOX_POSITION__NOT_LETTERBOXED_POSITION; 61 import static com.android.internal.util.FrameworkStatsLog.APP_COMPAT_STATE_CHANGED__STATE__LETTERBOXED_FOR_ASPECT_RATIO; 62 import static com.android.internal.util.FrameworkStatsLog.APP_COMPAT_STATE_CHANGED__STATE__LETTERBOXED_FOR_FIXED_ORIENTATION; 63 import static com.android.internal.util.FrameworkStatsLog.APP_COMPAT_STATE_CHANGED__STATE__LETTERBOXED_FOR_SIZE_COMPAT_MODE; 64 import static com.android.internal.util.FrameworkStatsLog.APP_COMPAT_STATE_CHANGED__STATE__NOT_LETTERBOXED; 65 import static com.android.internal.util.FrameworkStatsLog.APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE; 66 import static com.android.internal.util.FrameworkStatsLog.APP_START_OCCURRED__PACKAGE_STOPPED_STATE__PACKAGE_STATE_NORMAL; 67 import static com.android.internal.util.FrameworkStatsLog.APP_START_OCCURRED__PACKAGE_STOPPED_STATE__PACKAGE_STATE_STOPPED; 68 import static com.android.internal.util.FrameworkStatsLog.CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__APPEARED_APPLY_TREATMENT; 69 import static com.android.internal.util.FrameworkStatsLog.CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__APPEARED_REVERT_TREATMENT; 70 import static com.android.internal.util.FrameworkStatsLog.CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__CLICKED_APPLY_TREATMENT; 71 import static com.android.internal.util.FrameworkStatsLog.CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__CLICKED_DISMISS; 72 import static com.android.internal.util.FrameworkStatsLog.CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__CLICKED_REVERT_TREATMENT; 73 import static com.android.server.am.MemoryStatUtil.MemoryStat; 74 import static com.android.server.am.MemoryStatUtil.readMemoryStatFromFilesystem; 75 import static com.android.server.am.ProcessList.INVALID_ADJ; 76 import static com.android.server.wm.ActivityTaskManagerDebugConfig.DEBUG_METRICS; 77 import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_ATM; 78 import static com.android.server.wm.ActivityTaskManagerDebugConfig.TAG_WITH_CLASS_NAME; 79 import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_RECENTS_ANIM; 80 import static com.android.server.wm.ActivityTaskManagerInternal.APP_TRANSITION_TIMEOUT; 81 import static com.android.server.wm.EventLogTags.WM_ACTIVITY_LAUNCH_TIME; 82 83 import android.annotation.NonNull; 84 import android.annotation.Nullable; 85 import android.app.ActivityOptions; 86 import android.app.ActivityOptions.SourceInfo; 87 import android.app.TaskInfo; 88 import android.app.TaskInfo.CameraCompatControlState; 89 import android.app.WaitResult; 90 import android.app.WindowConfiguration.WindowingMode; 91 import android.content.ComponentName; 92 import android.content.Intent; 93 import android.content.pm.ApplicationInfo; 94 import android.content.pm.IncrementalStatesInfo; 95 import android.content.pm.dex.ArtManagerInternal; 96 import android.content.pm.dex.PackageOptimizationInfo; 97 import android.metrics.LogMaker; 98 import android.os.Handler; 99 import android.os.Looper; 100 import android.os.SystemClock; 101 import android.os.Trace; 102 import android.os.incremental.IncrementalManager; 103 import android.util.ArrayMap; 104 import android.util.EventLog; 105 import android.util.Log; 106 import android.util.Slog; 107 import android.util.SparseArray; 108 import android.util.TimeUtils; 109 110 import com.android.internal.annotations.VisibleForTesting; 111 import com.android.internal.logging.MetricsLogger; 112 import com.android.internal.util.FrameworkStatsLog; 113 import com.android.internal.util.LatencyTracker; 114 import com.android.internal.util.function.pooled.PooledLambda; 115 import com.android.server.FgThread; 116 import com.android.server.LocalServices; 117 import com.android.server.apphibernation.AppHibernationManagerInternal; 118 import com.android.server.apphibernation.AppHibernationService; 119 120 import java.util.ArrayList; 121 import java.util.concurrent.TimeUnit; 122 123 /** 124 * Listens to activity launches, transitions, visibility changes and window drawn callbacks to 125 * determine app launch times and draw delays. Source of truth for activity metrics and provides 126 * data for Tron, logcat, event logs and {@link android.app.WaitResult}. 127 * <p> 128 * A typical sequence of a launch event could be: 129 * {@link #notifyActivityLaunching}, {@link #notifyActivityLaunched}, 130 * {@link #notifyStartingWindowDrawn} (optional), {@link #notifyTransitionStarting} 131 * {@link #notifyWindowsDrawn}. 132 * <p> 133 * Tests: 134 * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests 135 */ 136 class ActivityMetricsLogger { 137 138 private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_ATM; 139 140 // Window modes we are interested in logging. If we ever introduce a new type, we need to add 141 // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array. 142 private static final int WINDOW_STATE_STANDARD = 0; 143 private static final int WINDOW_STATE_SIDE_BY_SIDE = 1; 144 private static final int WINDOW_STATE_FREEFORM = 2; 145 private static final int WINDOW_STATE_ASSISTANT = 3; 146 private static final int WINDOW_STATE_MULTI_WINDOW = 4; 147 private static final int WINDOW_STATE_INVALID = -1; 148 149 /** 150 * If a launching activity isn't visible within this duration when the device is sleeping, e.g. 151 * keyguard is locked, its transition info will be dropped. 152 */ 153 private static final long UNKNOWN_VISIBILITY_CHECK_DELAY_MS = 3000; 154 155 /** 156 * If the recents animation is finished before the delay since the window drawn, do not log the 157 * action because the duration is too small that may be just an accidentally touch. 158 */ 159 private static final long LATENCY_TRACKER_RECENTS_DELAY_MS = 300; 160 161 /** 162 * The flag for {@link #notifyActivityLaunching} to skip associating a new launch with an active 163 * transition, in the case the launch is standalone (e.g. from recents). 164 */ 165 private static final int IGNORE_CALLER = -1; 166 167 // Preallocated strings we are sending to tron, so we don't have to allocate a new one every 168 // time we log. 169 private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = { 170 "window_time_0", "window_time_1", "window_time_2", "window_time_3", "window_time_4"}; 171 172 private int mWindowState = WINDOW_STATE_STANDARD; 173 private long mLastLogTimeSecs; 174 private final ActivityTaskSupervisor mSupervisor; 175 private final MetricsLogger mMetricsLogger = new MetricsLogger(); 176 private final Handler mLoggerHandler = FgThread.getHandler(); 177 178 /** All active transitions. */ 179 private final ArrayList<TransitionInfo> mTransitionInfoList = new ArrayList<>(); 180 /** Map : Last launched activity => {@link TransitionInfo} */ 181 private final ArrayMap<ActivityRecord, TransitionInfo> mLastTransitionInfo = new ArrayMap<>(); 182 /** SparseArray : Package UID => {@link PackageCompatStateInfo} */ 183 private final SparseArray<PackageCompatStateInfo> mPackageUidToCompatStateInfo = 184 new SparseArray<>(0); 185 186 private ArtManagerInternal mArtManagerInternal; 187 private final StringBuilder mStringBuilder = new StringBuilder(); 188 189 /** 190 * Due to the global single concurrent launch sequence, all calls to this observer must be made 191 * in-order on the same thread to fulfill the "happens-before" guarantee in LaunchObserver. 192 */ 193 private final LaunchObserverRegistryImpl mLaunchObserver; 194 private final ArrayMap<String, Boolean> mLastHibernationStates = new ArrayMap<>(); 195 private AppHibernationManagerInternal mAppHibernationManagerInternal; 196 197 /** 198 * The information created when an intent is incoming but we do not yet know whether it will be 199 * launched successfully. 200 */ 201 static final class LaunchingState { 202 /** 203 * The device uptime of {@link #notifyActivityLaunching}. It can be used as a key for 204 * observer to identify which callbacks belong to a launch event. 205 */ 206 final long mStartUptimeNs = SystemClock.uptimeNanos(); 207 /** 208 * The timestamp of {@link #notifyActivityLaunching}. It is used to provide the time 209 * relative to the wall-time. 210 */ 211 final long mStartRealtimeNs = SystemClock.elapsedRealtimeNanos(); 212 /** Non-null when a {@link TransitionInfo} is created for this state. */ 213 private TransitionInfo mAssociatedTransitionInfo; 214 /** The sequence id for trace. It is used to map the traces before resolving intent. */ 215 private static int sTraceSeqId; 216 /** The trace format is "launchingActivity#$seqId:$state(:$packageName)". */ 217 String mTraceName; 218 LaunchingState()219 LaunchingState() { 220 if (!Trace.isTagEnabled(Trace.TRACE_TAG_ACTIVITY_MANAGER)) { 221 return; 222 } 223 // Use an id because the launching app is not yet known before resolving intent. 224 sTraceSeqId++; 225 mTraceName = "launchingActivity#" + sTraceSeqId; 226 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, mTraceName, 0); 227 } 228 stopTrace(boolean abort, TransitionInfo endInfo)229 void stopTrace(boolean abort, TransitionInfo endInfo) { 230 if (mTraceName == null) return; 231 if (!abort && endInfo != mAssociatedTransitionInfo) { 232 // Multiple TransitionInfo can be associated with the same LaunchingState (e.g. a 233 // launching activity launches another activity in a different windowing mode or 234 // display). Only the original associated info can emit a "completed" trace. 235 return; 236 } 237 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, mTraceName, 0); 238 final String launchResult; 239 if (mAssociatedTransitionInfo == null) { 240 launchResult = ":failed"; 241 } else { 242 final String status; 243 if (abort) { 244 status = ":canceled:"; 245 } else if (!mAssociatedTransitionInfo.mProcessSwitch) { 246 status = ":completed-same-process:"; 247 } else { 248 if (endInfo.mTransitionType == TYPE_TRANSITION_HOT_LAUNCH) { 249 status = ":completed-hot:"; 250 } else if (endInfo.mTransitionType == TYPE_TRANSITION_WARM_LAUNCH) { 251 status = ":completed-warm:"; 252 } else { 253 status = ":completed-cold:"; 254 } 255 } 256 launchResult = status + mAssociatedTransitionInfo.mLastLaunchedActivity.packageName; 257 } 258 // Put a supplement trace as the description of the async trace with the same id. 259 Trace.instant(Trace.TRACE_TAG_ACTIVITY_MANAGER, mTraceName + launchResult); 260 mTraceName = null; 261 } 262 263 @VisibleForTesting allDrawn()264 boolean allDrawn() { 265 return mAssociatedTransitionInfo != null && mAssociatedTransitionInfo.mIsDrawn; 266 } 267 hasActiveTransitionInfo()268 boolean hasActiveTransitionInfo() { 269 return mAssociatedTransitionInfo != null; 270 } 271 contains(ActivityRecord r)272 boolean contains(ActivityRecord r) { 273 return mAssociatedTransitionInfo != null && mAssociatedTransitionInfo.contains(r); 274 } 275 } 276 277 /** The information created when an activity is confirmed to be launched. */ 278 private static final class TransitionInfo { 279 /** 280 * The field to lookup and update an existing transition efficiently between 281 * {@link #notifyActivityLaunching} and {@link #notifyActivityLaunched}. 282 * 283 * @see LaunchingState#mAssociatedTransitionInfo 284 */ 285 final LaunchingState mLaunchingState; 286 287 /** The type can be cold (new process), warm (new activity), or hot (bring to front). */ 288 int mTransitionType; 289 /** Whether the process was already running when the transition started. */ 290 boolean mProcessRunning; 291 /** whether the process of the launching activity didn't have any active activity. */ 292 final boolean mProcessSwitch; 293 /** The process state of the launching activity prior to the launch */ 294 final int mProcessState; 295 /** The oom adj score of the launching activity prior to the launch */ 296 final int mProcessOomAdj; 297 /** Whether the activity is launched above a visible activity in the same task. */ 298 final boolean mIsInTaskActivityStart; 299 /** Whether the last launched activity has reported drawn. */ 300 boolean mIsDrawn; 301 /** The latest activity to have been launched. */ 302 @NonNull ActivityRecord mLastLaunchedActivity; 303 304 /** The type of the source that triggers the launch event. */ 305 @SourceInfo.SourceType int mSourceType; 306 /** The time from the source event (e.g. touch) to {@link #notifyActivityLaunching}. */ 307 int mSourceEventDelayMs = INVALID_DELAY; 308 /** The time from {@link #notifyActivityLaunching} to {@link #notifyTransitionStarting}. */ 309 int mCurrentTransitionDelayMs; 310 /** The time from {@link #notifyActivityLaunching} to {@link #notifyStartingWindowDrawn}. */ 311 int mStartingWindowDelayMs = INVALID_DELAY; 312 /** The time from {@link #notifyActivityLaunching} to {@link #notifyBindApplication}. */ 313 int mBindApplicationDelayMs = INVALID_DELAY; 314 /** Elapsed time from when we launch an activity to when its windows are drawn. */ 315 int mWindowsDrawnDelayMs; 316 /** The reason why the transition started (see ActivityManagerInternal.APP_TRANSITION_*). */ 317 int mReason = APP_TRANSITION_TIMEOUT; 318 /** The flag ensures that {@link #mStartingWindowDelayMs} is only set once. */ 319 boolean mLoggedStartingWindowDrawn; 320 /** If the any app transitions have been logged as starting. */ 321 boolean mLoggedTransitionStarting; 322 /** Whether any activity belonging to this transition has relaunched. */ 323 boolean mRelaunched; 324 325 /** Non-null if the application has reported drawn but its window hasn't. */ 326 @Nullable Runnable mPendingFullyDrawn; 327 /** Non-null if the trace is active. */ 328 @Nullable String mLaunchTraceName; 329 330 /** @return Non-null if there will be a window drawn event for the launch. */ 331 @Nullable create(@onNull ActivityRecord r, @NonNull LaunchingState launchingState, @Nullable ActivityOptions options, boolean processRunning, boolean processSwitch, int processState, int processOomAdj, boolean newActivityCreated, boolean isInTaskActivityStart, int startResult)332 static TransitionInfo create(@NonNull ActivityRecord r, 333 @NonNull LaunchingState launchingState, @Nullable ActivityOptions options, 334 boolean processRunning, boolean processSwitch, int processState, int processOomAdj, 335 boolean newActivityCreated, boolean isInTaskActivityStart, int startResult) { 336 if (startResult != START_SUCCESS && startResult != START_TASK_TO_FRONT) { 337 return null; 338 } 339 final int transitionType; 340 if (processRunning) { 341 transitionType = !newActivityCreated && r.attachedToProcess() 342 ? TYPE_TRANSITION_HOT_LAUNCH 343 : TYPE_TRANSITION_WARM_LAUNCH; 344 } else { 345 // Task may still exist when cold launching an activity and the start result will be 346 // set to START_TASK_TO_FRONT. Treat this as a COLD launch. 347 transitionType = TYPE_TRANSITION_COLD_LAUNCH; 348 } 349 return new TransitionInfo(r, launchingState, options, transitionType, processRunning, 350 processSwitch, processState, processOomAdj, isInTaskActivityStart); 351 } 352 353 /** Use {@link TransitionInfo#create} instead to ensure the transition type is valid. */ TransitionInfo(ActivityRecord r, LaunchingState launchingState, ActivityOptions options, int transitionType, boolean processRunning, boolean processSwitch, int processState, int processOomAdj, boolean isInTaskActivityStart)354 private TransitionInfo(ActivityRecord r, LaunchingState launchingState, 355 ActivityOptions options, int transitionType, boolean processRunning, 356 boolean processSwitch, int processState, int processOomAdj, 357 boolean isInTaskActivityStart) { 358 mLaunchingState = launchingState; 359 mTransitionType = transitionType; 360 mProcessRunning = processRunning; 361 mProcessSwitch = processSwitch; 362 mProcessState = processState; 363 mProcessOomAdj = processOomAdj; 364 mIsInTaskActivityStart = isInTaskActivityStart; 365 setLatestLaunchedActivity(r); 366 // The launching state can be reused by consecutive launch. Its original association 367 // shouldn't be changed by a separated transition. 368 if (launchingState.mAssociatedTransitionInfo == null) { 369 launchingState.mAssociatedTransitionInfo = this; 370 } 371 if (options != null) { 372 final SourceInfo sourceInfo = options.getSourceInfo(); 373 if (sourceInfo != null) { 374 mSourceType = sourceInfo.type; 375 mSourceEventDelayMs = (int) (TimeUnit.NANOSECONDS.toMillis( 376 launchingState.mStartUptimeNs) - sourceInfo.eventTimeMs); 377 } 378 } 379 } 380 381 /** 382 * Remembers the latest launched activity to represent the final transition. This also 383 * tracks the activities that should be drawn, so a consecutive launching sequence can be 384 * coalesced as one event. 385 */ setLatestLaunchedActivity(ActivityRecord r)386 void setLatestLaunchedActivity(ActivityRecord r) { 387 if (mLastLaunchedActivity == r) { 388 return; 389 } 390 if (mLastLaunchedActivity != null) { 391 // Transfer the launch cookie and launch root task because it is a consecutive 392 // launch event. 393 r.mLaunchCookie = mLastLaunchedActivity.mLaunchCookie; 394 mLastLaunchedActivity.mLaunchCookie = null; 395 r.mLaunchRootTask = mLastLaunchedActivity.mLaunchRootTask; 396 mLastLaunchedActivity.mLaunchRootTask = null; 397 } 398 mLastLaunchedActivity = r; 399 mIsDrawn = r.isReportedDrawn(); 400 } 401 402 /** Returns {@code true} if the incoming activity can belong to this transition. */ canCoalesce(ActivityRecord r)403 boolean canCoalesce(ActivityRecord r) { 404 if (mLastLaunchedActivity.mDisplayContent != r.mDisplayContent 405 || mLastLaunchedActivity.getWindowingMode() != r.getWindowingMode()) { 406 return false; 407 } 408 // The current task should be non-null because it is just launched. While the 409 // last task can be cleared when starting activity with FLAG_ACTIVITY_CLEAR_TASK. 410 final Task lastTask = mLastLaunchedActivity.getTask(); 411 final Task currentTask = r.getTask(); 412 if (lastTask != null && currentTask != null) { 413 if (lastTask == currentTask) { 414 return true; 415 } 416 return lastTask.getBounds().equals(currentTask.getBounds()); 417 } 418 return mLastLaunchedActivity.isUid(r.launchedFromUid); 419 } 420 421 /** @return {@code true} if the activity matches a launched activity in this transition. */ contains(ActivityRecord r)422 boolean contains(ActivityRecord r) { 423 return r == mLastLaunchedActivity; 424 } 425 426 /** 427 * @return {@code true} if the transition info should be sent to MetricsLogger, StatsLog, or 428 * LaunchObserver. 429 */ isInterestingToLoggerAndObserver()430 boolean isInterestingToLoggerAndObserver() { 431 return mProcessSwitch; 432 } 433 calculateCurrentDelay()434 int calculateCurrentDelay() { 435 return calculateDelay(SystemClock.uptimeNanos()); 436 } 437 calculateDelay(long timestampNs)438 int calculateDelay(long timestampNs) { 439 // Shouldn't take more than 25 days to launch an app, so int is fine here. 440 return (int) TimeUnit.NANOSECONDS.toMillis( 441 timestampNs - mLaunchingState.mStartUptimeNs); 442 } 443 444 @Override toString()445 public String toString() { 446 return "TransitionInfo{" + Integer.toHexString(System.identityHashCode(this)) 447 + " a=" + mLastLaunchedActivity + " d=" + mIsDrawn + "}"; 448 } 449 } 450 451 static final class TransitionInfoSnapshot { 452 final private ApplicationInfo applicationInfo; 453 final private WindowProcessController processRecord; 454 final String packageName; 455 final String launchedActivityName; 456 final private String launchedActivityLaunchedFromPackage; 457 final private String launchedActivityLaunchToken; 458 final private String launchedActivityAppRecordRequiredAbi; 459 final String launchedActivityShortComponentName; 460 final private String processName; 461 @VisibleForTesting final @SourceInfo.SourceType int sourceType; 462 @VisibleForTesting final int sourceEventDelayMs; 463 final private int reason; 464 final private int startingWindowDelayMs; 465 final private int bindApplicationDelayMs; 466 final int windowsDrawnDelayMs; 467 final int type; 468 final int userId; 469 /** 470 * Elapsed time from when we launch an activity to when the app reported it was 471 * fully drawn. If this is not reported then the value is set to INVALID_DELAY. 472 */ 473 final int windowsFullyDrawnDelayMs; 474 final int activityRecordIdHashCode; 475 final boolean relaunched; 476 final long timestampNs; 477 TransitionInfoSnapshot(TransitionInfo info)478 private TransitionInfoSnapshot(TransitionInfo info) { 479 this(info, info.mLastLaunchedActivity, INVALID_DELAY); 480 } 481 TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity, int windowsFullyDrawnDelayMs)482 private TransitionInfoSnapshot(TransitionInfo info, ActivityRecord launchedActivity, 483 int windowsFullyDrawnDelayMs) { 484 applicationInfo = launchedActivity.info.applicationInfo; 485 packageName = launchedActivity.packageName; 486 launchedActivityName = launchedActivity.info.name; 487 launchedActivityLaunchedFromPackage = launchedActivity.launchedFromPackage; 488 launchedActivityLaunchToken = launchedActivity.info.launchToken; 489 launchedActivityAppRecordRequiredAbi = launchedActivity.app == null 490 ? null 491 : launchedActivity.app.getRequiredAbi(); 492 reason = info.mReason; 493 sourceEventDelayMs = info.mSourceEventDelayMs; 494 startingWindowDelayMs = info.mStartingWindowDelayMs; 495 bindApplicationDelayMs = info.mBindApplicationDelayMs; 496 windowsDrawnDelayMs = info.mWindowsDrawnDelayMs; 497 type = info.mTransitionType; 498 processRecord = launchedActivity.app; 499 processName = launchedActivity.processName; 500 sourceType = info.mSourceType; 501 userId = launchedActivity.mUserId; 502 launchedActivityShortComponentName = launchedActivity.shortComponentName; 503 activityRecordIdHashCode = System.identityHashCode(launchedActivity); 504 this.windowsFullyDrawnDelayMs = windowsFullyDrawnDelayMs; 505 relaunched = info.mRelaunched; 506 timestampNs = info.mLaunchingState.mStartRealtimeNs; 507 } 508 getLaunchState()509 @WaitResult.LaunchState int getLaunchState() { 510 switch (type) { 511 case TYPE_TRANSITION_WARM_LAUNCH: 512 return LAUNCH_STATE_WARM; 513 case TYPE_TRANSITION_HOT_LAUNCH: 514 return relaunched ? LAUNCH_STATE_RELAUNCH : LAUNCH_STATE_HOT; 515 case TYPE_TRANSITION_COLD_LAUNCH: 516 return LAUNCH_STATE_COLD; 517 default: 518 return -1; 519 } 520 } 521 isInterestedToEventLog()522 boolean isInterestedToEventLog() { 523 return type == TYPE_TRANSITION_WARM_LAUNCH || type == TYPE_TRANSITION_COLD_LAUNCH; 524 } 525 getPackageOptimizationInfo(ArtManagerInternal artManagerInternal)526 PackageOptimizationInfo getPackageOptimizationInfo(ArtManagerInternal artManagerInternal) { 527 return artManagerInternal == null || launchedActivityAppRecordRequiredAbi == null 528 ? PackageOptimizationInfo.createWithNoInfo() 529 : artManagerInternal.getPackageOptimizationInfo(applicationInfo, 530 launchedActivityAppRecordRequiredAbi, launchedActivityName); 531 } 532 } 533 534 /** Information about the App Compat state logging associated with a package UID . */ 535 private static final class PackageCompatStateInfo { 536 /** All activities that have a visible state. */ 537 final ArrayList<ActivityRecord> mVisibleActivities = new ArrayList<>(); 538 /** The last logged state. */ 539 int mLastLoggedState = APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE; 540 @Nullable ActivityRecord mLastLoggedActivity; 541 } 542 ActivityMetricsLogger(ActivityTaskSupervisor supervisor, Looper looper)543 ActivityMetricsLogger(ActivityTaskSupervisor supervisor, Looper looper) { 544 mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000; 545 mSupervisor = supervisor; 546 mLaunchObserver = new LaunchObserverRegistryImpl(looper); 547 } 548 logWindowState(String state, int durationSecs)549 private void logWindowState(String state, int durationSecs) { 550 mMetricsLogger.count(state, durationSecs); 551 } 552 logWindowState()553 void logWindowState() { 554 final long now = SystemClock.elapsedRealtime() / 1000; 555 if (mWindowState != WINDOW_STATE_INVALID) { 556 // We log even if the window state hasn't changed, because the user might remain in 557 // home/fullscreen move forever and we would like to track this kind of behavior 558 // too. 559 mLoggerHandler.sendMessage(PooledLambda.obtainMessage( 560 ActivityMetricsLogger::logWindowState, this, 561 TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState], (int) (now - mLastLogTimeSecs))); 562 } 563 mLastLogTimeSecs = now; 564 565 mWindowState = WINDOW_STATE_INVALID; 566 final Task focusedTask = mSupervisor.mRootWindowContainer.getTopDisplayFocusedRootTask(); 567 if (focusedTask == null) return; 568 if (focusedTask.isActivityTypeAssistant()) { 569 mWindowState = WINDOW_STATE_ASSISTANT; 570 return; 571 } 572 573 @WindowingMode final int windowingMode = focusedTask.getWindowingMode(); 574 switch (windowingMode) { 575 case WINDOWING_MODE_FULLSCREEN: 576 mWindowState = WINDOW_STATE_STANDARD; 577 break; 578 case WINDOWING_MODE_FREEFORM: 579 mWindowState = WINDOW_STATE_FREEFORM; 580 break; 581 case WINDOWING_MODE_MULTI_WINDOW: 582 mWindowState = WINDOW_STATE_MULTI_WINDOW; 583 break; 584 default: 585 if (windowingMode != WINDOWING_MODE_UNDEFINED) { 586 Slog.wtf(TAG, "Unknown windowing mode for task=" + focusedTask 587 + " windowingMode=" + windowingMode); 588 } 589 } 590 } 591 592 /** @return Non-null {@link TransitionInfo} if the activity is found in an active transition. */ 593 @Nullable getActiveTransitionInfo(ActivityRecord r)594 private TransitionInfo getActiveTransitionInfo(ActivityRecord r) { 595 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { 596 final TransitionInfo info = mTransitionInfoList.get(i); 597 if (info.contains(r)) { 598 return info; 599 } 600 } 601 return null; 602 } 603 604 /** 605 * This method should be only used by starting recents and starting from recents, or internal 606 * tests. Because it doesn't lookup caller and always creates a new launching state. 607 * 608 * @see #notifyActivityLaunching(Intent, ActivityRecord, int) 609 */ notifyActivityLaunching(Intent intent)610 LaunchingState notifyActivityLaunching(Intent intent) { 611 return notifyActivityLaunching(intent, null /* caller */, IGNORE_CALLER); 612 } 613 614 /** 615 * Notifies the tracker at the earliest possible point when we are starting to launch an 616 * activity. The caller must ensure that {@link #notifyActivityLaunched} will be called later 617 * with the returned {@link LaunchingState}. If the caller is found in an active transition, 618 * it will be considered as consecutive launch and coalesced into the active transition. 619 */ notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller, int callingUid)620 LaunchingState notifyActivityLaunching(Intent intent, @Nullable ActivityRecord caller, 621 int callingUid) { 622 TransitionInfo existingInfo = null; 623 if (callingUid != IGNORE_CALLER) { 624 // Associate the launching event to an active transition if the caller is found in its 625 // launched activities. 626 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { 627 final TransitionInfo info = mTransitionInfoList.get(i); 628 if (caller != null && info.contains(caller)) { 629 existingInfo = info; 630 break; 631 } 632 if (existingInfo == null && callingUid == info.mLastLaunchedActivity.getUid()) { 633 // Fallback to check the most recent matched uid for the case that the caller is 634 // not an activity. 635 existingInfo = info; 636 } 637 } 638 } 639 if (DEBUG_METRICS) { 640 Slog.i(TAG, "notifyActivityLaunching intent=" + intent 641 + " existingInfo=" + existingInfo); 642 } 643 644 if (existingInfo == null) { 645 final LaunchingState launchingState = new LaunchingState(); 646 // Only notify the observer for a new launching event. 647 launchObserverNotifyIntentStarted(intent, launchingState.mStartUptimeNs); 648 return launchingState; 649 } 650 return existingInfo.mLaunchingState; 651 } 652 653 /** 654 * Notifies the tracker that the activity is actually launching. 655 * 656 * @param launchingState The launching state to track the new or active transition. 657 * @param resultCode One of the {@link android.app.ActivityManager}.START_* flags, indicating 658 * the result of the launch. 659 * @param launchedActivity The activity that is being launched 660 * @param newActivityCreated Whether a new activity instance is created. 661 * @param options The given options of the launching activity. 662 */ notifyActivityLaunched(@onNull LaunchingState launchingState, int resultCode, boolean newActivityCreated, @Nullable ActivityRecord launchedActivity, @Nullable ActivityOptions options)663 void notifyActivityLaunched(@NonNull LaunchingState launchingState, int resultCode, 664 boolean newActivityCreated, @Nullable ActivityRecord launchedActivity, 665 @Nullable ActivityOptions options) { 666 if (launchedActivity == null || launchedActivity.getTask() == null) { 667 // The launch is aborted, e.g. intent not resolved, class not found. 668 abort(launchingState, "nothing launched"); 669 return; 670 } 671 672 final WindowProcessController processRecord = launchedActivity.app != null 673 ? launchedActivity.app 674 : mSupervisor.mService.getProcessController( 675 launchedActivity.processName, launchedActivity.info.applicationInfo.uid); 676 // Whether the process that will contains the activity is already running. 677 final boolean processRunning = processRecord != null; 678 // We consider this a "process switch" if the process of the activity that gets launched 679 // didn't have an activity that was in started state. In this case, we assume that lot 680 // of caches might be purged so the time until it produces the first frame is very 681 // interesting. 682 final boolean processSwitch = !processRunning 683 || !processRecord.hasStartedActivity(launchedActivity); 684 final int processState; 685 final int processOomAdj; 686 if (processRunning) { 687 processState = processRecord.getCurrentProcState(); 688 processOomAdj = processRecord.getCurrentAdj(); 689 } else { 690 processState = PROCESS_STATE_NONEXISTENT; 691 processOomAdj = INVALID_ADJ; 692 } 693 694 final TransitionInfo info = launchingState.mAssociatedTransitionInfo; 695 if (DEBUG_METRICS) { 696 Slog.i(TAG, "notifyActivityLaunched" + " resultCode=" + resultCode 697 + " launchedActivity=" + launchedActivity + " processRunning=" + processRunning 698 + " processSwitch=" + processSwitch 699 + " processState=" + processState 700 + " processOomAdj=" + processOomAdj 701 + " newActivityCreated=" + newActivityCreated + " info=" + info); 702 } 703 704 if (launchedActivity.isReportedDrawn() && launchedActivity.isVisible()) { 705 // Launched activity is already visible. We cannot measure windows drawn delay. 706 abort(launchingState, "launched activity already visible"); 707 return; 708 } 709 710 // If the launched activity is started from an existing active transition, it will be put 711 // into the transition info. 712 if (info != null && info.canCoalesce(launchedActivity)) { 713 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched consecutive launch"); 714 715 final boolean crossPackage = 716 !info.mLastLaunchedActivity.packageName.equals(launchedActivity.packageName); 717 // The trace name uses package name so different packages should be separated. 718 if (crossPackage) { 719 stopLaunchTrace(info); 720 } 721 722 mLastTransitionInfo.remove(info.mLastLaunchedActivity); 723 // Coalesce multiple (trampoline) activities from a single sequence together. 724 info.setLatestLaunchedActivity(launchedActivity); 725 // Update the latest one so it can be found when reporting fully-drawn. 726 mLastTransitionInfo.put(launchedActivity, info); 727 728 if (crossPackage) { 729 startLaunchTrace(info); 730 } 731 scheduleCheckActivityToBeDrawnIfSleeping(launchedActivity); 732 return; 733 } 734 735 final boolean isInTaskActivityStart = launchedActivity.getTask().isVisible(); 736 final TransitionInfo newInfo = TransitionInfo.create(launchedActivity, launchingState, 737 options, processRunning, processSwitch, processState, processOomAdj, 738 newActivityCreated, isInTaskActivityStart, resultCode); 739 if (newInfo == null) { 740 abort(launchingState, "unrecognized launch"); 741 return; 742 } 743 744 if (DEBUG_METRICS) Slog.i(TAG, "notifyActivityLaunched successful"); 745 // A new launch sequence has begun. Start tracking it. 746 mTransitionInfoList.add(newInfo); 747 mLastTransitionInfo.put(launchedActivity, newInfo); 748 startLaunchTrace(newInfo); 749 if (newInfo.isInterestingToLoggerAndObserver()) { 750 launchObserverNotifyActivityLaunched(newInfo); 751 } else { 752 // As abort for no process switch. 753 launchObserverNotifyIntentFailed(newInfo.mLaunchingState.mStartUptimeNs); 754 } 755 scheduleCheckActivityToBeDrawnIfSleeping(launchedActivity); 756 757 // If the previous transitions are no longer visible, abort them to avoid counting the 758 // launch time when resuming from back stack. E.g. launch 2 independent tasks in a short 759 // time, the transition info of the first task should not keep active until it becomes 760 // visible such as after the top task is finished. 761 for (int i = mTransitionInfoList.size() - 2; i >= 0; i--) { 762 final TransitionInfo prevInfo = mTransitionInfoList.get(i); 763 if (prevInfo.mIsDrawn || !prevInfo.mLastLaunchedActivity.isVisibleRequested()) { 764 scheduleCheckActivityToBeDrawn(prevInfo.mLastLaunchedActivity, 0 /* delay */); 765 } 766 } 767 } 768 scheduleCheckActivityToBeDrawnIfSleeping(@onNull ActivityRecord r)769 private void scheduleCheckActivityToBeDrawnIfSleeping(@NonNull ActivityRecord r) { 770 if (r.mDisplayContent.isSleeping()) { 771 // It is unknown whether the activity can be drawn or not, e.g. it depends on the 772 // keyguard states and the attributes or flags set by the activity. If the activity 773 // keeps invisible in the grace period, the tracker will be cancelled so it won't get 774 // a very long launch time that takes unlocking as the end of launch. 775 scheduleCheckActivityToBeDrawn(r, UNKNOWN_VISIBILITY_CHECK_DELAY_MS); 776 } 777 } 778 779 /** 780 * Notifies the tracker that all windows of the app have been drawn. 781 * 782 * @return Non-null info if the activity was pending to draw, otherwise it might have been set 783 * to invisible (removed from active transition) or it was already drawn. 784 */ 785 @Nullable notifyWindowsDrawn(@onNull ActivityRecord r)786 TransitionInfoSnapshot notifyWindowsDrawn(@NonNull ActivityRecord r) { 787 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn " + r); 788 789 final long timestampNs = SystemClock.uptimeNanos(); 790 final TransitionInfo info = getActiveTransitionInfo(r); 791 if (info == null || info.mIsDrawn) { 792 if (DEBUG_METRICS) Slog.i(TAG, "notifyWindowsDrawn not pending drawn " + info); 793 return null; 794 } 795 // Always calculate the delay because the caller may need to know the individual drawn time. 796 info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs); 797 info.mIsDrawn = true; 798 final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info); 799 if (info.mLoggedTransitionStarting || (!r.mDisplayContent.mOpeningApps.contains(r) 800 && !r.mTransitionController.isCollecting(r))) { 801 done(false /* abort */, info, "notifyWindowsDrawn", timestampNs); 802 } 803 return infoSnapshot; 804 } 805 806 /** 807 * Notifies the tracker that the starting window was drawn. 808 */ notifyStartingWindowDrawn(@onNull ActivityRecord r)809 void notifyStartingWindowDrawn(@NonNull ActivityRecord r) { 810 final TransitionInfo info = getActiveTransitionInfo(r); 811 if (info == null || info.mLoggedStartingWindowDrawn) { 812 return; 813 } 814 if (DEBUG_METRICS) Slog.i(TAG, "notifyStartingWindowDrawn " + r); 815 info.mLoggedStartingWindowDrawn = true; 816 info.mStartingWindowDelayMs = info.calculateCurrentDelay(); 817 } 818 819 /** 820 * Notifies the tracker that the app transition is starting. 821 * 822 * @param activityToReason A map from activity to a reason integer, which must be on of 823 * ActivityTaskManagerInternal.APP_TRANSITION_* reasons. 824 */ notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason)825 void notifyTransitionStarting(ArrayMap<WindowContainer, Integer> activityToReason) { 826 if (DEBUG_METRICS) Slog.i(TAG, "notifyTransitionStarting " + activityToReason); 827 828 final long timestampNs = SystemClock.uptimeNanos(); 829 for (int index = activityToReason.size() - 1; index >= 0; index--) { 830 final WindowContainer<?> wc = activityToReason.keyAt(index); 831 final ActivityRecord activity = wc.asActivityRecord(); 832 final ActivityRecord r = activity != null ? activity 833 : wc.getTopActivity(false /* includeFinishing */, true /* includeOverlays */); 834 final TransitionInfo info = getActiveTransitionInfo(r); 835 if (info == null || info.mLoggedTransitionStarting) { 836 // Ignore any subsequent notifyTransitionStarting. 837 continue; 838 } 839 if (DEBUG_METRICS) { 840 Slog.i(TAG, "notifyTransitionStarting activity=" + wc + " info=" + info); 841 } 842 843 info.mCurrentTransitionDelayMs = info.calculateDelay(timestampNs); 844 info.mReason = activityToReason.valueAt(index); 845 info.mLoggedTransitionStarting = true; 846 if (info.mIsDrawn) { 847 done(false /* abort */, info, "notifyTransitionStarting drawn", timestampNs); 848 } 849 } 850 } 851 notifyActivityRelaunched(ActivityRecord r)852 void notifyActivityRelaunched(ActivityRecord r) { 853 final TransitionInfo info = getActiveTransitionInfo(r); 854 if (info != null) { 855 info.mRelaunched = true; 856 } 857 } 858 859 /** Makes sure that the reference to the removed activity is cleared. */ notifyActivityRemoved(@onNull ActivityRecord r)860 void notifyActivityRemoved(@NonNull ActivityRecord r) { 861 mLastTransitionInfo.remove(r); 862 final TransitionInfo info = getActiveTransitionInfo(r); 863 if (info != null) { 864 abort(info, "removed"); 865 } 866 867 final int packageUid = r.info.applicationInfo.uid; 868 final PackageCompatStateInfo compatStateInfo = mPackageUidToCompatStateInfo.get(packageUid); 869 if (compatStateInfo == null) { 870 return; 871 } 872 873 compatStateInfo.mVisibleActivities.remove(r); 874 if (compatStateInfo.mLastLoggedActivity == r) { 875 compatStateInfo.mLastLoggedActivity = null; 876 } 877 } 878 879 /** 880 * Notifies the tracker that the visibility of an app is changing. 881 * 882 * @param r the app that is changing its visibility 883 */ notifyVisibilityChanged(@onNull ActivityRecord r)884 void notifyVisibilityChanged(@NonNull ActivityRecord r) { 885 final TransitionInfo info = getActiveTransitionInfo(r); 886 if (info == null) { 887 return; 888 } 889 if (DEBUG_METRICS) { 890 Slog.i(TAG, "notifyVisibilityChanged " + r + " visible=" + r.isVisibleRequested() 891 + " state=" + r.getState() + " finishing=" + r.finishing); 892 } 893 if (r.isState(ActivityRecord.State.RESUMED) && r.mDisplayContent.isSleeping()) { 894 // The activity may be launching while keyguard is locked. The keyguard may be dismissed 895 // after the activity finished relayout, so skip the visibility check to avoid aborting 896 // the tracking of launch event. 897 return; 898 } 899 if (!r.isVisibleRequested() || r.finishing) { 900 // Check if the tracker can be cancelled because the last launched activity may be 901 // no longer visible. 902 scheduleCheckActivityToBeDrawn(r, 0 /* delay */); 903 } 904 } 905 scheduleCheckActivityToBeDrawn(@onNull ActivityRecord r, long delay)906 private void scheduleCheckActivityToBeDrawn(@NonNull ActivityRecord r, long delay) { 907 // The activity and its task are passed separately because it is possible that the activity 908 // is removed from the task later. 909 r.mAtmService.mH.sendMessageDelayed(PooledLambda.obtainMessage( 910 ActivityMetricsLogger::checkActivityToBeDrawn, this, r.getTask(), r), delay); 911 } 912 913 /** Cancels the tracking of launch if there won't be an activity to be drawn. */ checkActivityToBeDrawn(Task t, ActivityRecord r)914 private void checkActivityToBeDrawn(Task t, ActivityRecord r) { 915 synchronized (mSupervisor.mService.mGlobalLock) { 916 final TransitionInfo info = getActiveTransitionInfo(r); 917 918 // If we have an active transition that's waiting on a certain activity that will be 919 // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary. 920 921 // We have no active transitions. Or the notified activity whose visibility changed is 922 // no longer the launched activity, then we can still wait to get onWindowsDrawn. 923 if (info == null) { 924 return; 925 } 926 927 // If the task of the launched activity contains any activity to be drawn, then the 928 // window drawn event should report later to complete the transition. Otherwise all 929 // activities in this task may be finished, invisible or drawn, so the transition event 930 // should be cancelled. 931 if (t != null && t.forAllActivities( 932 a -> a.isVisibleRequested() && !a.isReportedDrawn() && !a.finishing)) { 933 return; 934 } 935 936 if (DEBUG_METRICS) Slog.i(TAG, "checkActivityToBeDrawn cancels activity=" + r); 937 logAppTransitionCancel(info); 938 abort(info, "checkActivityToBeDrawn (invisible or drawn already)"); 939 } 940 } 941 942 @Nullable getAppHibernationManagerInternal()943 private AppHibernationManagerInternal getAppHibernationManagerInternal() { 944 if (!AppHibernationService.isAppHibernationEnabled()) return null; 945 if (mAppHibernationManagerInternal == null) { 946 mAppHibernationManagerInternal = 947 LocalServices.getService(AppHibernationManagerInternal.class); 948 } 949 return mAppHibernationManagerInternal; 950 } 951 952 /** 953 * Notifies the tracker before the package is unstopped because of launching activity. 954 * @param packageName The package to be unstopped. 955 */ notifyBeforePackageUnstopped(@onNull String packageName)956 void notifyBeforePackageUnstopped(@NonNull String packageName) { 957 final AppHibernationManagerInternal ahmInternal = getAppHibernationManagerInternal(); 958 if (ahmInternal != null) { 959 mLastHibernationStates.put(packageName, ahmInternal.isHibernatingGlobally(packageName)); 960 } 961 } 962 963 /** 964 * Notifies the tracker that we called immediately before we call bindApplication on the client. 965 * 966 * @param appInfo The client into which we'll call bindApplication. 967 */ notifyBindApplication(ApplicationInfo appInfo)968 void notifyBindApplication(ApplicationInfo appInfo) { 969 for (int i = mTransitionInfoList.size() - 1; i >= 0; i--) { 970 final TransitionInfo info = mTransitionInfoList.get(i); 971 972 // App isn't attached to record yet, so match with info. 973 if (info.mLastLaunchedActivity.info.applicationInfo == appInfo) { 974 info.mBindApplicationDelayMs = info.calculateCurrentDelay(); 975 if (info.mProcessRunning) { 976 // It was HOT/WARM launch, but the process was died somehow right after the 977 // launch request. 978 info.mProcessRunning = false; 979 info.mTransitionType = TYPE_TRANSITION_COLD_LAUNCH; 980 final String msg = "Process " + info.mLastLaunchedActivity.info.processName 981 + " restarted"; 982 Slog.i(TAG, msg); 983 if (info.mLaunchingState.mTraceName != null) { 984 Trace.instant(Trace.TRACE_TAG_ACTIVITY_MANAGER, msg + "#" 985 + LaunchingState.sTraceSeqId); 986 } 987 } 988 } 989 } 990 } 991 abort(@onNull LaunchingState state, String cause)992 private void abort(@NonNull LaunchingState state, String cause) { 993 if (state.mAssociatedTransitionInfo != null) { 994 abort(state.mAssociatedTransitionInfo, cause); 995 return; 996 } 997 if (DEBUG_METRICS) Slog.i(TAG, "abort launch cause=" + cause); 998 state.stopTrace(true /* abort */, null /* endInfo */); 999 launchObserverNotifyIntentFailed(state.mStartUptimeNs); 1000 } 1001 1002 /** Aborts tracking of current launch metrics. */ abort(@onNull TransitionInfo info, String cause)1003 private void abort(@NonNull TransitionInfo info, String cause) { 1004 done(true /* abort */, info, cause, 0L /* timestampNs */); 1005 } 1006 1007 /** Called when the given transition (info) is no longer active. */ done(boolean abort, @NonNull TransitionInfo info, String cause, long timestampNs)1008 private void done(boolean abort, @NonNull TransitionInfo info, String cause, 1009 long timestampNs) { 1010 if (DEBUG_METRICS) { 1011 Slog.i(TAG, "done abort=" + abort + " cause=" + cause + " timestamp=" + timestampNs 1012 + " info=" + info); 1013 } 1014 info.mLaunchingState.stopTrace(abort, info); 1015 stopLaunchTrace(info); 1016 final Boolean isHibernating = 1017 mLastHibernationStates.remove(info.mLastLaunchedActivity.packageName); 1018 if (abort) { 1019 mLastTransitionInfo.remove(info.mLastLaunchedActivity); 1020 mSupervisor.stopWaitingForActivityVisible(info.mLastLaunchedActivity); 1021 launchObserverNotifyActivityLaunchCancelled(info); 1022 } else { 1023 if (info.isInterestingToLoggerAndObserver()) { 1024 launchObserverNotifyActivityLaunchFinished(info, timestampNs); 1025 } 1026 logAppTransitionFinished(info, isHibernating != null ? isHibernating : false); 1027 if (info.mReason == APP_TRANSITION_RECENTS_ANIM) { 1028 logRecentsAnimationLatency(info); 1029 } 1030 } 1031 mTransitionInfoList.remove(info); 1032 } 1033 logAppTransitionCancel(TransitionInfo info)1034 private void logAppTransitionCancel(TransitionInfo info) { 1035 final int type = info.mTransitionType; 1036 final ActivityRecord activity = info.mLastLaunchedActivity; 1037 final LogMaker builder = new LogMaker(APP_TRANSITION_CANCELLED); 1038 builder.setPackageName(activity.packageName); 1039 builder.setType(type); 1040 builder.addTaggedData(FIELD_CLASS_NAME, activity.info.name); 1041 mMetricsLogger.write(builder); 1042 FrameworkStatsLog.write( 1043 FrameworkStatsLog.APP_START_CANCELED, 1044 activity.info.applicationInfo.uid, 1045 activity.packageName, 1046 getAppStartTransitionType(type, info.mRelaunched), 1047 activity.info.name); 1048 if (DEBUG_METRICS) { 1049 Slog.i(TAG, String.format("APP_START_CANCELED(%s, %s, %s, %s)", 1050 activity.info.applicationInfo.uid, 1051 activity.packageName, 1052 getAppStartTransitionType(type, info.mRelaunched), 1053 activity.info.name)); 1054 } 1055 } 1056 logAppTransitionFinished(@onNull TransitionInfo info, boolean isHibernating)1057 private void logAppTransitionFinished(@NonNull TransitionInfo info, boolean isHibernating) { 1058 if (DEBUG_METRICS) Slog.i(TAG, "logging finished transition " + info); 1059 1060 // Take a snapshot of the transition info before sending it to the handler for logging. 1061 // This will avoid any races with other operations that modify the ActivityRecord. 1062 final TransitionInfoSnapshot infoSnapshot = new TransitionInfoSnapshot(info); 1063 final boolean isOpaque = info.mLastLaunchedActivity.mStyleFillsParent; 1064 final long uptimeNs = info.mLaunchingState.mStartUptimeNs; 1065 final int transitionDelay = info.mCurrentTransitionDelayMs; 1066 final int processState = info.mProcessState; 1067 final int processOomAdj = info.mProcessOomAdj; 1068 mLoggerHandler.post(() -> { 1069 if (info.isInterestingToLoggerAndObserver()) { 1070 logAppTransition(uptimeNs, transitionDelay, infoSnapshot, isHibernating, 1071 processState, processOomAdj); 1072 } 1073 if (info.mIsInTaskActivityStart) { 1074 logInTaskActivityStart(infoSnapshot, isOpaque, transitionDelay); 1075 } 1076 if (infoSnapshot.isInterestedToEventLog()) { 1077 logAppDisplayed(infoSnapshot); 1078 } 1079 }); 1080 if (info.mPendingFullyDrawn != null) { 1081 info.mPendingFullyDrawn.run(); 1082 } 1083 1084 info.mLastLaunchedActivity.info.launchToken = null; 1085 } 1086 1087 // This gets called on another thread without holding the activity manager lock. logAppTransition(long transitionDeviceUptimeNs, int currentTransitionDelayMs, TransitionInfoSnapshot info, boolean isHibernating, int processState, int processOomAdj)1088 private void logAppTransition(long transitionDeviceUptimeNs, 1089 int currentTransitionDelayMs, TransitionInfoSnapshot info, boolean isHibernating, 1090 int processState, int processOomAdj) { 1091 final LogMaker builder = new LogMaker(APP_TRANSITION); 1092 builder.setPackageName(info.packageName); 1093 builder.setType(info.type); 1094 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName); 1095 final boolean isInstantApp = info.applicationInfo.isInstantApp(); 1096 if (info.launchedActivityLaunchedFromPackage != null) { 1097 builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME, 1098 info.launchedActivityLaunchedFromPackage); 1099 } 1100 String launchToken = info.launchedActivityLaunchToken; 1101 if (launchToken != null) { 1102 builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, launchToken); 1103 } 1104 builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0); 1105 builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS, 1106 TimeUnit.NANOSECONDS.toSeconds(transitionDeviceUptimeNs)); 1107 builder.addTaggedData(APP_TRANSITION_DELAY_MS, currentTransitionDelayMs); 1108 builder.setSubtype(info.reason); 1109 if (info.startingWindowDelayMs != INVALID_DELAY) { 1110 builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS, 1111 info.startingWindowDelayMs); 1112 } 1113 if (info.bindApplicationDelayMs != INVALID_DELAY) { 1114 builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS, 1115 info.bindApplicationDelayMs); 1116 } 1117 builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs); 1118 final PackageOptimizationInfo packageOptimizationInfo = 1119 info.getPackageOptimizationInfo(getArtManagerInternal()); 1120 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_REASON, 1121 packageOptimizationInfo.getCompilationReason()); 1122 builder.addTaggedData(PACKAGE_OPTIMIZATION_COMPILATION_FILTER, 1123 packageOptimizationInfo.getCompilationFilter()); 1124 mMetricsLogger.write(builder); 1125 1126 // Incremental info 1127 boolean isIncremental = false, isLoading = false; 1128 final String codePath = info.applicationInfo.getCodePath(); 1129 if (codePath != null && IncrementalManager.isIncrementalPath(codePath)) { 1130 isIncremental = true; 1131 isLoading = isIncrementalLoading(info.packageName, info.userId); 1132 } 1133 final boolean stopped = (info.applicationInfo.flags & ApplicationInfo.FLAG_STOPPED) != 0; 1134 final int packageState = stopped 1135 ? APP_START_OCCURRED__PACKAGE_STOPPED_STATE__PACKAGE_STATE_STOPPED 1136 : APP_START_OCCURRED__PACKAGE_STOPPED_STATE__PACKAGE_STATE_NORMAL; 1137 FrameworkStatsLog.write( 1138 FrameworkStatsLog.APP_START_OCCURRED, 1139 info.applicationInfo.uid, 1140 info.packageName, 1141 getAppStartTransitionType(info.type, info.relaunched), 1142 info.launchedActivityName, 1143 info.launchedActivityLaunchedFromPackage, 1144 isInstantApp, 1145 0 /* deprecated transitionDeviceUptimeMs */, 1146 info.reason, 1147 currentTransitionDelayMs, 1148 info.startingWindowDelayMs, 1149 info.bindApplicationDelayMs, 1150 info.windowsDrawnDelayMs, 1151 launchToken, 1152 packageOptimizationInfo.getCompilationReason(), 1153 packageOptimizationInfo.getCompilationFilter(), 1154 info.sourceType, 1155 info.sourceEventDelayMs, 1156 isHibernating, 1157 isIncremental, 1158 isLoading, 1159 info.launchedActivityName.hashCode(), 1160 TimeUnit.NANOSECONDS.toMillis(info.timestampNs), 1161 processState, 1162 processOomAdj, 1163 packageState); 1164 1165 if (DEBUG_METRICS) { 1166 Slog.i(TAG, String.format("APP_START_OCCURRED(%s, %s, %s, %s, %s)", 1167 info.applicationInfo.uid, 1168 info.packageName, 1169 getAppStartTransitionType(info.type, info.relaunched), 1170 info.launchedActivityName, 1171 info.launchedActivityLaunchedFromPackage)); 1172 } 1173 1174 1175 logAppStartMemoryStateCapture(info); 1176 } 1177 isIncrementalLoading(String packageName, int userId)1178 private boolean isIncrementalLoading(String packageName, int userId) { 1179 final IncrementalStatesInfo info = mSupervisor.mService.getPackageManagerInternalLocked() 1180 .getIncrementalStatesInfo(packageName, 0 /* filterCallingUid */, userId); 1181 return info != null && info.isLoading(); 1182 } 1183 1184 @VisibleForTesting logInTaskActivityStart(TransitionInfoSnapshot info, boolean isOpaque, int transitionDelayMs)1185 void logInTaskActivityStart(TransitionInfoSnapshot info, boolean isOpaque, 1186 int transitionDelayMs) { 1187 if (DEBUG_METRICS) { 1188 Slog.i(TAG, "IN_TASK_ACTIVITY_STARTED " + info.launchedActivityName 1189 + " transitionDelayMs=" + transitionDelayMs + "ms"); 1190 } 1191 FrameworkStatsLog.write(FrameworkStatsLog.IN_TASK_ACTIVITY_STARTED, 1192 info.applicationInfo.uid, 1193 getAppStartTransitionType(info.type, info.relaunched), 1194 isOpaque, 1195 transitionDelayMs, 1196 info.windowsDrawnDelayMs, 1197 TimeUnit.NANOSECONDS.toMillis(info.timestampNs)); 1198 } 1199 logAppDisplayed(TransitionInfoSnapshot info)1200 private void logAppDisplayed(TransitionInfoSnapshot info) { 1201 EventLog.writeEvent(WM_ACTIVITY_LAUNCH_TIME, 1202 info.userId, info.activityRecordIdHashCode, info.launchedActivityShortComponentName, 1203 info.windowsDrawnDelayMs); 1204 1205 StringBuilder sb = mStringBuilder; 1206 sb.setLength(0); 1207 sb.append("Displayed "); 1208 sb.append(info.launchedActivityShortComponentName); 1209 sb.append(" for user "); 1210 sb.append(info.userId); 1211 sb.append(": "); 1212 TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb); 1213 Log.i(TAG, sb.toString()); 1214 } 1215 logRecentsAnimationLatency(TransitionInfo info)1216 private void logRecentsAnimationLatency(TransitionInfo info) { 1217 final int duration = info.mSourceEventDelayMs + info.mWindowsDrawnDelayMs; 1218 final ActivityRecord r = info.mLastLaunchedActivity; 1219 final long lastTopLossTime = r.topResumedStateLossTime; 1220 final WindowManagerService wm = mSupervisor.mService.mWindowManager; 1221 final Object controller = wm.getRecentsAnimationController(); 1222 mLoggerHandler.postDelayed(() -> { 1223 if (lastTopLossTime != r.topResumedStateLossTime 1224 || controller != wm.getRecentsAnimationController()) { 1225 // Skip if the animation was finished in a short time. 1226 return; 1227 } 1228 wm.mLatencyTracker.logAction(LatencyTracker.ACTION_START_RECENTS_ANIMATION, duration); 1229 }, LATENCY_TRACKER_RECENTS_DELAY_MS); 1230 } 1231 getAppStartTransitionType(int tronType, boolean relaunched)1232 private static int getAppStartTransitionType(int tronType, boolean relaunched) { 1233 if (tronType == TYPE_TRANSITION_COLD_LAUNCH) { 1234 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__COLD; 1235 } 1236 if (tronType == TYPE_TRANSITION_WARM_LAUNCH) { 1237 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__WARM; 1238 } 1239 if (tronType == TYPE_TRANSITION_HOT_LAUNCH) { 1240 return relaunched 1241 ? FrameworkStatsLog.APP_START_OCCURRED__TYPE__RELAUNCH 1242 : FrameworkStatsLog.APP_START_OCCURRED__TYPE__HOT; 1243 } 1244 return FrameworkStatsLog.APP_START_OCCURRED__TYPE__UNKNOWN; 1245 } 1246 1247 /** @see android.app.Activity#reportFullyDrawn */ notifyFullyDrawn(ActivityRecord r, boolean restoredFromBundle)1248 TransitionInfoSnapshot notifyFullyDrawn(ActivityRecord r, boolean restoredFromBundle) { 1249 final TransitionInfo info = mLastTransitionInfo.get(r); 1250 if (info == null) { 1251 return null; 1252 } 1253 if (!info.mIsDrawn && info.mPendingFullyDrawn == null) { 1254 // There are still undrawn activities, postpone reporting fully drawn until all of its 1255 // windows are drawn. So that is closer to an usable state. 1256 info.mPendingFullyDrawn = () -> { 1257 notifyFullyDrawn(r, restoredFromBundle); 1258 info.mPendingFullyDrawn = null; 1259 }; 1260 return null; 1261 } 1262 1263 final long currentTimestampNs = SystemClock.uptimeNanos(); 1264 final long startupTimeMs = info.mPendingFullyDrawn != null 1265 ? info.mWindowsDrawnDelayMs 1266 : TimeUnit.NANOSECONDS.toMillis( 1267 currentTimestampNs - info.mLaunchingState.mStartUptimeNs); 1268 final TransitionInfoSnapshot infoSnapshot = 1269 new TransitionInfoSnapshot(info, r, (int) startupTimeMs); 1270 if (infoSnapshot.isInterestedToEventLog()) { 1271 mLoggerHandler.post(() -> logAppFullyDrawn(infoSnapshot)); 1272 } 1273 mLastTransitionInfo.remove(r); 1274 1275 if (!info.isInterestingToLoggerAndObserver()) { 1276 return infoSnapshot; 1277 } 1278 1279 // Record the handling of the reportFullyDrawn callback in the trace system. This is not 1280 // actually used to trace this function, but instead the logical task that this function 1281 // fullfils (handling reportFullyDrawn() callbacks). 1282 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1283 "ActivityManager:ReportingFullyDrawn " + info.mLastLaunchedActivity.packageName); 1284 mLoggerHandler.post(() -> logAppFullyDrawnMetrics(infoSnapshot, restoredFromBundle, 1285 info.mProcessRunning)); 1286 // Ends the trace started at the beginning of this function. This is located here to allow 1287 // the trace slice to have a noticable duration. 1288 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1289 1290 // Notify reportFullyDrawn event. 1291 launchObserverNotifyReportFullyDrawn(info, currentTimestampNs); 1292 1293 return infoSnapshot; 1294 } 1295 logAppFullyDrawnMetrics(TransitionInfoSnapshot info, boolean restoredFromBundle, boolean processRunning)1296 private void logAppFullyDrawnMetrics(TransitionInfoSnapshot info, boolean restoredFromBundle, 1297 boolean processRunning) { 1298 final LogMaker builder = new LogMaker(APP_TRANSITION_REPORTED_DRAWN); 1299 builder.setPackageName(info.packageName); 1300 builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivityName); 1301 builder.addTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS, 1302 (long) info.windowsFullyDrawnDelayMs); 1303 builder.setType(restoredFromBundle 1304 ? TYPE_TRANSITION_REPORTED_DRAWN_WITH_BUNDLE 1305 : TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE); 1306 builder.addTaggedData(APP_TRANSITION_PROCESS_RUNNING, processRunning ? 1 : 0); 1307 mMetricsLogger.write(builder); 1308 final PackageOptimizationInfo packageOptimizationInfo = 1309 info.getPackageOptimizationInfo(getArtManagerInternal()); 1310 // Incremental info 1311 boolean isIncremental = false, isLoading = false; 1312 final String codePath = info.applicationInfo.getCodePath(); 1313 if (codePath != null && IncrementalManager.isIncrementalPath(codePath)) { 1314 isIncremental = true; 1315 isLoading = isIncrementalLoading(info.packageName, info.userId); 1316 } 1317 FrameworkStatsLog.write( 1318 FrameworkStatsLog.APP_START_FULLY_DRAWN, 1319 info.applicationInfo.uid, 1320 info.packageName, 1321 restoredFromBundle 1322 ? FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITH_BUNDLE 1323 : FrameworkStatsLog.APP_START_FULLY_DRAWN__TYPE__WITHOUT_BUNDLE, 1324 info.launchedActivityName, 1325 processRunning, 1326 info.windowsFullyDrawnDelayMs, 1327 packageOptimizationInfo.getCompilationReason(), 1328 packageOptimizationInfo.getCompilationFilter(), 1329 info.sourceType, 1330 info.sourceEventDelayMs, 1331 isIncremental, 1332 isLoading, 1333 info.launchedActivityName.hashCode(), 1334 TimeUnit.NANOSECONDS.toMillis(info.timestampNs)); 1335 } 1336 logAppFullyDrawn(TransitionInfoSnapshot info)1337 private void logAppFullyDrawn(TransitionInfoSnapshot info) { 1338 StringBuilder sb = mStringBuilder; 1339 sb.setLength(0); 1340 sb.append("Fully drawn "); 1341 sb.append(info.launchedActivityShortComponentName); 1342 sb.append(": "); 1343 TimeUtils.formatDuration(info.windowsFullyDrawnDelayMs, sb); 1344 Log.i(TAG, sb.toString()); 1345 } 1346 logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp, int callingUid, String callingPackage, int callingUidProcState, boolean callingUidHasAnyVisibleWindow, int realCallingUid, int realCallingUidProcState, boolean realCallingUidHasAnyVisibleWindow, boolean comingFromPendingIntent)1347 void logAbortedBgActivityStart(Intent intent, WindowProcessController callerApp, 1348 int callingUid, String callingPackage, int callingUidProcState, 1349 boolean callingUidHasAnyVisibleWindow, 1350 int realCallingUid, int realCallingUidProcState, 1351 boolean realCallingUidHasAnyVisibleWindow, 1352 boolean comingFromPendingIntent) { 1353 1354 final long nowElapsed = SystemClock.elapsedRealtime(); 1355 final long nowUptime = SystemClock.uptimeMillis(); 1356 final LogMaker builder = new LogMaker(ACTION_ACTIVITY_START); 1357 builder.setTimestamp(System.currentTimeMillis()); 1358 builder.addTaggedData(FIELD_CALLING_UID, callingUid); 1359 builder.addTaggedData(FIELD_CALLING_PACKAGE_NAME, callingPackage); 1360 builder.addTaggedData(FIELD_CALLING_UID_PROC_STATE, 1361 processStateAmToProto(callingUidProcState)); 1362 builder.addTaggedData(FIELD_CALLING_UID_HAS_ANY_VISIBLE_WINDOW, 1363 callingUidHasAnyVisibleWindow ? 1 : 0); 1364 builder.addTaggedData(FIELD_REAL_CALLING_UID, realCallingUid); 1365 builder.addTaggedData(FIELD_REAL_CALLING_UID_PROC_STATE, 1366 processStateAmToProto(realCallingUidProcState)); 1367 builder.addTaggedData(FIELD_REAL_CALLING_UID_HAS_ANY_VISIBLE_WINDOW, 1368 realCallingUidHasAnyVisibleWindow ? 1 : 0); 1369 builder.addTaggedData(FIELD_COMING_FROM_PENDING_INTENT, comingFromPendingIntent ? 1 : 0); 1370 if (intent != null) { 1371 builder.addTaggedData(FIELD_INTENT_ACTION, intent.getAction()); 1372 ComponentName component = intent.getComponent(); 1373 if (component != null) { 1374 builder.addTaggedData(FIELD_TARGET_SHORT_COMPONENT_NAME, 1375 component.flattenToShortString()); 1376 } 1377 } 1378 if (callerApp != null) { 1379 builder.addTaggedData(FIELD_PROCESS_RECORD_PROCESS_NAME, callerApp.mName); 1380 builder.addTaggedData(FIELD_PROCESS_RECORD_CUR_PROC_STATE, 1381 processStateAmToProto(callerApp.getCurrentProcState())); 1382 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_CLIENT_ACTIVITIES, 1383 callerApp.hasClientActivities() ? 1 : 0); 1384 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_SERVICES, 1385 callerApp.hasForegroundServices() ? 1 : 0); 1386 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_FOREGROUND_ACTIVITIES, 1387 callerApp.hasForegroundActivities() ? 1 : 0); 1388 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_TOP_UI, callerApp.hasTopUi() ? 1 : 0); 1389 builder.addTaggedData(FIELD_PROCESS_RECORD_HAS_OVERLAY_UI, 1390 callerApp.hasOverlayUi() ? 1 : 0); 1391 builder.addTaggedData(FIELD_PROCESS_RECORD_PENDING_UI_CLEAN, 1392 callerApp.hasPendingUiClean() ? 1 : 0); 1393 if (callerApp.getInteractionEventTime() != 0) { 1394 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_LAST_INTERACTION_EVENT, 1395 (nowElapsed - callerApp.getInteractionEventTime())); 1396 } 1397 if (callerApp.getFgInteractionTime() != 0) { 1398 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_FG_INTERACTION, 1399 (nowElapsed - callerApp.getFgInteractionTime())); 1400 } 1401 if (callerApp.getWhenUnimportant() != 0) { 1402 builder.addTaggedData(FIELD_PROCESS_RECORD_MILLIS_SINCE_UNIMPORTANT, 1403 (nowUptime - callerApp.getWhenUnimportant())); 1404 } 1405 } 1406 mMetricsLogger.write(builder); 1407 } 1408 logAppStartMemoryStateCapture(TransitionInfoSnapshot info)1409 private void logAppStartMemoryStateCapture(TransitionInfoSnapshot info) { 1410 if (info.processRecord == null) { 1411 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture processRecord null"); 1412 return; 1413 } 1414 1415 final int pid = info.processRecord.getPid(); 1416 final int uid = info.applicationInfo.uid; 1417 final MemoryStat memoryStat = readMemoryStatFromFilesystem(uid, pid); 1418 if (memoryStat == null) { 1419 if (DEBUG_METRICS) Slog.i(TAG, "logAppStartMemoryStateCapture memoryStat null"); 1420 return; 1421 } 1422 1423 FrameworkStatsLog.write( 1424 FrameworkStatsLog.APP_START_MEMORY_STATE_CAPTURED, 1425 uid, 1426 info.processName, 1427 info.launchedActivityName, 1428 memoryStat.pgfault, 1429 memoryStat.pgmajfault, 1430 memoryStat.rssInBytes, 1431 memoryStat.cacheInBytes, 1432 memoryStat.swapInBytes); 1433 } 1434 1435 /** 1436 * Logs the current App Compat state of the given {@link ActivityRecord} with its package 1437 * UID, if all of the following hold: 1438 * <ul> 1439 * <li>The current state is different than the last logged state for the package UID of the 1440 * activity. 1441 * <li>If the current state is NOT_VISIBLE, there is a previously logged state for the 1442 * package UID and there are no other visible activities with the same package UID. 1443 * <li>The last logged activity with the same package UID is either {@code activity} (or an 1444 * activity that has been removed) or the last logged state is NOT_VISIBLE or NOT_LETTERBOXED. 1445 * </ul> 1446 * 1447 * <p>If the current state is NOT_VISIBLE and the previous state which was logged by {@code 1448 * activity} (or an activity that has been removed) wasn't, looks for the first visible activity 1449 * with the same package UID that has a letterboxed state, or a non-letterboxed state if 1450 * there isn't one, and logs that state. 1451 * 1452 * <p>This method assumes that the caller is wrapping the call with a synchronized block so 1453 * that there won't be a race condition between two activities with the same package. 1454 */ logAppCompatState(@onNull ActivityRecord activity)1455 void logAppCompatState(@NonNull ActivityRecord activity) { 1456 final int packageUid = activity.info.applicationInfo.uid; 1457 final int state = activity.getAppCompatState(); 1458 1459 if (!mPackageUidToCompatStateInfo.contains(packageUid)) { 1460 mPackageUidToCompatStateInfo.put(packageUid, new PackageCompatStateInfo()); 1461 } 1462 final PackageCompatStateInfo compatStateInfo = mPackageUidToCompatStateInfo.get(packageUid); 1463 final int lastLoggedState = compatStateInfo.mLastLoggedState; 1464 final ActivityRecord lastLoggedActivity = compatStateInfo.mLastLoggedActivity; 1465 1466 final boolean isVisible = state != APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE; 1467 final ArrayList<ActivityRecord> visibleActivities = compatStateInfo.mVisibleActivities; 1468 if (isVisible && !visibleActivities.contains(activity)) { 1469 visibleActivities.add(activity); 1470 } else if (!isVisible) { 1471 visibleActivities.remove(activity); 1472 if (visibleActivities.isEmpty()) { 1473 // No need to keep the entry if there are no visible activities. 1474 mPackageUidToCompatStateInfo.remove(packageUid); 1475 } 1476 } 1477 1478 if (state == lastLoggedState) { 1479 // We don’t want to log the same state twice or log DEFAULT_NOT_VISIBLE before any 1480 // visible state was logged. 1481 return; 1482 } 1483 1484 if (!isVisible && !visibleActivities.isEmpty()) { 1485 // There is another visible activity for this package UID. 1486 if (lastLoggedActivity == null || activity == lastLoggedActivity) { 1487 // Make sure a new visible state is logged if needed. 1488 findAppCompatStateToLog(compatStateInfo, packageUid); 1489 } 1490 return; 1491 } 1492 1493 if (lastLoggedActivity != null && activity != lastLoggedActivity 1494 && lastLoggedState != APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE 1495 && lastLoggedState != APP_COMPAT_STATE_CHANGED__STATE__NOT_LETTERBOXED) { 1496 // Another visible activity for this package UID has logged a letterboxed state. 1497 return; 1498 } 1499 1500 logAppCompatStateInternal(activity, state, compatStateInfo); 1501 } 1502 1503 /** 1504 * Looks for the first visible activity in {@code compatStateInfo} that has a letterboxed 1505 * state, or a non-letterboxed state if there isn't one, and logs that state for the given 1506 * {@code packageUid}. 1507 * 1508 * <p>If there is a visible activity in {@code compatStateInfo} with the same state as the 1509 * last logged state for the given {@code packageUid}, changes the last logged activity to 1510 * reference the first such activity without actually logging the same state twice. 1511 */ findAppCompatStateToLog(PackageCompatStateInfo compatStateInfo, int packageUid)1512 private void findAppCompatStateToLog(PackageCompatStateInfo compatStateInfo, int packageUid) { 1513 final ArrayList<ActivityRecord> visibleActivities = compatStateInfo.mVisibleActivities; 1514 final int lastLoggedState = compatStateInfo.mLastLoggedState; 1515 1516 ActivityRecord activityToLog = null; 1517 int stateToLog = APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE; 1518 for (int i = 0; i < visibleActivities.size(); i++) { 1519 ActivityRecord activity = visibleActivities.get(i); 1520 int state = activity.getAppCompatState(); 1521 if (state == lastLoggedState) { 1522 // Change last logged activity without logging the same state twice. 1523 compatStateInfo.mLastLoggedActivity = activity; 1524 return; 1525 } 1526 if (state == APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE) { 1527 // This shouldn't happen. 1528 Slog.w(TAG, "Visible activity with NOT_VISIBLE App Compat state for package UID: " 1529 + packageUid); 1530 continue; 1531 } 1532 if (stateToLog == APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE || ( 1533 stateToLog == APP_COMPAT_STATE_CHANGED__STATE__NOT_LETTERBOXED 1534 && state != APP_COMPAT_STATE_CHANGED__STATE__NOT_LETTERBOXED)) { 1535 activityToLog = activity; 1536 stateToLog = state; 1537 } 1538 } 1539 if (activityToLog != null && stateToLog != APP_COMPAT_STATE_CHANGED__STATE__NOT_VISIBLE) { 1540 logAppCompatStateInternal(activityToLog, stateToLog, compatStateInfo); 1541 } 1542 } 1543 isAppCompateStateChangedToLetterboxed(int state)1544 private static boolean isAppCompateStateChangedToLetterboxed(int state) { 1545 return state == APP_COMPAT_STATE_CHANGED__STATE__LETTERBOXED_FOR_ASPECT_RATIO 1546 || state == APP_COMPAT_STATE_CHANGED__STATE__LETTERBOXED_FOR_FIXED_ORIENTATION 1547 || state == APP_COMPAT_STATE_CHANGED__STATE__LETTERBOXED_FOR_SIZE_COMPAT_MODE; 1548 } 1549 logAppCompatStateInternal(@onNull ActivityRecord activity, int state, PackageCompatStateInfo compatStateInfo)1550 private void logAppCompatStateInternal(@NonNull ActivityRecord activity, int state, 1551 PackageCompatStateInfo compatStateInfo) { 1552 compatStateInfo.mLastLoggedState = state; 1553 compatStateInfo.mLastLoggedActivity = activity; 1554 int packageUid = activity.info.applicationInfo.uid; 1555 1556 int positionToLog = APP_COMPAT_STATE_CHANGED__LETTERBOX_POSITION__NOT_LETTERBOXED_POSITION; 1557 if (isAppCompateStateChangedToLetterboxed(state)) { 1558 positionToLog = activity.mLetterboxUiController.getLetterboxPositionForLogging(); 1559 } 1560 FrameworkStatsLog.write(FrameworkStatsLog.APP_COMPAT_STATE_CHANGED, 1561 packageUid, state, positionToLog); 1562 1563 if (DEBUG_METRICS) { 1564 Slog.i(TAG, String.format("APP_COMPAT_STATE_CHANGED(%s, %s, %s)", 1565 packageUid, state, positionToLog)); 1566 } 1567 } 1568 1569 /** 1570 * Logs the changing of the letterbox position along with its package UID 1571 */ logLetterboxPositionChange(@onNull ActivityRecord activity, int position)1572 void logLetterboxPositionChange(@NonNull ActivityRecord activity, int position) { 1573 int packageUid = activity.info.applicationInfo.uid; 1574 FrameworkStatsLog.write(FrameworkStatsLog.LETTERBOX_POSITION_CHANGED, packageUid, position); 1575 1576 if (!mPackageUidToCompatStateInfo.contains(packageUid)) { 1577 // There is no last logged activity for this packageUid so we should not log the 1578 // position change as we can only log the position change for the current activity 1579 return; 1580 } 1581 final PackageCompatStateInfo compatStateInfo = mPackageUidToCompatStateInfo.get(packageUid); 1582 final ActivityRecord lastLoggedActivity = compatStateInfo.mLastLoggedActivity; 1583 if (activity != lastLoggedActivity) { 1584 // Only log the position change for the current activity to be consistent with 1585 // findAppCompatStateToLog and ensure that metrics for the state changes are computed 1586 // correctly 1587 return; 1588 } 1589 int state = activity.getAppCompatState(); 1590 logAppCompatStateInternal(activity, state, compatStateInfo); 1591 1592 if (DEBUG_METRICS) { 1593 Slog.i(TAG, String.format("LETTERBOX_POSITION_CHANGED(%s, %s)", 1594 packageUid, position)); 1595 } 1596 } 1597 1598 /** 1599 * Logs the Camera Compat Control appeared event that corresponds to the given {@code state} 1600 * with the given {@code packageUid}. 1601 */ logCameraCompatControlAppearedEventReported(@ameraCompatControlState int state, int packageUid)1602 void logCameraCompatControlAppearedEventReported(@CameraCompatControlState int state, 1603 int packageUid) { 1604 switch (state) { 1605 case TaskInfo.CAMERA_COMPAT_CONTROL_TREATMENT_SUGGESTED: 1606 logCameraCompatControlEventReported( 1607 CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__APPEARED_APPLY_TREATMENT, 1608 packageUid); 1609 break; 1610 case TaskInfo.CAMERA_COMPAT_CONTROL_TREATMENT_APPLIED: 1611 logCameraCompatControlEventReported( 1612 CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__APPEARED_REVERT_TREATMENT, 1613 packageUid); 1614 break; 1615 case TaskInfo.CAMERA_COMPAT_CONTROL_HIDDEN: 1616 // Nothing to log. 1617 break; 1618 default: 1619 Slog.w(TAG, "Unexpected state in logCameraCompatControlAppearedEventReported: " 1620 + state); 1621 break; 1622 } 1623 } 1624 1625 /** 1626 * Logs the Camera Compat Control clicked event that corresponds to the given {@code state} 1627 * with the given {@code packageUid}. 1628 */ logCameraCompatControlClickedEventReported(@ameraCompatControlState int state, int packageUid)1629 void logCameraCompatControlClickedEventReported(@CameraCompatControlState int state, 1630 int packageUid) { 1631 switch (state) { 1632 case TaskInfo.CAMERA_COMPAT_CONTROL_TREATMENT_APPLIED: 1633 logCameraCompatControlEventReported( 1634 CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__CLICKED_APPLY_TREATMENT, 1635 packageUid); 1636 break; 1637 case TaskInfo.CAMERA_COMPAT_CONTROL_TREATMENT_SUGGESTED: 1638 logCameraCompatControlEventReported( 1639 CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__CLICKED_REVERT_TREATMENT, 1640 packageUid); 1641 break; 1642 case TaskInfo.CAMERA_COMPAT_CONTROL_DISMISSED: 1643 logCameraCompatControlEventReported( 1644 CAMERA_COMPAT_CONTROL_EVENT_REPORTED__EVENT__CLICKED_DISMISS, 1645 packageUid); 1646 break; 1647 default: 1648 Slog.w(TAG, "Unexpected state in logCameraCompatControlAppearedEventReported: " 1649 + state); 1650 break; 1651 } 1652 } 1653 logCameraCompatControlEventReported(int event, int packageUid)1654 private void logCameraCompatControlEventReported(int event, int packageUid) { 1655 FrameworkStatsLog.write(FrameworkStatsLog.CAMERA_COMPAT_CONTROL_EVENT_REPORTED, packageUid, 1656 event); 1657 if (DEBUG_METRICS) { 1658 Slog.i(TAG, String.format("CAMERA_COMPAT_CONTROL_EVENT_REPORTED(%s, %s)", packageUid, 1659 event)); 1660 } 1661 } 1662 getArtManagerInternal()1663 private ArtManagerInternal getArtManagerInternal() { 1664 if (mArtManagerInternal == null) { 1665 // Note that this may be null. 1666 // ArtManagerInternal is registered during PackageManagerService 1667 // initialization which happens after ActivityManagerService. 1668 mArtManagerInternal = LocalServices.getService(ArtManagerInternal.class); 1669 } 1670 return mArtManagerInternal; 1671 } 1672 1673 /** Starts trace for an activity is actually launching. */ startLaunchTrace(@onNull TransitionInfo info)1674 private void startLaunchTrace(@NonNull TransitionInfo info) { 1675 if (DEBUG_METRICS) Slog.i(TAG, "startLaunchTrace " + info); 1676 if (info.mLaunchingState.mTraceName == null) { 1677 return; 1678 } 1679 info.mLaunchTraceName = "launching: " + info.mLastLaunchedActivity.packageName; 1680 Trace.asyncTraceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName, 1681 (int) info.mLaunchingState.mStartRealtimeNs /* cookie */); 1682 } 1683 1684 /** Stops trace for the launch is completed or cancelled. */ stopLaunchTrace(@onNull TransitionInfo info)1685 private void stopLaunchTrace(@NonNull TransitionInfo info) { 1686 if (DEBUG_METRICS) Slog.i(TAG, "stopLaunchTrace " + info); 1687 if (info.mLaunchTraceName == null) { 1688 return; 1689 } 1690 Trace.asyncTraceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER, info.mLaunchTraceName, 1691 (int) info.mLaunchingState.mStartRealtimeNs /* cookie */); 1692 info.mLaunchTraceName = null; 1693 } 1694 getLaunchObserverRegistry()1695 public ActivityMetricsLaunchObserverRegistry getLaunchObserverRegistry() { 1696 return mLaunchObserver; 1697 } 1698 1699 /** Notify the {@link ActivityMetricsLaunchObserver} that a new launch sequence has begun. */ launchObserverNotifyIntentStarted(Intent intent, long timestampNs)1700 private void launchObserverNotifyIntentStarted(Intent intent, long timestampNs) { 1701 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1702 "MetricsLogger:launchObserverNotifyIntentStarted"); 1703 1704 // Beginning a launch is timing sensitive and so should be observed as soon as possible. 1705 mLaunchObserver.onIntentStarted(intent, timestampNs); 1706 1707 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1708 } 1709 1710 /** 1711 * Notify the {@link ActivityMetricsLaunchObserver} that the previous launch sequence has 1712 * aborted due to intent failure (e.g. intent resolve failed or security error, etc) or 1713 * intent being delivered to the top running activity. 1714 */ launchObserverNotifyIntentFailed(long id)1715 private void launchObserverNotifyIntentFailed(long id) { 1716 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1717 "MetricsLogger:launchObserverNotifyIntentFailed"); 1718 1719 mLaunchObserver.onIntentFailed(id); 1720 1721 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1722 } 1723 1724 /** 1725 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity 1726 * has started. 1727 */ launchObserverNotifyActivityLaunched(TransitionInfo info)1728 private void launchObserverNotifyActivityLaunched(TransitionInfo info) { 1729 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1730 "MetricsLogger:launchObserverNotifyActivityLaunched"); 1731 1732 @ActivityMetricsLaunchObserver.Temperature int temperature = 1733 convertTransitionTypeToLaunchObserverTemperature(info.mTransitionType); 1734 1735 // Beginning a launch is timing sensitive and so should be observed as soon as possible. 1736 mLaunchObserver.onActivityLaunched(info.mLaunchingState.mStartUptimeNs, 1737 info.mLastLaunchedActivity.mActivityComponent, temperature); 1738 1739 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1740 } 1741 1742 /** 1743 * Notifies the {@link ActivityMetricsLaunchObserver} the reportFullDrawn event. 1744 */ launchObserverNotifyReportFullyDrawn(TransitionInfo info, long timestampNs)1745 private void launchObserverNotifyReportFullyDrawn(TransitionInfo info, long timestampNs) { 1746 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1747 "MetricsLogger:launchObserverNotifyReportFullyDrawn"); 1748 mLaunchObserver.onReportFullyDrawn(info.mLaunchingState.mStartUptimeNs, timestampNs); 1749 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1750 } 1751 1752 /** 1753 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence is 1754 * cancelled. 1755 */ launchObserverNotifyActivityLaunchCancelled(TransitionInfo info)1756 private void launchObserverNotifyActivityLaunchCancelled(TransitionInfo info) { 1757 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1758 "MetricsLogger:launchObserverNotifyActivityLaunchCancelled"); 1759 1760 mLaunchObserver.onActivityLaunchCancelled(info.mLaunchingState.mStartUptimeNs); 1761 1762 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1763 } 1764 1765 /** 1766 * Notify the {@link ActivityMetricsLaunchObserver} that the current launch sequence's activity 1767 * has fully finished (successfully). 1768 */ launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs)1769 private void launchObserverNotifyActivityLaunchFinished(TransitionInfo info, long timestampNs) { 1770 Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, 1771 "MetricsLogger:launchObserverNotifyActivityLaunchFinished"); 1772 1773 mLaunchObserver.onActivityLaunchFinished(info.mLaunchingState.mStartUptimeNs, 1774 info.mLastLaunchedActivity.mActivityComponent, timestampNs); 1775 1776 Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); 1777 } 1778 1779 private static @ActivityMetricsLaunchObserver.Temperature int convertTransitionTypeToLaunchObserverTemperature(int transitionType)1780 convertTransitionTypeToLaunchObserverTemperature(int transitionType) { 1781 switch (transitionType) { 1782 case TYPE_TRANSITION_WARM_LAUNCH: 1783 return ActivityMetricsLaunchObserver.TEMPERATURE_WARM; 1784 case TYPE_TRANSITION_HOT_LAUNCH: 1785 return ActivityMetricsLaunchObserver.TEMPERATURE_HOT; 1786 case TYPE_TRANSITION_COLD_LAUNCH: 1787 return ActivityMetricsLaunchObserver.TEMPERATURE_COLD; 1788 default: 1789 return -1; 1790 } 1791 } 1792 } 1793