What is the best practice to determine the execution time of the business relevant code of my junit?

Question

The test execution time which is displayed in eclipse->junit-view depends on the whole test case execution which includes:

• Testdata preperation
• Executing businesslogic
• assert results

I need a more detailed statement about the execution time of my businesslogic and only my businesslogic. That is what I have done inside my testcase:

Date lNow = new Date();
List<Geo> lAllBasisGeo = mGeoEvaluator.evaluateAllGeo(lGeoFixture.getGeo(), lAllGeo);
Date lStop = new Date();
System.out.println("Time of execution in seconds:"+((lStop.getTime()-lNow.getTime())/1000));

Well... I think I determine the time in a realy awkward way. Furthermore I dont think that it is necessary to declare two Date variables.

I need advice writing that code more efficiently...

Answer 1

in a unit test I would prefer to add a timeout to the Test with a JUnit 4 annotation, to determine whether the test passes (fast enough) or not:

@Test(timeout=100)//let the test fail after 100 MilliSeconds
public void infinity() {
  while(true);
}

To determine the exact Runtime of your business logic I would add the Time statements right before and after your critical Codepath like you did, repeat it several times to get scholastically correct results, and remove the statements again, so slim the code.

long start = System.currentTimeMillis();
//execute logic in between
long end = System.currentTimeMillis();
System.out.println("DEBUG: Logic A took " + (end - start) + " MilliSeconds");

Answer 2

JUnit 4.12 introduced the Stopwatch @Rule. It is quite straigthforward to use and should become the de facto way of verifying time spent during tests. Here's a sample class showcasing its functionalities:

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);
     }

     @Test
     public void performanceTest() throws InterruptedException {
         // An example to assert runtime:
         long delta = 30;
         Thread.sleep(300L);
         assertEquals(300d, stopwatch.runtime(MILLISECONDS), delta);
         Thread.sleep(500L);
         assertEquals(800d, stopwatch.runtime(MILLISECONDS), delta);
     }
}

Answer 3

There is a very useful utility for this in the Guava library - Stopwatch.
This would allow you to write the following

import com.google.common.base.Stopwatch;

final Stopwatch stopwatch = Stopwatch.createStarted();
//dostuff
System.out.println("Time of execution in seconds:" + stopwatch.stop().elapsed(TimeUnit.SECONDS));

Answer 4

If you want to assert on specific commands and leave out the delays of the test-setup, you can use Stopwatch just for the piece of code you want to check. So if you want couple of commands to take less than 500millis:

Stopwatch stopwatch = createStarted();
firstCommandToBeTimed();
secondCommandToBeTimed();
assertThat(stopwatch.elapsed(TimeUnit.MILLISECONDS)).isLessThan(500);

Now Stopwatch is beta (in some guava versions) and you ll get some ugly intellij warnings. Also you might dont want to use 3rd party libs. In that case you can do the same by using Instant:

Instant start = Clock.systemDefaultZone().instant();
firstCommandToBeTimed();
secondCommandToBeTimed();
assertThat(start.until(Clock.systemDefaultZone().instant(), MILLIS)).isLessThan(500);

---

Final note, if you still want to use Stopwatch, but want to get ride of the warning or remove duplicated code, you can create a method for wrapping the code you want to time and annotate out the warning:

{
    assertExecutionTime(() -> {
        firstCommandToBeTimed();
        secondCommandToBeTimed();
    },  500);
}
//....
@SuppressWarnings("UnstableApiUsage")
private void assertExecutionTime(Runnable runnable, int timeoutInMillis) {
    Stopwatch stopwatch = createStarted();
    runnable.run();
    assertThat(stopwatch.elapsed(TimeUnit.MILLISECONDS)).isLessThan(timeoutInMillis);
}

(And similar approach can be taken for Instant, to remove duplication)