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