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 1/8] 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( From 008aa0ca59a5d413e6e81a049f9db0f9c773ec66 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 1 Sep 2021 14:29:03 -0300 Subject: [PATCH 2/8] Use fake timers for duration tests --- features/support/hooks.ts | 6 +++--- features/usage_formatter.feature | 3 +++ 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/features/support/hooks.ts b/features/support/hooks.ts index 0a3fe8cd8..16e79a864 100644 --- a/features/support/hooks.ts +++ b/features/support/hooks.ts @@ -1,5 +1,5 @@ import FakeTimers, { InstalledClock } from '@sinonjs/fake-timers' -import timeMethods from '../time' +import timeMethods from '../../src/time' import { After, Before, formatterHelpers } from '../../' import fs from 'fs' @@ -116,10 +116,10 @@ After(async function (this: World) { let clock: InstalledClock -Before(async function () { +Before('@fake-timers', function () { clock = FakeTimers.withGlobal(timeMethods).install() }) -After(async function () { +After('@fake-timers', function () { clock.uninstall() }) diff --git a/features/usage_formatter.feature b/features/usage_formatter.feature index 921f0feca..106467d3e 100644 --- a/features/usage_formatter.feature +++ b/features/usage_formatter.feature @@ -5,6 +5,7 @@ Feature: usage formatter So I know where my bottelnecks are and what step definitions I can remove + @fake-timers Scenario: Given a file named "features/a.feature" with: """ @@ -50,6 +51,8 @@ Feature: usage formatter └────────────────────┴──────────────┴───────────────────────────────────────┘ """ + + @fake-timers Scenario: only list 5 slowest matches Given a file named "features/a.feature" with: """ From 5da8dcefca7d791495f73a31033e338e3efc4e96 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 1 Sep 2021 14:39:00 -0300 Subject: [PATCH 3/8] Nomalize dash caracter on tables --- features/support/helpers.ts | 1 + features/support/hooks.ts | 13 ------------- features/usage_formatter.feature | 2 -- 3 files changed, 1 insertion(+), 15 deletions(-) diff --git a/features/support/helpers.ts b/features/support/helpers.ts index 4fa7586f0..334a114ef 100644 --- a/features/support/helpers.ts +++ b/features/support/helpers.ts @@ -11,6 +11,7 @@ export function normalizeText(text: string): string { .replace(/\d+(.\d+)?ms/g, 'ms') .replace(/\//g, path.sep) .replace(/ +/g, ' ') + .replace('/─+/g', '─') .split('\n') .map((line) => line.trim()) .join('\n') diff --git a/features/support/hooks.ts b/features/support/hooks.ts index 16e79a864..04d5bee06 100644 --- a/features/support/hooks.ts +++ b/features/support/hooks.ts @@ -1,6 +1,3 @@ -import FakeTimers, { InstalledClock } from '@sinonjs/fake-timers' -import timeMethods from '../../src/time' - import { After, Before, formatterHelpers } from '../../' import fs from 'fs' import fsExtra from 'fs-extra' @@ -113,13 +110,3 @@ After(async function (this: World) { ) } }) - -let clock: InstalledClock - -Before('@fake-timers', function () { - clock = FakeTimers.withGlobal(timeMethods).install() -}) - -After('@fake-timers', function () { - clock.uninstall() -}) diff --git a/features/usage_formatter.feature b/features/usage_formatter.feature index 106467d3e..b751a9b8d 100644 --- a/features/usage_formatter.feature +++ b/features/usage_formatter.feature @@ -5,7 +5,6 @@ Feature: usage formatter So I know where my bottelnecks are and what step definitions I can remove - @fake-timers Scenario: Given a file named "features/a.feature" with: """ @@ -52,7 +51,6 @@ Feature: usage formatter """ - @fake-timers Scenario: only list 5 slowest matches Given a file named "features/a.feature" with: """ From 8a4fc7b41affaa3f6d9d7b79b7034ac3e9d89a78 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 1 Sep 2021 14:53:49 -0300 Subject: [PATCH 4/8] Make the normalization dash insensitive --- features/support/helpers.ts | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/features/support/helpers.ts b/features/support/helpers.ts index 334a114ef..99f58537e 100644 --- a/features/support/helpers.ts +++ b/features/support/helpers.ts @@ -11,9 +11,13 @@ export function normalizeText(text: string): string { .replace(/\d+(.\d+)?ms/g, 'ms') .replace(/\//g, path.sep) .replace(/ +/g, ' ') - .replace('/─+/g', '─') + .replace(/─+/ug, '─') .split('\n') .map((line) => line.trim()) .join('\n') + + console.log(normalized); + return normalizeSummaryDuration(normalized) + } From 2be65467001a4fac474418c0574a5e027ecaec22 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 1 Sep 2021 14:55:43 -0300 Subject: [PATCH 5/8] Remove console log and fix linter issues --- features/support/helpers.ts | 5 +-- features/usage_formatter.feature | 53 ++++++++++++++++---------------- 2 files changed, 27 insertions(+), 31 deletions(-) diff --git a/features/support/helpers.ts b/features/support/helpers.ts index 99f58537e..a17b1dc57 100644 --- a/features/support/helpers.ts +++ b/features/support/helpers.ts @@ -11,13 +11,10 @@ export function normalizeText(text: string): string { .replace(/\d+(.\d+)?ms/g, 'ms') .replace(/\//g, path.sep) .replace(/ +/g, ' ') - .replace(/─+/ug, '─') + .replace(/─+/gu, '─') .split('\n') .map((line) => line.trim()) .join('\n') - console.log(normalized); - return normalizeSummaryDuration(normalized) - } diff --git a/features/usage_formatter.feature b/features/usage_formatter.feature index b751a9b8d..a53a2d9cd 100644 --- a/features/usage_formatter.feature +++ b/features/usage_formatter.feature @@ -33,24 +33,23 @@ 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 Given a file named "features/a.feature" with: """ @@ -82,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 │ │ │ + └──────────────────┴──────────┴──────────────────────────────────────┘ """ From 824e90a2b9ce9a700a532a21a6e18a3363f03645 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Thu, 2 Sep 2021 10:41:25 -0300 Subject: [PATCH 6/8] Update CHANGELOG.md MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Aurélien Reeves --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 90fbbd2d6..65870b86d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ See the [migration guide](./docs/migration.md) for details of how to migrate fro ### Changed * Use performance timers for test case duration measurement. + [#1793](https://github.com/cucumber/cucumber-js/pull/1793) ### Deprecated From dfcf58713b29e6a3278d042445ad3f5c25edd8aa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 8 Sep 2021 14:44:54 -0300 Subject: [PATCH 7/8] Limit number of decimal places to 2 on usage formatter --- src/formatter/usage_formatter.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/formatter/usage_formatter.ts b/src/formatter/usage_formatter.ts index 5b7a29ed5..ff6afe142 100644 --- a/src/formatter/usage_formatter.ts +++ b/src/formatter/usage_formatter.ts @@ -60,7 +60,7 @@ export default class UsageFormatter extends Formatter { col2.push( `${messages.TimeConversion.durationToMilliseconds( match.duration - ).toString()}ms` + ).toFixed(2)}ms` ) } else { col2.push('-') From 96ce2fd2d3a0d002157a48ef25a464b744984e02 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Joaqu=C3=ADn=20Sorianello?= Date: Wed, 8 Sep 2021 14:47:23 -0300 Subject: [PATCH 8/8] Fix usage formatter test --- src/formatter/usage_formatter_spec.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/formatter/usage_formatter_spec.ts b/src/formatter/usage_formatter_spec.ts index 89da62e57..5c8545124 100644 --- a/src/formatter/usage_formatter_spec.ts +++ b/src/formatter/usage_formatter_spec.ts @@ -125,8 +125,8 @@ describe('UsageFormatter', () => { │ Pattern / Text │ Duration │ Location │ ├────────────────┼──────────┼───────────────────┤ │ /def?/ │ 1.50ms │ usage_steps.ts:16 │ - │ def │ 2ms │ a.feature:3 │ - │ de │ 1ms │ a.feature:4 │ + │ def │ 2.00ms │ a.feature:3 │ + │ de │ 1.00ms │ a.feature:4 │ ├────────────────┼──────────┼───────────────────┤ │ abc │ UNUSED │ usage_steps.ts:11 │ ├────────────────┼──────────┼───────────────────┤