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