Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 1 | package com.android.server.am; |
| 2 | |
| 3 | import static android.app.ActivityManager.StackId.DOCKED_STACK_ID; |
| 4 | import static android.app.ActivityManager.StackId.FREEFORM_WORKSPACE_STACK_ID; |
| 5 | import static android.app.ActivityManager.StackId.FULLSCREEN_WORKSPACE_STACK_ID; |
Filip Gruszczynski | caae14e | 2015-12-16 14:40:04 -0800 | [diff] [blame] | 6 | import static android.app.ActivityManager.StackId.PINNED_STACK_ID; |
Matthew Ng | ae1ff4f | 2016-11-10 15:49:14 -0800 | [diff] [blame] | 7 | |
Jorim Jaggi | f970410 | 2016-05-05 19:14:22 -0700 | [diff] [blame] | 8 | import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM; |
| 9 | import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME; |
Filip Gruszczynski | 0e381e2 | 2016-01-14 16:31:33 -0800 | [diff] [blame] | 10 | import static com.android.server.am.ActivityStack.STACK_INVISIBLE; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 11 | |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 12 | import android.annotation.Nullable; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 13 | import android.app.ActivityManager.StackId; |
| 14 | import android.content.Context; |
| 15 | import android.os.SystemClock; |
Jorim Jaggi | f970410 | 2016-05-05 19:14:22 -0700 | [diff] [blame] | 16 | import android.util.Slog; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 17 | |
Chris Wren | b623714 | 2017-01-23 16:42:58 -0500 | [diff] [blame] | 18 | import android.metrics.LogMaker; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 19 | import com.android.internal.logging.MetricsLogger; |
Tamas Berghammer | 383db5eb | 2016-06-22 15:21:38 +0100 | [diff] [blame] | 20 | import com.android.internal.logging.nano.MetricsProto.MetricsEvent; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 21 | |
Jorim Jaggi | 1e630c0 | 2016-05-16 12:13:13 -0700 | [diff] [blame] | 22 | import java.util.ArrayList; |
| 23 | |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 24 | /** |
| 25 | * Handles logging into Tron. |
| 26 | */ |
| 27 | class ActivityMetricsLogger { |
Jorim Jaggi | f970410 | 2016-05-05 19:14:22 -0700 | [diff] [blame] | 28 | |
| 29 | private static final String TAG = TAG_WITH_CLASS_NAME ? "ActivityMetricsLogger" : TAG_AM; |
| 30 | |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 31 | // Window modes we are interested in logging. If we ever introduce a new type, we need to add |
| 32 | // a value here and increase the {@link #TRON_WINDOW_STATE_VARZ_STRINGS} array. |
| 33 | private static final int WINDOW_STATE_STANDARD = 0; |
| 34 | private static final int WINDOW_STATE_SIDE_BY_SIDE = 1; |
| 35 | private static final int WINDOW_STATE_FREEFORM = 2; |
| 36 | private static final int WINDOW_STATE_INVALID = -1; |
| 37 | |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 38 | private static final long INVALID_START_TIME = -1; |
| 39 | |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 40 | // Preallocated strings we are sending to tron, so we don't have to allocate a new one every |
| 41 | // time we log. |
| 42 | private static final String[] TRON_WINDOW_STATE_VARZ_STRINGS = { |
Chris Wren | ae255ee | 2016-01-04 16:20:17 -0500 | [diff] [blame] | 43 | "window_time_0", "window_time_1", "window_time_2"}; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 44 | |
| 45 | private int mWindowState = WINDOW_STATE_STANDARD; |
| 46 | private long mLastLogTimeSecs; |
| 47 | private final ActivityStackSupervisor mSupervisor; |
| 48 | private final Context mContext; |
| 49 | |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 50 | private long mCurrentTransitionStartTime = INVALID_START_TIME; |
| 51 | private boolean mLoggedWindowsDrawn; |
| 52 | private boolean mLoggedStartingWindowDrawn; |
| 53 | private boolean mLoggedTransitionStarting; |
| 54 | |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 55 | ActivityMetricsLogger(ActivityStackSupervisor supervisor, Context context) { |
| 56 | mLastLogTimeSecs = SystemClock.elapsedRealtime() / 1000; |
| 57 | mSupervisor = supervisor; |
| 58 | mContext = context; |
| 59 | } |
| 60 | |
| 61 | void logWindowState() { |
| 62 | final long now = SystemClock.elapsedRealtime() / 1000; |
| 63 | if (mWindowState != WINDOW_STATE_INVALID) { |
| 64 | // We log even if the window state hasn't changed, because the user might remain in |
| 65 | // home/fullscreen move forever and we would like to track this kind of behavior |
| 66 | // too. |
| 67 | MetricsLogger.count(mContext, TRON_WINDOW_STATE_VARZ_STRINGS[mWindowState], |
| 68 | (int) (now - mLastLogTimeSecs)); |
| 69 | } |
| 70 | mLastLogTimeSecs = now; |
| 71 | |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 72 | ActivityStack stack = mSupervisor.getStack(DOCKED_STACK_ID); |
Wale Ogunwale | 8051c5c | 2016-03-04 10:27:32 -0800 | [diff] [blame] | 73 | if (stack != null && stack.getStackVisibilityLocked(null) != STACK_INVISIBLE) { |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 74 | mWindowState = WINDOW_STATE_SIDE_BY_SIDE; |
Filip Gruszczynski | caae14e | 2015-12-16 14:40:04 -0800 | [diff] [blame] | 75 | return; |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 76 | } |
Filip Gruszczynski | caae14e | 2015-12-16 14:40:04 -0800 | [diff] [blame] | 77 | mWindowState = WINDOW_STATE_INVALID; |
| 78 | stack = mSupervisor.getFocusedStack(); |
| 79 | if (stack.mStackId == PINNED_STACK_ID) { |
| 80 | stack = mSupervisor.findStackBehind(stack); |
| 81 | } |
Matthew Ng | ae1ff4f | 2016-11-10 15:49:14 -0800 | [diff] [blame] | 82 | if (StackId.isHomeOrRecentsStack(stack.mStackId) |
Filip Gruszczynski | caae14e | 2015-12-16 14:40:04 -0800 | [diff] [blame] | 83 | || stack.mStackId == FULLSCREEN_WORKSPACE_STACK_ID) { |
| 84 | mWindowState = WINDOW_STATE_STANDARD; |
| 85 | } else if (stack.mStackId == DOCKED_STACK_ID) { |
Jorim Jaggi | f970410 | 2016-05-05 19:14:22 -0700 | [diff] [blame] | 86 | Slog.wtf(TAG, "Docked stack shouldn't be the focused stack, because it reported not" |
| 87 | + " being visible."); |
| 88 | mWindowState = WINDOW_STATE_INVALID; |
Filip Gruszczynski | caae14e | 2015-12-16 14:40:04 -0800 | [diff] [blame] | 89 | } else if (stack.mStackId == FREEFORM_WORKSPACE_STACK_ID) { |
| 90 | mWindowState = WINDOW_STATE_FREEFORM; |
| 91 | } else if (StackId.isStaticStack(stack.mStackId)) { |
| 92 | throw new IllegalStateException("Unknown stack=" + stack); |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 93 | } |
| 94 | } |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 95 | |
| 96 | /** |
| 97 | * Notifies the tracker at the earliest possible point when we are starting to launch an |
| 98 | * activity. |
| 99 | */ |
| 100 | void notifyActivityLaunching() { |
| 101 | mCurrentTransitionStartTime = System.currentTimeMillis(); |
| 102 | } |
| 103 | |
| 104 | /** |
Jorim Jaggi | 1e630c0 | 2016-05-16 12:13:13 -0700 | [diff] [blame] | 105 | * Notifies the tracker that the activity is actually launching. |
| 106 | * |
| 107 | * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the |
| 108 | * launch |
| 109 | * @param launchedActivity the activity that is being launched |
| 110 | */ |
| 111 | void notifyActivityLaunched(int resultCode, ActivityRecord launchedActivity) { |
| 112 | final ProcessRecord processRecord = launchedActivity != null |
| 113 | ? mSupervisor.mService.mProcessNames.get(launchedActivity.processName, |
| 114 | launchedActivity.appInfo.uid) |
| 115 | : null; |
| 116 | final boolean processRunning = processRecord != null; |
| 117 | final String componentName = launchedActivity != null |
| 118 | ? launchedActivity.shortComponentName |
| 119 | : null; |
| 120 | |
| 121 | // We consider this a "process switch" if the process of the activity that gets launched |
| 122 | // didn't have an activity that was in started state. In this case, we assume that lot |
| 123 | // of caches might be purged so the time until it produces the first frame is very |
| 124 | // interesting. |
| 125 | final boolean processSwitch = processRecord == null |
| 126 | || !hasStartedActivity(processRecord, launchedActivity); |
| 127 | |
| 128 | notifyActivityLaunched(resultCode, componentName, processRunning, processSwitch); |
| 129 | } |
| 130 | |
| 131 | private boolean hasStartedActivity(ProcessRecord record, ActivityRecord launchedActivity) { |
| 132 | final ArrayList<ActivityRecord> activities = record.activities; |
| 133 | for (int i = activities.size() - 1; i >= 0; i--) { |
| 134 | final ActivityRecord activity = activities.get(i); |
| 135 | if (launchedActivity == activity) { |
| 136 | continue; |
| 137 | } |
| 138 | if (!activity.stopped) { |
| 139 | return true; |
| 140 | } |
| 141 | } |
| 142 | return false; |
| 143 | } |
| 144 | |
| 145 | /** |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 146 | * Notifies the tracker the the activity is actually launching. |
| 147 | * |
| 148 | * @param resultCode one of the ActivityManager.START_* flags, indicating the result of the |
| 149 | * launch |
| 150 | * @param componentName the component name of the activity being launched |
| 151 | * @param processRunning whether the process that will contains the activity is already running |
Jorim Jaggi | be67c90 | 2016-04-12 00:53:16 -0700 | [diff] [blame] | 152 | * @param processSwitch whether the process that will contain the activity didn't have any |
| 153 | * activity that was stopped, i.e. the started activity is "switching" |
| 154 | * processes |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 155 | */ |
Jorim Jaggi | 1e630c0 | 2016-05-16 12:13:13 -0700 | [diff] [blame] | 156 | private void notifyActivityLaunched(int resultCode, @Nullable String componentName, |
Jorim Jaggi | be67c90 | 2016-04-12 00:53:16 -0700 | [diff] [blame] | 157 | boolean processRunning, boolean processSwitch) { |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 158 | |
Jorim Jaggi | be67c90 | 2016-04-12 00:53:16 -0700 | [diff] [blame] | 159 | if (resultCode < 0 || componentName == null || !processSwitch) { |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 160 | |
Jorim Jaggi | be67c90 | 2016-04-12 00:53:16 -0700 | [diff] [blame] | 161 | // Failed to launch or it was not a process switch, so we don't care about the timing. |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 162 | reset(); |
| 163 | return; |
| 164 | } |
| 165 | |
| 166 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_COMPONENT_NAME, |
| 167 | componentName); |
| 168 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_PROCESS_RUNNING, |
| 169 | processRunning); |
| 170 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS, |
| 171 | (int) (SystemClock.uptimeMillis() / 1000)); |
Alison Cichowlas | 803054d | 2016-12-13 14:38:01 -0500 | [diff] [blame] | 172 | |
Chris Wren | b623714 | 2017-01-23 16:42:58 -0500 | [diff] [blame] | 173 | LogMaker builder = new LogMaker(MetricsEvent.APP_TRANSITION); |
Alison Cichowlas | 803054d | 2016-12-13 14:38:01 -0500 | [diff] [blame] | 174 | builder.addTaggedData(MetricsEvent.APP_TRANSITION_COMPONENT_NAME, componentName); |
| 175 | builder.addTaggedData(MetricsEvent.APP_TRANSITION_PROCESS_RUNNING, processRunning ? 1 : 0); |
| 176 | builder.addTaggedData(MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS, |
| 177 | SystemClock.uptimeMillis() / 1000); |
| 178 | MetricsLogger.action(builder); |
Jorim Jaggi | 275561a | 2016-02-23 10:11:02 -0500 | [diff] [blame] | 179 | } |
| 180 | |
| 181 | /** |
| 182 | * Notifies the tracker that all windows of the app have been drawn. |
| 183 | */ |
| 184 | void notifyWindowsDrawn() { |
| 185 | if (!isTransitionActive() || mLoggedWindowsDrawn) { |
| 186 | return; |
| 187 | } |
| 188 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS, |
| 189 | calculateCurrentDelay()); |
| 190 | mLoggedWindowsDrawn = true; |
| 191 | if (mLoggedTransitionStarting) { |
| 192 | reset(); |
| 193 | } |
| 194 | } |
| 195 | |
| 196 | /** |
| 197 | * Notifies the tracker that the starting window was drawn. |
| 198 | */ |
| 199 | void notifyStartingWindowDrawn() { |
| 200 | if (!isTransitionActive() || mLoggedStartingWindowDrawn) { |
| 201 | return; |
| 202 | } |
| 203 | mLoggedStartingWindowDrawn = true; |
| 204 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS, |
| 205 | calculateCurrentDelay()); |
| 206 | } |
| 207 | |
| 208 | /** |
| 209 | * Notifies the tracker that the app transition is starting. |
| 210 | * |
| 211 | * @param reason The reason why we started it. Must be on of |
| 212 | * ActivityManagerInternal.APP_TRANSITION_* reasons. |
| 213 | */ |
| 214 | void notifyTransitionStarting(int reason) { |
| 215 | if (!isTransitionActive() || mLoggedTransitionStarting) { |
| 216 | return; |
| 217 | } |
| 218 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_REASON, reason); |
| 219 | MetricsLogger.action(mContext, MetricsEvent.APP_TRANSITION_DELAY_MS, |
| 220 | calculateCurrentDelay()); |
| 221 | mLoggedTransitionStarting = true; |
| 222 | if (mLoggedWindowsDrawn) { |
| 223 | reset(); |
| 224 | } |
| 225 | } |
| 226 | |
| 227 | private boolean isTransitionActive() { |
| 228 | return mCurrentTransitionStartTime != INVALID_START_TIME; |
| 229 | } |
| 230 | |
| 231 | private void reset() { |
| 232 | mCurrentTransitionStartTime = INVALID_START_TIME; |
| 233 | mLoggedWindowsDrawn = false; |
| 234 | mLoggedTransitionStarting = false; |
| 235 | mLoggedStartingWindowDrawn = false; |
| 236 | } |
| 237 | |
| 238 | private int calculateCurrentDelay() { |
| 239 | |
| 240 | // Shouldn't take more than 25 days to launch an app, so int is fine here. |
| 241 | return (int) (System.currentTimeMillis() - mCurrentTransitionStartTime); |
| 242 | } |
Filip Gruszczynski | 77d9448 | 2015-12-11 13:59:52 -0800 | [diff] [blame] | 243 | } |