Skip to content

Commit

Permalink
Refactor and better document Stopwatch extension
Browse files Browse the repository at this point in the history
  • Loading branch information
Nicolai Parlog committed May 26, 2022
1 parent a1d0d19 commit 3ea07ee
Show file tree
Hide file tree
Showing 4 changed files with 63 additions and 29 deletions.
36 changes: 29 additions & 7 deletions docs/stopwatch.adoc
Expand Up @@ -3,18 +3,40 @@
:xp-demo-dir: ../src/demo/java
:demo: {xp-demo-dir}/org/junitpioneer/jupiter/StopwatchExtensionDemo.java

== Introduction

Test shall be fast.
To get a feeling how fast or slow a specific test is, the `@Stopwatch` annotation can be used.
It will measure elapsed time and pass the result to the `https://junit.org/junit5/docs/current/api/org.junit.jupiter.api/org/junit/jupiter/api/TestReporter.html[TestReporter]`, which will publish it.
Annotating a test with `@Stopwatch` will measure the time it takes to execute and report the result to the `https://junit.org/junit5/docs/current/api/org.junit.jupiter.api/org/junit/jupiter/api/TestReporter.html[TestReporter]`.
How that information is displayed depends on the tool used to run the tests and how it processes test report entries.

== Usage

To measure elapsed time just add the `@Stopwatch` annotation to a class or, like in the following example, to a method:
`@Stopwatch` can be applied to a method to report its execution time:

[source,java,indent=0]
----
include::{demo}[tag=method]
----

It can also be applied to a class, in which case it reports the execution times of each test as if it were applied to each method individually:

[source,java,indent=0]
----
include::{demo}[tag=stopwatch_demo]
include::{demo}[tag=class]
----

It can also be applied to a class and a method therein but since a class-level annotation already works as if each method was annotated, the method-level annotations would be redundant.

== Output

This is how IntelliJ displays a report entry (in the Run/Debug panel):

----
timestamp = 2022-05-26T12:16:14.021646, StopwatchExtension = Execution of 'test()' took [11] ms.
----

Other tools may or may not print report entries.

The most reliable way to gather entries is to create a https://junit.org/junit5/docs/current/api/org.junit.platform.launcher/org/junit/platform/launcher/TestExecutionListener.html[`TestExecutionListener`] and register it with the launcher.
https://junit.org/junit5/docs/current/api/org.junit.platform.engine/org/junit/platform/engine/reporting/ReportEntry.html[Report entries] from the stopwatch extension can be identified by checking their https://junit.org/junit5/docs/current/api/org.junit.platform.engine/org/junit/platform/engine/reporting/ReportEntry.html#getKeyValuePairs()[key-value pairs] - at least one key will start with the string `"StopwatchExtension"`.

== Thread-Safety

This extension is safe to use during https://junit.org/junit5/docs/current/user-guide/#writing-tests-parallel-execution[parallel test execution].
26 changes: 22 additions & 4 deletions src/demo/java/org/junitpioneer/jupiter/StopwatchExtensionDemo.java
Expand Up @@ -14,12 +14,30 @@

public class StopwatchExtensionDemo {

// tag::stopwatch_demo[]
@Stopwatch
// tag::method[]
@Test
@Stopwatch
void test() {
// Some test
// execution time will be reported
}
// end::method[]

// tag::class[]
@Stopwatch
class TestCases {

@Test
void test_1() {
// execution time will be reported
}

@Test
void test_s() {
// execution time will be reported
}

}
// end::class[]


// end::stopwatch_demo[]
}
21 changes: 3 additions & 18 deletions src/main/java/org/junitpioneer/jupiter/StopwatchExtension.java
Expand Up @@ -36,30 +36,15 @@ public void afterTestExecution(ExtensionContext context) {
calculateAndReportElapsedTime(context);
}

/**
* Stores the current time for the method in the execution context.
*
* @param context Extension context of the class
*/
void storeNowAsLaunchTime(ExtensionContext context) {
private void storeNowAsLaunchTime(ExtensionContext context) {
context.getStore(NAMESPACE).put(context.getUniqueId(), clock.instant().toEpochMilli());
}

/**
* Loads the stored time for method from the execution context.
*
* @param context Extension context of the class
*/
long loadLaunchTime(ExtensionContext context) {
private long loadLaunchTime(ExtensionContext context) {
return context.getStore(NAMESPACE).get(context.getUniqueId(), long.class);
}

/**
* Calculates the elapsed time method and publishes it to the execution context.
*
* @param context Extension context of the class
*/
void calculateAndReportElapsedTime(ExtensionContext context) {
private void calculateAndReportElapsedTime(ExtensionContext context) {
long launchTime = loadLaunchTime(context);
long elapsedTime = clock.instant().toEpochMilli() - launchTime;

Expand Down
Expand Up @@ -12,6 +12,7 @@

import static org.junitpioneer.testkit.assertion.PioneerAssert.assertThat;

import org.assertj.core.api.Assertions;
import org.junit.jupiter.api.DisplayName;
import org.junit.jupiter.api.Test;
import org.junitpioneer.testkit.ExecutionResults;
Expand Down Expand Up @@ -61,6 +62,14 @@ void runAnnotationTest() {
assertThat(results).hasNumberOfReportEntries(0);
}

@Test
@DisplayName("should not change the report entry key")
void verifyReportEntryKey() {
// the store key is mentioned in the documentation and changing it would break
// `TestExecutionListener` implementations that use it to filter stopwatch report entries
Assertions.assertThat(StopwatchExtension.STORE_KEY).startsWith("StopwatchExtension");
}

private void assertStringStartWithUnitAndContainsName(ExecutionResults results, String methodName) {
ReportEntryContentAssert reportEntry = assertThat(results).hasNumberOfReportEntries(1);
reportEntry.firstValue().matches(String.format("Execution of '%s\\(\\)' took \\[[0-9]*\\] ms.", methodName));
Expand Down

0 comments on commit 3ea07ee

Please sign in to comment.