services/core/java/com/android/server/am/ActivityMetricsLogger.java

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