Print execution duration in summary

CHANGELOG.md

@@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ### Added
 - [JavaScript] Add `SummaryPrinter` ([#40](https://github.com/cucumber/pretty-formatter/pull/40))
 - [JavaScript] Add `ProgressPrinter` ([#40](https://github.com/cucumber/pretty-formatter/pull/40))
+- Print execution duration in summary ([#62](https://github.com/cucumber/pretty-formatter/pull/62))
 
 ### Changed
 - [JavaScript] BREAKING CHANGE: Expose `PrettyPrinter` rather than a high-level formatter ([#40](https://github.com/cucumber/pretty-formatter/pull/40))

java/src/main/java/io/cucumber/prettyformatter/SummaryReportWriter.java

@@ -1,5 +1,6 @@
 package io.cucumber.prettyformatter;
 
+import io.cucumber.messages.Convertor;
 import io.cucumber.messages.types.Exception;
 import io.cucumber.messages.types.Hook;
 import io.cucumber.messages.types.HookType;
@@ -102,7 +103,7 @@ private void printStats() {
         printGlobalHookCount();
         printScenarioCounts();
         printStepCounts();
-        printDuration();
+        printDurations();
     }
 
     private void printNonPassingGlobalHooks() {
@@ -317,12 +318,25 @@ private <T> String formatSubCounts(
         return joiner.toString();
     }
 
-    private void printDuration() {
+    private void printDurations() {
         query.findTestRunDuration()
-                .map(SummaryReportWriter::formatDuration)
+                .map(testRunDuration -> String.format("%s (%s executing your code)", formatDuration(testRunDuration), formatDuration(getExecutionDuration())))
                 .ifPresent(out::println);
     }
 
+    private Duration getExecutionDuration() {
+        Stream<Duration> durationsFromHooks = query.findAllTestRunHookFinished()
+                .stream()
+                .map(hookFinished -> hookFinished.getResult().getDuration())
+                .map(Convertor::toDuration);
+        Stream<Duration> durationsFromSteps = query.findAllTestStepFinished()
+                .stream()
+                .map(hookFinished -> hookFinished.getTestStepResult().getDuration())
+                .map(Convertor::toDuration);
+        return Stream.concat(durationsFromHooks, durationsFromSteps)
+                .reduce(Duration.ZERO, Duration::plus);
+    }
+
     private static String formatDuration(Duration duration) {
         long minutes = duration.toMinutes();
         long seconds = duration.minusMinutes(minutes).getSeconds();

java/src/test/java/io/cucumber/prettyformatter/MessagesToSummaryWriterTest.java

@@ -29,7 +29,7 @@ void it_writes_two_messages_to_summary() throws IOException {
         assertThat(out).isEqualToNormalizingNewlines("\n" +
                 "0 scenarios\n" +
                 "0 steps\n" +
-                "0m 20.0s\n"
+                "0m 20.0s (0m 0.0s executing your code)\n"
         );
     }
 

javascript/src/SummaryPrinter.ts

@@ -1,9 +1,8 @@
 import {
+  Duration,
   Location,
   Pickle,
   TestCaseStarted,
-  TestRunFinished,
-  TestRunStarted,
   TestStepResult,
   TestStepResultStatus,
 } from '@cucumber/messages'
@@ -13,7 +12,7 @@ import {
   ensure,
   ERROR_INDENT_LENGTH,
   formatCounts,
-  formatDuration,
+  formatDurations,
   formatForStatus,
   formatHookLocation,
   formatHookTitle,
@@ -64,7 +63,7 @@ export class SummaryPrinter {
     this.printGlobalHookCounts()
     this.printScenarioCounts()
     this.printStepCounts()
-    this.printDuration()
+    this.printDurations()
   }
 
   private printNonPassingScenarios() {
@@ -298,11 +297,18 @@ export class SummaryPrinter {
     this.println(formatCounts('steps', stepCountsByStatus, this.options.theme, this.stream))
   }
 
-  private printDuration() {
-    const testRunStarted = this.query.findTestRunStarted() as TestRunStarted
-    const testRunFinished = this.query.findTestRunFinished() as TestRunFinished
+  private printDurations() {
+    const testRunDuration = this.query.findTestRunDuration() as Duration
 
-    this.println(formatDuration(testRunStarted.timestamp, testRunFinished.timestamp))
+    const testRunHookDurations = this.query
+      .findAllTestRunHookFinished()
+      .map((hookFinished) => hookFinished.result.duration)
+    const testStepDurations = this.query
+      .findAllTestStepFinished()
+      .map((stepFinished) => stepFinished.testStepResult.duration)
+    const executionDurations = [...testRunHookDurations, ...testStepDurations]
+
+    this.println(formatDurations(testRunDuration, executionDurations))
   }
 
   private printSnippets() {

javascript/src/helpers.ts

@@ -3,6 +3,7 @@ import { stripVTControlCharacters } from 'node:util'
 import {
   Attachment,
   AttachmentContentEncoding,
+  Duration,
   Feature,
   Hook,
   HookType,
@@ -20,9 +21,8 @@ import {
   TestStepResult,
   TestStepResultStatus,
   TimeConversion,
-  Timestamp,
 } from '@cucumber/messages'
-import { Interval } from 'luxon'
+import { Duration as LuxonDuration } from 'luxon'
 
 import { TextBuilder } from './TextBuilder'
 import { Style, Theme } from './types'
@@ -438,15 +438,19 @@ export function formatCounts(
   return builder.build()
 }
 
-export function formatDuration(start: Timestamp, finish: Timestamp) {
-  const startMillis = new Date(TimeConversion.timestampToMillisecondsSinceEpoch(start))
-  const finishMillis = new Date(TimeConversion.timestampToMillisecondsSinceEpoch(finish))
-  const duration = Interval.fromDateTimes(startMillis, finishMillis).toDuration([
-    'minutes',
-    'seconds',
-    'milliseconds',
-  ])
-  return duration.toFormat(DURATION_FORMAT)
+export function formatDurations(
+  testRunDuration: Duration,
+  executionDurations: ReadonlyArray<Duration>
+) {
+  const testRunLuxon = LuxonDuration.fromMillis(
+    TimeConversion.durationToMilliseconds(testRunDuration)
+  )
+
+  const executionLuxon = LuxonDuration.fromMillis(
+    executionDurations.reduce((prev, curr) => prev + TimeConversion.durationToMilliseconds(curr), 0)
+  )
+
+  return `${testRunLuxon.toFormat(DURATION_FORMAT)} (${executionLuxon.toFormat(DURATION_FORMAT)} executing your code)`
 }
 
 export function titleCaseStatus(status: TestStepResultStatus) {

testdata/src/ambiguous.cucumber.summary.log

@@ -4,4 +4,4 @@
 
 1 scenarios (1 ambiguous)
 1 steps (1 ambiguous)
-0m 0.5s
+0m 0.5s (0m 0.0s executing your code)

testdata/src/ambiguous.plain.summary.log

@@ -4,4 +4,4 @@ Ambiguous scenarios:
 
 1 scenarios (1 ambiguous)
 1 steps (1 ambiguous)
-0m 0.5s
+0m 0.5s (0m 0.0s executing your code)

testdata/src/attachments.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 7 scenarios (7 passed)
 7 steps (7 passed)
-0m 0.36s
+0m 0.36s (0m 0.7s executing your code)

testdata/src/attachments.plain.summary.log

@@ -1,4 +1,4 @@
 
 7 scenarios (7 passed)
 7 steps (7 passed)
-0m 0.36s
+0m 0.36s (0m 0.7s executing your code)

testdata/src/backgrounds.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 2 scenarios (2 passed)
 10 steps (10 passed)
-0m 0.25s
+0m 0.25s (0m 0.10s executing your code)

testdata/src/backgrounds.plain.summary.log

@@ -1,4 +1,4 @@
 
 2 scenarios (2 passed)
 10 steps (10 passed)
-0m 0.25s
+0m 0.25s (0m 0.10s executing your code)

testdata/src/cdata.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 1 steps (1 passed)
-0m 0.5s
+0m 0.5s (0m 0.1s executing your code)

testdata/src/cdata.plain.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 1 steps (1 passed)
-0m 0.5s
+0m 0.5s (0m 0.1s executing your code)

testdata/src/data-tables.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 2 steps (2 passed)
-0m 0.7s
+0m 0.7s (0m 0.2s executing your code)

testdata/src/data-tables.plain.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 2 steps (2 passed)
-0m 0.7s
+0m 0.7s (0m 0.2s executing your code)

testdata/src/doc-strings.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 3 scenarios (3 passed)
 3 steps (3 passed)
-0m 0.13s
+0m 0.13s (0m 0.3s executing your code)

testdata/src/doc-strings.plain.summary.log

@@ -1,4 +1,4 @@
 
 3 scenarios (3 passed)
 3 steps (3 passed)
-0m 0.13s
+0m 0.13s (0m 0.3s executing your code)

testdata/src/empty.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 0 steps
-0m 0.3s
+0m 0.3s (0m 0.0s executing your code)

testdata/src/empty.plain.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 0 steps
-0m 0.3s
+0m 0.3s (0m 0.0s executing your code)

testdata/src/examples-tables-attachment.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 2 scenarios (2 passed)
 2 steps (2 passed)
-0m 0.11s
+0m 0.11s (0m 0.2s executing your code)

testdata/src/examples-tables-attachment.plain.summary.log

@@ -1,4 +1,4 @@
 
 2 scenarios (2 passed)
 2 steps (2 passed)
-0m 0.11s
+0m 0.11s (0m 0.2s executing your code)

testdata/src/examples-tables-undefined.cucumber.summary.log

@@ -6,7 +6,7 @@
 
 3 scenarios (3 undefined)
 9 steps (3 passed, 3 skipped, 3 undefined)
-0m 0.25s
+0m 0.25s (0m 0.3s executing your code)
 
 You can implement missing steps with the snippets below:
 

testdata/src/examples-tables-undefined.plain.summary.log

@@ -6,7 +6,7 @@ Undefined scenarios:
 
 3 scenarios (3 undefined)
 9 steps (3 passed, 3 skipped, 3 undefined)
-0m 0.25s
+0m 0.25s (0m 0.3s executing your code)
 
 You can implement missing steps with the snippets below:
 

testdata/src/examples-tables.cucumber.summary.log

@@ -17,4 +17,4 @@
 
 7 scenarios (5 passed, 2 failed)
 21 steps (19 passed, 2 failed)
-0m 0.57s
+0m 0.57s (0m 0.21s executing your code)

testdata/src/examples-tables.plain.summary.log

@@ -17,4 +17,4 @@ Failed scenarios:
 
 7 scenarios (5 passed, 2 failed)
 21 steps (19 passed, 2 failed)
-0m 0.57s
+0m 0.57s (0m 0.21s executing your code)

testdata/src/global-hooks-afterall-error.cucumber.summary.log

@@ -8,4 +8,4 @@
 5 hooks (4 passed, 1 failed)
 1 scenarios (1 passed)
 1 steps (1 passed)
-0m 0.15s
+0m 0.15s (0m 0.6s executing your code)

testdata/src/global-hooks-afterall-error.plain.summary.log

@@ -8,4 +8,4 @@ Failed hooks:
 5 hooks (4 passed, 1 failed)
 1 scenarios (1 passed)
 1 steps (1 passed)
-0m 0.15s
+0m 0.15s (0m 0.6s executing your code)

testdata/src/global-hooks-attachments.cucumber.summary.log

@@ -2,4 +2,4 @@
 2 hooks (2 passed)
 1 scenarios (1 passed)
 1 steps (1 passed)
-0m 0.11s
+0m 0.11s (0m 0.3s executing your code)

testdata/src/global-hooks-attachments.plain.summary.log

@@ -2,4 +2,4 @@
 2 hooks (2 passed)
 1 scenarios (1 passed)
 1 steps (1 passed)
-0m 0.11s
+0m 0.11s (0m 0.3s executing your code)

testdata/src/global-hooks-beforeall-error.cucumber.summary.log

@@ -8,4 +8,4 @@
 5 hooks (4 passed, 1 failed)
 0 scenarios
 0 steps
-0m 0.11s
+0m 0.11s (0m 0.5s executing your code)

testdata/src/global-hooks-beforeall-error.plain.summary.log

@@ -8,4 +8,4 @@ Failed hooks:
 5 hooks (4 passed, 1 failed)
 0 scenarios
 0 steps
-0m 0.11s
+0m 0.11s (0m 0.5s executing your code)

testdata/src/global-hooks.cucumber.summary.log

@@ -8,4 +8,4 @@
 4 hooks (4 passed)
 2 scenarios (1 passed, 1 failed)
 2 steps (1 passed, 1 failed)
-0m 0.17s
+0m 0.17s (0m 0.6s executing your code)

testdata/src/global-hooks.plain.summary.log

@@ -8,4 +8,4 @@ Failed scenarios:
 4 hooks (4 passed)
 2 scenarios (1 passed, 1 failed)
 2 steps (1 passed, 1 failed)
-0m 0.17s
+0m 0.17s (0m 0.6s executing your code)

testdata/src/hooks-attachment.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 3 steps (3 passed)
-0m 0.11s
+0m 0.11s (0m 0.3s executing your code)

testdata/src/hooks-attachment.plain.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 3 steps (3 passed)
-0m 0.11s
+0m 0.11s (0m 0.3s executing your code)

testdata/src/hooks-conditional.cucumber.summary.log

@@ -11,4 +11,4 @@
 
 3 scenarios (1 passed, 2 failed)
 7 steps (4 passed, 1 skipped, 2 failed)
-0m 0.21s
+0m 0.21s (0m 0.6s executing your code)

testdata/src/hooks-conditional.plain.summary.log

@@ -11,4 +11,4 @@ Failed scenarios:
 
 3 scenarios (1 passed, 2 failed)
 7 steps (4 passed, 1 skipped, 2 failed)
-0m 0.21s
+0m 0.21s (0m 0.6s executing your code)

testdata/src/hooks-named.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 3 steps (3 passed)
-0m 0.9s
+0m 0.9s (0m 0.3s executing your code)

testdata/src/hooks-named.plain.summary.log

@@ -1,4 +1,4 @@
 
 1 scenarios (1 passed)
 3 steps (3 passed)
-0m 0.9s
+0m 0.9s (0m 0.3s executing your code)

testdata/src/hooks-skipped.cucumber.summary.log

@@ -1,4 +1,4 @@
 
 3 scenarios (3 skipped)
 17 steps (12 passed, 5 skipped)
-0m 0.41s
+0m 0.41s (0m 0.15s executing your code)

testdata/src/hooks-skipped.plain.summary.log

@@ -1,4 +1,4 @@
 
 3 scenarios (3 skipped)
 17 steps (12 passed, 5 skipped)
-0m 0.41s
+0m 0.41s (0m 0.15s executing your code)

testdata/src/hooks-undefined.cucumber.summary.log

@@ -4,7 +4,7 @@
 
 1 scenarios (1 undefined)
 3 steps (2 passed, 1 undefined)
-0m 0.9s
+0m 0.9s (0m 0.2s executing your code)
 
 You can implement missing steps with the snippets below: