Increase precision of test case duration measurements.

[joac]

Description

I was working on a custom formatter for pickled-cucumber and 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

Motivation & context

The durations numbers reported by cucumber were not accurate.

Type of change

• Refactoring/debt (improvement to code design or tooling without changing behaviour)

Checklist:

• My code follows the code style of this project.
• My change requires a change to the documentation.
• I have updated the documentation accordingly.
• I have read the CONTRIBUTING document.
• I have added tests to cover my changes.
• All new and existing tests passed.

[joac]

Test are failing due to inaccurate nanos, It will be really hard to fix those tests, due to the jitter we can expect between test runs. I will need some help here. 🙏

[aurelien-reeves]

For the tests, we are using https://github.com/sinonjs/fake-timers to have predictable timestamps.
sinonjs/fake-timers can fake performance.now, but only in browser. So we may need to find an alternative.

[aurelien-reeves]

Found how to fix the tests: this is the why of the "methods" object.

Add the "performance" object to the "methods":

const methods: any = {
  // snip...
  Date,
  performance,
  // snip...
}

And use it in getTimestamp:

function getTimestamp(): number {
  return methods.performance.now()
}

In the unit tests, we are installing sinonjs/fake-timers with that "methods" object. Adding the "performance" entry in it, sinonjs/fake-timer will found it and replace it with its fake one

[joac]

@aurelien-reeves will research a bit about alternatives to fix that, thanks!

[aurelien-reeves]

@joac I've found a way, please check my previous message

[joac]

I had to increase the colum size for durations in msecs on usage formatter tests, due to bigger numbers being reported, do you think is ok @aurelien-reeves o we should use Math.round or Math.floor on the formatter itself?

[coveralls]

Coverage increased (+0.0009%) to 98.248% when pulling 96ce2fd on joac:main into c87b6dc on cucumber:main.

[joac]

Seems that the tests that break are not using the fake timers. I don't understand well the initialization process of the test suite 😢

[aurelien-reeves]

Seems that the tests that break are not using the fake timers. I don't understand well the initialization process of the test suite 😢

You do not have to force push a single commit each time.
Actually that prevent us to see the history of the CI.

I had to increase the colum size for durations in msecs on usage formatter tests, due to bigger numbers being reported, do you think is ok @aurelien-reeves o we should use Math.round or Math.floor on the formatter itself?

I think that technically, it looks good to me. And I like your enhancement.
But I would wait for the opinion of @davidjgoss, @charlierudolph or @aslakhellesoy about it as I am still relatively new on the project, I may miss some edge cases here 😅.

[aurelien-reeves]

I think you should revert your changes on features/support/hooks.ts
It seems to be responsible for the CI being stuck

[joac]

I think you should revert your changes on features/support/hooks.ts
It seems to be responsible for the CI being stuck

@aurelien-reeves Was a failed attempt to fake the timers (a bad import). I changed the approach for testing and CI is green now.

[aurelien-reeves]

Nice, well done!

It looks good to me. I like your PR!

But as I said, I prefer to wait for some more experienced folks to review it before approving it. I don't know if using the monotonic performance clock could have some undesirable impact somewhere with the reports.

@davidjgoss @charlierudolph @aslakhellesoy any objection with this?

[aslakhellesoy]

But as I said, I prefer to wait for some more experienced folks to review it before approving it. I don't know if using the monotonic performance clock could have some undesirable impact somewhere with the reports.

As long as the measurement unit is the same (milliseconds I presume) I have no objections. Using a monotonic clock is the correct way to measure duration in any software system (using a wall clock is always wrong).

[davidjgoss]

I had to increase the colum size for durations in msecs on usage formatter tests

Do we have an example of how this comes out?

[aurelien-reeves]

I had to increase the colum size for durations in msecs on usage formatter tests

Do we have an example of how this comes out?

Looks like that:

$ node ./bin/cucumber-js --format usage
┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────┬───────────────┬───────────────────────────────────────────────────────┐
│ Pattern / Text                                                                                                 │ Duration      │ Location                                              │
├────────────────────────────────────────────────────────────────────────────────────────────────────────────────┼───────────────┼───────────────────────────────────────────────────────┤
│ /^I run cucumber-js(?: with `(|.+)`)?$/                                                                        │ 47788.62ms    │ features/step_definitions/cli_steps.ts:19             │
│   I run cucumber-js                                                                                            │ 11874726.13ms │ features/fake_time.feature:39                         │
│   I run cucumber-js                                                                                            │ 1445.457999ms │ features/exit.feature:28                              │
│   I run cucumber-js with `--parallel 2`                                                                        │ 1253.9458ms   │ features/parallel.feature:21                          │
│   I run cucumber-js                                                                                            │ 1014.318199ms │ features/before_after_all_hook_timeouts.feature:51    │
│   I run cucumber-js                                                                                            │ 1009.0063ms   │ features/step_definition_timeouts.feature:105         │
│   244 more                                                                                                     │               │                                                       │
├────────────────────────────────────────────────────────────────────────────────────────────────────────────────┼───────────────┼───────────────────────────────────────────────────────┤
│ /^I run cucumber-js with env `(|.+)`$/                                                                         │ 416.24ms      │ features/step_definitions/cli_steps.ts:40             │
│   I run cucumber-js with env `CUCUMBER_PUBLISH_TOKEN=keyboardcat`                                              │ 416.2368ms    │ features/publish.feature:108                          │
├────────────────────────────────────────────────────────────────────────────────────────────────────────────────┼───────────────┼───────────────────────────────────────────────────────┤
│ /^I run cucumber-js with arguments `(|.+)` and env `(|.+)`$/                                                   │ 396.73ms      │ features/step_definitions/cli_steps.ts:29             │
│   I run cucumber-js with arguments `--publish` and env ``                                                      │ 613.364ms     │ features/publish.feature:121                          │
│   I run cucumber-js with arguments `` and env `CUCUMBER_PUBLISH_ENABLED=true`                                  │ 492.013ms     │ features/publish.feature:121                          │
│   I run cucumber-js with arguments `` and env `CUCUMBER_PUBLISH_TOKEN=f318d9ec-5a3d-4727-adec-bd7b69e2edd3`    │ 453.223999ms  │ features/publish.feature:58                           │
│   I run cucumber-js with arguments `` and env `CUCUMBER_PUBLISH_ENABLED=1`                                     │ 446.359299ms  │ features/publish.feature:40                           │
│   I run cucumber-js with arguments `` and env `CUCUMBER_PUBLISH_TOKEN=f318d9ec-5a3d-4727-adec-bd7b69e2edd3`    │ 435.3693ms    │ features/publish.feature:121                          │
│   5 more                                                                                                       │               │                                                       │
├────────────────────────────────────────────────────────────────────────────────────────────────────────────────┼───────────────┼───────────────────────────────────────────────────────┤
│ /^I run cucumber-js \(installed (locally|globally)\)$/                                                         │ 253.48ms      │ features/step_definitions/cli_steps.ts:65             │
│   I run cucumber-js (installed locally)                                                                        │ 260.915699ms  │ features/global_install.feature:26                    │
│   I run cucumber-js (installed globally)                                                                       │ 246.0365ms    │ features/global_install.feature:17                    │
├────────────────────────────────────────────────────────────────────────────────────────────────────────────────┼───────────────┼───────────────────────────────────────────────────────┤

[davidjgoss]

@aurelien-reeves thanks for posting - I think the durations look a little noisy there, it would benefit from maybe limiting to 2 or 3 decimal places in the formatter, but I don't think it's a huge deal.

[joac]

@aurelien-reeves thanks for posting - I think the durations look a little noisy there, it would benefit from maybe limiting to 2 or 3 decimal places in the formatter, but I don't think it's a huge deal.

@davidjgoss Do you think that we should address that on this PR or a separate one?.

[joac]

As long as the measurement unit is the same (milliseconds I presume) I have no objections. Using a monotonic clock is the correct way to measure duration in any software system (using a wall clock is always wrong).

@aslakhellesoy From node the documentation:
Returns the current high resolution millisecond timestamp, where 0 represents the start of the current node process.
It didn't say anything about being monotonic, but the implementation uses process.hrtime() that claims These times are relative to an arbitrary time in the past, and not related to the time of day and therefore not subject to clock drift. From that, I understand that is a monotonic clock.

[davidjgoss]

@joac if you have time to do on this PR that’s be great!

[joac]

@davidjgoss It's done!

[aslakhellesoy]

Hi @joac,

Thanks for your making your first contribution to Cucumber, and welcome to the Cucumber committers team! You can now push directly to this repo and all other repos under the cucumber organization! 🍾

In return for this generous offer we hope you will:

• ✅ Continue to use branches and pull requests. When someone on the core team approves a pull request (yours or someone else's), you're welcome to merge it yourself.
• 💚 Commit to setting a good example by following and upholding our code of conduct in your interactions with other collaborators and users.
• 💬 Join the community Slack channel to meet the rest of the team and make yourself at home.
• ℹ️ Don't feel obliged to help, just do what you can if you have the time and the energy.
• 🙋 Ask if you need anything. We're looking for feedback about how to make the project more welcoming, so please tell us!

On behalf of the Cucumber core team,
Aslak Hellesøy
Creator of Cucumber