Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Backport v6.x] test: less flaky timers acceptance test, rework fast timer tests to pass them faster #3679

Merged
merged 1 commit into from
Oct 4, 2024
Merged

[Backport v6.x] test: less flaky timers acceptance test, rework fast timer tests to pass them faster #3679

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 2 additions & 5 deletions lib/util/timers.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand Down Expand Up @@ -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)
},
/**
Expand All @@ -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)
}
},
/**
Expand Down
170 changes: 115 additions & 55 deletions test/timers.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 })
Expand All @@ -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) => {
Expand All @@ -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)
Expand All @@ -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)
Expand All @@ -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()

Expand All @@ -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
})
})