package com.android.server.am; import static android.app.ActivityManager.START_SUCCESS; import static android.app.ActivityManager.START_TASK_TO_FRONT; import static android.app.ActivityManager.StackId.ASSISTANT_STACK_ID; import static android.app.ActivityManager.StackId.DOCKED_STACK_ID; import static android.app.ActivityManager.StackId.FREEFORM_WORKSPACE_STACK_ID; import static android.app.ActivityManager.StackId.FULLSCREEN_WORKSPACE_STACK_ID; import static android.app.ActivityManager.StackId.INVALID_STACK_ID; import static android.app.ActivityManager.StackId.PINNED_STACK_ID; import static android.app.ActivityManagerInternal.APP_TRANSITION_TIMEOUT; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_BIND_APPLICATION_DELAY_MS; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CALLING_PACKAGE_NAME; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_IS_EPHEMERAL; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_INSTANT_APP_LAUNCH_TOKEN; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH; import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH; import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM; import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME; import static com.android.server.am.ActivityStack.STACK_INVISIBLE; import android.app.ActivityManager.StackId; import android.content.Context; import android.metrics.LogMaker; import android.os.SystemClock; import android.util.Slog; import android.util.SparseArray; import android.util.SparseIntArray; import com.android.internal.logging.MetricsLogger; import java.util.ArrayList; /** * Handles logging into Tron. */ class ActivityMetricsLogger { private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_AM; // Window modes we are interested in logging. If we ever introduce a new type, we need to add // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array. private static final int WINDOW_STATE_STANDARD = 0; private static final int WINDOW_STATE_SIDE_BY_SIDE = 1; private static final int WINDOW_STATE_FREEFORM = 2; private static final int WINDOW_STATE_ASSISTANT = 3; private static final int WINDOW_STATE_INVALID = -1; private static final long INVALID_START_TIME = -1; // Preallocated strings we are sending to tron, so we don't have to allocate a new one every // time we log. private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = { "window_time_0", "window_time_1", "window_time_2", "window_time_3"}; private int mWindowState = WINDOW_STATE_STANDARD; private long mLastLogTimeSecs; private final ActivityStackSupervisor mSupervisor; private final Context mContext; private final MetricsLogger mMetricsLogger = new MetricsLogger(); private long mCurrentTransitionStartTime = INVALID_START_TIME; private int mCurrentTransitionDeviceUptime; private int mCurrentTransitionDelayMs; private boolean mLoggedTransitionStarting; private final SparseArray mStackTransitionInfo = new SparseArray<>(); private final class StackTransitionInfo { private ActivityRecord launchedActivity; private int startResult; private boolean currentTransitionProcessRunning; private int windowsDrawnDelayMs; private int startingWindowDelayMs = -1; private int bindApplicationDelayMs = -1; private int reason = APP_TRANSITION_TIMEOUT; private boolean loggedWindowsDrawn; private boolean loggedStartingWindowDrawn; } ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context) { mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000; mSupervisor = supervisor; mContext = context; } void logWindowState() { final long now = SystemClock.elapsedRealtime() / 1000; if (mWindowState != WINDOW_STATE_INVALID) { // We log even if the window state hasn't changed, because the user might remain in // home/fullscreen move forever and we would like to track this kind of behavior // too. MetricsLogger.count(mContext, TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState], (int) (now - mLastLogTimeSecs)); } mLastLogTimeSecs = now; ActivityStack stack = mSupervisor.getStack(DOCKED_STACK_ID); if (stack != null && stack.shouldBeVisible(null) != STACK_INVISIBLE) { mWindowState = WINDOW_STATE_SIDE_BY_SIDE; return; } mWindowState = WINDOW_STATE_INVALID; stack = mSupervisor.getFocusedStack(); if (stack.mStackId == PINNED_STACK_ID) { stack = mSupervisor.findStackBehind(stack); } if (StackId.isHomeOrRecentsStack(stack.mStackId) || stack.mStackId == FULLSCREEN_WORKSPACE_STACK_ID) { mWindowState = WINDOW_STATE_STANDARD; } else if (stack.mStackId == DOCKED_STACK_ID) { Slog.wtf(TAG, "Docked stack shouldn't be the focused stack, because it reported not" + " being visible."); mWindowState = WINDOW_STATE_INVALID; } else if (stack.mStackId == FREEFORM_WORKSPACE_STACK_ID) { mWindowState = WINDOW_STATE_FREEFORM; } else if (stack.mStackId == ASSISTANT_STACK_ID) { mWindowState = WINDOW_STATE_ASSISTANT; } else if (StackId.isStaticStack(stack.mStackId)) { throw new IllegalStateException("Unknown stack=" + stack); } } /** * Notifies the tracker at the earliest possible point when we are starting to launch an * activity. */ void notifyActivityLaunching() { if (!isAnyTransitionActive()) { mCurrentTransitionStartTime = SystemClock.uptimeMillis(); } } /** * Notifies the tracker that the activity is actually launching. * * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the * launch * @param launchedActivity the activity that is being launched */ void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity) { final ProcessRecord processRecord = launchedActivity != null ? mSupervisor.mService.mProcessNames.get(launchedActivity.processName, launchedActivity.appInfo.uid) : null; final boolean processRunning = processRecord != null; // We consider this a "process switch" if the process of the activity that gets launched // didn't have an activity that was in started state. In this case, we assume that lot // of caches might be purged so the time until it produces the first frame is very // interesting. final boolean processSwitch = processRecord == null || !hasStartedActivity(processRecord, launchedActivity); notifyActivityLaunched(resultCode, launchedActivity, processRunning, processSwitch); } private boolean hasStartedActivity(ProcessRecord record, ActivityRecord launchedActivity) { final ArrayList activities = record.activities; for (int i = activities.size() - 1; i >= 0; i--) { final ActivityRecord activity = activities.get(i); if (launchedActivity == activity) { continue; } if (!activity.stopped) { return true; } } return false; } /** * Notifies the tracker the the activity is actually launching. * * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the * launch * @param launchedActivity the activity being launched * @param processRunning whether the process that will contains the activity is already running * @param processSwitch whether the process that will contain the activity didn't have any * activity that was stopped, i.e. the started activity is "switching" * processes */ private void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity, boolean processRunning, boolean processSwitch) { // If we are already in an existing transition, only update the activity name, but not the // other attributes. final int stackId = launchedActivity != null && launchedActivity.getStack() != null ? launchedActivity.getStack().mStackId : INVALID_STACK_ID; if (mCurrentTransitionStartTime == INVALID_START_TIME) { return; } final StackTransitionInfo info = mStackTransitionInfo.get(stackId); if (launchedActivity != null && info != null) { info.launchedActivity = launchedActivity; return; } final boolean otherStacksLaunching = mStackTransitionInfo.size() > 0 && info == null; if ((resultCode < 0 || launchedActivity == null || !processSwitch || stackId == INVALID_STACK_ID) && !otherStacksLaunching) { // Failed to launch or it was not a process switch, so we don't care about the timing. reset(true /* abort */); return; } else if (otherStacksLaunching) { // Don't log this stack but continue with the other stacks. return; } final StackTransitionInfo newInfo = new StackTransitionInfo(); newInfo.launchedActivity = launchedActivity; newInfo.currentTransitionProcessRunning = processRunning; newInfo.startResult = resultCode; mStackTransitionInfo.append(stackId, newInfo); mCurrentTransitionDeviceUptime = (int) (SystemClock.uptimeMillis() / 1000); } /** * Notifies the tracker that all windows of the app have been drawn. */ void notifyWindowsDrawn(int stackId, long timestamp) { final StackTransitionInfo info = mStackTransitionInfo.get(stackId); if (info == null || info.loggedWindowsDrawn) { return; } info.windowsDrawnDelayMs = calculateDelay(timestamp); info.loggedWindowsDrawn = true; if (allStacksWindowsDrawn() && mLoggedTransitionStarting) { reset(false /* abort */); } } /** * Notifies the tracker that the starting window was drawn. */ void notifyStartingWindowDrawn(int stackId, long timestamp) { final StackTransitionInfo info = mStackTransitionInfo.get(stackId); if (info == null || info.loggedStartingWindowDrawn) { return; } info.loggedStartingWindowDrawn = true; info.startingWindowDelayMs = calculateDelay(timestamp); } /** * Notifies the tracker that the app transition is starting. * * @param stackIdReasons A map from stack id to a reason integer, which must be on of * ActivityManagerInternal.APP_TRANSITION_* reasons. */ void notifyTransitionStarting(SparseIntArray stackIdReasons, long timestamp) { if (!isAnyTransitionActive() || mLoggedTransitionStarting) { return; } mCurrentTransitionDelayMs = calculateDelay(timestamp); mLoggedTransitionStarting = true; for (int index = stackIdReasons.size() - 1; index >= 0; index--) { final int stackId = stackIdReasons.keyAt(index); final StackTransitionInfo info = mStackTransitionInfo.get(stackId); if (info == null) { continue; } info.reason = stackIdReasons.valueAt(index); } if (allStacksWindowsDrawn()) { reset(false /* abort */); } } /** * Notifies the tracker that the visibility of an app is changing. * * @param activityRecord the app that is changing its visibility * @param visible whether it's going to be visible or not */ void notifyVisibilityChanged(ActivityRecord activityRecord, boolean visible) { final StackTransitionInfo info = mStackTransitionInfo.get(activityRecord.getStackId()); // If we have an active transition that's waiting on a certain activity that will be // invisible now, we'll never get onWindowsDrawn, so abort the transition if necessary. if (info != null && !visible && info.launchedActivity == activityRecord) { mStackTransitionInfo.remove(activityRecord.getStackId()); if (mStackTransitionInfo.size() == 0) { reset(true /* abort */); } } } /** * Notifies the tracker that we called immediately before we call bindApplication on the client. * * @param app The client into which we'll call bindApplication. */ void notifyBindApplication(ProcessRecord app) { for (int i = mStackTransitionInfo.size() - 1; i >= 0; i--) { final StackTransitionInfo info = mStackTransitionInfo.valueAt(i); // App isn't attached to record yet, so match with info. if (info.launchedActivity.appInfo == app.info) { info.bindApplicationDelayMs = calculateCurrentDelay(); } } } private boolean allStacksWindowsDrawn() { for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) { if (!mStackTransitionInfo.valueAt(index).loggedWindowsDrawn) { return false; } } return true; } private boolean isAnyTransitionActive() { return mCurrentTransitionStartTime != INVALID_START_TIME && mStackTransitionInfo.size() > 0; } private void reset(boolean abort) { if (!abort && isAnyTransitionActive()) { logAppTransitionMultiEvents(); } mCurrentTransitionStartTime = INVALID_START_TIME; mCurrentTransitionDelayMs = -1; mLoggedTransitionStarting = false; mStackTransitionInfo.clear(); } private int calculateCurrentDelay() { // Shouldn't take more than 25 days to launch an app, so int is fine here. return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime); } private int calculateDelay(long timestamp) { // Shouldn't take more than 25 days to launch an app, so int is fine here. return (int) (timestamp - mCurrentTransitionStartTime); } private void logAppTransitionMultiEvents() { for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) { final StackTransitionInfo info = mStackTransitionInfo.valueAt(index); final int type = getTransitionType(info); if (type == -1) { return; } final LogMaker builder = new LogMaker(APP_TRANSITION); builder.setPackageName(info.launchedActivity.packageName); builder.setType(type); builder.addTaggedData(FIELD_CLASS_NAME, info.launchedActivity.info.name); final boolean isInstantApp = info.launchedActivity.info.applicationInfo.isInstantApp(); if (isInstantApp && info.launchedActivity.launchedFromPackage != null) { builder.addTaggedData(APP_TRANSITION_CALLING_PACKAGE_NAME, info.launchedActivity.launchedFromPackage); } if (info.launchedActivity.info.launchToken != null) { builder.addTaggedData(FIELD_INSTANT_APP_LAUNCH_TOKEN, info.launchedActivity.info.launchToken); info.launchedActivity.info.launchToken = null; } builder.addTaggedData(APP_TRANSITION_IS_EPHEMERAL, isInstantApp ? 1 : 0); builder.addTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS, mCurrentTransitionDeviceUptime); builder.addTaggedData(APP_TRANSITION_DELAY_MS, mCurrentTransitionDelayMs); builder.setSubtype(info.reason); if (info.startingWindowDelayMs != -1) { builder.addTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS, info.startingWindowDelayMs); } if (info.bindApplicationDelayMs != -1) { builder.addTaggedData(APP_TRANSITION_BIND_APPLICATION_DELAY_MS, info.bindApplicationDelayMs); } builder.addTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, info.windowsDrawnDelayMs); mMetricsLogger.write(builder); } } private int getTransitionType(StackTransitionInfo info) { if (info.currentTransitionProcessRunning) { if (info.startResult == START_SUCCESS) { return TYPE_TRANSITION_WARM_LAUNCH; } else if (info.startResult == START_TASK_TO_FRONT) { return TYPE_TRANSITION_HOT_LAUNCH; } } else if (info.startResult == START_SUCCESS) { return TYPE_TRANSITION_COLD_LAUNCH; } return -1; } }