test: less flaky timers acceptance test, rework fast timer tests to p…

…ass them faster (#3656) (#3679)

* test: less flaky timers acceptance test

* use fake timers

* tick 10

* one tick

---------

Co-authored-by: Carlos Fuentes <me@metcoder.dev>
(cherry picked from commit 5308d29)

Co-authored-by: Aras Abbasi <aras.abbasi@googlemail.com>

lib/util/timers.js

@@ -14,9 +14,6 @@
  * Consequently, timers may trigger later than their scheduled time.
  */
 
-const nativeSetTimeout = global.setTimeout
-const nativeClearTimeout = global.clearTimeout
-
 /**
  * The fastNow variable contains the internal fast timer clock value.
  *
@@ -340,7 +337,7 @@ module.exports = {
     // If the delay is less than or equal to the RESOLUTION_MS value return a
     // native Node.js Timer instance.
     return delay <= RESOLUTION_MS
-      ? nativeSetTimeout(callback, delay, arg)
+      ? setTimeout(callback, delay, arg)
       : new FastTimer(callback, delay, arg)
   },
   /**
@@ -359,7 +356,7 @@ module.exports = {
       // Otherwise it is an instance of a native NodeJS.Timeout, so call the
       // Node.js native clearTimeout function.
     } else {
-      nativeClearTimeout(timeout)
+      clearTimeout(timeout)
     }
   },
   /**

test/timers.js

@@ -2,10 +2,25 @@
 
 const { tspl } = require('@matteo.collina/tspl')
 const { describe, test } = require('node:test')
+const FakeTimers = require('@sinonjs/fake-timers')
+
+const clock = FakeTimers.install()
 
 const timers = require('../lib/util/timers')
 const { eventLoopBlocker } = require('./utils/event-loop-blocker')
 
+// timers.setTimeout implements a low resolution timer with a 500 ms granularity
+// It is expected that in the worst case, a timer will fire about 500 ms after the
+// intended amount of time, an extra 200 ms is added to account event loop overhead
+// Timers should never fire excessively early, 1ms early is tolerated
+const ACCEPTABLE_DELTA = 700
+
+function tick (duration) {
+  for (let i = 0; i < duration; ++i) {
+    clock.tick(1)
+  }
+}
+
 describe('timers', () => {
   test('timers exports a clearTimeout', (t) => {
     t = tspl(t, { plan: 1 })
@@ -26,20 +41,19 @@ describe('timers', () => {
     t.strictEqual(timers.setTimeout(() => { }, 1e3)[timers.kFastTimer], undefined)
   })
 
-  test('setTimeout instantiates a FastTimer when delay is smaller than 1e3 ms', (t) => {
+  test('setTimeout instantiates a FastTimer when delay is bigger than 1e3 ms', (t) => {
     t = tspl(t, { plan: 1 })
 
     const timeout = timers.setTimeout(() => { }, 1001)
     t.strictEqual(timeout[timers.kFastTimer], true)
   })
 
   test('clearTimeout can clear a node native Timeout', (t) => {
-    t = tspl(t, { plan: 3 })
+    t = tspl(t, { plan: 1 })
 
-    const nativeTimeoutId = setTimeout(() => { }, 1e6)
-    t.equal(nativeTimeoutId._idleTimeout, 1e6)
+    const nativeTimeoutId = setTimeout(() => { t.fail() }, 1)
     t.ok(timers.clearTimeout(nativeTimeoutId) === undefined)
-    t.equal(nativeTimeoutId._idleTimeout, -1)
+    tick(10)
   })
 
   test('a FastTimer will get a _idleStart value after short time', async (t) => {
@@ -51,7 +65,8 @@ describe('timers', () => {
 
     t.strictEqual(timer[timers.kFastTimer], true)
     t.strictEqual(timer._idleStart, -1)
-    await new Promise((resolve) => setTimeout(resolve, 750))
+
+    tick(1e3)
     t.notStrictEqual(timer._idleStart, -1)
 
     timers.clearTimeout(timer)
@@ -66,7 +81,7 @@ describe('timers', () => {
 
     t.strictEqual(timer[timers.kFastTimer], true)
     t.strictEqual(timer._idleStart, -1)
-    await new Promise((resolve) => setTimeout(resolve, 750))
+    tick(750)
     t.notStrictEqual(timer._idleStart, -1)
     timers.clearTimeout(timer)
     t.strictEqual(timer._idleStart, -1)
@@ -83,100 +98,113 @@ describe('timers', () => {
     timers.clearTimeout(timer)
 
     t.strictEqual(timer._idleStart, -1)
-    await new Promise((resolve) => setTimeout(resolve, 750))
+    tick(750)
     t.strictEqual(timer._idleStart, -1)
   })
 
   test('a cleared FastTimer can be refreshed', async (t) => {
     t = tspl(t, { plan: 2 })
 
-    const timer = timers.setTimeout(() => {
+    const timer = timers.setFastTimeout(() => {
       t.ok('pass')
     }, 1001)
 
     t.strictEqual(timer[timers.kFastTimer], true)
     timers.clearTimeout(timer)
     timer.refresh()
-    await new Promise((resolve) => setTimeout(resolve, 2000))
+    tick(2000)
     timers.clearTimeout(timer)
   })
 
   const getDelta = (start, target) => {
-    const end = process.hrtime.bigint()
-    const actual = (end - start) / 1_000_000n
-    return actual - BigInt(target)
+    const end = performance.now()
+    const actual = end - start
+    return actual - target
   }
 
-  // timers.setTimeout implements a low resolution timer with a 500 ms granularity
-  // It is expected that in the worst case, a timer will fire about 500 ms after the
-  // intended amount of time, an extra 200 ms is added to account event loop overhead
-  // Timers should never fire excessively early, 1ms early is tolerated
-  const ACCEPTABLE_DELTA = 700n
-
-  test('meet acceptable resolution time', async (t) => {
-    const testTimeouts = [0, 1, 499, 500, 501, 990, 999, 1000, 1001, 1100, 1400, 1499, 1500, 4000, 5000]
-
-    t = tspl(t, { plan: 1 + testTimeouts.length * 2 })
-
-    const start = process.hrtime.bigint()
-
-    for (const target of testTimeouts) {
-      timers.setTimeout(() => {
-        const delta = getDelta(start, target)
-
-        t.ok(delta >= -1n, `${target}ms fired early`)
-        t.ok(delta < ACCEPTABLE_DELTA, `${target}ms fired late, got difference of ${delta}ms`)
-      }, target)
-    }
-
-    setTimeout(() => t.ok(true), 6000)
-    await t.completed
-  })
-
   test('refresh correctly with timeout < TICK_MS', async (t) => {
     t = tspl(t, { plan: 3 })
 
-    const start = process.hrtime.bigint()
+    const start = performance.now()
 
     const timeout = timers.setTimeout(() => {
-      // 400 ms timer was refreshed after 600ms; total target is 1000
-      const delta = getDelta(start, 1000)
+      // 80 ms timer was refreshed after 120 ms; total target is 200 ms
+      const delta = getDelta(start, 200)
 
-      t.ok(delta >= -1n, 'refreshed timer fired early')
+      t.ok(delta >= -1, 'refreshed timer fired early')
       t.ok(delta < ACCEPTABLE_DELTA, 'refreshed timer fired late')
-    }, 400)
+    }, 80)
 
-    setTimeout(() => timeout.refresh(), 200)
-    setTimeout(() => timeout.refresh(), 400)
-    setTimeout(() => timeout.refresh(), 600)
+    setTimeout(() => timeout.refresh(), 40)
+    setTimeout(() => timeout.refresh(), 80)
+    setTimeout(() => timeout.refresh(), 120)
 
-    setTimeout(() => t.ok(true), 1500)
+    setTimeout(() => t.ok(true), 260)
+
+    tick(500)
     await t.completed
   })
 
   test('refresh correctly with timeout > TICK_MS', async (t) => {
     t = tspl(t, { plan: 3 })
 
-    const start = process.hrtime.bigint()
+    const start = performance.now()
 
     const timeout = timers.setTimeout(() => {
       // 501ms timer was refreshed after 1250ms; total target is 1751
       const delta = getDelta(start, 1751)
 
-      t.ok(delta >= -1n, 'refreshed timer fired early')
+      t.ok(delta >= -1, 'refreshed timer fired early')
       t.ok(delta < ACCEPTABLE_DELTA, 'refreshed timer fired late')
     }, 501)
 
     setTimeout(() => timeout.refresh(), 250)
     setTimeout(() => timeout.refresh(), 750)
     setTimeout(() => timeout.refresh(), 1250)
 
-    setTimeout(() => t.ok(true), 3000)
+    setTimeout(() => t.ok(true), 1800)
+
+    tick(2000)
+    await t.completed
+  })
+
+  test('refresh correctly FastTimer with timeout > TICK_MS', async (t) => {
+    t = tspl(t, { plan: 3 })
+
+    // The long running FastTimer will ensure that the internal clock is
+    // incremented by the TICK_MS value in the onTick function
+    const longRunningFastTimer = timers.setTimeout(() => {}, 1e10)
+
+    const start = timers.now()
+
+    const timeout = timers.setFastTimeout(() => {
+      const delta = (timers.now() - start) - 2493
+
+      t.ok(delta >= -1, `refreshed timer fired early (${delta} ms)`)
+      t.ok(delta < ACCEPTABLE_DELTA, `refreshed timer fired late (${delta} ms)`)
+    }, 1001)
+
+    tick(250)
+    timeout.refresh()
+
+    tick(250)
+    timeout.refresh()
+
+    tick(250)
+    timeout.refresh()
+
+    tick(250)
+    timeout.refresh()
+
+    timers.clearTimeout(longRunningFastTimer)
+    setTimeout(() => t.ok(true), 500)
+
+    tick(5000)
     await t.completed
   })
 
   test('a FastTimer will only increment by the defined TICK_MS value', async (t) => {
-    t = tspl(t, { plan: 2 })
+    t = tspl(t, { plan: 6 })
 
     const startInternalClock = timers.now()
 
@@ -187,12 +215,44 @@ describe('timers', () => {
     eventLoopBlocker(1000)
 
     // wait to ensure the timer has fired in the next loop
-    await new Promise((resolve) => setTimeout(resolve, 1))
+    await new Promise((resolve) => resolve())
 
+    tick(250)
+    t.strictEqual(timers.now() - startInternalClock, 0)
+    tick(250)
+    t.strictEqual(timers.now() - startInternalClock, 499)
+    tick(250)
     t.strictEqual(timers.now() - startInternalClock, 499)
-    await new Promise((resolve) => setTimeout(resolve, 1000))
-    t.ok(timers.now() - startInternalClock <= 1497)
+    tick(250)
+    t.strictEqual(timers.now() - startInternalClock, 998)
+    tick(250)
+    t.strictEqual(timers.now() - startInternalClock, 998)
+    tick(250)
+    t.strictEqual(timers.now() - startInternalClock, 1497)
 
     timers.clearTimeout(longRunningFastTimer)
   })
+
+  test('meet acceptable resolution time', async (t) => {
+    const testTimeouts = [0, 1, 499, 500, 501, 990, 999, 1000, 1001, 1100, 1400, 1499, 1500, 4000, 5000]
+
+    t = tspl(t, { plan: testTimeouts.length * 2 })
+
+    const start = performance.now()
+
+    for (const target of testTimeouts) {
+      timers.setTimeout(() => {
+        const delta = getDelta(start, target)
+
+        t.ok(delta >= -1, `${target}ms fired early`)
+        t.ok(delta < ACCEPTABLE_DELTA, `${target}ms fired late, got difference of ${delta}ms`)
+      }, target)
+    }
+
+    for (let i = 0; i < 6000; ++i) {
+      clock.tick(1)
+    }
+
+    await t.completed
+  })
 })