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 package android.platform.test.microbenchmark; 17 18 import static com.google.common.truth.Truth.assertThat; 19 import static org.junit.Assert.assertTrue; 20 import static org.mockito.ArgumentMatchers.any; 21 import static org.mockito.Mockito.doReturn; 22 import static org.mockito.Mockito.never; 23 import static org.mockito.Mockito.verify; 24 25 import android.os.Bundle; 26 import android.os.SystemClock; 27 import android.platform.test.microbenchmark.Microbenchmark.TerminateEarlyException; 28 import android.platform.test.rule.TestWatcher; 29 import android.platform.test.rule.TracePointRule; 30 31 import org.junit.After; 32 import org.junit.Before; 33 import org.junit.ClassRule; 34 import org.junit.Rule; 35 import org.junit.Test; 36 import org.junit.rules.TestRule; 37 import org.junit.runner.Description; 38 import org.junit.runner.JUnitCore; 39 import org.junit.runner.Result; 40 import org.junit.runner.RunWith; 41 import org.junit.runner.notification.Failure; 42 import org.junit.runner.notification.RunNotifier; 43 import org.junit.runners.JUnit4; 44 import org.junit.runners.model.InitializationError; 45 import org.junit.runners.model.Statement; 46 import org.mockito.ArgumentCaptor; 47 import org.mockito.Mockito; 48 49 import java.util.ArrayList; 50 import java.util.List; 51 52 /** 53 * Unit tests for the {@link Microbenchmark} runner. 54 */ 55 @RunWith(JUnit4.class) 56 public final class MicrobenchmarkTest { 57 // Static logs are needed to validate dynamic rules, which are instantiated reflectively and 58 // cannot access non-static variables. 59 private static List<String> sLogs = new ArrayList<>(); 60 61 @Before setUp()62 public void setUp() { 63 sLogs.clear(); 64 } 65 66 /** 67 * Tests that iterations are respected for microbenchmark tests. 68 */ 69 @Test testIterationCount()70 public void testIterationCount() throws InitializationError { 71 Bundle args = new Bundle(); 72 args.putString("iterations", "10"); 73 Microbenchmark microbench = new Microbenchmark(BasicTest.class, args); 74 assertThat(microbench.testCount()).isEqualTo(10); 75 } 76 77 public static class BasicTest { 78 @Test doNothingTest()79 public void doNothingTest() { } 80 } 81 82 /** 83 * Tests that {@link TracePointRule} and {@link TightMethodRule}s are properly ordered. 84 * 85 * Before --> TightBefore --> Trace (begin) --> Test --> Trace(end) --> TightAfter --> After 86 */ 87 @Test testFeatureExecutionOrder()88 public void testFeatureExecutionOrder() throws InitializationError { 89 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark(LoggingTest.class); 90 loggingRunner.setOperationLog(new ArrayList<String>()); 91 Result result = new JUnitCore().run(loggingRunner); 92 assertThat(result.wasSuccessful()).isTrue(); 93 assertThat(loggingRunner.getOperationLog()).containsExactly( 94 "before", 95 "tight before", 96 "begin: testMethod(" 97 + "android.platform.test.microbenchmark.MicrobenchmarkTest$LoggingTest)", 98 "test", 99 "end", 100 "tight after", 101 "after") 102 .inOrder(); 103 } 104 105 /** 106 * Test iterations number are added to the test name with default suffix. 107 * 108 * Before --> TightBefore --> Trace (begin) with suffix @1 --> Test --> Trace(end) 109 * --> TightAfter --> After --> Before --> TightBefore --> Trace (begin) with suffix @2 110 * --> Test --> Trace(end) --> TightAfter --> After 111 */ 112 @Test testMultipleIterationsWithRename()113 public void testMultipleIterationsWithRename() throws InitializationError { 114 Bundle args = new Bundle(); 115 args.putString("iterations", "2"); 116 args.putString("rename-iterations", "true"); 117 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark(LoggingTest.class, args); 118 loggingRunner.setOperationLog(new ArrayList<String>()); 119 Result result = new JUnitCore().run(loggingRunner); 120 assertThat(result.wasSuccessful()).isTrue(); 121 assertThat(loggingRunner.getOperationLog()).containsExactly( 122 "before", 123 "tight before", 124 "begin: testMethod(" 125 + "android.platform.test.microbenchmark.MicrobenchmarkTest$LoggingTest$1)", 126 "test", 127 "end", 128 "tight after", 129 "after", 130 "before", 131 "tight before", 132 "begin: testMethod(" 133 + "android.platform.test.microbenchmark.MicrobenchmarkTest$LoggingTest$2)", 134 "test", 135 "end", 136 "tight after", 137 "after") 138 .inOrder(); 139 } 140 141 /** 142 * Test iterations number are added to the test name with custom suffix. 143 * 144 * Before --> TightBefore --> Trace (begin) with suffix --1 --> Test --> Trace(end) 145 * --> TightAfter --> After --> Before --> TightBefore --> Trace (begin) with suffix --2 146 * --> Test --> Trace(end) --> TightAfter --> After 147 */ 148 @Test testMultipleIterationsWithDifferentSuffix()149 public void testMultipleIterationsWithDifferentSuffix() throws InitializationError { 150 Bundle args = new Bundle(); 151 args.putString("iterations", "2"); 152 args.putString("rename-iterations", "true"); 153 args.putString("iteration-separator", "--"); 154 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark(LoggingTest.class, args); 155 loggingRunner.setOperationLog(new ArrayList<String>()); 156 Result result = new JUnitCore().run(loggingRunner); 157 assertThat(result.wasSuccessful()).isTrue(); 158 assertThat(loggingRunner.getOperationLog()).containsExactly( 159 "before", 160 "tight before", 161 "begin: testMethod(" 162 + "android.platform.test.microbenchmark.MicrobenchmarkTest$LoggingTest--1)", 163 "test", 164 "end", 165 "tight after", 166 "after", 167 "before", 168 "tight before", 169 "begin: testMethod(" 170 + "android.platform.test.microbenchmark.MicrobenchmarkTest$LoggingTest--2)", 171 "test", 172 "end", 173 "tight after", 174 "after") 175 .inOrder(); 176 } 177 178 /** 179 * Test iteration number are not added to the test name when explictly disabled. 180 * 181 * Before --> TightBefore --> Trace (begin) --> Test --> Trace(end) --> TightAfter 182 * --> After 183 */ 184 @Test testMultipleIterationsWithoutRename()185 public void testMultipleIterationsWithoutRename() throws InitializationError { 186 Bundle args = new Bundle(); 187 args.putString("iterations", "1"); 188 args.putString("rename-iterations", "false"); 189 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark(LoggingTest.class, args); 190 loggingRunner.setOperationLog(new ArrayList<String>()); 191 Result result = new JUnitCore().run(loggingRunner); 192 assertThat(result.wasSuccessful()).isTrue(); 193 assertThat(loggingRunner.getOperationLog()) 194 .containsExactly( 195 "before", 196 "tight before", 197 "begin: testMethod(" 198 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 199 + "$LoggingTest)", 200 "test", 201 "end", 202 "tight after", 203 "after") 204 .inOrder(); 205 } 206 207 /** 208 * Test method iteration will iterate the inner-most test method N times. 209 * 210 * <p>Before --> TightBefore --> Trace (begin) --> Test x N --> Trace(end) --> TightAfter --> 211 * After 212 */ 213 @Test testMultipleMethodIterations()214 public void testMultipleMethodIterations() throws InitializationError { 215 Bundle args = new Bundle(); 216 args.putString("iterations", "1"); 217 args.putString("method-iterations", "10"); 218 args.putString("rename-iterations", "false"); 219 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark(LoggingTest.class, args); 220 loggingRunner.setOperationLog(new ArrayList<String>()); 221 Result result = new JUnitCore().run(loggingRunner); 222 assertThat(result.wasSuccessful()).isTrue(); 223 assertThat(loggingRunner.getOperationLog()) 224 .containsExactly( 225 "before", 226 "tight before", 227 "begin: testMethod(" 228 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 229 + "$LoggingTest)", 230 "test", 231 "test", 232 "test", 233 "test", 234 "test", 235 "test", 236 "test", 237 "test", 238 "test", 239 "test", 240 "end", 241 "tight after", 242 "after") 243 .inOrder(); 244 } 245 246 /** Test that the microbenchmark will terminate if the battery is too low. */ 247 @Test testStopsEarly_ifBatteryLevelIsBelowThreshold()248 public void testStopsEarly_ifBatteryLevelIsBelowThreshold() throws InitializationError { 249 Bundle args = new Bundle(); 250 args.putString(Microbenchmark.MIN_BATTERY_LEVEL_OPTION, "50"); 251 args.putString(Microbenchmark.MAX_BATTERY_DRAIN_OPTION, "20"); 252 Microbenchmark runner = Mockito.spy(new Microbenchmark(LoggingTest.class, args)); 253 doReturn(49).when(runner).getBatteryLevel(); 254 255 RunNotifier notifier = Mockito.mock(RunNotifier.class); 256 runner.run(notifier); 257 258 ArgumentCaptor<Failure> failureCaptor = ArgumentCaptor.forClass(Failure.class); 259 verify(notifier).fireTestFailure(failureCaptor.capture()); 260 261 Failure failure = failureCaptor.getValue(); 262 Throwable throwable = failure.getException(); 263 assertTrue( 264 String.format( 265 "Exception was not a TerminateEarlyException. Instead, it was: %s", 266 throwable.getClass()), 267 throwable instanceof TerminateEarlyException); 268 assertThat(throwable) 269 .hasMessageThat() 270 .matches("Terminating early.*battery level.*threshold."); 271 } 272 273 /** Test that the microbenchmark will terminate if the battery is too low. */ 274 @Test testStopsEarly_ifBatteryDrainIsAboveThreshold()275 public void testStopsEarly_ifBatteryDrainIsAboveThreshold() throws InitializationError { 276 Bundle args = new Bundle(); 277 args.putString(Microbenchmark.MIN_BATTERY_LEVEL_OPTION, "40"); 278 args.putString(Microbenchmark.MAX_BATTERY_DRAIN_OPTION, "20"); 279 Microbenchmark runner = Mockito.spy(new Microbenchmark(LoggingTest.class, args)); 280 doReturn(80).doReturn(50).when(runner).getBatteryLevel(); 281 282 RunNotifier notifier = Mockito.mock(RunNotifier.class); 283 runner.run(notifier); 284 285 ArgumentCaptor<Failure> failureCaptor = ArgumentCaptor.forClass(Failure.class); 286 verify(notifier).fireTestFailure(failureCaptor.capture()); 287 288 Failure failure = failureCaptor.getValue(); 289 Throwable throwable = failure.getException(); 290 assertTrue( 291 String.format( 292 "Exception was not a TerminateEarlyException. Instead, it was: %s", 293 throwable.getClass()), 294 throwable instanceof TerminateEarlyException); 295 assertThat(throwable) 296 .hasMessageThat() 297 .matches("Terminating early.*battery drain.*threshold."); 298 } 299 300 /** Test that the microbenchmark will align starting with the battery charge counter. */ 301 @Test testAlignWithBatteryChargeCounter()302 public void testAlignWithBatteryChargeCounter() throws InitializationError { 303 Bundle args = new Bundle(); 304 args.putString("align-with-charge-counter", "true"); 305 args.putString("counter-decrement-timeout_ms", "5000"); 306 307 Microbenchmark runner = Mockito.spy(new Microbenchmark(LoggingTest.class, args)); 308 doReturn(99999) 309 .doReturn(99999) 310 .doReturn(99999) 311 .doReturn(88888) 312 .when(runner) 313 .getBatteryChargeCounter(); 314 doReturn(10L).when(runner).getCounterPollingInterval(); 315 316 RunNotifier notifier = Mockito.mock(RunNotifier.class); 317 318 Thread thread = 319 new Thread( 320 new Runnable() { 321 public void run() { 322 runner.run(notifier); 323 } 324 }); 325 326 thread.start(); 327 SystemClock.sleep(20); 328 verify(notifier, never()).fireTestStarted(any(Description.class)); 329 SystemClock.sleep(20); 330 verify(notifier).fireTestStarted(any(Description.class)); 331 } 332 333 /** Test that the microbenchmark counter alignment will time out if there's no change. */ 334 @Test testAlignWithBatteryChargeCounter_timesOut()335 public void testAlignWithBatteryChargeCounter_timesOut() throws InitializationError { 336 Bundle args = new Bundle(); 337 args.putString("align-with-charge-counter", "true"); 338 args.putString("counter-decrement-timeout_ms", "30"); 339 340 Microbenchmark runner = Mockito.spy(new Microbenchmark(LoggingTest.class, args)); 341 doReturn(99999).when(runner).getBatteryChargeCounter(); 342 doReturn(10L).when(runner).getCounterPollingInterval(); 343 344 RunNotifier notifier = Mockito.mock(RunNotifier.class); 345 346 Thread thread = 347 new Thread( 348 new Runnable() { 349 public void run() { 350 runner.run(notifier); 351 } 352 }); 353 354 thread.start(); 355 SystemClock.sleep(20); 356 verify(notifier, never()).fireTestStarted(any(Description.class)); 357 SystemClock.sleep(30); 358 verify(notifier).fireTestStarted(any(Description.class)); 359 } 360 361 /** 362 * Test successive iteration will not be executed when the terminate on test fail 363 * option is enabled. 364 */ 365 @Test testTerminateOnTestFailOptionEnabled()366 public void testTerminateOnTestFailOptionEnabled() throws InitializationError { 367 Bundle args = new Bundle(); 368 args.putString("iterations", "2"); 369 args.putString("rename-iterations", "false"); 370 args.putString("terminate-on-test-fail", "true"); 371 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark( 372 LoggingFailedTest.class, args); 373 loggingRunner.setOperationLog(new ArrayList<String>()); 374 Result result = new JUnitCore().run(loggingRunner); 375 assertThat(result.wasSuccessful()).isFalse(); 376 assertThat(loggingRunner.getOperationLog()) 377 .containsExactly( 378 "before", 379 "tight before", 380 "begin: testMethod(" 381 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 382 + "$LoggingFailedTest)", 383 "end", 384 "after") 385 .inOrder(); 386 } 387 388 /** 389 * Test successive iteration will be executed when the terminate on test fail 390 * option is disabled. 391 */ 392 @Test testTerminateOnTestFailOptionDisabled()393 public void testTerminateOnTestFailOptionDisabled() throws InitializationError { 394 Bundle args = new Bundle(); 395 args.putString("iterations", "2"); 396 args.putString("rename-iterations", "false"); 397 args.putString("terminate-on-test-fail", "false"); 398 LoggingMicrobenchmark loggingRunner = new LoggingMicrobenchmark( 399 LoggingFailedTest.class, args); 400 loggingRunner.setOperationLog(new ArrayList<String>()); 401 Result result = new JUnitCore().run(loggingRunner); 402 assertThat(result.wasSuccessful()).isFalse(); 403 assertThat(loggingRunner.getOperationLog()) 404 .containsExactly( 405 "before", 406 "tight before", 407 "begin: testMethod(" 408 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 409 + "$LoggingFailedTest)", 410 "end", 411 "after", 412 "before", 413 "tight before", 414 "begin: testMethod(" 415 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 416 + "$LoggingFailedTest)", 417 "end", 418 "after") 419 .inOrder(); 420 } 421 422 /** Test dynamic test rule injection. */ 423 @Test testDynamicTestRuleInjection()424 public void testDynamicTestRuleInjection() throws InitializationError { 425 Bundle args = new Bundle(); 426 args.putString("iterations", "2"); 427 args.putString("rename-iterations", "false"); 428 args.putString("terminate-on-test-fail", "false"); 429 args.putString( 430 Microbenchmark.DYNAMIC_INNER_TEST_RULES_OPTION, LoggingRule1.class.getName()); 431 args.putString( 432 Microbenchmark.DYNAMIC_OUTER_TEST_RULES_OPTION, LoggingRule2.class.getName()); 433 LoggingMicrobenchmark loggingRunner = 434 new LoggingMicrobenchmark(LoggingTestWithRules.class, args); 435 loggingRunner.setOperationLog(sLogs); 436 new JUnitCore().run(loggingRunner); 437 assertThat(sLogs) 438 .containsExactly( 439 "hardcoded class rule starting", 440 "logging rule 2 starting", 441 "hardcoded test rule starting", 442 "logging rule 1 starting", 443 "before", 444 "tight before", 445 "begin: testMethod(" 446 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 447 + "$LoggingTestWithRules)", 448 "test", 449 "end", 450 "tight after", 451 "after", 452 "logging rule 1 finished", 453 "hardcoded test rule finished", 454 "logging rule 2 finished", 455 "logging rule 2 starting", 456 "hardcoded test rule starting", 457 "logging rule 1 starting", 458 "before", 459 "tight before", 460 "begin: testMethod(" 461 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 462 + "$LoggingTestWithRules)", 463 "test", 464 "end", 465 "tight after", 466 "after", 467 "logging rule 1 finished", 468 "hardcoded test rule finished", 469 "logging rule 2 finished", 470 "hardcoded class rule finished") 471 .inOrder(); 472 } 473 474 /** Test dynamic class rule injection. */ 475 @Test testDynamicClassRuleInjection()476 public void testDynamicClassRuleInjection() throws InitializationError { 477 Bundle args = new Bundle(); 478 args.putString("iterations", "2"); 479 args.putString("rename-iterations", "false"); 480 args.putString("terminate-on-test-fail", "false"); 481 args.putString( 482 Microbenchmark.DYNAMIC_INNER_CLASS_RULES_OPTION, LoggingRule1.class.getName()); 483 args.putString( 484 Microbenchmark.DYNAMIC_OUTER_CLASS_RULES_OPTION, LoggingRule2.class.getName()); 485 LoggingMicrobenchmark loggingRunner = 486 new LoggingMicrobenchmark(LoggingTestWithRules.class, args); 487 loggingRunner.setOperationLog(sLogs); 488 new JUnitCore().run(loggingRunner); 489 assertThat(sLogs) 490 .containsExactly( 491 "logging rule 2 starting", 492 "hardcoded class rule starting", 493 "logging rule 1 starting", 494 "hardcoded test rule starting", 495 "before", 496 "tight before", 497 "begin: testMethod(" 498 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 499 + "$LoggingTestWithRules)", 500 "test", 501 "end", 502 "tight after", 503 "after", 504 "hardcoded test rule finished", 505 "hardcoded test rule starting", 506 "before", 507 "tight before", 508 "begin: testMethod(" 509 + "android.platform.test.microbenchmark.MicrobenchmarkTest" 510 + "$LoggingTestWithRules)", 511 "test", 512 "end", 513 "tight after", 514 "after", 515 "hardcoded test rule finished", 516 "logging rule 1 finished", 517 "hardcoded class rule finished", 518 "logging rule 2 finished") 519 .inOrder(); 520 } 521 522 /** 523 * An extensions of the {@link Microbenchmark} runner that logs the start and end of collecting 524 * traces. It also passes the operation log to the provided test {@code Class}, if it is a 525 * {@link LoggingTest}. This is used for ensuring the proper order for evaluating test {@link 526 * Statement}s. 527 */ 528 public static class LoggingMicrobenchmark extends Microbenchmark { 529 private List<String> mOperationLog; 530 LoggingMicrobenchmark(Class<?> klass)531 public LoggingMicrobenchmark(Class<?> klass) throws InitializationError { 532 super(klass); 533 } 534 LoggingMicrobenchmark(Class<?> klass, Bundle arguments)535 LoggingMicrobenchmark(Class<?> klass, Bundle arguments) throws InitializationError { 536 super(klass, arguments); 537 } 538 createTest()539 protected Object createTest() throws Exception { 540 Object test = super.createTest(); 541 if (test instanceof LoggingTest) { 542 ((LoggingTest)test).setOperationLog(mOperationLog); 543 } 544 return test; 545 } 546 setOperationLog(List<String> log)547 void setOperationLog(List<String> log) { 548 mOperationLog = log; 549 } 550 getOperationLog()551 List<String> getOperationLog() { 552 return mOperationLog; 553 } 554 555 @Override getTracePointRule()556 protected TracePointRule getTracePointRule() { 557 return new LoggingTracePointRule(); 558 } 559 560 class LoggingTracePointRule extends TracePointRule { 561 @Override beginSection(String sectionTag)562 protected void beginSection(String sectionTag) { 563 mOperationLog.add(String.format("begin: %s", sectionTag)); 564 } 565 566 @Override endSection()567 protected void endSection() { 568 mOperationLog.add("end"); 569 } 570 } 571 } 572 573 /** 574 * A test that logs {@link Before}, {@link After}, {@link Test}, and the logging {@link 575 * TightMethodRule} included, used in conjunction with {@link LoggingMicrobenchmark} to 576 * determine all {@link Statement}s are evaluated in the proper order. 577 */ 578 public static class LoggingTest { 579 @Microbenchmark.TightMethodRule 580 public TightRule orderRule = new TightRule(); 581 582 private List<String> mOperationLog; 583 setOperationLog(List<String> log)584 void setOperationLog(List<String> log) { 585 mOperationLog = log; 586 } 587 588 @Before beforeMethod()589 public void beforeMethod() { 590 mOperationLog.add("before"); 591 } 592 593 @Test testMethod()594 public void testMethod() { 595 mOperationLog.add("test"); 596 } 597 598 @After afterMethod()599 public void afterMethod() { 600 mOperationLog.add("after"); 601 } 602 603 class TightRule implements TestRule { 604 @Override apply(Statement base, Description description)605 public Statement apply(Statement base, Description description) { 606 return new Statement() { 607 @Override 608 public void evaluate() throws Throwable { 609 mOperationLog.add("tight before"); 610 base.evaluate(); 611 mOperationLog.add("tight after"); 612 } 613 }; 614 } 615 } 616 } 617 618 public static class LoggingTestWithRules extends LoggingTest { 619 @ClassRule 620 public static TestRule hardCodedClassRule = 621 new TestWatcher() { 622 @Override 623 public void starting(Description description) { 624 sLogs.add("hardcoded class rule starting"); 625 } 626 627 @Override 628 public void finished(Description description) { 629 sLogs.add("hardcoded class rule finished"); 630 } 631 }; 632 633 @Rule 634 public TestRule hardCodedRule = 635 new TestWatcher() { 636 @Override 637 public void starting(Description description) { 638 sLogs.add("hardcoded test rule starting"); 639 } 640 641 @Override 642 public void finished(Description description) { 643 sLogs.add("hardcoded test rule finished"); 644 } 645 }; 646 } 647 648 public static class LoggingFailedTest extends LoggingTest { 649 @Test 650 public void testMethod() { 651 throw new RuntimeException("I failed."); 652 } 653 } 654 655 public static class LoggingRule1 extends TestWatcher { 656 @Override 657 public void starting(Description description) { 658 sLogs.add("logging rule 1 starting"); 659 } 660 661 @Override 662 public void finished(Description description) { 663 sLogs.add("logging rule 1 finished"); 664 } 665 } 666 667 public static class LoggingRule2 extends TestWatcher { 668 @Override 669 public void starting(Description description) { 670 sLogs.add("logging rule 2 starting"); 671 } 672 673 @Override 674 public void finished(Description description) { 675 sLogs.add("logging rule 2 finished"); 676 } 677 } 678 } 679