sinonjs / fake-timers

Fake setTimeout and friends (collectively known as "timers"). Useful in your JavaScript tests. Extracted from Sinon.JS
BSD 3-Clause "New" or "Revised" License
793 stars 103 forks source link

process.hrtime gives incorrect results #471

Closed mrft closed 1 year ago

mrft commented 1 year ago

IMPORTANT: my tests only started failing after I was playing with tsconfig.json settings in order to produce an EcmaScript Module instead of a CommonsJS module. In order to get that working

What did you expect to happen? calling hrtime() after advancing the clock should return the start time + the number of milliseconds that the clock has advanced,

What actually happens it always returns 0, while the version that uses Date.now() works as expected.

How to reproduce Configure the project to be ESM by creating a similar configuration as shown above, and then run this test.

import FakeTimers from "@sinonjs/fake-timers";
import { assert } from "chai";

describe("@sinonjs/fake-timers", () => {
  it("should behave as expected when using process.hrtime", async () => {
    const clock = FakeTimers.install();
    try {
      const start = process.hrtime()[0];
      const start2 = Date.now();
      // await awaitPromiseWithFakeTimers(clock, sleep(50));
      clock.tick(50);
      const stop = process.hrtime()[0];
      const stop2 = Date.now();
      assert.equal(stop2 - start2, 50, "Date.now() gives incorrect results");
      assert.equal(stop - start, 50, "process.hrtime gives incorrect results");
    } finally {
      clock.uninstall();
    }
  });
});

(The actual code that worked for me (different tests where I was using fake-timers) can be found here: https://github.com/mrft/itr8 (npm install && npm run test) The changes to tsconfig that made it start failing have not been committed yet)

fatso83 commented 1 year ago

Thanks for reporting this and good details in the report!

The reproduction case seemed a bit elaborate and also was not so easily runnable, but seeing that this was essentially about CJS vs ESM it seemed fair to just run the code directly using those modes in Node, as there was no typescript specifics here. We also do not support Typescript (which does not mean you should not use it, just that TS specifics is not for us to debug as they often just obscure the real underlying issues with non-standard ES extensions such as decorators).

I just copied your code into repro.test.mjs and added the dependencies and as expected the tests failed. So ✅ . Then I copied the test file to repro.test.js and changed the imports to require calls. Tests still failed. So ❌ on there being a difference.

I have found an issue with how you use process.hrtime() (details about that below), but I don't see any difference between running tests in either mode.

So I cannot verify your issue about ESM being different than CJS. Unless you are able to come up with some reproduction case (TS or ES, does not matter), I will probably remove the TS specifics detail for clarity for latecomers.


Repro:

**package.json** ```json { "name": "foo2", "version": "1.0.0", "description": "", "main": "index.js", "scripts": { "test": "mocha ./repro.test.mjs" }, "keywords": [], "author": "", "license": "ISC", "dependencies": { "@sinonjs/fake-timers": "^11.0.0", "chai": "^4.3.7", "mocha": "^10.2.0" }, "devDependencies": { "@types/mocha": "^10.0.1", "@types/node": "^20.3.1" } } ``` Copy your own code into `repro.test.mjs` and run `npm test`. ----

About using process.hrtime() wrong

The docs for process.hrtime() states:

returns the current high-resolution real time in a [seconds, nanoseconds] tuple Array, where nanoseconds is the remaining part of the real time that can't be represented in second precision.

I understood something was off when console.log-ing the start and end process.hrtime results (with the full array), as it clearly adds 50 ms. This is what you get if you capture the full array and print both start and end:

[ 0, 0 ] [ 0, 50000000 ]

That's 0 seconds and 0.05 seconds in process.hrtime, but you are only comparing the seconds, not the nanoseconds. So changing your test to account for hrtime counting in nanosecons (1 ms = 1 million nanosecs) and comparing the right component of the array (😄) you get your test to pass with this diff:

<       const start = process.hrtime()[0];
---
>       const start = process.hrtime();
12c12
<       const stop = process.hrtime()[0];
---
>       const stop = process.hrtime();
15c15,19
<       assert.equal(stop - start, 50, "process.hrtime gives incorrect results");
---
>       assert.equal(
>         stop[1] - start[1],
>         50 * 1e6,
>         "process.hrtime gives incorrect results"
>       );
fatso83 commented 1 year ago

P.S. You might want to be aware that process.hrtime() has been marked as a legacy API for the last 5 years (Node v10) and that you should prefer to use process.hrtime.bigint() these days. It has a simple API, as it returns a scalar return value which would have avoided this bug altogether 👍

P.P.S. If you somehow manage to reproduce the ESM vs CJS inconsistency, please shout out so that we can take a look. We need to have two bits of code: the one that passes and the one that fails.

mrft commented 1 year ago

@fatso83 Thanks a lot for investigating.

The [0] in the provided test case was just an example I did here trying to stick to the essence.

I still don't understand why my tests would suddenly start failing after changing the tsconfig settings, but I realised that if I used fake-timers in my tests, I could just as well use Date.now() instead, and only use process.hrtime.bigint() for some performance tests (which will not use fake-timers).

So I have found an easy workaround by now, but I did want to let you know in case it was some hidden issue in this library.

fatso83 commented 1 year ago

@mrft No worries, glad if I could remove some sources of confusion. If you still experience this and manage to find some way of consistently reproducing this, please create a minimally reproducible test case and I will check it out asap. Until then, I will just assume this was some other temporary weirdness causing issues 😄

P.S. You should be able to use process.hrtime.bigint() with fake-timers. We mock that as well.