diff --git a/vpro-shared-test/src/main/java/nl/vpro/test/jupiter/TimingExtension.java b/vpro-shared-test/src/main/java/nl/vpro/test/jupiter/TimingExtension.java index 261d1e54d..ae53bb9af 100644 --- a/vpro-shared-test/src/main/java/nl/vpro/test/jupiter/TimingExtension.java +++ b/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 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 durationsMap = store.get(DURATIONS, Map.class); + durationsMap.put(key, duration); + } + repeated.ifPresent(annotation -> { + String rk = getRepetitionKey(context, annotation); + Map 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 durations = store.get(DURATIONS, Map.class); + Map startTimes = store.get(START_TIMES, Map.class); + + + Map repetitions = store.get(REPETITIONS, Map.class); + for (Map.Entry 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,6 +109,7 @@ public void afterAll(ExtensionContext context) throws Exception { } + private ExtensionContext.Store getStore(ExtensionContext context) { return context.getStore(ExtensionContext.Namespace.create(context.getRequiredTestClass(), TimingExtension.class)); } @@ -83,5 +117,16 @@ private ExtensionContext.Store getStore(ExtensionContext context) { private String getKey(ExtensionContext context) { return context.getDisplayName(); } + private String getRepetitionKey(ExtensionContext context, RepeatedTest repeatedTest) { + return "average(" + context.getRequiredTestMethod().getName() + " " + repeatedTest.name() + ")"; + } + + + protected Optional isRepeatedTest(ExtensionContext context) { + return context.getTestMethod() + .map(m -> m.getAnnotation(RepeatedTest.class)) + .filter(Objects::nonNull); + + } } diff --git a/vpro-shared-test/src/test/java/nl/vpro/test/jupiter/TimingExtensionTest.java b/vpro-shared-test/src/test/java/nl/vpro/test/jupiter/TimingExtensionTest.java new file mode 100644 index 000000000..566799e52 --- /dev/null +++ b/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); + } + +} diff --git a/vpro-shared-test/src/test/resources/log4j2.xml b/vpro-shared-test/src/test/resources/log4j2.xml index d1fb6f74e..f431e2b57 100644 --- a/vpro-shared-test/src/test/resources/log4j2.xml +++ b/vpro-shared-test/src/test/resources/log4j2.xml @@ -6,7 +6,7 @@ - +