3

JUnit looks like it's including the time taken to perform @BeforeClass @Before when it reports my test timing.

I'm using JUnit 4.12

junit timing

In this case it shows 23.863 seconds against the test and 25.649 total. When I manually instrument all the methods, this is the breakdown:

10:11:20.074 [INFO] [mainId] beforeClass completed in 12516ms
10:11:40.083 [INFO] [mainId] beforeTest completed in 20009ms
10:11:44.171 [INFO] [mainId] start_test completed in 4076ms 

So if I add beforeTest and start_test timing I get close to the time reported in the UI.

  • Is there a way to tell JUnit to only display the start_test time?

Right now I just manually output the timing like in this post: https://stackoverflow.com/a/180191/1165140

UPDATE 2017-07-27 Actually problem is with before test methods (@Before) not @BeforeClass as I previously thought - error in my logging. Still in my view it should be configurable whether this time is included. I'm using @beforetest to setup data before each test.

I've confirmed that the inflated time is outputted in the UI as well as the maven surefire XML output from the command line.

Avner
  • 4,286
  • 2
  • 35
  • 42
  • 1
    According to the javadoc junit.sourceforge.net/javadoc/org/junit/runner/notification/‌​… testStarted() is called when each @ Test is about to be called and testFinished() is called when each @ Test has finished whether it passed or failed. How about this? – anshul Gupta Jul 21 '17 at 14:40
  • As an example see this https://tenpercentnotcrap.wordpress.com/2016/04/24/junit-test-report-sorted-by-run-time/ – anshul Gupta Jul 21 '17 at 14:44
  • thanks for this suggestion @ansh . I will try it out. – Avner Jul 24 '17 at 04:31
  • I tried using the RunListener, but the times still include the beforeTest time. Internally it must call testStarted when beforeTest starts. – Avner Jul 25 '17 at 01:12

1 Answers1

0
public static class StopwatchTest {
     private static final Logger logger = Logger.getLogger("");

     private static void logInfo(Description description, String status, long nanos) {
         String testName = description.getMethodName();
         logger.info(String.format("Test %s %s, spent %d microseconds",
                                   testName, status, TimeUnit.NANOSECONDS.toMicros(nanos)));
     }

     @Rule
     public Stopwatch stopwatch = new Stopwatch() {
         @Override
         protected void succeeded(long nanos, Description description) {
             logInfo(description, "succeeded", nanos);
         }

         @Override
         protected void failed(long nanos, Throwable e, Description description) {
             logInfo(description, "failed", nanos);
         }

         @Override
         protected void skipped(long nanos, AssumptionViolatedException e, Description description) {
             logInfo(description, "skipped", nanos);
         }

         @Override
         protected void finished(long nanos, Description description) {
             logInfo(description, "finished", nanos);
         }
     };

     @Test
     public void succeeds() {
     }

     @Test
     public void fails() {
         fail();
     }

     @Test
     public void skips() {
         assumeTrue(false);
     }
 }

Taken from Stopwatch

Abhijit Sarkar
  • 21,927
  • 20
  • 110
  • 219
  • Thanks, but this outputs to a logger as far as I can tell, which I already have (though this is neater). Unless it shows these timings in the UI as well? – Avner Jul 21 '17 at 00:54
  • @avvi who cares what shows in the UI? Do you send your computer to the managers when they ask for a test report? – Abhijit Sarkar Jul 21 '17 at 00:55
  • Actually, I care what shows up in the UI when I'm unit testing locally. This leads to a second question, what timings will the Junit.xml report show? – Avner Jul 21 '17 at 01:00