Skip to content

Commit a37816b

Browse files
authored
test(debugger): fix flaky time budget integration test (#7103)
Adds unit tests with mocked time for the debugger snapshot collector deadline mechanism and removes strict timing assertions from the flaky 1ms budget integration test. The integration test was failing in CI due to unpredictable execution times in GitHub Actions environments. The test set a 1ms capture timeout and expected thread pause time ≤16ms, which was too tight for resource-constrained CI environments.
1 parent a1f53d8 commit a37816b

2 files changed

Lines changed: 225 additions & 7 deletions

File tree

integration-tests/debugger/snapshot-time-budget.spec.js

Lines changed: 20 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -20,8 +20,11 @@ describe('Dynamic Instrumentation', function () {
2020

2121
it(
2222
'should include partial snapshot marked with notCapturedReason: timeout',
23-
// A tolerance of 15ms is used to avoid flakiness
24-
test({ t, maxPausedTime: budget + 15, breakpointIndex: 0, maxReferenceDepth: 5 }, (locals) => {
23+
// Timing is tested in unit tests with mocked time (collector-deadline.spec.js).
24+
// This integration test verifies the end-to-end behavior: that timeout markers
25+
// appear in snapshots when the budget is exceeded. We don't assert on exact timing
26+
// to avoid flakiness in CI environments where execution time is unpredictable.
27+
test({ t, breakpointIndex: 0, maxReferenceDepth: 5 }, (locals) => {
2528
assert.strictEqual(
2629
containsTimeBudget(locals),
2730
true,
@@ -187,7 +190,15 @@ describe('Dynamic Instrumentation', function () {
187190
})
188191
})
189192

190-
function test ({ t, maxPausedTime = 0, breakpointIndex, maxReferenceDepth }, assertFn) {
193+
/**
194+
* @param {object} config
195+
* @param {object} config.t - Test environment
196+
* @param {number} [config.maxPausedTime] - Optional maximum pause time in ms (skips timing assertion if not provided)
197+
* @param {number} config.breakpointIndex - Index of the breakpoint to test
198+
* @param {number} config.maxReferenceDepth - Maximum reference depth for snapshot
199+
* @param {Function} [assertFn] - Optional assertion function for the snapshot locals
200+
*/
201+
function test ({ t, maxPausedTime, breakpointIndex, maxReferenceDepth }, assertFn) {
191202
const breakpoint = t.breakpoints[breakpointIndex]
192203

193204
return async function () {
@@ -200,10 +211,12 @@ function test ({ t, maxPausedTime = 0, breakpointIndex, maxReferenceDepth }, ass
200211

201212
const { data } = await breakpoint.triggerBreakpoint()
202213

203-
assert.ok(
204-
data.paused <= maxPausedTime,
205-
`expected thread to be paused <=${maxPausedTime}ms, but was paused for ~${data.paused}ms`
206-
)
214+
if (maxPausedTime !== undefined) {
215+
assert.ok(
216+
data.paused <= maxPausedTime,
217+
`expected thread to be paused <=${maxPausedTime}ms, but was paused for ~${data.paused}ms`
218+
)
219+
}
207220

208221
const snapshot = await snapshotPromise
209222
assertFn?.(snapshot.captures.lines[breakpoint.line].locals)
Lines changed: 205 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,205 @@
1+
'use strict'
2+
3+
const assert = require('node:assert/strict')
4+
const { afterEach, beforeEach, describe, it } = require('mocha')
5+
const sinon = require('sinon')
6+
require('../../../setup/mocha')
7+
8+
const session = require('./stub-session')
9+
const proxyquire = require('proxyquire')
10+
const { timeBudgetSym } = require('../../../../src/debugger/devtools_client/snapshot/symbols')
11+
12+
describe('debugger -> devtools client -> snapshot collector deadline', function () {
13+
let collectObjectProperties
14+
let clock
15+
16+
beforeEach(async function () {
17+
clock = sinon.useFakeTimers()
18+
19+
// Stub the collector with the stubbed session
20+
const collectorWithStub = proxyquire('../../../../src/debugger/devtools_client/snapshot/collector', {
21+
'../session': session
22+
})
23+
collectObjectProperties = collectorWithStub.collectObjectProperties
24+
25+
await session.post('Debugger.enable')
26+
})
27+
28+
afterEach(async function () {
29+
session.removeAllListeners('Debugger.scriptParsed')
30+
session.removeAllListeners('Debugger.paused')
31+
await session.post('Debugger.disable')
32+
clock.restore()
33+
})
34+
35+
it('should not mark properties with timeout when deadline is not exceeded', async function () {
36+
const ctx = {
37+
deadlineReached: false,
38+
captureErrors: []
39+
}
40+
41+
const opts = {
42+
maxReferenceDepth: 3,
43+
maxCollectionSize: 100,
44+
maxFieldCount: 100,
45+
deadlineNs: 100_000_000n, // 100ms
46+
ctx
47+
}
48+
49+
const obj = { a: 1, b: 2, c: 3 }
50+
51+
const objectId = await getObjectIdForObject(obj)
52+
const properties = await collectObjectProperties(objectId, opts, 0)
53+
54+
// Verify no properties are marked with timeout symbol
55+
for (const prop of properties) {
56+
assert.strictEqual(prop.value?.[timeBudgetSym], undefined)
57+
}
58+
59+
// Verify deadline was not reached
60+
assert.strictEqual(ctx.deadlineReached, false)
61+
})
62+
63+
it('should mark properties with timeout when deadline is exceeded', async function () {
64+
// Override the hrtime stub to advance time on each call
65+
// This simulates time passing during collection
66+
sinon.restore()
67+
clock = sinon.useFakeTimers()
68+
sinon.stub(process.hrtime, 'bigint').callsFake(() => {
69+
const time = BigInt(clock.now) * 1_000_000n
70+
clock.tick(50) // Advance by 50ms after each call
71+
return time
72+
})
73+
74+
const ctx = {
75+
deadlineReached: false,
76+
captureErrors: []
77+
}
78+
79+
const opts = {
80+
maxReferenceDepth: 5, // Deep enough to require multiple calls
81+
maxCollectionSize: 100,
82+
maxFieldCount: 100,
83+
deadlineNs: 10_000_000n, // 10ms (very tight deadline)
84+
ctx
85+
}
86+
87+
// Create a nested object structure that will take time to collect
88+
const nestedObj = {
89+
level1: {
90+
level2: {
91+
level3: {
92+
level4: {
93+
level5: { a: 1, b: 2, c: 3 }
94+
}
95+
}
96+
}
97+
}
98+
}
99+
100+
const objectId = await getObjectIdForObject(nestedObj)
101+
await collectObjectProperties(objectId, opts, 0)
102+
103+
// Verify deadline was reached during collection
104+
assert.strictEqual(ctx.deadlineReached, true)
105+
})
106+
107+
it('should cache deadline reached state in ctx', async function () {
108+
let hrtimeCallCount = 0
109+
110+
// Override the hrtime stub to track calls and advance time
111+
sinon.restore()
112+
clock = sinon.useFakeTimers()
113+
sinon.stub(process.hrtime, 'bigint').callsFake(() => {
114+
const time = BigInt(clock.now) * 1_000_000n
115+
hrtimeCallCount++
116+
clock.tick(30) // Advance by 30ms after each call
117+
return time
118+
})
119+
120+
const ctx = {
121+
deadlineReached: false,
122+
captureErrors: []
123+
}
124+
125+
const opts = {
126+
maxReferenceDepth: 5,
127+
maxCollectionSize: 100,
128+
maxFieldCount: 100,
129+
deadlineNs: 50_000_000n, // 50ms (will be exceeded after a few calls)
130+
ctx
131+
}
132+
133+
// Create an object with multiple nested properties to trigger multiple overBudget checks
134+
const objWithManyProps = {
135+
a: { nested: { deep: 1 } },
136+
b: { nested: { deep: 2 } },
137+
c: { nested: { deep: 3 } },
138+
d: { nested: { deep: 4 } }
139+
}
140+
141+
const objectId = await getObjectIdForObject(objWithManyProps)
142+
await collectObjectProperties(objectId, opts, 0)
143+
144+
// Verify deadline was reached
145+
assert.strictEqual(ctx.deadlineReached, true)
146+
147+
// The hrtime should be called at least a couple times
148+
// but once deadlineReached is cached, it shouldn't be called again
149+
assert.ok(hrtimeCallCount >= 2, `Expected at least 2 hrtime calls, got ${hrtimeCallCount}`)
150+
})
151+
152+
it('should immediately return true for overBudget when deadline already reached', async function () {
153+
// Advance time past deadline
154+
clock.tick(200)
155+
156+
const ctx = {
157+
deadlineReached: true, // Already marked as reached
158+
captureErrors: []
159+
}
160+
161+
const opts = {
162+
maxReferenceDepth: 5,
163+
maxCollectionSize: 100,
164+
maxFieldCount: 100,
165+
deadlineNs: 100_000_000n, // 100ms
166+
ctx
167+
}
168+
169+
// Track CDP calls to verify we short-circuit
170+
let cdpCallCount = 0
171+
const originalPost = session.post.bind(session)
172+
session.post = function (method, params) {
173+
if (method === 'Runtime.getProperties') {
174+
cdpCallCount++
175+
}
176+
return originalPost(method, params)
177+
}
178+
179+
// Create a nested object that would normally require many CDP calls
180+
const nestedObj = {
181+
a: { nested: { deep: 1 } },
182+
b: { nested: { deep: 2 } },
183+
c: { nested: { deep: 3 } },
184+
d: { nested: { deep: 4 } }
185+
}
186+
187+
const objectId = await getObjectIdForObject(nestedObj)
188+
await collectObjectProperties(objectId, opts, 0)
189+
190+
// Restore original
191+
session.post = originalPost
192+
193+
// Verify ctx.deadlineReached remains true
194+
assert.strictEqual(ctx.deadlineReached, true)
195+
196+
// Verify we made very few CDP calls (should be 1 for the root object only)
197+
// If deadline wasn't already reached, this would make many more calls for nested properties
198+
assert.ok(cdpCallCount <= 1, `Expected at most 1 CDP call due to short-circuit, but made ${cdpCallCount}`)
199+
})
200+
})
201+
202+
async function getObjectIdForObject (obj) {
203+
const { result: { objectId } } = await session.post('Runtime.evaluate', { expression: `(${JSON.stringify(obj)})` })
204+
return objectId
205+
}

0 commit comments

Comments
 (0)