Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
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
193 changes: 159 additions & 34 deletions integration-tests/debugger/snapshot-time-budget.spec.js
Original file line number Diff line number Diff line change
Expand Up @@ -2,10 +2,14 @@

const assert = require('node:assert')
const { setup } = require('./utils')
const {
DEFAULT_MAX_COLLECTION_SIZE,
LARGE_OBJECT_SKIP_THRESHOLD
} = require('../../packages/dd-trace/src/debugger/devtools_client/snapshot/constants')

describe('Dynamic Instrumentation', function () {
describe('input messages', function () {
describe('with snapshot under tight time budget', function () {
describe('with snapshot under time budget', function () {
context('1ms time budget', function () {
// Force a very small time budget in ms to trigger partial snapshots
const budget = 1
Expand All @@ -17,57 +21,177 @@ describe('Dynamic Instrumentation', function () {
it(
'should include partial snapshot marked with notCapturedReason: timeout',
// A tolerance of 15ms is used to avoid flakiness
test({ t, maxPausedTime: budget + 15, breakpointIndex: 0, maxReferenceDepth: 5 })
test({ t, maxPausedTime: budget + 15, breakpointIndex: 0, maxReferenceDepth: 5 }, (locals) => {
assert.strictEqual(
containsTimeBudget(locals),
true,
'expected at least one field/element to be marked with notCapturedReason: "timeout"'
)
})
)
})

context('default time budget', function () {
const budget = 15 // default time budget in ms
const t = setup({ dependencies: ['fastify'] })

// TODO: Make this pass
// eslint-disable-next-line mocha/no-pending-tests
it.skip(
'should keep budget when state includes an object with 1 million properties',
// A tolerance of 5ms is used to avoid flakiness
test({ t, maxPausedTime: budget + 5, breakpointIndex: 1, maxReferenceDepth: 1 })
it(
'should timeout first, then disable subsequent snapshots and emit error diagnostics',
async function () {
const breakpoint = t.breakpoints[1]
const expectedEvaluationErrors = [{
expr: '',
message: 'An object with 1000000 properties was detected while collecting a snapshot. This exceeds ' +
`the maximum number of allowed properties of ${LARGE_OBJECT_SKIP_THRESHOLD}. Future snapshots for ` +
'existing probes in this location will be skipped until the Node.js process is restarted'
}]

// Listen for the first snapshot payload (should contain notCapturedReason: "timeout")
const firstPayloadReceived = new Promise(/** @type {() => void} */ (resolve) => {
t.agent.once('debugger-input', ({ payload: [{ debugger: { snapshot } }] }) => {
const { locals } = snapshot.captures.lines[breakpoint.line]
assert.strictEqual(
containsTimeBudget(locals),
true,
'expected at least one field/element to be marked with notCapturedReason: "timeout"'
)
assert.deepStrictEqual(snapshot.evaluationErrors, expectedEvaluationErrors)
resolve()
})
})

// Install probe with snapshot capture enabled
t.agent.addRemoteConfig(breakpoint.generateRemoteConfig({
captureSnapshot: true,
capture: { maxReferenceDepth: 1 }
}))

// Trigger once; this run is expected to be slow and mark fields with "timeout"
const result1 = /** @type {import('axios').AxiosResponse<{ paused: number }>} */
(await breakpoint.triggerBreakpoint())
assert.ok(
result1.data.paused >= 1_000,
`expected thread to be paused for at least 1 second, but was paused for ~${result1.data.paused}ms`
)

await firstPayloadReceived

// Prepare to assert that no snapshot is produced on a subsequent trigger
const secondPayloadReceived = new Promise(/** @type {() => void} */ (resolve) => {
t.agent.once('debugger-input', ({ payload: [{ debugger: { snapshot } }] }) => {
assert.ok(!Object.hasOwn(snapshot, 'captures'))
assert.deepStrictEqual(snapshot.evaluationErrors, expectedEvaluationErrors)
resolve()
})
})

// Trigger the same breakpoint again directly
const result2 = await t.axios.get(breakpoint.url)
assert.ok(
result2.data.paused <= 50,
`expected thread to be paused <=50ms, but was paused for ~${result2.data.paused}ms`
)

await secondPayloadReceived
}
)
})

context('large object thresholds', function () {
// The tests in this group, should take a lot longer than 100ms to capture a snapshot if no thresholds are
// applied. But they should take a lot less than the 100ms budget if thresholds are applied. Using 100ms means
// that the tests should not be flaky, but still fail if the thresholds are not applied.
const budget = 100
const t = setup({
dependencies: ['fastify'],
env: { DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS: String(budget) }
})

// TODO: Make this pass
// eslint-disable-next-line mocha/no-pending-tests
it.skip(
'should keep budget when state includes an array of 1 million primitives',
// A tolerance of 5ms is used to avoid flakiness
test({ t, maxPausedTime: budget + 5, breakpointIndex: 2, maxReferenceDepth: 1 })
it(
'should keep budget when state includes collections with 1 million elements',
test({ t, maxPausedTime: budget, breakpointIndex: 2, maxReferenceDepth: 1 }, (locals) => {
const notCapturedReason = `Large collection with too many elements (skip threshold: ${
LARGE_OBJECT_SKIP_THRESHOLD
})`
assert.strictEqual(locals.arrOfPrimitives.notCapturedReason, notCapturedReason)
assert.strictEqual(locals.arrOfPrimitives.size, 1_000_000)
assert.strictEqual(locals.arrOfPrimitives.elements.length, 0)
assert.strictEqual(locals.arrOfObjects.notCapturedReason, notCapturedReason)
assert.strictEqual(locals.arrOfObjects.size, 1_000_000)
assert.strictEqual(locals.arrOfObjects.elements.length, 0)
assert.strictEqual(locals.map.notCapturedReason, notCapturedReason)
assert.strictEqual(locals.map.size, 1_000_000)
assert.strictEqual(locals.map.entries.length, 0)
assert.strictEqual(locals.set.notCapturedReason, notCapturedReason)
assert.strictEqual(locals.set.size, 1_000_000)
assert.strictEqual(locals.set.elements.length, 0)
})
)

// TODO: Make this pass
// eslint-disable-next-line mocha/no-pending-tests
it.skip(
'should keep budget when state includes an array of 1 million objects',
// A tolerance of 5ms is used to avoid flakiness
test({ t, maxPausedTime: budget + 5, breakpointIndex: 3, maxReferenceDepth: 1 })
it(
'should keep budget when state includes collections with less than the size threshold',
test({ t, maxPausedTime: budget, breakpointIndex: 3, maxReferenceDepth: 1 }, (locals) => {
assert.strictEqual(locals.arrOfPrimitives.notCapturedReason, 'collectionSize')
assert.strictEqual(locals.arrOfPrimitives.size, LARGE_OBJECT_SKIP_THRESHOLD - 1)
assert.strictEqual(locals.arrOfPrimitives.elements.length, DEFAULT_MAX_COLLECTION_SIZE)
assert.strictEqual(locals.arrOfObjects.notCapturedReason, 'collectionSize')
assert.strictEqual(locals.arrOfObjects.size, LARGE_OBJECT_SKIP_THRESHOLD - 1)
assert.strictEqual(locals.arrOfObjects.elements.length, DEFAULT_MAX_COLLECTION_SIZE)
assert.strictEqual(locals.map.notCapturedReason, 'collectionSize')
assert.strictEqual(locals.map.size, LARGE_OBJECT_SKIP_THRESHOLD - 1)
assert.strictEqual(locals.map.entries.length, DEFAULT_MAX_COLLECTION_SIZE)
assert.strictEqual(locals.set.notCapturedReason, 'collectionSize')
assert.strictEqual(locals.set.size, LARGE_OBJECT_SKIP_THRESHOLD - 1)
assert.strictEqual(locals.set.elements.length, DEFAULT_MAX_COLLECTION_SIZE)
})
)
})

context('fuzzing', function () {
for (let budget = 0; budget < 20; budget++) {
context(`graceful handling with time budget of ${budget}ms`, function () {
// Anything longer than this, and the debugger worker thread most likely crashed.
// Run test with `DD_TRACE_DEBUG=true` to see more.
this.timeout(2000)

const t = setup({
dependencies: ['fastify'],
env: { DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS: String(budget) }
})

// If this test uncovers any issues, it will show itself as being flaky, as the exact timing of how long it
// takes to collect the snapshot is not deterministic.
it('should send a probe result to the agent', async function () {
t.agent.addRemoteConfig(t.generateRemoteConfig({
captureSnapshot: true,
capture: { maxReferenceDepth: 5 }
}))
t.triggerBreakpoint()

const { captures } = await t.snapshotReceived()
// If the snapshot contains a `captures` field, it means it was captured and processes without any issues
assert.ok(
captures !== null && typeof captures === 'object',
'expected snapshot to contain a `captures` object'
)
// To make this test more future-proof, we also assert that the snapshot contains at least one local
// property, though currently this is not necessary.
assert.ok(
Object.keys(captures.lines[t.breakpoint.line].locals).length > 0,
'expected snapshot to contain at least one local property'
)
})
})
}
})
})
})
})

function test ({ t, maxPausedTime, breakpointIndex, maxReferenceDepth }) {
function test ({ t, maxPausedTime = 0, breakpointIndex, maxReferenceDepth }, assertFn) {
const breakpoint = t.breakpoints[breakpointIndex]

return async function () {
const payloadReceived = new Promise((/** @type {(value?: unknown) => void} */ resolve) => {
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { captures } } }] }) => {
const { locals } = captures.lines[breakpoint.line]
assert.strictEqual(
containsTimeBudget(locals),
true,
'expected at least one field/element to be marked with notCapturedReason: "timeout"'
)
resolve()
})
})
const snapshotPromise = t.snapshotReceived()

t.agent.addRemoteConfig(breakpoint.generateRemoteConfig({
captureSnapshot: true,
Expand All @@ -81,7 +205,8 @@ function test ({ t, maxPausedTime, breakpointIndex, maxReferenceDepth }) {
`expected thread to be paused <=${maxPausedTime}ms, but was paused for ~${data.paused}ms`
)

await payloadReceived
const snapshot = await snapshotPromise
assertFn?.(snapshot.captures.lines[breakpoint.line].locals)
}
}

Expand Down
27 changes: 19 additions & 8 deletions integration-tests/debugger/target-app/snapshot-time-budget.js
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,10 @@ require('dd-trace/init')

// @ts-expect-error This code is running in a sandbox where fastify is available
const Fastify = require('fastify')
const {
LARGE_OBJECT_SKIP_THRESHOLD
// @ts-expect-error This code is running in a sandbox where dd-trace is available
} = require('dd-trace/packages/dd-trace/src/debugger/devtools_client/snapshot/constants')

const fastify = Fastify({ logger: { level: 'error' } })

Expand All @@ -18,24 +22,31 @@ fastify.get('/deeply-nested-large-object', function handler () {
return { paused: Number(diff) / 1_000_000 }
})

fastify.get('/large-object-of-primitives', function handler () {
fastify.get('/object-with-many-properties', function handler () {
const obj = generateObject(0, 1_000_000) // eslint-disable-line no-unused-vars
const start = process.hrtime.bigint()
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-object-of-primitives
const diff = process.hrtime.bigint() - start // BREAKPOINT: /object-with-many-properties
return { paused: Number(diff) / 1_000_000 }
})

fastify.get('/large-array-of-primitives', function handler () {
const arr = Array.from({ length: 1_000_000 }, (_, i) => i) // eslint-disable-line no-unused-vars
fastify.get('/large-collections', function handler () {
const arrOfPrimitives = Array.from({ length: 1_000_000 }, (_, i) => i) // eslint-disable-line no-unused-vars
const arrOfObjects = Array.from({ length: 1_000_000 }, (_, i) => ({ i }))
const map = new Map(arrOfObjects.map((obj, i) => [i, obj])) // eslint-disable-line no-unused-vars
const set = new Set(arrOfObjects) // eslint-disable-line no-unused-vars
const start = process.hrtime.bigint()
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-array-of-primitives
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-collections
return { paused: Number(diff) / 1_000_000 }
})

fastify.get('/large-array-of-objects', function handler () {
const arr = Array.from({ length: 1_000_000 }, (_, i) => ({ i })) // eslint-disable-line no-unused-vars
fastify.get('/large-collections-below-size-threshold', function handler () {
// eslint-disable-next-line no-unused-vars
const arrOfPrimitives = Array.from({ length: LARGE_OBJECT_SKIP_THRESHOLD - 1 }, (_, i) => i)
const arrOfObjects = Array.from({ length: LARGE_OBJECT_SKIP_THRESHOLD - 1 }, (_, i) => ({ i }))
const map = new Map(arrOfObjects.map((obj, i) => [i, obj])) // eslint-disable-line no-unused-vars
const set = new Set(arrOfObjects) // eslint-disable-line no-unused-vars
const start = process.hrtime.bigint()
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-array-of-objects
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-collections-below-size-threshold
return { paused: Number(diff) / 1_000_000 }
})

Expand Down
13 changes: 11 additions & 2 deletions integration-tests/debugger/utils.js
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ const pollInterval = 0.1
*
* @typedef {BreakpointInfo & {
* rcConfig: object|null,
* triggerBreakpoint: (url: string) => Promise<import('axios').AxiosResponse<unknown>>,
* triggerBreakpoint: () => Promise<import('axios').AxiosResponse<unknown>>,
* generateRemoteConfig: (overrides?: object) => object,
* generateProbeConfig: BoundGenerateProbeConfigFn
* }} EnrichedBreakpoint
Expand All @@ -66,6 +66,7 @@ const pollInterval = 0.1
* once installed.
* @property {(overrides?: object) => object} generateRemoteConfig - Generates RC for the primary breakpoint.
* @property {BoundGenerateProbeConfigFn} generateProbeConfig - Generates probe config for the primary breakpoint.
* @property {() => Promise<object>} snapshotReceived - Waits for a snapshot to be received from the test app.
*/

module.exports = {
Expand Down Expand Up @@ -129,7 +130,15 @@ function setup ({ env, testApp, testAppSource, dependencies, silent, stdioHandle
rcConfig: null,
triggerBreakpoint: triggerBreakpoint.bind(null, breakpoints[0].url),
generateRemoteConfig: generateRemoteConfig.bind(null, breakpoints[0]),
generateProbeConfig: generateProbeConfig.bind(null, breakpoints[0])
generateProbeConfig: generateProbeConfig.bind(null, breakpoints[0]),

snapshotReceived () {
return new Promise((/** @type {(value: object) => void} */ resolve) => {
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot } }] }) => {
resolve(snapshot)
})
})
}
}

/**
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ session.on('Debugger.paused', async ({ params: { hitBreakpoints: [hitBreakpoint]

const stack = getStackFromCallFrames(callFrames)

const getLocalState = await getLocalStateForCallFrame(callFrames[0])
const { processLocalState } = await getLocalStateForCallFrame(callFrames[0])

await session.post('Debugger.resume')

Expand All @@ -48,17 +48,13 @@ session.on('Debugger.paused', async ({ params: { hitBreakpoints: [hitBreakpoint]
version: '0',
location: probe.location
},
captures: {
lines: { [probe.location.lines[0]]: { locals: processLocalState() } }
},
stack,
language: 'javascript'
}

const state = getLocalState()
if (state) {
snapshot.captures = {
lines: { [probe.location.lines[0]]: { locals: state } }
}
}

breakpointHitChannel.postMessage({ snapshot })
})

Expand Down
Loading