• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /*
2  * Copyright (C) 2018 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License
15  */
16 
17 package android.server.wm;
18 
19 import static android.app.WindowConfiguration.WINDOWING_MODE_FULLSCREEN;
20 import static android.os.SystemClock.sleep;
21 import static android.server.wm.ActivityLauncher.KEY_LAUNCH_ACTIVITY;
22 import static android.server.wm.ActivityLauncher.KEY_TARGET_COMPONENT;
23 import static android.server.wm.WindowManagerState.STATE_STOPPED;
24 import static android.server.wm.app.Components.ENTRY_POINT_ALIAS_ACTIVITY;
25 import static android.server.wm.app.Components.LAUNCHING_ACTIVITY;
26 import static android.server.wm.app.Components.NO_DISPLAY_ACTIVITY;
27 import static android.server.wm.app.Components.REPORT_FULLY_DRAWN_ACTIVITY;
28 import static android.server.wm.app.Components.SINGLE_TASK_ACTIVITY;
29 import static android.server.wm.app.Components.TEST_ACTIVITY;
30 import static android.server.wm.app.Components.TRANSLUCENT_TEST_ACTIVITY;
31 import static android.server.wm.app.Components.TRANSLUCENT_TOP_ACTIVITY;
32 import static android.server.wm.app.Components.TopActivity.EXTRA_FINISH_IN_ON_CREATE;
33 import static android.server.wm.second.Components.SECOND_ACTIVITY;
34 import static android.server.wm.third.Components.THIRD_ACTIVITY;
35 import static android.util.TimeUtils.formatDuration;
36 
37 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION;
38 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_CANCELLED;
39 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DELAY_MS;
40 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_DEVICE_UPTIME_SECONDS;
41 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN;
42 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_REPORTED_DRAWN_MS;
43 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_STARTING_WINDOW_DELAY_MS;
44 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS;
45 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.FIELD_CLASS_NAME;
46 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_COLD_LAUNCH;
47 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_HOT_LAUNCH;
48 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE;
49 import static com.android.internal.logging.nano.MetricsProto.MetricsEvent.TYPE_TRANSITION_WARM_LAUNCH;
50 
51 import static org.hamcrest.MatcherAssert.assertThat;
52 import static org.hamcrest.Matchers.containsString;
53 import static org.hamcrest.Matchers.greaterThanOrEqualTo;
54 import static org.hamcrest.Matchers.lessThanOrEqualTo;
55 import static org.junit.Assert.assertEquals;
56 import static org.junit.Assert.assertNotEquals;
57 import static org.junit.Assert.assertNotNull;
58 import static org.junit.Assert.assertNull;
59 import static org.junit.Assert.fail;
60 
61 import android.app.Activity;
62 import android.content.ComponentName;
63 import android.metrics.LogMaker;
64 import android.metrics.MetricsReader;
65 import android.os.Process;
66 import android.os.SystemClock;
67 import android.platform.test.annotations.Presubmit;
68 import android.server.wm.CommandSession.ActivitySessionClient;
69 import android.support.test.metricshelper.MetricsAsserts;
70 import android.util.EventLog.Event;
71 
72 
73 import androidx.annotation.NonNull;
74 import androidx.annotation.Nullable;
75 
76 import com.android.compatibility.common.util.SystemUtil;
77 
78 import org.hamcrest.collection.IsIn;
79 import org.junit.Before;
80 import org.junit.Test;
81 
82 import java.util.Arrays;
83 import java.util.List;
84 import java.util.Objects;
85 import java.util.Queue;
86 import java.util.concurrent.TimeUnit;
87 import java.util.function.IntConsumer;
88 
89 /**
90  * CTS device tests for {@link com.android.server.wm.ActivityMetricsLogger}.
91  * Build/Install/Run:
92  * atest CtsWindowManagerDeviceTestCases:ActivityMetricsLoggerTests
93  */
94 @Presubmit
95 public class ActivityMetricsLoggerTests extends ActivityManagerTestBase {
96     private static final String TAG_ATM = "ActivityTaskManager";
97     private static final String LAUNCH_STATE_COLD = "COLD";
98     private static final String LAUNCH_STATE_WARM = "WARM";
99     private static final String LAUNCH_STATE_HOT = "HOT";
100     private static final String LAUNCH_STATE_RELAUNCH = "RELAUNCH";
101     private static final int EVENT_WM_ACTIVITY_LAUNCH_TIME = 30009;
102     private static final int APP_TRANSITION_STARTING_WINDOW = 1;
103     private static final int APP_TRANSITION_WINDOWS_DRAWN = 2;
104     private static final int APP_TRANSITION_TIMEOUT = 3;
105     private final MetricsReader mMetricsReader = new MetricsReader();
106     private long mPreUptimeMs;
107     private LogSeparator mLogSeparator;
108 
109     @Before
setUp()110     public void setUp() throws Exception {
111         super.setUp();
112         mPreUptimeMs = SystemClock.uptimeMillis();
113         mMetricsReader.checkpoint(); // clear out old logs
114         mLogSeparator = separateLogs(); // add a new separator for logs
115     }
116 
117     /**
118      * Launch an app and verify:
119      * - appropriate metrics logs are added
120      * - "Displayed activity ..." log is added to logcat
121      * - am_activity_launch_time event is generated
122      * In all three cases, verify the delay measurements are the same.
123      */
124     @Test
testAppLaunchIsLogged()125     public void testAppLaunchIsLogged() {
126         launchAndWaitForActivity(TEST_ACTIVITY);
127 
128         final LogMaker metricsLog = waitForMetricsLog(TEST_ACTIVITY, APP_TRANSITION);
129         final String[] deviceLogs = getDeviceLogsForComponents(mLogSeparator, TAG_ATM);
130         final List<Event> eventLogs = getEventLogsForComponents(mLogSeparator,
131                 EVENT_WM_ACTIVITY_LAUNCH_TIME);
132 
133         final long postUptimeMs = SystemClock.uptimeMillis();
134         assertMetricsLogs(TEST_ACTIVITY, APP_TRANSITION, metricsLog, mPreUptimeMs, postUptimeMs);
135         assertTransitionStartReason(metricsLog);
136         final int windowsDrawnDelayMs =
137                 (int) metricsLog.getTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS);
138         final String expectedLog =
139                 "Displayed " + TEST_ACTIVITY.flattenToShortString()  + " for user "
140                         + Process.myUserHandle().getIdentifier()
141                         + ": " + formatDuration(windowsDrawnDelayMs);
142         assertLogsContain(deviceLogs, expectedLog);
143         assertEventLogsContainsLaunchTime(eventLogs, TEST_ACTIVITY, windowsDrawnDelayMs);
144     }
145 
assertMetricsLogs(ComponentName componentName, int category, LogMaker log, long preUptimeMs, long postUptimeMs)146     private void assertMetricsLogs(ComponentName componentName,
147             int category, LogMaker log, long preUptimeMs, long postUptimeMs) {
148         assertNotNull("did not find the metrics log for: " + componentName
149                 + " category:" + categoryToString(category), log);
150         int startUptimeSec =
151                 ((Number) log.getTaggedData(APP_TRANSITION_DEVICE_UPTIME_SECONDS)).intValue();
152         int preUptimeSec = (int) (TimeUnit.MILLISECONDS.toSeconds(preUptimeMs));
153         int postUptimeSec = (int) (TimeUnit.MILLISECONDS.toSeconds(postUptimeMs));
154         long testElapsedTimeMs = postUptimeMs - preUptimeMs;
155         assertThat("must be either cold or warm launch", log.getType(),
156                 IsIn.oneOf(TYPE_TRANSITION_COLD_LAUNCH, TYPE_TRANSITION_WARM_LAUNCH));
157         assertThat("reported uptime should be after the app was started", startUptimeSec,
158                 greaterThanOrEqualTo(preUptimeSec));
159         assertThat("reported uptime should be before assertion time", startUptimeSec,
160                 lessThanOrEqualTo(postUptimeSec));
161         assertNotNull("log should have delay", log.getTaggedData(APP_TRANSITION_DELAY_MS));
162         assertNotNull("log should have windows drawn delay",
163                 log.getTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS));
164         long windowsDrawnDelayMs = (int) log.getTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS);
165         assertThat("windows drawn delay should be less that total elapsed time",
166                 windowsDrawnDelayMs,  lessThanOrEqualTo(testElapsedTimeMs));
167     }
168 
assertTransitionStartReason(LogMaker log)169     private void assertTransitionStartReason(LogMaker log) {
170         if (isLeanBack()) return;
171 
172         final int transitionStartReason = log.getSubtype();
173         switch (transitionStartReason) {
174             case APP_TRANSITION_STARTING_WINDOW:
175                 assertNotNull("Transition started by starting window should include delay time",
176                         log.getTaggedData(APP_TRANSITION_STARTING_WINDOW_DELAY_MS));
177                 break;
178             case APP_TRANSITION_WINDOWS_DRAWN:
179                 // It is fine if the activity is drawn faster than the starting window.
180                 StateLogger.logAlways("APP_TRANSITION_WINDOWS_DRAWN");
181                 break;
182             case APP_TRANSITION_TIMEOUT:
183                 // There might be other issues in system, but it isn't in the scope of this test.
184                 StateLogger.logE("APP_TRANSITION_TIMEOUT");
185                 break;
186             default:
187                 fail("Unexpected transition start reason " + transitionStartReason);
188         }
189     }
190 
assertEventLogsContainsLaunchTime(List<Event> events, ComponentName componentName, int windowsDrawnDelayMs)191     private void assertEventLogsContainsLaunchTime(List<Event> events, ComponentName componentName,
192             int windowsDrawnDelayMs) {
193         verifyLaunchTimeEventLogs(events, componentName,
194                 delay -> assertEquals("Unexpected windows drawn delay for " + componentName,
195                         delay, windowsDrawnDelayMs));
196     }
197 
verifyLaunchTimeEventLogs(List<Event> launchTimeEvents, ComponentName componentName, IntConsumer launchTimeVerifier)198     private void verifyLaunchTimeEventLogs(List<Event> launchTimeEvents,
199             ComponentName componentName, IntConsumer launchTimeVerifier) {
200         for (Event event : launchTimeEvents) {
201             final Object[] arr = (Object[]) event.getData();
202             assertEquals(4, arr.length);
203             final String name = (String) arr[2];
204             final int launchTime = (int) arr[3];
205             if (name.equals(componentName.flattenToShortString())) {
206                 launchTimeVerifier.accept(launchTime);
207                 return;
208             }
209         }
210         fail("Could not find wm_activity_launch_time for " + componentName);
211     }
212 
213     /**
214      * Start an activity that reports full drawn and verify:
215      * - fully drawn metrics are added to metrics logs
216      * - "Fully drawn activity ..." log is added to logcat
217      * In both cases verify fully drawn delay measurements are equal.
218      * See {@link Activity#reportFullyDrawn()}
219      */
220     @Test
testAppFullyDrawnReportIsLogged()221     public void testAppFullyDrawnReportIsLogged() {
222         launchAndWaitForActivity(REPORT_FULLY_DRAWN_ACTIVITY);
223 
224         // Sleep until activity under test has reported drawn (after 500ms)
225         sleep(1000);
226 
227         final LogMaker metricsLog = waitForMetricsLog(REPORT_FULLY_DRAWN_ACTIVITY,
228                 APP_TRANSITION_REPORTED_DRAWN);
229         final String[] deviceLogs = getDeviceLogsForComponents(mLogSeparator, TAG_ATM);
230 
231         assertNotNull("did not find the metrics log for: " + REPORT_FULLY_DRAWN_ACTIVITY
232                 + " category:" + APP_TRANSITION_REPORTED_DRAWN, metricsLog);
233         assertThat("test activity has a 500ms delay before reporting fully drawn",
234                 (long) metricsLog.getTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS),
235                 greaterThanOrEqualTo(500L));
236         assertEquals(TYPE_TRANSITION_REPORTED_DRAWN_NO_BUNDLE, metricsLog.getType());
237 
238         final long fullyDrawnDelayMs =
239                 (long) metricsLog.getTaggedData(APP_TRANSITION_REPORTED_DRAWN_MS);
240         final String expectedLog =
241                 "Fully drawn " + REPORT_FULLY_DRAWN_ACTIVITY.flattenToShortString()
242                         + ": " + formatDuration(fullyDrawnDelayMs);
243         assertLogsContain(deviceLogs, expectedLog);
244     }
245 
246     /**
247      * Warm launch an activity with wait option and verify that {@link android.app.WaitResult#totalTime}
248      * totalTime is set correctly. Make sure the reported value is consistent with value reported to
249      * metrics logs. Verify we output the correct launch state.
250      */
251     @Test
testAppWarmLaunchSetsWaitResultDelayData()252     public void testAppWarmLaunchSetsWaitResultDelayData() {
253         try (ActivitySessionClient client = createActivitySessionClient()) {
254             client.startActivity(getLaunchActivityBuilder()
255                     .setUseInstrumentation()
256                     .setTargetActivity(TEST_ACTIVITY)
257                     .setWaitForLaunched(true));
258             separateTestJournal();
259             // The activity will be finished when closing the session client.
260         }
261         assertActivityDestroyed(TEST_ACTIVITY);
262         mMetricsReader.checkpoint(); // clear out old logs
263 
264         // This is warm launch because its process should be alive after the above steps.
265         final String amStartOutput = SystemUtil.runShellCommand(
266                 "am start -W " + TEST_ACTIVITY.flattenToShortString());
267 
268         final LogMaker metricsLog = waitForMetricsLog(TEST_ACTIVITY, APP_TRANSITION);
269         final int windowsDrawnDelayMs =
270                 (int) metricsLog.getTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS);
271 
272         assertEquals("Expected a cold launch.", metricsLog.getType(), TYPE_TRANSITION_WARM_LAUNCH);
273 
274         assertLaunchComponentStateAndTime(amStartOutput, TEST_ACTIVITY, LAUNCH_STATE_WARM,
275                 windowsDrawnDelayMs);
276     }
277 
278     /**
279      * Hot launch an activity with wait option and verify that {@link android.app.WaitResult#totalTime}
280      * totalTime is set correctly. Make sure the reported value is consistent with value reported to
281      * metrics logs. Verify we output the correct launch state.
282      */
283     @Test
testAppHotLaunchSetsWaitResultDelayData()284     public void testAppHotLaunchSetsWaitResultDelayData() {
285         SystemUtil.runShellCommand("am start -S -W " + TEST_ACTIVITY.flattenToShortString());
286 
287         // Test hot launch
288         launchHomeActivityNoWait();
289         waitAndAssertActivityState(TEST_ACTIVITY, STATE_STOPPED, "Activity should be stopped");
290         mMetricsReader.checkpoint(); // clear out old logs
291 
292         final String amStartOutput = SystemUtil.runShellCommand(
293                 "am start -W " + TEST_ACTIVITY.flattenToShortString());
294 
295         final LogMaker metricsLog = waitForMetricsLog(TEST_ACTIVITY, APP_TRANSITION);
296         final int windowsDrawnDelayMs =
297                 (int) metricsLog.getTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS);
298 
299         assertEquals("Expected a cold launch.", metricsLog.getType(), TYPE_TRANSITION_HOT_LAUNCH);
300 
301         assertLaunchComponentStateAndTime(amStartOutput, TEST_ACTIVITY, LAUNCH_STATE_HOT,
302                 windowsDrawnDelayMs);
303     }
304 
305     /**
306      * Launch an existing background activity after the device configuration is changed and the
307      * activity doesn't declare to handle the change. The state should be RELAUNCH instead of HOT.
308      */
309     @Test
testAppRelaunchSetsWaitResultDelayData()310     public void testAppRelaunchSetsWaitResultDelayData() {
311         final String startTestActivityCmd = "am start -W " + TEST_ACTIVITY.flattenToShortString();
312         SystemUtil.runShellCommand(startTestActivityCmd);
313 
314         launchHomeActivityNoWait();
315         waitAndAssertActivityState(TEST_ACTIVITY, STATE_STOPPED, "Activity should be stopped");
316 
317         final float originalFontScale = mContext.getResources().getConfiguration().fontScale;
318         final FontScaleSession fontScaleSession = createManagedFontScaleSession();
319         fontScaleSession.set(fontScaleSession.get() + 0.1f);
320         Condition.waitFor("font scale changed", () ->
321                 originalFontScale != mContext.getResources().getConfiguration().fontScale);
322 
323         // Move the task of test activity to front.
324         final String amStartOutput = SystemUtil.runShellCommand(startTestActivityCmd);
325         assertLaunchComponentState(amStartOutput, TEST_ACTIVITY, LAUNCH_STATE_RELAUNCH);
326     }
327 
328     /**
329      * Cold launch an activity with wait option and verify that {@link android.app.WaitResult#totalTime}
330      * totalTime is set correctly. Make sure the reported value is consistent with value reported to
331      * metrics logs. Verify we output the correct launch state.
332      */
333     @Test
testAppColdLaunchSetsWaitResultDelayData()334     public void testAppColdLaunchSetsWaitResultDelayData() {
335         final String amStartOutput = SystemUtil.runShellCommand(
336                 "am start -S -W " + TEST_ACTIVITY.flattenToShortString());
337 
338         final LogMaker metricsLog = waitForMetricsLog(TEST_ACTIVITY, APP_TRANSITION);
339         final int windowsDrawnDelayMs =
340                 (int) metricsLog.getTaggedData(APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS);
341 
342         assertEquals("Expected a cold launch.", metricsLog.getType(), TYPE_TRANSITION_COLD_LAUNCH);
343 
344         assertLaunchComponentStateAndTime(amStartOutput, TEST_ACTIVITY, LAUNCH_STATE_COLD,
345                 windowsDrawnDelayMs);
346     }
347 
348     /**
349      * Launch an app that is already visible and verify we handle cases where we will not
350      * receive a windows drawn message.
351      * see b/117148004
352      */
353     @Test
testLaunchOfVisibleApp()354     public void testLaunchOfVisibleApp() {
355         // Launch an activity.
356         launchAndWaitForActivity(SECOND_ACTIVITY);
357 
358         // Launch a translucent activity on top.
359         launchAndWaitForActivity(TRANSLUCENT_TEST_ACTIVITY);
360 
361         // Launch the first activity again. This will not trigger a windows drawn message since
362         // its windows were visible before launching.
363         mMetricsReader.checkpoint(); // clear out old logs
364         launchAndWaitForActivity(SECOND_ACTIVITY);
365 
366         LogMaker metricsLog = getMetricsLog(SECOND_ACTIVITY, APP_TRANSITION);
367         // Verify transition logs are absent since we cannot measure windows drawn delay.
368         assertNull("transition logs should be reset.", metricsLog);
369 
370         // Verify metrics for subsequent launches are generated as expected.
371         mPreUptimeMs = SystemClock.uptimeMillis();
372         mMetricsReader.checkpoint(); // clear out old logs
373 
374         launchAndWaitForActivity(THIRD_ACTIVITY);
375 
376         long postUptimeMs = SystemClock.uptimeMillis();
377         metricsLog = waitForMetricsLog(THIRD_ACTIVITY, APP_TRANSITION);
378         assertMetricsLogs(THIRD_ACTIVITY, APP_TRANSITION, metricsLog, mPreUptimeMs,
379                 postUptimeMs);
380         assertTransitionStartReason(metricsLog);
381     }
382 
383     @Test
testAppLaunchCancelledSameTask()384     public void testAppLaunchCancelledSameTask() {
385         launchAndWaitForActivity(TEST_ACTIVITY);
386 
387         // Start a non-opaque activity in a different process in the same task.
388         getLaunchActivityBuilder()
389                 .setUseInstrumentation()
390                 .setTargetActivity(TRANSLUCENT_TOP_ACTIVITY)
391                 .setIntentExtra(extra -> extra.putBoolean(EXTRA_FINISH_IN_ON_CREATE, true))
392                 .setWaitForLaunched(false)
393                 .execute();
394 
395         final LogMaker metricsLog = waitForMetricsLog(TRANSLUCENT_TOP_ACTIVITY,
396                 APP_TRANSITION_CANCELLED);
397 
398         assertNotNull("Metrics log APP_TRANSITION_CANCELLED not found", metricsLog);
399     }
400 
401     /**
402      * Launch a NoDisplay activity and verify it does not affect subsequent activity launch
403      * metrics. NoDisplay activities do not draw any windows and may be incorrectly identified as a
404      * trampoline activity. See b/80380150 (Long warm launch times reported in dev play console)
405      */
406     @Test
testNoDisplayActivityLaunch()407     public void testNoDisplayActivityLaunch() {
408         launchAndWaitForActivity(NO_DISPLAY_ACTIVITY);
409 
410         mPreUptimeMs = SystemClock.uptimeMillis();
411         launchAndWaitForActivity(SECOND_ACTIVITY);
412 
413         final LogMaker metricsLog = waitForMetricsLog(SECOND_ACTIVITY, APP_TRANSITION);
414         final long postUptimeMs = SystemClock.uptimeMillis();
415         assertMetricsLogs(SECOND_ACTIVITY, APP_TRANSITION, metricsLog, mPreUptimeMs, postUptimeMs);
416         assertTransitionStartReason(metricsLog);
417     }
418 
419     /**
420      * Launch an activity with a trampoline activity and verify launch metrics measures the complete
421      * launch sequence from when the trampoline activity is launching to when the target activity
422      * draws on screen.
423      */
424     @Test
testTrampolineActivityLaunch()425     public void testTrampolineActivityLaunch() {
426         // Launch a trampoline activity that will launch single task activity.
427         launchAndWaitForActivity(ENTRY_POINT_ALIAS_ACTIVITY);
428         final LogMaker metricsLog = waitForMetricsLog(SINGLE_TASK_ACTIVITY, APP_TRANSITION);
429         final long postUptimeMs = SystemClock.uptimeMillis();
430         assertMetricsLogs(SINGLE_TASK_ACTIVITY, APP_TRANSITION, metricsLog, mPreUptimeMs,
431                         postUptimeMs);
432     }
433 
434     /**
435      * Launch an activity which will start another activity immediately. The reported component
436      * name should be the last one with valid launch state.
437      */
438     @Test
testConsecutiveLaunch()439     public void testConsecutiveLaunch() {
440         final String amStartOutput = SystemUtil.runShellCommand(
441                 "am start --ez " + KEY_LAUNCH_ACTIVITY
442                 + " true --es " + KEY_TARGET_COMPONENT + " " + TEST_ACTIVITY.flattenToShortString()
443                 + " -W " + LAUNCHING_ACTIVITY.flattenToShortString());
444         assertLaunchComponentState(amStartOutput, TEST_ACTIVITY, LAUNCH_STATE_COLD);
445     }
446 
447     @Test
testLaunchTimeEventLogNonProcessSwitch()448     public void testLaunchTimeEventLogNonProcessSwitch() {
449         launchAndWaitForActivity(SINGLE_TASK_ACTIVITY);
450         mLogSeparator = separateLogs();
451 
452         // Launch another activity in the same process.
453         launchAndWaitForActivity(TEST_ACTIVITY);
454         final List<Event> eventLogs = getEventLogsForComponents(mLogSeparator,
455                 EVENT_WM_ACTIVITY_LAUNCH_TIME);
456         verifyLaunchTimeEventLogs(eventLogs, TEST_ACTIVITY, time -> assertNotEquals(0, time));
457     }
458 
launchAndWaitForActivity(ComponentName activity)459     private void launchAndWaitForActivity(ComponentName activity) {
460         getLaunchActivityBuilder()
461                 .setUseInstrumentation()
462                 .setTargetActivity(activity)
463                 .setWindowingMode(WINDOWING_MODE_FULLSCREEN)
464                 .setWaitForLaunched(true)
465                 .execute();
466     }
467 
468     @NonNull
waitForMetricsLog(ComponentName componentName, int category)469     private LogMaker waitForMetricsLog(ComponentName componentName, int category) {
470         final String categoryName = categoryToString(category);
471         final String message = componentName.toShortString() + " with category " + categoryName;
472         final LogMaker metricsLog = Condition.waitForResult(new Condition<LogMaker>(message)
473                 .setResultSupplier(() -> getMetricsLog(componentName, category))
474                 .setResultValidator(Objects::nonNull));
475         if (metricsLog != null) {
476             return metricsLog;
477         }
478 
479         // Fallback to check again from raw event log. Not sure if sometimes MetricsAsserts cannot
480         // find the expected log.
481         final LogMaker template = new LogMaker(category);
482         final List<Event> eventLogs = getEventLogsForComponents(mLogSeparator,
483                 android.util.EventLog.getTagCode("sysui_multi_action"));
484         for (Event event : eventLogs) {
485             final LogMaker log = new LogMaker((Object[]) event.getData());
486             if (isComponentMatched(log, componentName) && template.isSubsetOf(log)) {
487                 return log;
488             }
489         }
490 
491         throw new AssertionError("Log should have " + categoryName + " of " + componentName);
492     }
493 
494     @Nullable
getMetricsLog(ComponentName componentName, int category)495     private LogMaker getMetricsLog(ComponentName componentName, int category) {
496         final Queue<LogMaker> startLogs = MetricsAsserts.findMatchingLogs(mMetricsReader,
497                 new LogMaker(category));
498         return startLogs.stream().filter(log -> isComponentMatched(log, componentName))
499                 .findFirst().orElse(null);
500     }
501 
isComponentMatched(LogMaker log, ComponentName componentName)502     private static boolean isComponentMatched(LogMaker log, ComponentName componentName) {
503         final String actualClassName = (String) log.getTaggedData(FIELD_CLASS_NAME);
504         final String actualPackageName = log.getPackageName();
505         return componentName.getClassName().equals(actualClassName) &&
506                 componentName.getPackageName().equals(actualPackageName);
507     }
508 
categoryToString(int category)509     private static String categoryToString(int category) {
510         return (category == APP_TRANSITION ? "APP_TRANSITION"
511                 : category == APP_TRANSITION_CANCELLED ? "APP_TRANSITION_CANCELLED"
512                 : category == APP_TRANSITION_REPORTED_DRAWN ? "APP_TRANSITION_REPORTED_DRAWN"
513                 : "Unknown") + "(" + category + ")";
514     }
515 
assertLaunchComponentState(String amStartOutput, ComponentName component, String state)516     private static void assertLaunchComponentState(String amStartOutput, ComponentName component,
517             String state) {
518         assertThat("did not find component in am start output.", amStartOutput,
519                 containsString(component.flattenToShortString()));
520         assertThat("did not find launch state in am start output.", amStartOutput,
521                 containsString(state));
522     }
523 
assertLaunchComponentStateAndTime(String amStartOutput, ComponentName component, String state, int windowsDrawnDelayMs)524     private static void assertLaunchComponentStateAndTime(String amStartOutput,
525             ComponentName component, String state, int windowsDrawnDelayMs) {
526         assertLaunchComponentState(amStartOutput, component, state);
527         assertThat("did not find windows drawn delay time in am start output.", amStartOutput,
528                 containsString(Integer.toString(windowsDrawnDelayMs)));
529     }
530 
assertLogsContain(String[] logs, String expectedLog)531     private void assertLogsContain(String[] logs, String expectedLog) {
532         for (String line : logs) {
533             if (line.contains(expectedLog)) {
534                 return;
535             }
536         }
537         fail("Expected to find '" + expectedLog + "' in " + Arrays.toString(logs));
538     }
539 }
540