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