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

Hide file tree

Showing 4 changed files with 99 additions and 80 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,21 +1,24 @@
-import { After, Before, formatterHelpers } from '../../'
-import fs from 'fs'
-import fsExtra from 'fs-extra'
-import path from 'path'
-import tmp from 'tmp'
-import { doesHaveValue } from '../../src/value_checker'
-import { World } from './world'
-import { ITestCaseHookParameter } from '../../src/support_code_library_builder/types'
+import FakeTimers, { InstalledClock } from "@sinonjs/fake-timers";
+import timeMethods from "../time";
 
-const projectPath = path.join(__dirname, '..', '..')
+import { After, Before, formatterHelpers } from "../../";
+import fs from "fs";
+import fsExtra from "fs-extra";
+import path from "path";
+import tmp from "tmp";
+import { doesHaveValue } from "../../src/value_checker";
+import { World } from "./world";
+import { ITestCaseHookParameter } from "../../src/support_code_library_builder/types";
 
-Before('@debug', function (this: World) {
-  this.debug = true
-})
+const projectPath = path.join(__dirname, "..", "..");
 
-Before('@spawn', function (this: World) {
-  this.spawn = true
-})
+Before("@debug", function (this: World) {
+  this.debug = true;
+});
+
+Before("@spawn", function (this: World) {
+  this.spawn = true;
+});
 
 Before(function (
   this: World,
@@ -24,79 +27,82 @@ Before(function (
   const { line } = formatterHelpers.PickleParser.getPickleLocation({
     gherkinDocument,
     pickle,
-  })
+  });
   this.tmpDir = path.join(
     projectPath,
-    'tmp',
+    "tmp",
     `${path.basename(pickle.uri)}_${line.toString()}`
-  )
+  );
 
-  fsExtra.removeSync(this.tmpDir)
+  fsExtra.removeSync(this.tmpDir);
 
-  const tmpDirNodeModulesPath = path.join(this.tmpDir, 'node_modules')
+  const tmpDirNodeModulesPath = path.join(this.tmpDir, "node_modules");
   const tmpDirCucumberPath = path.join(
     tmpDirNodeModulesPath,
-    '@cucumber',
-    'cucumber'
-  )
-  fsExtra.ensureSymlinkSync(projectPath, tmpDirCucumberPath)
-  this.localExecutablePath = path.join(projectPath, 'bin', 'cucumber-js')
-})
+    "@cucumber",
+    "cucumber"
+  );
+  fsExtra.ensureSymlinkSync(projectPath, tmpDirCucumberPath);
+  this.localExecutablePath = path.join(projectPath, "bin", "cucumber-js");
+});
 
-Before('@global-install', function (this: World) {
-  const tmpObject = tmp.dirSync({ unsafeCleanup: true })
+Before("@global-install", function (this: World) {
+  const tmpObject = tmp.dirSync({ unsafeCleanup: true });
 
   // Symlink everything in node_modules so the fake global install has all the dependencies it needs
-  const projectNodeModulesPath = path.join(projectPath, 'node_modules')
-  const projectNodeModulesDirs = fs.readdirSync(projectNodeModulesPath)
-  const globalInstallNodeModulesPath = path.join(tmpObject.name, 'node_modules')
+  const projectNodeModulesPath = path.join(projectPath, "node_modules");
+  const projectNodeModulesDirs = fs.readdirSync(projectNodeModulesPath);
+  const globalInstallNodeModulesPath = path.join(
+    tmpObject.name,
+    "node_modules"
+  );
   projectNodeModulesDirs.forEach((nodeModuleDir) => {
-    let pathsToLink = [nodeModuleDir]
-    if (nodeModuleDir[0] === '@') {
+    let pathsToLink = [nodeModuleDir];
+    if (nodeModuleDir[0] === "@") {
       const scopeNodeModuleDirs = fs.readdirSync(
         path.join(projectNodeModulesPath, nodeModuleDir)
-      )
-      pathsToLink = scopeNodeModuleDirs.map((x) => path.join(nodeModuleDir, x))
+      );
+      pathsToLink = scopeNodeModuleDirs.map((x) => path.join(nodeModuleDir, x));
     }
     pathsToLink.forEach((pathToLink) => {
       const globalInstallNodeModulePath = path.join(
         globalInstallNodeModulesPath,
         pathToLink
-      )
+      );
       const projectNodeModulePath = path.join(
         projectNodeModulesPath,
         pathToLink
-      )
+      );
       fsExtra.ensureSymlinkSync(
         projectNodeModulePath,
         globalInstallNodeModulePath
-      )
-    })
-  })
+      );
+    });
+  });
 
   const globalInstallCucumberPath = path.join(
     globalInstallNodeModulesPath,
-    '@cucumber',
-    'cucumber'
-  )
-  const itemsToCopy = ['bin', 'lib', 'package.json']
+    "@cucumber",
+    "cucumber"
+  );
+  const itemsToCopy = ["bin", "lib", "package.json"];
   itemsToCopy.forEach((item) => {
     fsExtra.copySync(
       path.join(projectPath, item),
       path.join(globalInstallCucumberPath, item)
-    )
-  })
+    );
+  });
 
   this.globalExecutablePath = path.join(
     globalInstallCucumberPath,
-    'bin',
-    'cucumber-js'
-  )
-})
+    "bin",
+    "cucumber-js"
+  );
+});
 
 After(async function (this: World) {
   if (this.reportServer?.started) {
-    await this.reportServer.stop()
+    await this.reportServer.stop();
   }
 
   if (
@@ -107,6 +113,16 @@ After(async function (this: World) {
     throw new Error(
       `Last run errored unexpectedly. Output:\n\n${this.lastRun.output}\n\n` +
         `Error Output:\n\n${this.lastRun.errorOutput}`
-    )
+    );
   }
-})
+});
+
+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(