From 7c16400fb0c4a9802ba1c5b9b7da2ba089f85064 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 1 Sep 2021 11:04:56 -0300 Subject: [PATCH] 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 --- CHANGELOG.md | 1 + features/support/hooks.ts | 13 ++++++++ features/usage_formatter.feature | 52 ++++++++++++++++---------------- src/time.ts | 4 ++- 4 files changed, 43 insertions(+), 27 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 32d9c3602..90fbbd2d6 100644 --- 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 index 04d5bee06..0a3fe8cd8 100644 --- 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 index a53a2d9cd..921f0feca 100644 --- 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 │ ms │ features/step_definitions/steps.js:3 │ - │ step A │ ms │ features/a.feature:3 │ - ├────────────────────┼──────────┼───────────────────────────────────────┤ - │ /^(slow )?step B$/ │ ms │ features/step_definitions/steps.js:4 │ - │ slow step B │ ms │ features/a.feature:5 │ - │ step B │ ms │ features/a.feature:4 │ - ├────────────────────┼──────────┼───────────────────────────────────────┤ - │ step C │ ms │ features/step_definitions/steps.js:11 │ - │ step C │ ms │ features/a.feature:6 │ - ├────────────────────┼──────────┼───────────────────────────────────────┤ - │ step D │ UNUSED │ features/step_definitions/steps.js:12 │ - └────────────────────┴──────────┴───────────────────────────────────────┘ + ┌────────────────────┬──────────────┬───────────────────────────────────────┐ + │ Pattern / Text │ Duration │ Location │ + ├────────────────────┼──────────────┼───────────────────────────────────────┤ + │ step A │ ms │ features/step_definitions/steps.js:3 │ + │ step A │ ms │ features/a.feature:3 │ + ├────────────────────┼──────────────┼───────────────────────────────────────┤ + │ /^(slow )?step B$/ │ ms │ features/step_definitions/steps.js:4 │ + │ slow step B │ ms │ features/a.feature:5 │ + │ step B │ ms │ features/a.feature:4 │ + ├────────────────────┼──────────────┼───────────────────────────────────────┤ + │ step C │ ms │ features/step_definitions/steps.js:11 │ + │ step C │ 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$/ │ ms │ features/step_definitions/steps.js:3 │ - │ slow step │ ms │ features/a.feature:3 │ - │ slow step │ ms │ features/a.feature:3 │ - │ slow step │ ms │ features/a.feature:3 │ - │ slow step │ ms │ features/a.feature:3 │ - │ slow step │ ms │ features/a.feature:3 │ - │ 5 more │ │ │ - └──────────────────┴──────────┴──────────────────────────────────────┘ + ┌──────────────────┬──────────────┬──────────────────────────────────────┐ + │ Pattern / Text │ Duration │ Location │ + ├──────────────────┼──────────────┼──────────────────────────────────────┤ + │ /^(slow )?step$/ │ ms │ features/step_definitions/steps.js:3 │ + │ slow step │ ms │ features/a.feature:3 │ + │ slow step │ ms │ features/a.feature:3 │ + │ slow step │ ms │ features/a.feature:3 │ + │ slow step │ ms │ features/a.feature:3 │ + │ slow step │ ms │ features/a.feature:3 │ + │ 5 more │ │ │ + └──────────────────┴──────────────┴──────────────────────────────────────┘ """ diff --git a/src/time.ts b/src/time.ts index ab3d50cda..32ec1c9ed 100644 --- 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(