Use higher definition clock for test case run time measurement

I noticed that fast tests always reported 0 as the duration, after some debugging I noticed that we were not using the most accurate clock, so I changed it for `performance.now` from perf hooks https://nodejs.org/api/perf_hooks.html#perf_hooks_performance_now As a side effect, that seems to be a monotonic clock, making the measurements not affected by leap seconds
cucumber · Sep 1, 2021 · fd13b11 · fd13b11
1 parent 06be59a
commit fd13b11
Show file tree

Hide file tree

Showing 3 changed files with 30 additions and 27 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -20,6 +20,7 @@ See the [migration guide](./docs/migration.md) for details of how to migrate fro
 ### Added
 
 ### Changed
+* Use performance timers for test case duration measurement.
 
 ### Deprecated
 

diff --git a/features/usage_formatter.feature b/features/usage_formatter.feature
@@ -33,21 +33,21 @@ Feature: usage formatter
     When I run cucumber-js with `--format usage`
     Then it outputs the text:
       """
-      ┌────────────────────┬──────────┬───────────────────────────────────────┐
-      │ Pattern / Text     │ Duration │ Location                              │
-      ├────────────────────┼──────────┼───────────────────────────────────────┤
-      │ step A             │ <d>ms    │ features/step_definitions/steps.js:3  │
-      │   step A           │ <d>ms    │ features/a.feature:3                  │
-      ├────────────────────┼──────────┼───────────────────────────────────────┤
-      │ /^(slow )?step B$/ │ <d>ms    │ features/step_definitions/steps.js:4  │
-      │   slow step B      │ <d>ms    │ features/a.feature:5                  │
-      │   step B           │ <d>ms    │ features/a.feature:4                  │
-      ├────────────────────┼──────────┼───────────────────────────────────────┤
-      │ step C             │ <d>ms    │ features/step_definitions/steps.js:11 │
-      │   step C           │ <d>ms    │ features/a.feature:6                  │
-      ├────────────────────┼──────────┼───────────────────────────────────────┤
-      │ step D             │ UNUSED   │ features/step_definitions/steps.js:12 │
-      └────────────────────┴──────────┴───────────────────────────────────────┘
+      ┌────────────────────┬──────────────┬───────────────────────────────────────┐
+      │ Pattern / Text     │ Duration     │ Location                              │
+      ├────────────────────┼──────────────┼───────────────────────────────────────┤
+      │ step A             │ <d>ms        │ features/step_definitions/steps.js:3  │
+      │   step A           │ <d>ms        │ features/a.feature:3                  │
+      ├────────────────────┼──────────────┼───────────────────────────────────────┤
+      │ /^(slow )?step B$/ │ <d>ms        │ features/step_definitions/steps.js:4  │
+      │   slow step B      │ <d>ms        │ features/a.feature:5                  │
+      │   step B           │ <d>ms        │ features/a.feature:4                  │
+      ├────────────────────┼──────────────┼───────────────────────────────────────┤
+      │ step C             │ <d>ms        │ features/step_definitions/steps.js:11 │
+      │   step C           │ <d>ms        │ features/a.feature:6                  │
+      ├────────────────────┼──────────────┼───────────────────────────────────────┤
+      │ step D             │ UNUSED       │ features/step_definitions/steps.js:12 │
+      └────────────────────┴──────────────┴───────────────────────────────────────┘
       """
 
   Scenario: only list 5 slowest matches
@@ -81,15 +81,15 @@ Feature: usage formatter
     When I run cucumber-js with `--format usage`
     Then it outputs the text:
       """
-      ┌──────────────────┬──────────┬──────────────────────────────────────┐
-      │ Pattern / Text   │ Duration │ Location                             │
-      ├──────────────────┼──────────┼──────────────────────────────────────┤
-      │ /^(slow )?step$/ │ <d>ms    │ features/step_definitions/steps.js:3 │
-      │   slow step      │ <d>ms    │ features/a.feature:3                 │
-      │   slow step      │ <d>ms    │ features/a.feature:3                 │
-      │   slow step      │ <d>ms    │ features/a.feature:3                 │
-      │   slow step      │ <d>ms    │ features/a.feature:3                 │
-      │   slow step      │ <d>ms    │ features/a.feature:3                 │
-      │   5 more         │          │                                      │
-      └──────────────────┴──────────┴──────────────────────────────────────┘
+      ┌──────────────────┬─────────────┬──────────────────────────────────────┐
+      │ Pattern / Text   │ Duration    │ Location                             │
+      ├──────────────────┼─────────────┼──────────────────────────────────────┤
+      │ /^(slow )?step$/ │ <d>ms       │ features/step_definitions/steps.js:3 │
+      │   slow step      │ <d>ms       │ features/a.feature:3                 │
+      │   slow step      │ <d>ms       │ features/a.feature:3                 │
+      │   slow step      │ <d>ms       │ features/a.feature:3                 │
+      │   slow step      │ <d>ms       │ features/a.feature:3                 │
+      │   slow step      │ <d>ms       │ features/a.feature:3                 │
+      │   5 more         │             │                                      │
+      └──────────────────┴─────────────┴──────────────────────────────────────┘
       """
diff --git a/src/time.ts b/src/time.ts
@@ -1,3 +1,4 @@
+import { performance } from 'perf_hooks'
 import * as messages from '@cucumber/messages'
 
 let previousTimestamp: number
@@ -14,6 +15,7 @@ const methods: any = {
   },
   setInterval: setInterval.bind(global),
   setTimeout: setTimeout.bind(global),
+  performance,
 }
 
 if (typeof setImmediate !== 'undefined') {
@@ -22,7 +24,7 @@ if (typeof setImmediate !== 'undefined') {
 }
 
 function getTimestamp(): number {
-  return new methods.Date().getTime()
+  return methods.performance.now()
 }
 
 export function durationBetweenTimestamps(