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