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