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