Skip to content

Commit 2dd3573

Browse files
authored
feat(debugger): add snapshot time budget (#6897)
Enforce a per-snapshot time budget. By default this budget is 15ms, but can be modified by the experimental config, either as an environment variable: DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS=20 Or programatically: tracer.init({ dynamicInstrumentation: { captureTimeoutMs: 20 } }) When the budget is exceeded, remaining values that are not already resolved, are marked with `notCapturedReason: 'timeout'`.
1 parent 06285b6 commit 2dd3573

File tree

21 files changed

+531
-60
lines changed

21 files changed

+531
-60
lines changed

integration-tests/debugger/basic.spec.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -641,7 +641,7 @@ describe('Dynamic Instrumentation', function () {
641641
})
642642

643643
describe('condition', function () {
644-
beforeEach(t.triggerBreakpoint)
644+
beforeEach(() => { t.triggerBreakpoint() })
645645

646646
it('should trigger when condition is met', function (done) {
647647
t.agent.on('debugger-input', () => {

integration-tests/debugger/snapshot-global-sample-rate.spec.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ describe('Dynamic Instrumentation', function () {
1111

1212
describe('input messages', function () {
1313
describe('with snapshot', function () {
14-
beforeEach(t.triggerBreakpoint)
14+
beforeEach(() => { t.triggerBreakpoint() })
1515

1616
it('should respect global max snapshot sampling rate', function (_done) {
1717
const MAX_SNAPSHOTS_PER_SECOND_GLOBALLY = 25

integration-tests/debugger/snapshot-pruning.spec.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ describe('Dynamic Instrumentation', function () {
88

99
describe('input messages', function () {
1010
describe('with snapshot', function () {
11-
beforeEach(t.triggerBreakpoint)
11+
beforeEach(() => { t.triggerBreakpoint() })
1212

1313
it('should prune snapshot if payload is too large', function (done) {
1414
t.agent.on('debugger-input', ({ payload: [payload] }) => {
Lines changed: 95 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,95 @@
1+
'use strict'
2+
3+
const assert = require('node:assert')
4+
const { setup } = require('./utils')
5+
6+
describe('Dynamic Instrumentation', function () {
7+
describe('input messages', function () {
8+
describe('with snapshot under tight time budget', function () {
9+
context('1ms time budget', function () {
10+
// Force a very small time budget in ms to trigger partial snapshots
11+
const budget = 1
12+
const t = setup({
13+
dependencies: ['fastify'],
14+
env: { DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS: String(budget) }
15+
})
16+
17+
it(
18+
'should include partial snapshot marked with notCapturedReason: timeout',
19+
// A tolerance of 15ms is used to avoid flakiness
20+
test({ t, maxPausedTime: budget + 15, breakpointIndex: 0, maxReferenceDepth: 5 })
21+
)
22+
})
23+
24+
context('default time budget', function () {
25+
const budget = 15 // default time budget in ms
26+
const t = setup({ dependencies: ['fastify'] })
27+
28+
// TODO: Make this pass
29+
// eslint-disable-next-line mocha/no-pending-tests
30+
it.skip(
31+
'should keep budget when state includes an object with 1 million properties',
32+
// A tolerance of 5ms is used to avoid flakiness
33+
test({ t, maxPausedTime: budget + 5, breakpointIndex: 1, maxReferenceDepth: 1 })
34+
)
35+
36+
// TODO: Make this pass
37+
// eslint-disable-next-line mocha/no-pending-tests
38+
it.skip(
39+
'should keep budget when state includes an array of 1 million primitives',
40+
// A tolerance of 5ms is used to avoid flakiness
41+
test({ t, maxPausedTime: budget + 5, breakpointIndex: 2, maxReferenceDepth: 1 })
42+
)
43+
44+
// TODO: Make this pass
45+
// eslint-disable-next-line mocha/no-pending-tests
46+
it.skip(
47+
'should keep budget when state includes an array of 1 million objects',
48+
// A tolerance of 5ms is used to avoid flakiness
49+
test({ t, maxPausedTime: budget + 5, breakpointIndex: 3, maxReferenceDepth: 1 })
50+
)
51+
})
52+
})
53+
})
54+
})
55+
56+
function test ({ t, maxPausedTime, breakpointIndex, maxReferenceDepth }) {
57+
const breakpoint = t.breakpoints[breakpointIndex]
58+
59+
return async function () {
60+
const payloadReceived = new Promise((/** @type {(value?: unknown) => void} */ resolve) => {
61+
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { captures } } }] }) => {
62+
const { locals } = captures.lines[breakpoint.line]
63+
assert.strictEqual(
64+
containsTimeBudget(locals),
65+
true,
66+
'expected at least one field/element to be marked with notCapturedReason: "timeout"'
67+
)
68+
resolve()
69+
})
70+
})
71+
72+
t.agent.addRemoteConfig(breakpoint.generateRemoteConfig({
73+
captureSnapshot: true,
74+
capture: { maxReferenceDepth }
75+
}))
76+
77+
const { data } = await breakpoint.triggerBreakpoint()
78+
79+
assert.ok(
80+
data.paused <= maxPausedTime,
81+
`expected thread to be paused <=${maxPausedTime}ms, but was paused for ~${data.paused}ms`
82+
)
83+
84+
await payloadReceived
85+
}
86+
}
87+
88+
function containsTimeBudget (node) {
89+
if (node == null || typeof node !== 'object') return false
90+
if (node.notCapturedReason === 'timeout') return true
91+
for (const value of Object.values(node)) {
92+
if (containsTimeBudget(value)) return true
93+
}
94+
return false
95+
}

integration-tests/debugger/snapshot.spec.js

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

99
describe('input messages', function () {
1010
describe('with snapshot', function () {
11-
beforeEach(t.triggerBreakpoint)
11+
beforeEach(() => { t.triggerBreakpoint() })
1212

1313
it('should capture a snapshot', function (done) {
1414
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { captures } } }] }) => {
@@ -209,12 +209,12 @@ describe('Dynamic Instrumentation', function () {
209209
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { captures } } }] }) => {
210210
const { locals } = captures.lines[t.breakpoint.line]
211211

212-
assert.deepStrictEqual(Object.keys(locals), [
212+
assert.deepStrictEqual(Object.keys(locals).sort(), [
213213
// Up to 3 properties from the closure scope
214214
'fastify', 'getUndefined',
215215
// Up to 3 properties from the local scope
216216
'request', 'nil', 'undef'
217-
])
217+
].sort())
218218

219219
assert.strictEqual(locals.request.type, 'Request')
220220
assert.strictEqual(Object.keys(locals.request.fields).length, maxFieldCount)

integration-tests/debugger/source-map-support.spec.js

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ describe('Dynamic Instrumentation', function () {
1111
testAppSource: 'target-app/source-map-support/typescript.ts'
1212
})
1313

14-
beforeEach(t.triggerBreakpoint)
14+
beforeEach(() => { t.triggerBreakpoint() })
1515

1616
it('should support source maps', function (done) {
1717
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { probe: { location } } } }] }) => {
@@ -32,7 +32,7 @@ describe('Dynamic Instrumentation', function () {
3232
testAppSource: 'target-app/source-map-support/minify.js'
3333
})
3434

35-
beforeEach(t.triggerBreakpoint)
35+
beforeEach(() => { t.triggerBreakpoint() })
3636

3737
it('should support source maps', function (done) {
3838
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { probe: { location } } } }] }) => {
@@ -56,7 +56,7 @@ describe('Dynamic Instrumentation', function () {
5656
dependencies: []
5757
})
5858

59-
beforeEach(t.triggerBreakpoint)
59+
beforeEach(() => { t.triggerBreakpoint() })
6060

6161
it('should support relative source paths in source maps', function (done) {
6262
t.agent.on('debugger-input', ({ payload: [{ debugger: { snapshot: { probe: { location } } } }] }) => {
Lines changed: 118 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,118 @@
1+
'use strict'
2+
3+
require('dd-trace/init')
4+
5+
const Fastify = require('fastify')
6+
7+
const fastify = Fastify({ logger: { level: 'error' } })
8+
9+
fastify.get('/deeply-nested-large-object', function handler () {
10+
// The size of `obj` generated is carefully tuned to never result in a snapshot larger than the 1MB size limit, while
11+
// still being large enough to trigger the time budget limit. However, the size of `fastify` and `request` is not
12+
// stable across Node.js and Fastify versions, so the generated object might need to be adjusted.
13+
const obj = generateObject(5, 12) // eslint-disable-line no-unused-vars
14+
const start = process.hrtime.bigint()
15+
const diff = process.hrtime.bigint() - start // BREAKPOINT: /deeply-nested-large-object
16+
return { paused: Number(diff) / 1_000_000 }
17+
})
18+
19+
fastify.get('/large-object-of-primitives', function handler () {
20+
const obj = generateObject(0, 1_000_000) // eslint-disable-line no-unused-vars
21+
const start = process.hrtime.bigint()
22+
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-object-of-primitives
23+
return { paused: Number(diff) / 1_000_000 }
24+
})
25+
26+
fastify.get('/large-array-of-primitives', function handler () {
27+
const arr = Array.from({ length: 1_000_000 }, (_, i) => i) // eslint-disable-line no-unused-vars
28+
const start = process.hrtime.bigint()
29+
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-array-of-primitives
30+
return { paused: Number(diff) / 1_000_000 }
31+
})
32+
33+
fastify.get('/large-array-of-objects', function handler () {
34+
const arr = Array.from({ length: 1_000_000 }, (_, i) => ({ i })) // eslint-disable-line no-unused-vars
35+
const start = process.hrtime.bigint()
36+
const diff = process.hrtime.bigint() - start // BREAKPOINT: /large-array-of-objects
37+
return { paused: Number(diff) / 1_000_000 }
38+
})
39+
40+
fastify.listen({ port: process.env.APP_PORT || 0 }, (err) => {
41+
if (err) {
42+
fastify.log.error(err)
43+
process.exit(1)
44+
}
45+
process.send?.({ port: fastify.server.address().port })
46+
})
47+
48+
const leafValues = [null, undefined, true, 1, '']
49+
const complexTypes = ['object', 'array', 'map', 'set']
50+
51+
/**
52+
* Generate a complex nested object that requires a lot of async CDP calls to traverse
53+
*/
54+
function generateObject (depth, breath) {
55+
const obj = {}
56+
for (let i = 0; i < breath; i++) {
57+
const key = `p${i}`
58+
if (depth === 0) {
59+
obj[key] = leafValues[i % leafValues.length]
60+
} else {
61+
const type = complexTypes[i % complexTypes.length]
62+
obj[key] = generateType(type, depth - 1, breath)
63+
}
64+
}
65+
return obj
66+
}
67+
68+
function generateArray (depth, breath) {
69+
const arr = []
70+
for (let i = 0; i < breath; i++) {
71+
if (depth === 0) {
72+
arr.push(leafValues[i % leafValues.length])
73+
} else {
74+
const type = complexTypes[i % complexTypes.length]
75+
arr.push(generateType(type, depth - 1, breath))
76+
}
77+
}
78+
return arr
79+
}
80+
81+
function generateMap (depth, breath) {
82+
const map = new Map()
83+
for (let i = 0; i < breath; i++) {
84+
if (depth === 0) {
85+
map.set(i, leafValues[i % leafValues.length])
86+
} else {
87+
const type = complexTypes[i % complexTypes.length]
88+
map.set(i, generateType(type, depth - 1, breath))
89+
}
90+
}
91+
return map
92+
}
93+
94+
function generateSet (depth, breath) {
95+
const set = new Set()
96+
for (let i = 0; i < breath; i++) {
97+
if (depth === 0) {
98+
set.add(leafValues[i % leafValues.length])
99+
} else {
100+
const type = complexTypes[i % complexTypes.length]
101+
set.add(generateType(type, depth - 1, breath))
102+
}
103+
}
104+
return set
105+
}
106+
107+
function generateType (type, depth, breath) {
108+
switch (type) {
109+
case 'object':
110+
return generateObject(depth, breath)
111+
case 'array':
112+
return generateArray(depth, breath)
113+
case 'map':
114+
return generateMap(depth, breath)
115+
case 'set':
116+
return generateSet(depth, breath)
117+
}
118+
}

integration-tests/debugger/template.spec.js

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ describe('Dynamic Instrumentation', function () {
1111
describe('template evaluation', function () {
1212
const t = setup({ dependencies: ['fastify'] })
1313

14-
beforeEach(t.triggerBreakpoint)
14+
beforeEach(() => { t.triggerBreakpoint() })
1515

1616
it('should evaluate template if it requires evaluation', function (done) {
1717
t.agent.on('debugger-input', ({ payload: [payload] }) => {

integration-tests/debugger/utils.js

Lines changed: 9 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -53,14 +53,16 @@ function setup ({ env, testApp, testAppSource, dependencies, silent, stdioHandle
5353
}
5454

5555
// Trigger the breakpoint once probe is successfully installed
56-
function triggerBreakpoint (url) {
56+
async function triggerBreakpoint (url) {
5757
let triggered = false
58-
t.agent.on('debugger-diagnostics', ({ payload }) => {
59-
payload.forEach((event) => {
60-
if (!triggered && event.debugger.diagnostics.status === 'INSTALLED') {
61-
triggered = true
62-
t.axios.get(url)
63-
}
58+
return new Promise((resolve, reject) => {
59+
t.agent.on('debugger-diagnostics', ({ payload }) => {
60+
payload.forEach((event) => {
61+
if (!triggered && event.debugger.diagnostics.status === 'INSTALLED') {
62+
triggered = true
63+
t.axios.get(url).then(resolve).catch(reject)
64+
}
65+
})
6466
})
6567
})
6668
}

packages/dd-trace/src/config.js

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -446,6 +446,7 @@ class Config {
446446
DD_DBM_PROPAGATION_MODE,
447447
DD_DOGSTATSD_HOST,
448448
DD_DOGSTATSD_PORT,
449+
DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS,
449450
DD_DYNAMIC_INSTRUMENTATION_ENABLED,
450451
DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE,
451452
DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS,
@@ -684,6 +685,8 @@ class Config {
684685
this.#setString(target, 'dogstatsd.hostname', DD_DOGSTATSD_HOST)
685686
this.#setString(target, 'dogstatsd.port', DD_DOGSTATSD_PORT)
686687
this.#setBoolean(target, 'dsmEnabled', DD_DATA_STREAMS_ENABLED)
688+
target['dynamicInstrumentation.captureTimeoutMs'] = maybeInt(DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS)
689+
unprocessedTarget['dynamicInstrumentation.captureTimeoutMs'] = DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS
687690
this.#setBoolean(target, 'dynamicInstrumentation.enabled', DD_DYNAMIC_INSTRUMENTATION_ENABLED)
688691
this.#setString(target, 'dynamicInstrumentation.probeFile', DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE)
689692
this.#setArray(target, 'dynamicInstrumentation.redactedIdentifiers',
@@ -984,6 +987,8 @@ class Config {
984987
this.#setString(opts, 'dogstatsd.port', options.dogstatsd.port)
985988
}
986989
this.#setBoolean(opts, 'dsmEnabled', options.dsmEnabled)
990+
opts['dynamicInstrumentation.captureTimeoutMs'] = maybeInt(options.dynamicInstrumentation?.captureTimeoutMs)
991+
this.#optsUnprocessed['dynamicInstrumentation.captureTimeoutMs'] = options.dynamicInstrumentation?.captureTimeoutMs
987992
this.#setBoolean(opts, 'dynamicInstrumentation.enabled', options.dynamicInstrumentation?.enabled)
988993
this.#setString(opts, 'dynamicInstrumentation.probeFile', options.dynamicInstrumentation?.probeFile)
989994
this.#setArray(

0 commit comments

Comments
 (0)