Small improvement: If the test is _repeated_, report only the average…

… duration (unless, debug enabled, then report also all individual ones)

vpro-shared-test/src/main/java/nl/vpro/test/jupiter/TimingExtension.java

@@ -1,14 +1,20 @@
 package nl.vpro.test.jupiter;
 
 import lombok.extern.log4j.Log4j2;
-import org.junit.jupiter.api.extension.*;
-import org.opentest4j.TestAbortedException;
 
 import java.time.Duration;
 import java.time.temporal.ChronoUnit;
 import java.util.*;
 import java.util.concurrent.atomic.AtomicInteger;
 
+import org.junit.jupiter.api.RepeatedTest;
+import org.junit.jupiter.api.extension.*;
+import org.meeuw.math.statistics.StatisticalLong;
+import org.meeuw.math.temporal.UncertainTemporal;
+import org.opentest4j.TestAbortedException;
+
+import nl.vpro.logging.Log4j2Helper;
+
 
 /**
  * Simple extension that times every individual test in the class.
@@ -26,27 +32,45 @@ public class TimingExtension implements
     private static final String START_All_TIME = "ALL";
     private static final String START_TIMES = "START_TIMES";
     private static final String DURATIONS = "DURATIONS";
+    private static final String REPETITIONS = "REPETITIONS";
+
 
 
     @Override
     public void beforeTestExecution(ExtensionContext context) throws Exception {
-        getStore(context).get(START_TIMES, Map.class).put(getKey(context), System.nanoTime());
+        ExtensionContext.Store store = getStore(context);
+        store.get(START_TIMES, Map.class).put(getKey(context), System.nanoTime());
     }
 
     @Override
     public void afterTestExecution(ExtensionContext context) throws Exception {
         ExtensionContext.Store store = getStore(context);
+        Optional<RepeatedTest> repeated = isRepeatedTest(context);
         if (context.getExecutionException().isPresent()) {
             if (context.getExecutionException().get() instanceof TestAbortedException) {
                 log.debug("Ignored aborted test");
                 return;
             }
         }
+
         String key = getKey(context);
+
         long startTime = (long) store.get(START_TIMES, Map.class).remove(key);
         Duration duration = Duration.ofNanos(System.nanoTime() - startTime);
-        store.get(DURATIONS, Map.class).put(key, duration);
-        log.info("{} took {}", key, duration.truncatedTo(ChronoUnit.MILLIS));
+
+        if (repeated.isEmpty() || log.isDebugEnabled()) {
+            Map<String, Object> durationsMap = store.get(DURATIONS, Map.class);
+            durationsMap.put(key, duration);
+        }
+        repeated.ifPresent(annotation -> {
+            String rk = getRepetitionKey(context, annotation);
+            Map<String, Object> repetitionsMap = store.get(REPETITIONS, Map.class);
+
+            StatisticalLong statisticalLong = (StatisticalLong) repetitionsMap.computeIfAbsent(rk, (kk) -> new StatisticalLong(UncertainTemporal.Mode.DURATION));
+            statisticalLong.enter(duration);
+        });
+
+        Log4j2Helper.debugOrInfo(log, repeated.isEmpty(), "{} took {}", key, duration.truncatedTo(ChronoUnit.MILLIS));
     }
 
     @Override
@@ -55,7 +79,8 @@ public void beforeAll(ExtensionContext context) throws Exception {
         store.put(START_All_TIME, System.nanoTime());
         store.put(START_TIMES, Collections.synchronizedMap(new HashMap<>()));
         store.put(DURATIONS, Collections.synchronizedMap(new HashMap<>()));
-        getStore(context).put(START_All_TIME, System.nanoTime());
+        store.put(REPETITIONS, Collections.synchronizedMap(new HashMap<>()));
+
     }
 
     @Override
@@ -64,6 +89,14 @@ public void afterAll(ExtensionContext context) throws Exception {
         long startTime = store.remove(START_All_TIME, long.class);
         Duration duration = Duration.ofNanos(System.nanoTime() - startTime);
         Map<String, Duration> durations = store.get(DURATIONS, Map.class);
+        Map<String, Long> startTimes = store.get(START_TIMES, Map.class);
+
+
+        Map<String, StatisticalLong> repetitions = store.get(REPETITIONS, Map.class);
+        for (Map.Entry<String , StatisticalLong> e: repetitions.entrySet()) {
+            log.info("{}x:\t{}: {}", e.getValue().getCount(), e.getValue().durationValue(), e.getKey());
+            durations.put(e.getKey(), e.getValue().durationValue());
+        }
 
         log.info("All {} took {}.", context.getRequiredTestClass(), duration.truncatedTo(ChronoUnit.SECONDS));
         AtomicInteger number = new AtomicInteger(0);
@@ -76,12 +109,24 @@ public void afterAll(ExtensionContext context) throws Exception {
     }
 
 
+
     private ExtensionContext.Store getStore(ExtensionContext context) {
         return context.getStore(ExtensionContext.Namespace.create(context.getRequiredTestClass(), TimingExtension.class));
     }
 
     private String getKey(ExtensionContext context) {
         return context.getDisplayName();
     }
+    private String getRepetitionKey(ExtensionContext context, RepeatedTest repeatedTest) {
+        return "average(" + context.getRequiredTestMethod().getName() + " " + repeatedTest.name() + ")";
+    }
+
+
+    protected Optional<RepeatedTest> isRepeatedTest(ExtensionContext context)  {
+        return context.getTestMethod()
+            .map(m -> m.getAnnotation(RepeatedTest.class))
+            .filter(Objects::nonNull);
+
+    }
 }
 

vpro-shared-test/src/test/java/nl/vpro/test/jupiter/TimingExtensionTest.java

@@ -0,0 +1,16 @@
+package nl.vpro.test.jupiter;
+
+import org.junit.jupiter.api.RepeatedTest;
+import org.junit.jupiter.api.extension.ExtendWith;
+
+import static java.lang.Thread.sleep;
+
+@ExtendWith(TimingExtension.class)
+class TimingExtensionTest {
+
+    @RepeatedTest(10)
+    public void test() throws InterruptedException {
+        sleep(10);
+    }
+
+}

vpro-shared-test/src/test/resources/log4j2.xml

@@ -6,7 +6,7 @@
     </Console>
   </Appenders>
   <Loggers>
-    <Root level="DEBUG">
+    <Root level="INFO">
       <Appender-Ref ref="stdout" />
     </Root>
   </Loggers>