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 · 7c16400 · 7c16400
1 parent 06be59a
commit 7c16400
Show file tree

Hide file tree

Showing 4 changed files with 43 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/support/hooks.ts b/features/support/hooks.ts
@@ -1,3 +1,6 @@
+import FakeTimers, { InstalledClock } from '@sinonjs/fake-timers'
+import timeMethods from '../time'
+
 import { After, Before, formatterHelpers } from '../../'
 import fs from 'fs'
 import fsExtra from 'fs-extra'
@@ -110,3 +113,13 @@ After(async function (this: World) {
  )
  }
 })
+
+let clock: InstalledClock
+
+Before(async function () {
+ clock = FakeTimers.withGlobal(timeMethods).install()
+})
+
+After(async function () {
+ clock.uninstall()
+})
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(