feat(test): reporting time spent to create context and perform each test

Closes: #79

Author: nergal-perm

src/main/java/ru/ewc/checklogic/testing/CheckFile.java

@@ -75,17 +75,28 @@ public List<TestResult> performChecks(final String root, final CheckSuite files)
         this.suite = files;
         return this.tests.stream()
             .filter(rule -> rule.getFragments().stream().anyMatch(f -> f.nonEmptyOfType("CND")))
-            .map(rule -> this.getTestResult(rule, ServerContextFactory.create(root).context()))
-            .toList();
+            .map(
+                rule -> {
+                    final long start = System.currentTimeMillis();
+                    final ComputationContext context = ServerContextFactory.create(root).context();
+                    final long elapsed = System.currentTimeMillis() - start;
+                    return this.getTestResult(rule, context, elapsed);
+                }
+            ).toList();
     }
 
     public void performInSameContext(final ComputationContext ctx, final CheckSuite files) {
         this.suite = files;
-        this.getTestResult(this.tests.getFirst(), ctx);
+        this.getTestResult(this.tests.getFirst(), ctx, 0);
     }
 
-    private TestResult getTestResult(final RuleFragments rule, final ComputationContext ctx) {
+    private TestResult getTestResult(
+        final RuleFragments rule,
+        final ComputationContext ctx,
+        final long time
+    ) {
         logCheckpoint(ctx, "%s - started".formatted(rule.header()));
+        final long start = System.currentTimeMillis();
         final OutputTracker<String> tracker = ctx.startTracking();
         final List<CheckFailure> failures = new ArrayList<>(1);
         for (final RuleFragment fragment : rule.getFragments()) {
@@ -112,11 +123,14 @@ private TestResult getTestResult(final RuleFragments rule, final ComputationCont
             }
         }
         logCheckpoint(ctx, "%s - %s".formatted(rule.header(), CheckFile.desc(failures)));
+        final long elapsed = System.currentTimeMillis() - start;
         return new TestResult(
             rule.header().replace("::", " - "),
             failures.isEmpty(),
             resultAsUnorderedList(failures),
-            tracker.events()
+            tracker.events(),
+            time,
+            elapsed
         );
     }
 

src/main/java/ru/ewc/checklogic/testing/CheckSuite.java

@@ -55,31 +55,43 @@ public final class CheckSuite {
      */
     private final String root;
 
-    private CheckSuite(final Collection<CheckFile> tests, final String root) {
+    /**
+     * Milliseconds elapsed to read all the test files.
+     */
+    private final long reading;
+
+    private CheckSuite(final Collection<CheckFile> tests, final String root, final long reading) {
         this.tests = tests;
         this.results = new ArrayList<>(tests.size());
         this.root = root;
+        this.reading = reading;
     }
 
     public static CheckSuite using(
         final ContentsReader reader,
         final String root,
         final String request
     ) {
-        return new CheckSuite(
-            reader.readAll().stream()
-                .map(sl -> new CheckFile(sl.fileName(), sl.specifiedRulesFragments(), request))
-                .toList(),
-            root
-        );
+        final long start = System.currentTimeMillis();
+        final List<CheckFile> files = reader.readAll().stream()
+            .map(sl -> new CheckFile(sl.fileName(), sl.specifiedRulesFragments(), request))
+            .toList();
+        final long elapsed = System.currentTimeMillis() - start;
+        return new CheckSuite(files, root, elapsed);
     }
 
     public String statsAsHtmlDiv(final double elapsed) {
-        return "%d test(s) performed in %.3f second(s), %d passed, %d failed".formatted(
+        return """
+            %d test(s) performed in %.3f second(s) (read time: %.3f), %d passed, %d failed</br>
+            %d milliseconds spent creating context, %d milliseconds spent in the tests
+            """.formatted(
             this.results.size(),
             elapsed,
+            this.reading / 1000.0,
             this.results.stream().filter(TestResult::successful).count(),
-            this.results.stream().filter(result -> !result.successful()).count()
+            this.results.stream().filter(result -> !result.successful()).count(),
+            this.results.stream().reduce(0L, (acc, result) -> acc + result.context(), Long::sum),
+            this.results.stream().reduce(0L, (acc, result) -> acc + result.elapsed(), Long::sum)
         );
     }
 

src/main/java/ru/ewc/checklogic/testing/TestResult.java

@@ -29,7 +29,9 @@ public record TestResult(
     String file,
     boolean successful,
     String error,
-    List<String> log
+    List<String> log,
+    long context,
+    long elapsed
 ) implements Comparable<TestResult> {
 
     public String result() {
@@ -44,14 +46,19 @@ public String result() {
 
     public String asHtmlTableRow() {
         return String.format(
-            "<tr class=\"%s\"><td>%s</td><td>%s</td><td>%s</td></tr>",
+            "<tr class=\"%s\"><td>%s</td><td>%s</td><td>%s</td><td>%s</td></tr>",
             this.classBasedOnSuccess(),
             this.file,
             this.result(),
+            this.time(),
             this.errorMessages()
         );
     }
 
+    private String time() {
+        return "C: %d ms, T: %d ms".formatted(this.context, this.elapsed);
+    }
+
     private String errorMessages() {
         final String result;
         if (this.successful) {

src/main/resources/templates/test.html

@@ -28,6 +28,7 @@ <h1>Test results</h1>
         <tr>
             <th scope="col">Test</th>
             <th scope="col">Result</th>
+            <th scope="col">Duration</th>
             <th scope="col">Message</th>
         </tr>
     </thead>