Skip to content

Commit 5308d29

Browse files
Uzlopakmetcoder95
Uzlopak
and
metcoder95
authored
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 <[email protected]>
1 parent 2d524cf commit 5308d29

2 files changed

Lines changed: 117 additions & 60 deletions

File tree

‎lib/util/timers.js‎

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -14,9 +14,6 @@
1414
* Consequently, timers may trigger later than their scheduled time.
1515
*/
1616

17-
const nativeSetTimeout = global.setTimeout
18-
const nativeClearTimeout = global.clearTimeout
19-
2017
/**
2118
* The fastNow variable contains the internal fast timer clock value.
2219
*
@@ -340,7 +337,7 @@ module.exports = {
340337
// If the delay is less than or equal to the RESOLUTION_MS value return a
341338
// native Node.js Timer instance.
342339
return delay <= RESOLUTION_MS
343-
? nativeSetTimeout(callback, delay, arg)
340+
? setTimeout(callback, delay, arg)
344341
: new FastTimer(callback, delay, arg)
345342
},
346343
/**
@@ -359,7 +356,7 @@ module.exports = {
359356
// Otherwise it is an instance of a native NodeJS.Timeout, so call the
360357
// Node.js native clearTimeout function.
361358
} else {
362-
nativeClearTimeout(timeout)
359+
clearTimeout(timeout)
363360
}
364361
},
365362
/**

‎test/timers.js‎

Lines changed: 115 additions & 55 deletions
Original file line numberDiff line numberDiff line change
@@ -2,10 +2,25 @@
22

33
const { tspl } = require('@matteo.collina/tspl')
44
const { describe, test } = require('node:test')
5+
const FakeTimers = require('@sinonjs/fake-timers')
6+
7+
const clock = FakeTimers.install()
58

69
const timers = require('../lib/util/timers')
710
const { eventLoopBlocker } = require('./utils/event-loop-blocker')
811

12+
// timers.setTimeout implements a low resolution timer with a 500 ms granularity
13+
// It is expected that in the worst case, a timer will fire about 500 ms after the
14+
// intended amount of time, an extra 200 ms is added to account event loop overhead
15+
// Timers should never fire excessively early, 1ms early is tolerated
16+
const ACCEPTABLE_DELTA = 700
17+
18+
function tick (duration) {
19+
for (let i = 0; i < duration; ++i) {
20+
clock.tick(1)
21+
}
22+
}
23+
924
describe('timers', () => {
1025
test('timers exports a clearTimeout', (t) => {
1126
t = tspl(t, { plan: 1 })
@@ -26,20 +41,19 @@ describe('timers', () => {
2641
t.strictEqual(timers.setTimeout(() => { }, 1e3)[timers.kFastTimer], undefined)
2742
})
2843

29-
test('setTimeout instantiates a FastTimer when delay is smaller than 1e3 ms', (t) => {
44+
test('setTimeout instantiates a FastTimer when delay is bigger than 1e3 ms', (t) => {
3045
t = tspl(t, { plan: 1 })
3146

3247
const timeout = timers.setTimeout(() => { }, 1001)
3348
t.strictEqual(timeout[timers.kFastTimer], true)
3449
})
3550

3651
test('clearTimeout can clear a node native Timeout', (t) => {
37-
t = tspl(t, { plan: 3 })
52+
t = tspl(t, { plan: 1 })
3853

39-
const nativeTimeoutId = setTimeout(() => { }, 1e6)
40-
t.equal(nativeTimeoutId._idleTimeout, 1e6)
54+
const nativeTimeoutId = setTimeout(() => { t.fail() }, 1)
4155
t.ok(timers.clearTimeout(nativeTimeoutId) === undefined)
42-
t.equal(nativeTimeoutId._idleTimeout, -1)
56+
tick(10)
4357
})
4458

4559
test('a FastTimer will get a _idleStart value after short time', async (t) => {
@@ -51,7 +65,8 @@ describe('timers', () => {
5165

5266
t.strictEqual(timer[timers.kFastTimer], true)
5367
t.strictEqual(timer._idleStart, -1)
54-
await new Promise((resolve) => setTimeout(resolve, 750))
68+
69+
tick(1e3)
5570
t.notStrictEqual(timer._idleStart, -1)
5671

5772
timers.clearTimeout(timer)
@@ -66,7 +81,7 @@ describe('timers', () => {
6681

6782
t.strictEqual(timer[timers.kFastTimer], true)
6883
t.strictEqual(timer._idleStart, -1)
69-
await new Promise((resolve) => setTimeout(resolve, 750))
84+
tick(750)
7085
t.notStrictEqual(timer._idleStart, -1)
7186
timers.clearTimeout(timer)
7287
t.strictEqual(timer._idleStart, -1)
@@ -83,100 +98,113 @@ describe('timers', () => {
8398
timers.clearTimeout(timer)
8499

85100
t.strictEqual(timer._idleStart, -1)
86-
await new Promise((resolve) => setTimeout(resolve, 750))
101+
tick(750)
87102
t.strictEqual(timer._idleStart, -1)
88103
})
89104

90105
test('a cleared FastTimer can be refreshed', async (t) => {
91106
t = tspl(t, { plan: 2 })
92107

93-
const timer = timers.setTimeout(() => {
108+
const timer = timers.setFastTimeout(() => {
94109
t.ok('pass')
95110
}, 1001)
96111

97112
t.strictEqual(timer[timers.kFastTimer], true)
98113
timers.clearTimeout(timer)
99114
timer.refresh()
100-
await new Promise((resolve) => setTimeout(resolve, 2000))
115+
tick(2000)
101116
timers.clearTimeout(timer)
102117
})
103118

104119
const getDelta = (start, target) => {
105-
const end = process.hrtime.bigint()
106-
const actual = (end - start) / 1_000_000n
107-
return actual - BigInt(target)
120+
const end = performance.now()
121+
const actual = end - start
122+
return actual - target
108123
}
109124

110-
// timers.setTimeout implements a low resolution timer with a 500 ms granularity
111-
// It is expected that in the worst case, a timer will fire about 500 ms after the
112-
// intended amount of time, an extra 200 ms is added to account event loop overhead
113-
// Timers should never fire excessively early, 1ms early is tolerated
114-
const ACCEPTABLE_DELTA = 700n
115-
116-
test('meet acceptable resolution time', async (t) => {
117-
const testTimeouts = [0, 1, 499, 500, 501, 990, 999, 1000, 1001, 1100, 1400, 1499, 1500, 4000, 5000]
118-
119-
t = tspl(t, { plan: 1 + testTimeouts.length * 2 })
120-
121-
const start = process.hrtime.bigint()
122-
123-
for (const target of testTimeouts) {
124-
timers.setTimeout(() => {
125-
const delta = getDelta(start, target)
126-
127-
t.ok(delta >= -1n, `${target}ms fired early`)
128-
t.ok(delta < ACCEPTABLE_DELTA, `${target}ms fired late, got difference of ${delta}ms`)
129-
}, target)
130-
}
131-
132-
setTimeout(() => t.ok(true), 6000)
133-
await t.completed
134-
})
135-
136125
test('refresh correctly with timeout < TICK_MS', async (t) => {
137126
t = tspl(t, { plan: 3 })
138127

139-
const start = process.hrtime.bigint()
128+
const start = performance.now()
140129

141130
const timeout = timers.setTimeout(() => {
142-
// 400 ms timer was refreshed after 600ms; total target is 1000
143-
const delta = getDelta(start, 1000)
131+
// 80 ms timer was refreshed after 120 ms; total target is 200 ms
132+
const delta = getDelta(start, 200)
144133

145-
t.ok(delta >= -1n, 'refreshed timer fired early')
134+
t.ok(delta >= -1, 'refreshed timer fired early')
146135
t.ok(delta < ACCEPTABLE_DELTA, 'refreshed timer fired late')
147-
}, 400)
136+
}, 80)
148137

149-
setTimeout(() => timeout.refresh(), 200)
150-
setTimeout(() => timeout.refresh(), 400)
151-
setTimeout(() => timeout.refresh(), 600)
138+
setTimeout(() => timeout.refresh(), 40)
139+
setTimeout(() => timeout.refresh(), 80)
140+
setTimeout(() => timeout.refresh(), 120)
152141

153-
setTimeout(() => t.ok(true), 1500)
142+
setTimeout(() => t.ok(true), 260)
143+
144+
tick(500)
154145
await t.completed
155146
})
156147

157148
test('refresh correctly with timeout > TICK_MS', async (t) => {
158149
t = tspl(t, { plan: 3 })
159150

160-
const start = process.hrtime.bigint()
151+
const start = performance.now()
161152

162153
const timeout = timers.setTimeout(() => {
163154
// 501ms timer was refreshed after 1250ms; total target is 1751
164155
const delta = getDelta(start, 1751)
165156

166-
t.ok(delta >= -1n, 'refreshed timer fired early')
157+
t.ok(delta >= -1, 'refreshed timer fired early')
167158
t.ok(delta < ACCEPTABLE_DELTA, 'refreshed timer fired late')
168159
}, 501)
169160

170161
setTimeout(() => timeout.refresh(), 250)
171162
setTimeout(() => timeout.refresh(), 750)
172163
setTimeout(() => timeout.refresh(), 1250)
173164

174-
setTimeout(() => t.ok(true), 3000)
165+
setTimeout(() => t.ok(true), 1800)
166+
167+
tick(2000)
168+
await t.completed
169+
})
170+
171+
test('refresh correctly FastTimer with timeout > TICK_MS', async (t) => {
172+
t = tspl(t, { plan: 3 })
173+
174+
// The long running FastTimer will ensure that the internal clock is
175+
// incremented by the TICK_MS value in the onTick function
176+
const longRunningFastTimer = timers.setTimeout(() => {}, 1e10)
177+
178+
const start = timers.now()
179+
180+
const timeout = timers.setFastTimeout(() => {
181+
const delta = (timers.now() - start) - 2493
182+
183+
t.ok(delta >= -1, `refreshed timer fired early (${delta} ms)`)
184+
t.ok(delta < ACCEPTABLE_DELTA, `refreshed timer fired late (${delta} ms)`)
185+
}, 1001)
186+
187+
tick(250)
188+
timeout.refresh()
189+
190+
tick(250)
191+
timeout.refresh()
192+
193+
tick(250)
194+
timeout.refresh()
195+
196+
tick(250)
197+
timeout.refresh()
198+
199+
timers.clearTimeout(longRunningFastTimer)
200+
setTimeout(() => t.ok(true), 500)
201+
202+
tick(5000)
175203
await t.completed
176204
})
177205

178206
test('a FastTimer will only increment by the defined TICK_MS value', async (t) => {
179-
t = tspl(t, { plan: 2 })
207+
t = tspl(t, { plan: 6 })
180208

181209
const startInternalClock = timers.now()
182210

@@ -187,12 +215,44 @@ describe('timers', () => {
187215
eventLoopBlocker(1000)
188216

189217
// wait to ensure the timer has fired in the next loop
190-
await new Promise((resolve) => setTimeout(resolve, 1))
218+
await new Promise((resolve) => resolve())
191219

220+
tick(250)
221+
t.strictEqual(timers.now() - startInternalClock, 0)
222+
tick(250)
223+
t.strictEqual(timers.now() - startInternalClock, 499)
224+
tick(250)
192225
t.strictEqual(timers.now() - startInternalClock, 499)
193-
await new Promise((resolve) => setTimeout(resolve, 1000))
194-
t.ok(timers.now() - startInternalClock <= 1497)
226+
tick(250)
227+
t.strictEqual(timers.now() - startInternalClock, 998)
228+
tick(250)
229+
t.strictEqual(timers.now() - startInternalClock, 998)
230+
tick(250)
231+
t.strictEqual(timers.now() - startInternalClock, 1497)
195232

196233
timers.clearTimeout(longRunningFastTimer)
197234
})
235+
236+
test('meet acceptable resolution time', async (t) => {
237+
const testTimeouts = [0, 1, 499, 500, 501, 990, 999, 1000, 1001, 1100, 1400, 1499, 1500, 4000, 5000]
238+
239+
t = tspl(t, { plan: testTimeouts.length * 2 })
240+
241+
const start = performance.now()
242+
243+
for (const target of testTimeouts) {
244+
timers.setTimeout(() => {
245+
const delta = getDelta(start, target)
246+
247+
t.ok(delta >= -1, `${target}ms fired early`)
248+
t.ok(delta < ACCEPTABLE_DELTA, `${target}ms fired late, got difference of ${delta}ms`)
249+
}, target)
250+
}
251+
252+
for (let i = 0; i < 6000; ++i) {
253+
clock.tick(1)
254+
}
255+
256+
await t.completed
257+
})
198258
})

0 commit comments

Comments
 (0)