From 5308d2924e1d9fa26a79f492b327af7f07a6e40c Mon Sep 17 00:00:00 2001 From: Aras Abbasi Date: Tue, 1 Oct 2024 22:03:44 +0200 Subject: [PATCH] test: less flaky timers acceptance test, rework fast timer tests to pass them faster (#3656) * test: less flaky timers acceptance test * use fake timers * tick 10 * one tick --------- Co-authored-by: Carlos Fuentes --- lib/util/timers.js | 7 +- test/timers.js | 170 ++++++++++++++++++++++++++++++--------------- 2 files changed, 117 insertions(+), 60 deletions(-) diff --git a/lib/util/timers.js b/lib/util/timers.js index 36b6bbf985e..c15bbc37aa1 100644 --- a/lib/util/timers.js +++ b/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) } }, /** diff --git a/test/timers.js b/test/timers.js index 621e1aa74bb..9d8cd596e90 100644 --- a/test/timers.js +++ b/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,7 +41,7 @@ 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) @@ -34,12 +49,11 @@ describe('timers', () => { }) 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,87 +98,63 @@ 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) @@ -171,12 +162,49 @@ describe('timers', () => { 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 + }) })