Skip to content

Commit

Permalink
test: less flaky timers acceptance test, rework fast timer tests to p…
Browse files Browse the repository at this point in the history 
…ass them faster (nodejs#3656)

* test: less flaky timers acceptance test

* use fake timers

* tick 10

* one tick

---------

Co-authored-by: Carlos Fuentes <me@metcoder.dev>
  • Loading branch information
@Uzlopak @metcoder95 @flakey5
2 people authored and flakey5 committed Oct 8, 2024
1 parent 5448e78 commit 61ec830
Show file tree
Hide file tree
Showing 2 changed files with 117 additions and 60 deletions.
7 changes: 2 additions & 5 deletions lib/util/timers.js
View file
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
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
})
})

0 comments on commit 61ec830

Please sign in to comment.