diff --git a/benchmark/sirun/debugger/start-devtools-client.js b/benchmark/sirun/debugger/start-devtools-client.js index 24cdc93f0a..bf7267a1b8 100644 --- a/benchmark/sirun/debugger/start-devtools-client.js +++ b/benchmark/sirun/debugger/start-devtools-client.js @@ -79,6 +79,7 @@ const config = { dynamicInstrumentation: { captureTimeoutMs: Number(process.env.DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS || '1000'), enabled: true, + evaluationTimeoutMs: Number(process.env.DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS || '10'), probeFile: undefined, queueMaxBytes: 10 * 1024 * 1024, redactedIdentifiers: [], diff --git a/index.d.ts b/index.d.ts index 831f35fe2c..ff2aac2a9d 100644 --- a/index.d.ts +++ b/index.d.ts @@ -1243,6 +1243,16 @@ declare namespace tracer { */ captureTimeoutMs?: number + /** + * Time budget in milliseconds for evaluating a probe's condition, log message template and capture expressions. + * An evaluation that exceeds the budget is reported as an evaluation error and the probe is not evaluated again + * for a while. + * @default 10 + * @env DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS + * Programmatic configuration takes precedence over the environment variables listed above. + */ + evaluationTimeoutMs?: number + /** * Interval in seconds between uploads of probe data. * @default 1 diff --git a/index.d.v5.ts b/index.d.v5.ts index e09fa6833a..6f2410bf35 100644 --- a/index.d.v5.ts +++ b/index.d.v5.ts @@ -1355,6 +1355,16 @@ declare namespace tracer { */ captureTimeoutMs?: number + /** + * Time budget in milliseconds for evaluating a probe's condition, log message template and capture expressions. + * An evaluation that exceeds the budget is reported as an evaluation error and the probe is not evaluated again + * for a while. + * @default 10 + * @env DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS + * Programmatic configuration takes precedence over the environment variables listed above. + */ + evaluationTimeoutMs?: number + /** * Interval in seconds between uploads of probe data. * @default 1 diff --git a/integration-tests/debugger/evaluation-time-budget.spec.js b/integration-tests/debugger/evaluation-time-budget.spec.js new file mode 100644 index 0000000000..9f463ee3d5 --- /dev/null +++ b/integration-tests/debugger/evaluation-time-budget.spec.js @@ -0,0 +1,91 @@ +'use strict' + +const assert = require('node:assert/strict') +const { inspect } = require('node:util') + +const { setup } = require('./utils') + +// The guardrail counters are converted into telemetry metrics every 10 seconds, which are then sent on the next +// telemetry heartbeat +const GUARDRAIL_METRICS_FLUSH_INTERVAL_MS = 10_000 + +// `^(a+)+$` backtracks exponentially against a non-matching input, so a few dozen characters blow past the budget. +// Regular expressions can't be interrupted, so the budget is enforced by reporting and throttling after the fact. +const REDOS_INPUT = 'a'.repeat(24) + '!' +const REDOS_CONDITION = { + dsl: 'request.params.name matches "^(a+)+$"', + json: { matches: [{ getmember: [{ getmember: [{ ref: 'request' }, 'params'] }, 'name'] }, '^(a+)+$'] }, +} + +describe('Dynamic Instrumentation', function () { + const t = setup({ + testApp: 'target-app/basic.js', + dependencies: ['fastify'], + env: { DD_TELEMETRY_HEARTBEAT_INTERVAL: '1' }, + }) + + describe('evaluation time budget', function () { + this.timeout(GUARDRAIL_METRICS_FLUSH_INTERVAL_MS * 3) + + it('should report a condition that exceeds its time budget once and skip the probe afterwards', async function () { + const rcConfig = t.generateRemoteConfig({ captureSnapshot: true, when: REDOS_CONDITION }) + const url = `/foo/${REDOS_INPUT}` + const results = [] + + t.agent.on('debugger-input', ({ payload }) => results.push(...payload)) + + const installed = new Promise((/** @type {(value?: void) => void} */ resolve) => { + t.agent.on('debugger-diagnostics', ({ payload }) => { + if (payload.some(({ debugger: { diagnostics } }) => diagnostics.status === 'INSTALLED')) resolve() + }) + }) + + const checkMetrics = t.agent.assertTelemetryReceived({ + fn: ({ payload }) => { + const { series } = payload.payload + const skipped = series.find((entry) => { + return entry.metric === 'events.skipped' && + entry.tags.includes('event_type:snapshot') && + entry.tags.includes('reason:evaluationTimeout') + }) + assert.ok(skipped, `Expected events.skipped metric in ${inspect(series)}`) + assert.strictEqual(skipped.type, 'count') + assert.strictEqual(skipped.points[0][1], 2) + }, + requestType: 'generate-metrics', + timeout: GUARDRAIL_METRICS_FLUSH_INTERVAL_MS * 2, + resolveAtFirstSuccess: true, + namespace: 'live_debugger', + }) + + t.agent.addRemoteConfig(rcConfig) + await installed + + // The first hit pays for the slow evaluation and reports it + const slowStart = Date.now() + await t.request(url) + const slowDuration = Date.now() - slowStart + + // The following hits are skipped at probe entry without evaluating the condition + const fastStart = Date.now() + await t.request(url) + await t.request(url) + const fastDuration = Date.now() - fastStart + + assert.ok( + fastDuration < slowDuration, + `Expected throttled hits (${fastDuration}ms for two) to be faster than the first hit (${slowDuration}ms)` + ) + + await checkMetrics + + assert.strictEqual(results.length, 1, `Expected exactly one probe result, got ${inspect(results)}`) + const { message, debugger: { snapshot } } = results[0] + assert.match(message, /^Condition evaluation exceeded its time budget of 10ms \(took \d+\.\dms\)$/) + assert.strictEqual(snapshot.evaluationErrors.length, 1) + assert.strictEqual(snapshot.evaluationErrors[0].expr, REDOS_CONDITION.dsl) + assert.strictEqual(snapshot.evaluationErrors[0].message, message) + assert.strictEqual(snapshot.captures, undefined, 'should not capture anything for a timed out condition') + }) + }) +}) diff --git a/packages/dd-trace/src/config/generated-config-types.d.ts b/packages/dd-trace/src/config/generated-config-types.d.ts index c24f4b2fa0..2c54a018b1 100644 --- a/packages/dd-trace/src/config/generated-config-types.d.ts +++ b/packages/dd-trace/src/config/generated-config-types.d.ts @@ -407,6 +407,7 @@ export interface GeneratedConfig { dynamicInstrumentation: { captureTimeoutMs: number; enabled: boolean; + evaluationTimeoutMs: number; probeFile: string | undefined; queueMaxBytes: number; redactedIdentifiers: string[]; @@ -692,6 +693,7 @@ export interface GeneratedEnvVarConfig { DD_DURABLE_CROSS_INVOCATION_TRACING_ENABLED: boolean; DD_DYNAMIC_INSTRUMENTATION_CAPTURE_TIMEOUT_MS: number; DD_DYNAMIC_INSTRUMENTATION_ENABLED: boolean; + DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS: number; DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE: string | undefined; DD_DYNAMIC_INSTRUMENTATION_QUEUE_MAX_BYTES: number; DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS: string[]; diff --git a/packages/dd-trace/src/config/supported-configurations.json b/packages/dd-trace/src/config/supported-configurations.json index 4e53064095..13415dbee8 100644 --- a/packages/dd-trace/src/config/supported-configurations.json +++ b/packages/dd-trace/src/config/supported-configurations.json @@ -768,6 +768,16 @@ "default": "false" } ], + "DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS": [ + { + "implementation": "A", + "type": "int", + "configurationNames": [ + "dynamicInstrumentation.evaluationTimeoutMs" + ], + "default": "10" + } + ], "DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE": [ { "implementation": "B", diff --git a/packages/dd-trace/src/debugger/devtools_client/config.js b/packages/dd-trace/src/debugger/devtools_client/config.js index 113ebc989d..96937f32ac 100644 --- a/packages/dd-trace/src/debugger/devtools_client/config.js +++ b/packages/dd-trace/src/debugger/devtools_client/config.js @@ -24,4 +24,6 @@ function updateConfig (updates) { // reconstructed into a URL here rather than read directly off a Config instance. config.url = new URL(updates.url) config.dynamicInstrumentation.captureTimeoutNs = BigInt(updates.dynamicInstrumentation.captureTimeoutMs) * 1_000_000n + config.dynamicInstrumentation.evaluationTimeoutNs = + BigInt(updates.dynamicInstrumentation.evaluationTimeoutMs) * 1_000_000n } diff --git a/packages/dd-trace/src/debugger/devtools_client/index.js b/packages/dd-trace/src/debugger/devtools_client/index.js index 428dd801a3..dc8b0cbb83 100644 --- a/packages/dd-trace/src/debugger/devtools_client/index.js +++ b/packages/dd-trace/src/debugger/devtools_client/index.js @@ -13,7 +13,7 @@ const { SAMPLED_PROBE_INDEXES_START, SAMPLED_PROBE_OVERFLOW_INDEX, } = require('../probe_sampler_constants') -const { getTakeConditionErrorExpression } = require('./probe_sampler') +const { getEvaluationTimedOutExpression, getTakeConditionErrorExpression } = require('./probe_sampler') const { breakpointToProbes, samplingIndexToProbe } = require('./state') const { refreshBreakpoint } = require('./breakpoints') const session = require('./session') @@ -58,6 +58,7 @@ session.on('Debugger.paused', async ({ params }) => { let maxLength = 0 let numberOfProbesWithSnapshots = 0 let probesWithCaptureExpressions = false + let probesWithTemplates = false const probes = [] // Expressions evaluated on the paused frame in one round trip, in the order of `probes`: the evaluated template for // probes whose template requires evaluation, and the recorded error for probes paused to report a condition error @@ -125,6 +126,7 @@ session.on('Debugger.paused', async ({ params }) => { } if (probe.templateRequiresEvaluation) { + probesWithTemplates = true frameExpressions += `,${probe.template}` } @@ -140,6 +142,7 @@ session.on('Debugger.paused', async ({ params }) => { const timestamp = Date.now() let evalResults + const evaluationStart = process.hrtime.bigint() const { result } = /** @type {EvaluateOnCallFrameResult} */ ( await session.post('Debugger.evaluateOnCallFrame', { callFrameId: params.callFrames[0].callFrameId, @@ -150,6 +153,10 @@ session.on('Debugger.paused', async ({ params }) => { includeCommandLineAPI: true, }) ) + // The templates of all probes at the location are evaluated together, so an exceeded budget is attributed to all of + // them. Evaluation can't be interrupted, so the budget is enforced by reporting and throttling after the fact. + const templatesTimedOut = probesWithTemplates && + process.hrtime.bigint() - evaluationStart > config.dynamicInstrumentation.evaluationTimeoutNs if (result?.subtype === 'error') { log.error('[debugger:devtools_client] Error evaluating code on call frame: %s', result?.description) evalResults = [] @@ -178,7 +185,8 @@ session.on('Debugger.paused', async ({ params }) => { captureExpressionResults.set(probe.id, await evaluateCaptureExpressions( params.callFrames[0], probe.compiledCaptureExpressions, - start + config.dynamicInstrumentation.captureTimeoutNs + start + config.dynamicInstrumentation.captureTimeoutNs, + config.dynamicInstrumentation.evaluationTimeoutNs )) } } @@ -305,6 +313,8 @@ session.on('Debugger.paused', async ({ params }) => { snapshot.evaluationErrors = [...probe.permanentEvaluationErrors] } + let evaluationTimedOut = captureExpressionResults?.get(probe.id)?.timedOut === true + let message = '' if (probe.templateRequiresEvaluation) { const results = evalResults[messageIndex++] @@ -325,6 +335,19 @@ session.on('Debugger.paused', async ({ params }) => { } } } + if (templatesTimedOut) { + evaluationTimedOut = true + const error = { + expr: '', + message: 'Template evaluation exceeded its time budget of ' + + `${config.dynamicInstrumentation.evaluationTimeoutNs / 1_000_000n}ms`, + } + if (snapshot.evaluationErrors === undefined) { + snapshot.evaluationErrors = [error] + } else { + snapshot.evaluationErrors.push(error) + } + } } else { message = probe.template } @@ -334,6 +357,8 @@ session.on('Debugger.paused', async ({ params }) => { send(message, logger, dd, snapshot, config.propagateProcessTags.enabled ? processTags.serialized : undefined, eventType, incompleteReasons) + + if (evaluationTimedOut) throttleProbe(probe) } if (captureDisabledProbe !== undefined) { @@ -349,6 +374,19 @@ session.on('Debugger.paused', async ({ params }) => { } }) +/** + * Throttle a probe in the runtime sampler because its template or capture expressions exceeded the evaluation time + * budget. The result has already been reported, so this only stops the probe from being evaluated again for a while. + * + * @param {{ id: string }} probe - The probe to throttle. + */ +function throttleProbe (probe) { + log.debug('[debugger:devtools_client] Evaluation of probe %s exceeded its time budget; throttling probe', probe.id) + session.post('Runtime.evaluate', { expression: getEvaluationTimedOutExpression(probe.id) }).catch((err) => { + log.error('[debugger:devtools_client] Error throttling probe %s', probe.id, err) + }) +} + function processDD (result) { return result?.trace_id === undefined ? undefined : result } diff --git a/packages/dd-trace/src/debugger/devtools_client/probe_sampler.js b/packages/dd-trace/src/debugger/devtools_client/probe_sampler.js index 3eee7ea67d..f7536e9746 100644 --- a/packages/dd-trace/src/debugger/devtools_client/probe_sampler.js +++ b/packages/dd-trace/src/debugger/devtools_client/probe_sampler.js @@ -7,6 +7,7 @@ const SAMPLER_EXPRESSION = `globalThis[Symbol.for(${JSON.stringify(DD_TRACE_SYMB module.exports = { compileBreakpointCondition, + getEvaluationTimedOutExpression, getRemoveProbeExpression, getTakeConditionErrorExpression, isSnapshotProducingProbe, @@ -24,6 +25,17 @@ function isSnapshotProducingProbe (probe) { return probe.captureSnapshot === true || probe.compiledCaptureExpressions !== undefined } +/** + * Build the expression that throttles a probe whose evaluation exceeded its time budget in the worker. Called by the + * devtools worker and evaluated on the debuggee. + * + * @param {string} id - The probe id. + * @returns {string} + */ +function getEvaluationTimedOutExpression (id) { + return `${SAMPLER_EXPRESSION}?.evaluationTimedOut(${JSON.stringify(id)})` +} + /** * Build the expression that removes a probe from runtime sampler state. Called by the devtools worker and evaluated on * the debuggee. @@ -90,22 +102,23 @@ function compileBreakpointCondition (probes) { * @returns {string} */ function compileProbeCondition (probe) { - const sample = `$dd_sampler.makeSampleDecision(${probe.samplingIndex}, ${JSON.stringify(probe.id)}, ` + - `${probe.nsBetweenSampling}n, ${isSnapshotProducingProbe(probe)})` + const id = JSON.stringify(probe.id) + const producesSnapshot = isSnapshotProducingProbe(probe) + const samplingArgs = `${probe.nsBetweenSampling}n, ${producesSnapshot}` if (probe.condition === undefined) { - return `$dd_sampled = ${sample} || $dd_sampled` + return `$dd_sampled = $dd_sampler.makeSampleDecision(${probe.samplingIndex}, ${id}, ${samplingArgs}) || $dd_sampled` } - // A condition that throws is reported once per throttle window and skipped at probe entry in between - return `if ($dd_sampler.shouldEvaluateCondition(${JSON.stringify(probe.id)})) { + // The condition is timed against the evaluation budget. A condition that throws or exceeds its budget is reported + // once per throttle window and skipped at probe entry in between. + return `if ($dd_sampler.shouldEvaluateCondition(${id}, ${producesSnapshot})) { + const $dd_start = $dd_sampler.now() try { - if ((${probe.condition}) === true) { - $dd_sampled = ${sample} || $dd_sampled - } + $dd_sampled = $dd_sampler.conditionEvaluated(${probe.samplingIndex}, ${id}, $dd_start, + (${probe.condition}) === true, ${samplingArgs}) || $dd_sampled } catch ($dd_error) { - $dd_sampled = $dd_sampler.conditionError(${probe.samplingIndex}, ${JSON.stringify(probe.id)}, $dd_error) || - $dd_sampled + $dd_sampled = $dd_sampler.conditionError(${probe.samplingIndex}, ${id}, $dd_error) || $dd_sampled } }` } diff --git a/packages/dd-trace/src/debugger/devtools_client/snapshot/index.js b/packages/dd-trace/src/debugger/devtools_client/snapshot/index.js index 7ed9ab9984..22fe29cf49 100644 --- a/packages/dd-trace/src/debugger/devtools_client/snapshot/index.js +++ b/packages/dd-trace/src/debugger/devtools_client/snapshot/index.js @@ -116,6 +116,7 @@ function isCollectable (scope) { * @property {import('./processor').IncompleteCapture} incomplete - The capture limits enforced on the expressions, * including a runtime error for every expression that threw or could not be evaluated. Only fully populated once * `processCaptureExpressions` has run. + * @property {boolean} timedOut - Whether evaluating an expression exceeded the evaluation time budget */ /** @@ -133,9 +134,16 @@ function isCollectable (scope) { * @param {CompiledCaptureExpression[]} expressions - The compiled expressions with precomputed capture limits * @param {bigint} [deadlineNs] - The deadline in nanoseconds. Defaults to {@link BIGINT_MAX}. If the deadline is * reached, the snapshot will be truncated. + * @param {bigint} [evaluationTimeoutNs] - The time budget in nanoseconds for evaluating a single expression. Defaults + * to {@link BIGINT_MAX}. Evaluation can't be interrupted, so an exceeded budget is reported as an evaluation error. * @returns {Promise} Raw results with deferred processing callback */ -async function evaluateCaptureExpressions (callFrame, expressions, deadlineNs = BIGINT_MAX) { +async function evaluateCaptureExpressions ( + callFrame, + expressions, + deadlineNs = BIGINT_MAX, + evaluationTimeoutNs = BIGINT_MAX +) { /** @type {{ name: string, remoteObject: object, maxLength: number }[]} */ const rawResults = [] /** @type {{ expr: string, message: string }[]} */ @@ -146,12 +154,14 @@ async function evaluateCaptureExpressions (callFrame, expressions, deadlineNs = const incomplete = { reasons: 0 } /** @type {Record> | null} */ let processedResult = null + let timedOut = false for (let i = 0; i < expressions.length; i++) { const { name, expression, limits } = expressions[i] const { maxReferenceDepth, maxCollectionSize, maxFieldCount, maxLength } = limits try { + const evaluationStart = process.hrtime.bigint() const { result, exceptionDetails } = /** @type {EvaluateOnCallFrameResult} */ ( // eslint-disable-next-line no-await-in-loop await session.post('Debugger.evaluateOnCallFrame', { @@ -159,6 +169,14 @@ async function evaluateCaptureExpressions (callFrame, expressions, deadlineNs = expression, }) ) + if (process.hrtime.bigint() - evaluationStart > evaluationTimeoutNs) { + incomplete.reasons |= INCOMPLETE_REASON.TIMEOUT + timedOut = true + evaluationErrors.push({ + expr: name, + message: `Expression evaluation exceeded its time budget of ${evaluationTimeoutNs / 1_000_000n}ms`, + }) + } // Handle evaluation exceptions (maybe transient - bad expression, undefined var, etc.) if (exceptionDetails) { @@ -238,6 +256,7 @@ async function evaluateCaptureExpressions (callFrame, expressions, deadlineNs = evaluationErrors, fatalErrors, incomplete, + timedOut, } } diff --git a/packages/dd-trace/src/debugger/index.js b/packages/dd-trace/src/debugger/index.js index 8aa27b5e93..77b33abbaa 100644 --- a/packages/dd-trace/src/debugger/index.js +++ b/packages/dd-trace/src/debugger/index.js @@ -16,7 +16,7 @@ const { INSPECT_SEGMENT_GLOBAL_PROPERTY, } = require('./constants') const { GuardrailMetrics, TELEMETRY_NAMESPACE } = require('./guardrail-metrics') -const { installProbeSampler, uninstallProbeSampler } = require('./probe_sampler') +const { configureProbeSampler, installProbeSampler, uninstallProbeSampler } = require('./probe_sampler') /** * @typedef {ReturnType} Config @@ -98,7 +98,7 @@ function start (config, rcInstance) { guardrailMetricsTimer.unref?.() dc.subscribe(TELEMETRY_APP_CLOSING_CHANNEL, flushGuardrailMetrics) - const probeSamplerBuffer = installProbeSampler(guardrailMetrics) + const probeSamplerBuffer = installProbeSampler(guardrailMetrics, config) readProbeFile(config.dynamicInstrumentation.probeFile, (probes) => { const action = 'apply' @@ -192,6 +192,7 @@ function configure (config) { log.error('[debugger] Invalid DD_SITE for agentless Dynamic Instrumentation: %s', config.site) return } + configureProbeSampler(config) configChannel.port2.postMessage(debuggerConfig) } diff --git a/packages/dd-trace/src/debugger/probe_sampler.js b/packages/dd-trace/src/debugger/probe_sampler.js index 6eec3acdc1..a42586bb80 100644 --- a/packages/dd-trace/src/debugger/probe_sampler.js +++ b/packages/dd-trace/src/debugger/probe_sampler.js @@ -17,28 +17,50 @@ const ddTraceGlobal = /** @type {Record} */ (globalThis)[Symbol.for(DD_TRACE_SYMBOL)] ) +/** + * @typedef {object} ProbeThrottle + * @property {bigint} untilNs - The probe is skipped at entry until this point in time + * @property {boolean} timedOut - Whether the throttle was caused by an evaluation exceeding its time budget + * @property {string | undefined} error - A condition error not yet handed over to the worker + */ + +let evaluationTimeoutNs = 0n + module.exports = { + configureProbeSampler, installProbeSampler, uninstallProbeSampler, } +/** + * Apply the evaluation time budget from the tracer configuration. + * + * @param {{ dynamicInstrumentation: { evaluationTimeoutMs: number } }} config - The tracer configuration. + */ +function configureProbeSampler (config) { + evaluationTimeoutNs = BigInt(config.dynamicInstrumentation.evaluationTimeoutMs) * 1_000_000n +} + /** * Install the runtime sampler in the debuggee context. * * @param {import('./guardrail-metrics').GuardrailMetrics} guardrailMetrics - Counters for skipped probe hits. + * @param {{ dynamicInstrumentation: { evaluationTimeoutMs: number } }} config - The tracer configuration. * @returns {SharedArrayBuffer} The shared sampler buffer to pass to the debugger worker. */ -function installProbeSampler (guardrailMetrics) { +function installProbeSampler (guardrailMetrics, config) { + configureProbeSampler(config) + const buffer = createProbeSamplerBuffer() const lastCaptureNsByProbeId = new Map() /** - * Probes whose condition recently failed to evaluate, keyed by probe id. The error is kept until the worker picks it - * up for the error result. + * Probes that are skipped at entry because a recent evaluation failed or exceeded its time budget. One error result + * is reported per throttle window, so the probe stays visible without repeatedly paying for the evaluation. * - * @type {Map} + * @type {Map} */ - const conditionErrorByProbeId = new Map() + const throttleByProbeId = new Map() const sampledProbeIndexes = new Int32Array(buffer) Atomics.store(sampledProbeIndexes, SAMPLED_PROBE_COUNT_INDEX, 0) Atomics.store(sampledProbeIndexes, SAMPLED_PROBE_OVERFLOW_INDEX, 0) @@ -49,7 +71,17 @@ function installProbeSampler (guardrailMetrics) { ddTraceGlobal[Symbol.for(PROBE_SAMPLER_SYMBOL)] = { /** - * Decide if a probe should be sampled and store sampled probe indexes for the debugger worker. + * The current monotonic time. Exposed so breakpoint conditions can time evaluations without depending on globals + * of the realm they run in. + * + * @returns {bigint} + */ + now () { + return process.hrtime.bigint() + }, + + /** + * Decide if a probe without a condition should be sampled and store sampled probe indexes for the debugger worker. * * @param {number} probeIndex - The worker-side probe sampling index. * @param {string} probeId - The probe id. @@ -59,56 +91,44 @@ function installProbeSampler (guardrailMetrics) { */ makeSampleDecision (probeIndex, probeId, nsBetweenSampling, isSnapshotProducingProbe) { const now = process.hrtime.bigint() - const lastCaptureNs = lastCaptureNsByProbeId.get(probeId) - if (lastCaptureNs !== undefined && now - lastCaptureNs < nsBetweenSampling) { - guardrailMetrics.eventSkipped( - SKIPPED_REASON.RATE_LIMIT_PROBE, - isSnapshotProducingProbe === true ? EVENT_TYPE.SNAPSHOT : EVENT_TYPE.LOG - ) - return false - } - - let shouldResetGlobalSnapshotRateWindow = false - if (isSnapshotProducingProbe === true) { - if (now - globalSnapshotSamplingRateWindowStart > oneSecondNs) { - shouldResetGlobalSnapshotRateWindow = true - } else if (snapshotsSampledWithinTheLastSecond >= MAX_SNAPSHOTS_PER_SECOND_GLOBALLY) { - guardrailMetrics.eventSkipped(SKIPPED_REASON.RATE_LIMIT_GLOBAL, EVENT_TYPE.SNAPSHOT) - return false - } - } - - if (!storeSampledProbeIndex(probeIndex)) return false - - if (isSnapshotProducingProbe === true) { - if (shouldResetGlobalSnapshotRateWindow === true) { - snapshotsSampledWithinTheLastSecond = 1 - globalSnapshotSamplingRateWindowStart = now - } else { - snapshotsSampledWithinTheLastSecond++ - } - } - - lastCaptureNsByProbeId.set(probeId, now) - return true + if (isThrottled(probeId, now, isSnapshotProducingProbe)) return false + return sample(probeIndex, probeId, now, nsBetweenSampling, isSnapshotProducingProbe) }, /** * Decide if a probe's condition should be evaluated, or skipped because a recent evaluation error throttled it. * * @param {string} probeId - The probe id. + * @param {boolean} isSnapshotProducingProbe - Whether this probe produces snapshots. * @returns {boolean} Whether the condition should be evaluated on this hit. */ - shouldEvaluateCondition (probeId) { - const state = conditionErrorByProbeId.get(probeId) - return state === undefined || process.hrtime.bigint() >= state.throttledUntilNs + shouldEvaluateCondition (probeId, isSnapshotProducingProbe) { + return !isThrottled(probeId, process.hrtime.bigint(), isSnapshotProducingProbe) }, /** - * Record that a probe's condition threw, throttle the probe, and request a pause so the error can be reported. + * Decide if a probe should be sampled now that its condition has been evaluated. A condition that exceeded the + * evaluation time budget is reported like a condition error instead, regardless of its result. * - * Error results bypass the per-probe and global rate limits: they are rate limited by the throttle instead, which - * allows one error result per probe per window. + * @param {number} probeIndex - The worker-side probe sampling index. + * @param {string} probeId - The probe id. + * @param {bigint} startNs - The time at which the condition evaluation started. + * @param {boolean} matched - Whether the condition evaluated to `true`. + * @param {bigint} nsBetweenSampling - Minimum nanoseconds between samples for this probe. + * @param {boolean} isSnapshotProducingProbe - Whether this probe counts toward the global snapshot sample limit. + * @returns {boolean} Whether this probe should make the breakpoint condition pause. + */ + conditionEvaluated (probeIndex, probeId, startNs, matched, nsBetweenSampling, isSnapshotProducingProbe) { + const now = process.hrtime.bigint() + const elapsedNs = now - startNs + if (elapsedNs > evaluationTimeoutNs) { + return recordConditionError(probeIndex, probeId, now, describeTimeout(elapsedNs), true) + } + return matched === true && sample(probeIndex, probeId, now, nsBetweenSampling, isSnapshotProducingProbe) + }, + + /** + * Record that a probe's condition threw, throttle the probe, and request a pause so the error can be reported. * * @param {number} probeIndex - The worker-side probe sampling index. * @param {string} probeId - The probe id. @@ -116,11 +136,7 @@ function installProbeSampler (guardrailMetrics) { * @returns {boolean} Whether this probe should make the breakpoint condition pause. */ conditionError (probeIndex, probeId, error) { - conditionErrorByProbeId.set(probeId, { - throttledUntilNs: process.hrtime.bigint() + CONDITION_ERROR_THROTTLE_NS, - error: describeError(error), - }) - return storeSampledProbeIndex(probeIndex | CONDITION_ERROR_FLAG) + return recordConditionError(probeIndex, probeId, process.hrtime.bigint(), describeError(error), false) }, /** @@ -130,13 +146,27 @@ function installProbeSampler (guardrailMetrics) { * @returns {string | undefined} The error description, if any. */ takeConditionError (probeId) { - const state = conditionErrorByProbeId.get(probeId) + const state = throttleByProbeId.get(probeId) if (state === undefined) return const { error } = state state.error = undefined return error }, + /** + * Throttle a probe whose evaluation exceeded its time budget in the worker, e.g. while evaluating its template. + * Called by the worker after the result has been reported. + * + * @param {string} probeId - The probe id. + */ + evaluationTimedOut (probeId) { + throttleByProbeId.set(probeId, { + untilNs: process.hrtime.bigint() + CONDITION_ERROR_THROTTLE_NS, + timedOut: true, + error: undefined, + }) + }, + /** * Remove cached sampling state for a probe. * @@ -144,10 +174,93 @@ function installProbeSampler (guardrailMetrics) { */ remove (probeId) { lastCaptureNsByProbeId.delete(probeId) - conditionErrorByProbeId.delete(probeId) + throttleByProbeId.delete(probeId) }, } + /** + * Check if a probe is skipped at entry because of a recent evaluation error, recording the skip when the error was + * an exceeded time budget. + * + * @param {string} probeId - The probe id. + * @param {bigint} now - The current time. + * @param {boolean} isSnapshotProducingProbe - Whether this probe produces snapshots. + * @returns {boolean} + */ + function isThrottled (probeId, now, isSnapshotProducingProbe) { + const state = throttleByProbeId.get(probeId) + if (state === undefined || now >= state.untilNs) return false + if (state.timedOut) { + guardrailMetrics.eventSkipped( + SKIPPED_REASON.EVALUATION_TIMEOUT, + isSnapshotProducingProbe === true ? EVENT_TYPE.SNAPSHOT : EVENT_TYPE.LOG + ) + } + return true + } + + /** + * Apply the per-probe and global rate limits and store the sampled probe index for the debugger worker. + * + * @param {number} probeIndex - The worker-side probe sampling index. + * @param {string} probeId - The probe id. + * @param {bigint} now - The current time. + * @param {bigint} nsBetweenSampling - Minimum nanoseconds between samples for this probe. + * @param {boolean} isSnapshotProducingProbe - Whether this probe counts toward the global snapshot sample limit. + * @returns {boolean} Whether this probe should make the breakpoint condition pause. + */ + function sample (probeIndex, probeId, now, nsBetweenSampling, isSnapshotProducingProbe) { + const lastCaptureNs = lastCaptureNsByProbeId.get(probeId) + if (lastCaptureNs !== undefined && now - lastCaptureNs < nsBetweenSampling) { + guardrailMetrics.eventSkipped( + SKIPPED_REASON.RATE_LIMIT_PROBE, + isSnapshotProducingProbe === true ? EVENT_TYPE.SNAPSHOT : EVENT_TYPE.LOG + ) + return false + } + + let shouldResetGlobalSnapshotRateWindow = false + if (isSnapshotProducingProbe === true) { + if (now - globalSnapshotSamplingRateWindowStart > oneSecondNs) { + shouldResetGlobalSnapshotRateWindow = true + } else if (snapshotsSampledWithinTheLastSecond >= MAX_SNAPSHOTS_PER_SECOND_GLOBALLY) { + guardrailMetrics.eventSkipped(SKIPPED_REASON.RATE_LIMIT_GLOBAL, EVENT_TYPE.SNAPSHOT) + return false + } + } + + if (!storeSampledProbeIndex(probeIndex)) return false + + if (isSnapshotProducingProbe === true) { + if (shouldResetGlobalSnapshotRateWindow === true) { + snapshotsSampledWithinTheLastSecond = 1 + globalSnapshotSamplingRateWindowStart = now + } else { + snapshotsSampledWithinTheLastSecond++ + } + } + + lastCaptureNsByProbeId.set(probeId, now) + return true + } + + /** + * Throttle a probe whose condition failed and request a pause so the error can be reported. Error results bypass the + * per-probe and global rate limits: they are rate limited by the throttle instead, which allows one error result per + * probe per window. + * + * @param {number} probeIndex - The worker-side probe sampling index. + * @param {string} probeId - The probe id. + * @param {bigint} now - The current time. + * @param {string} error - The error description. + * @param {boolean} timedOut - Whether the error is an exceeded time budget. + * @returns {boolean} Whether this probe should make the breakpoint condition pause. + */ + function recordConditionError (probeIndex, probeId, now, error, timedOut) { + throttleByProbeId.set(probeId, { untilNs: now + CONDITION_ERROR_THROTTLE_NS, timedOut, error }) + return storeSampledProbeIndex(probeIndex | CONDITION_ERROR_FLAG) + } + /** * Hand a sampled probe index over to the worker for the upcoming pause. * @@ -186,6 +299,17 @@ function describeError (error) { return typeof error === 'string' ? error : 'Unknown evaluation error' } +/** + * Describe a condition evaluation that exceeded its time budget. + * + * @param {bigint} elapsedNs - The time the evaluation took. + * @returns {string} + */ +function describeTimeout (elapsedNs) { + return `Condition evaluation exceeded its time budget of ${evaluationTimeoutNs / 1_000_000n}ms ` + + `(took ${(Number(elapsedNs) / 1_000_000).toFixed(1)}ms)` +} + /** * Create the shared buffer used to hand sampled probe indexes from breakpoint conditions to the debugger worker. * diff --git a/packages/dd-trace/test/config/index.spec.js b/packages/dd-trace/test/config/index.spec.js index 23be727a16..d0dcbe6031 100644 --- a/packages/dd-trace/test/config/index.spec.js +++ b/packages/dd-trace/test/config/index.spec.js @@ -1134,6 +1134,7 @@ describe('Config', () => { }, dynamicInstrumentation: { enabled: false, + evaluationTimeoutMs: 10, probeFile: undefined, queueMaxBytes: 10 * 1024 * 1024, uploadIntervalSeconds: 1, @@ -1270,6 +1271,7 @@ describe('Config', () => { { name: 'DD_DOGSTATSD_PORT', value: 8125, origin: 'default' }, { name: 'DD_DATA_STREAMS_ENABLED', value: false, origin: 'default' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_ENABLED', value: false, origin: 'default' }, + { name: 'DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS', value: 10, origin: 'default' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE', value: null, origin: 'default' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_QUEUE_MAX_BYTES', value: 10 * 1024 * 1024, origin: 'default' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS', value: '', origin: 'default' }, @@ -1474,6 +1476,7 @@ describe('Config', () => { process.env.DD_DOGSTATSD_HOSTNAME = 'dsd-agent' process.env.DD_DOGSTATSD_PORT = '5218' process.env.DD_DYNAMIC_INSTRUMENTATION_ENABLED = 'true' + process.env.DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS = '20' process.env.DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE = 'probes.json' process.env.DD_DYNAMIC_INSTRUMENTATION_QUEUE_MAX_BYTES = '1048576' process.env.DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS = 'foo,bar' @@ -1618,6 +1621,7 @@ describe('Config', () => { }, dynamicInstrumentation: { enabled: true, + evaluationTimeoutMs: 20, probeFile: 'probes.json', queueMaxBytes: 1024 * 1024, redactedIdentifiers: ['foo', 'bar'], @@ -1759,6 +1763,7 @@ describe('Config', () => { { name: 'DD_DOGSTATSD_HOST', value: 'dsd-agent', origin: 'env_var' }, { name: 'DD_DOGSTATSD_PORT', value: 5218, origin: 'env_var' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_ENABLED', value: true, origin: 'env_var' }, + { name: 'DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS', value: 20, origin: 'env_var' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE', value: 'probes.json', origin: 'env_var' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_QUEUE_MAX_BYTES', value: 1024 * 1024, origin: 'env_var' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS', value: 'foo,bar', origin: 'env_var' }, @@ -2123,6 +2128,7 @@ describe('Config', () => { }, dynamicInstrumentation: { enabled: true, + evaluationTimeoutMs: 30, probeFile: 'probes.json', queueMaxBytes: 2 * 1024 * 1024, redactedIdentifiers: ['foo', 'bar'], @@ -2237,6 +2243,7 @@ describe('Config', () => { }, dynamicInstrumentation: { enabled: true, + evaluationTimeoutMs: 30, probeFile: 'probes.json', queueMaxBytes: 2 * 1024 * 1024, uploadIntervalSeconds: 0.1, @@ -2385,6 +2392,7 @@ describe('Config', () => { { name: 'DD_DOGSTATSD_HOST', value: 'agent-dsd', origin: 'code' }, { name: 'DD_DOGSTATSD_PORT', value: '5218', origin: 'code' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_ENABLED', value: true, origin: 'code' }, + { name: 'DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS', value: 30, origin: 'code' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE', value: 'probes.json', origin: 'code' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_QUEUE_MAX_BYTES', value: 2 * 1024 * 1024, origin: 'code' }, { name: 'DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS', value: 'foo,bar', origin: 'code' }, @@ -2702,6 +2710,7 @@ describe('Config', () => { process.env.DD_CODE_ORIGIN_FOR_SPANS_EXPERIMENTAL_EXIT_SPANS_ENABLED = 'true' process.env.DD_DOGSTATSD_PORT = '5218' process.env.DD_DYNAMIC_INSTRUMENTATION_ENABLED = 'true' + process.env.DD_DYNAMIC_INSTRUMENTATION_EVALUATION_TIMEOUT_MS = '20' process.env.DD_DYNAMIC_INSTRUMENTATION_PROBE_FILE = 'probes.json' process.env.DD_DYNAMIC_INSTRUMENTATION_QUEUE_MAX_BYTES = '1048576' process.env.DD_DYNAMIC_INSTRUMENTATION_REDACTED_IDENTIFIERS = 'foo,bar' @@ -2797,6 +2806,7 @@ describe('Config', () => { }, dynamicInstrumentation: { enabled: false, + evaluationTimeoutMs: 30, probeFile: 'probes2.json', queueMaxBytes: 2 * 1024 * 1024, redactedIdentifiers: ['foo2', 'bar2'], @@ -2913,6 +2923,7 @@ describe('Config', () => { }, dynamicInstrumentation: { enabled: false, + evaluationTimeoutMs: 30, probeFile: 'probes2.json', queueMaxBytes: 2 * 1024 * 1024, redactedIdentifiers: ['foo2', 'bar2'], diff --git a/packages/dd-trace/test/debugger/devtools_client/index.spec.js b/packages/dd-trace/test/debugger/devtools_client/index.spec.js index 700566ef45..1a622dc845 100644 --- a/packages/dd-trace/test/debugger/devtools_client/index.spec.js +++ b/packages/dd-trace/test/debugger/devtools_client/index.spec.js @@ -59,7 +59,7 @@ describe('onPause', function () { let state /** @type {Int32Array} */ let sampledProbeIndexes - /** @type {unknown} */ + /** @type {{ error: sinon.SinonSpy, debug: sinon.SinonSpy, '@noCallThru': boolean }} */ let log beforeEach(async function () { @@ -93,6 +93,7 @@ describe('onPause', function () { parentThreadId, dynamicInstrumentation: { captureTimeoutNs: 15_000_000n, // Default value is 15ms + evaluationTimeoutNs: 10_000_000n, // Default value is 10ms redactedIdentifiers: [], redactionExcludedIdentifiers: [], }, @@ -102,7 +103,10 @@ describe('onPause', function () { send = sinon.spy() send['@noCallThru'] = true - sampledProbeIndexes = new Int32Array(installProbeSampler(new GuardrailMetrics(GuardrailMetrics.createBuffer()))) + sampledProbeIndexes = new Int32Array(installProbeSampler( + new GuardrailMetrics(GuardrailMetrics.createBuffer()), + { dynamicInstrumentation: { evaluationTimeoutMs: 10 } } + )) state = proxyquire('../../../src/debugger/devtools_client/state', { './session': session }) const loadStatus = proxyquire.noCallThru() @@ -547,6 +551,145 @@ describe('onPause', function () { }) }) + describe('evaluation time budget', function () { + const evaluationTimedOutExpression = 'globalThis[Symbol.for("dd-trace")]?.' + + '[Symbol.for("dd-trace.debugger.probeSampler")]?.evaluationTimedOut("probe-1")' + /** @type {sinon.SinonStub} */ + let hrtime + + beforeEach(function () { + hrtime = sinon.stub(process.hrtime, 'bigint').returns(0n) + }) + + afterEach(function () { + hrtime.restore() + }) + + it('should not report templates evaluated within the budget', async function () { + const probe = genProcessedProbe('probe-1') + probe.templateRequiresEvaluation = true + probe.template = '["hello ", foo]' + sampleProbe(probe) + + session.post = sinon.stub().callsFake((method) => { + if (method === 'Debugger.evaluateOnCallFrame') { + hrtime.returns(10_000_000n) // exactly the 10ms budget + return Promise.resolve({ result: { value: [{}, ['hello ', 'world']] } }) + } + return Promise.resolve({}) + }) + + await onPaused(event) + + sinon.assert.calledOnce(send) + assert.strictEqual(send.firstCall.args[0], 'hello world') + assert.strictEqual(send.firstCall.args[3].evaluationErrors, undefined) + sinon.assert.neverCalledWith(session.post, 'Runtime.evaluate') + }) + + it('should report templates that exceed the budget and throttle the probe', async function () { + const probe = genProcessedProbe('probe-1') + probe.templateRequiresEvaluation = true + probe.template = '["hello ", foo]' + sampleProbe(probe) + + session.post = sinon.stub().callsFake((method) => { + if (method === 'Debugger.evaluateOnCallFrame') { + hrtime.returns(10_000_001n) + return Promise.resolve({ result: { value: [{}, ['hello ', 'world']] } }) + } + return Promise.resolve({}) + }) + + await onPaused(event) + + sinon.assert.calledOnce(send) + const [message, , , snapshot] = send.firstCall.args + assert.strictEqual(message, 'hello world', 'should still report the result') + assert.deepStrictEqual(snapshot.evaluationErrors, [ + { expr: '', message: 'Template evaluation exceeded its time budget of 10ms' }, + ]) + sinon.assert.calledWith(session.post, 'Runtime.evaluate', { expression: evaluationTimedOutExpression }) + assert.ok( + session.post.withArgs('Runtime.evaluate').firstCall.calledAfter(send.firstCall), + 'should throttle after reporting the result' + ) + }) + + it('should not attribute a slow evaluation to probes without templates', async function () { + const probe = genProcessedProbe('probe-1') + sampleProbe(probe) + + session.post = sinon.stub().callsFake((method) => { + if (method === 'Debugger.evaluateOnCallFrame') { + hrtime.returns(10_000_001n) + return Promise.resolve({ result: { value: [{}] } }) + } + return Promise.resolve({}) + }) + + await onPaused(event) + + sinon.assert.calledOnce(send) + assert.strictEqual(send.firstCall.args[3].evaluationErrors, undefined) + sinon.assert.neverCalledWith(session.post, 'Runtime.evaluate') + }) + + it('should report capture expressions that exceed the budget and throttle the probe', async function () { + const probe = genProcessedProbe('probe-1') + probe.compiledCaptureExpressions = [{ + name: 'foo', + expression: 'foo', + limits: { maxReferenceDepth: 3, maxCollectionSize: 100, maxFieldCount: 20, maxLength: 255 }, + }] + sampleProbe(probe) + + session.post = sinon.stub().callsFake((method, params) => { + if (method === 'Debugger.evaluateOnCallFrame') { + if (params.expression === 'foo') { + hrtime.returns(10_000_001n) + return Promise.resolve({ result: { type: 'string', value: 'bar' } }) + } + return Promise.resolve({ result: { value: [{}] } }) + } + return Promise.resolve({}) + }) + + await onPaused(event) + + sinon.assert.calledOnce(send) + const [, , , snapshot, , , incompleteReasons] = send.firstCall.args + assert.deepStrictEqual(snapshot.captures.lines[1].captureExpressions.foo, { type: 'string', value: 'bar' }) + assert.deepStrictEqual(snapshot.evaluationErrors, [ + { expr: 'foo', message: 'Expression evaluation exceeded its time budget of 10ms' }, + ]) + assert.strictEqual(incompleteReasons, INCOMPLETE_REASON.TIMEOUT) + sinon.assert.calledWith(session.post, 'Runtime.evaluate', { expression: evaluationTimedOutExpression }) + }) + + it('should log if throttling the probe fails', async function () { + const probe = genProcessedProbe('probe-1') + probe.templateRequiresEvaluation = true + probe.template = '["hello"]' + sampleProbe(probe) + + const error = new Error('boom') + session.post = sinon.stub().callsFake((method) => { + if (method === 'Debugger.evaluateOnCallFrame') { + hrtime.returns(10_000_001n) + return Promise.resolve({ result: { value: [{}, ['hello']] } }) + } + if (method === 'Runtime.evaluate') return Promise.reject(error) + return Promise.resolve({}) + }) + + await onPaused(event) + await new Promise((resolve) => setImmediate(resolve)) + + sinon.assert.calledWith(log.error, '[debugger:devtools_client] Error throttling probe %s', 'probe-1', error) + }) + }) + it('should log sampler overflow', async function () { state.breakpointToProbes.set(breakpointId, new Map()) Atomics.store(sampledProbeIndexes, 1, 1) diff --git a/packages/dd-trace/test/debugger/devtools_client/snapshot/error-handling.spec.js b/packages/dd-trace/test/debugger/devtools_client/snapshot/error-handling.spec.js index 26eda47413..fefc174878 100644 --- a/packages/dd-trace/test/debugger/devtools_client/snapshot/error-handling.spec.js +++ b/packages/dd-trace/test/debugger/devtools_client/snapshot/error-handling.spec.js @@ -135,6 +135,48 @@ describe('debugger -> devtools client -> snapshot', function () { assert.ok(!('secondExpr' in captured)) }) + it('should report an expression that exceeds the evaluation time budget', async function () { + const expressions = [{ + name: 'slowExpr', + expression: 'slow', + limits: DEFAULT_CAPTURE_LIMITS, + }, { + name: 'fastExpr', + expression: 'fast', + limits: DEFAULT_CAPTURE_LIMITS, + }] + + let nowNs = 0n + const hrtime = sinon.stub(process.hrtime, 'bigint').callsFake(() => nowNs) + sessionPostStub = sinon.stub(session, 'post') + sessionPostStub.onCall(0).callsFake(() => { + nowNs += 10_000_001n + return Promise.resolve({ result: { type: 'string', value: 'slow' } }) + }) + sessionPostStub.onCall(1).callsFake(() => { + nowNs += 10_000_000n + return Promise.resolve({ result: { type: 'string', value: 'fast' } }) + }) + + let result + try { + result = await evaluateCaptureExpressions(mockCallFrame, expressions, undefined, 10_000_000n) + } finally { + hrtime.restore() + } + + assert.strictEqual(result.timedOut, true) + assert.strictEqual(result.incomplete.reasons, INCOMPLETE_REASON.TIMEOUT) + assert.deepStrictEqual(result.evaluationErrors, [{ + expr: 'slowExpr', + message: 'Expression evaluation exceeded its time budget of 10ms', + }]) + assert.deepStrictEqual(result.processCaptureExpressions(), { + slowExpr: { type: 'string', value: 'slow' }, + fastExpr: { type: 'string', value: 'fast' }, + }, 'should still capture the results') + }) + it('should distinguish between evaluationErrors and fatalErrors', async function () { const expressions = [{ name: 'undefinedVar', @@ -161,6 +203,7 @@ describe('debugger -> devtools client -> snapshot', function () { const result = await evaluateCaptureExpressions(mockCallFrame, expressions) // Should have one evaluation error (transient) + assert.strictEqual(result.timedOut, false) assert.deepStrictEqual(result.evaluationErrors, [{ expr: 'undefinedVar', message: 'ReferenceError: doesNotExist is not defined', diff --git a/packages/dd-trace/test/debugger/index.spec.js b/packages/dd-trace/test/debugger/index.spec.js index 215d40a92e..3cdc760c4a 100644 --- a/packages/dd-trace/test/debugger/index.spec.js +++ b/packages/dd-trace/test/debugger/index.spec.js @@ -72,6 +72,7 @@ describe('debugger/index', () => { debug: false, dynamicInstrumentation: { enabled: true, + evaluationTimeoutMs: 10, }, hostname: 'test-host', logLevel: 'info', @@ -266,6 +267,7 @@ describe('debugger/index', () => { debug: false, dynamicInstrumentation: { enabled: true, + evaluationTimeoutMs: 10, }, env: 'test-env', hostname: 'test-host', @@ -281,6 +283,30 @@ describe('debugger/index', () => { }) }) + it('should apply the evaluation time budget to the probe sampler', () => { + DynamicInstrumentation.start(config, rc) + const sampler = globalThis[Symbol.for('dd-trace')][Symbol.for('dd-trace.debugger.probeSampler')] + const hrtime = sinon.stub(process.hrtime, 'bigint') + try { + // A 15ms evaluation is within the configured 10ms budget only once the budget is raised + hrtime.returns(15_000_000n) + assert.strictEqual(sampler.conditionEvaluated(0, 'probe-1', 0n, true, 0n, false), true) + assert.strictEqual( + sampler.takeConditionError('probe-1'), + 'Condition evaluation exceeded its time budget of 10ms (took 15.0ms)' + ) + + config.dynamicInstrumentation.evaluationTimeoutMs = 20 + DynamicInstrumentation.configure(config) + sampler.remove('probe-1') + + assert.strictEqual(sampler.conditionEvaluated(0, 'probe-1', 0n, true, 0n, false), true) + assert.strictEqual(sampler.takeConditionError('probe-1'), undefined) + } finally { + hrtime.restore() + } + }) + it('should ignore an invalid agentless site', () => { DynamicInstrumentation.start(config, rc) const configPort = messageChannels[2].port2 diff --git a/packages/dd-trace/test/debugger/probe_sampler.spec.js b/packages/dd-trace/test/debugger/probe_sampler.spec.js index 0d0d2282e6..911ff48eae 100644 --- a/packages/dd-trace/test/debugger/probe_sampler.spec.js +++ b/packages/dd-trace/test/debugger/probe_sampler.spec.js @@ -31,9 +31,14 @@ const samplerSymbol = Symbol.for('dd-trace.debugger.probeSampler') * @property {Function} shouldEvaluateCondition * @property {Function} conditionError * @property {Function} takeConditionError + * @property {Function} conditionEvaluated + * @property {Function} evaluationTimedOut * @property {Function} remove */ +const EVALUATION_TIMEOUT_MS = 10 +const samplerConfig = { dynamicInstrumentation: { evaluationTimeoutMs: EVALUATION_TIMEOUT_MS } } + /** @type {GuardrailMetrics} */ let guardrailMetrics @@ -58,7 +63,7 @@ describe('probe sampler', function () { describe('shared buffer', function () { it('should create a shared buffer with the expected layout', function () { - const buffer = installProbeSampler(guardrailMetrics) + const buffer = installProbeSampler(guardrailMetrics, samplerConfig) const sampledProbeIndexes = new Int32Array(buffer) assert(buffer instanceof SharedArrayBuffer) @@ -66,7 +71,7 @@ describe('probe sampler', function () { }) it('should initialize the shared buffer', function () { - const installedBuffer = installProbeSampler(guardrailMetrics) + const installedBuffer = installProbeSampler(guardrailMetrics, samplerConfig) const installedSampledProbeIndexes = new Int32Array(installedBuffer) assert.strictEqual(Atomics.load(installedSampledProbeIndexes, SAMPLED_PROBE_COUNT_INDEX), 0) @@ -109,14 +114,13 @@ describe('probe sampler', function () { const $dd_sampler = globalThis[Symbol.for("dd-trace")]?.[Symbol.for("dd-trace.debugger.probeSampler")] if ($dd_sampler === undefined) return false let $dd_sampled = false - if ($dd_sampler.shouldEvaluateCondition("probe-1")) { + if ($dd_sampler.shouldEvaluateCondition("probe-1", true)) { + const $dd_start = $dd_sampler.now() try { - if (((foo) === (42)) === true) { - $dd_sampled = $dd_sampler.makeSampleDecision(0, "probe-1", 200000n, true) || $dd_sampled - } + $dd_sampled = $dd_sampler.conditionEvaluated(0, "probe-1", $dd_start, + ((foo) === (42)) === true, 200000n, true) || $dd_sampled } catch ($dd_error) { - $dd_sampled = $dd_sampler.conditionError(0, "probe-1", $dd_error) || - $dd_sampled + $dd_sampled = $dd_sampler.conditionError(0, "probe-1", $dd_error) || $dd_sampled } } return $dd_sampled @@ -154,6 +158,33 @@ describe('probe sampler', function () { now += CONDITION_ERROR_THROTTLE_NS assert.strictEqual(evaluate(), true, 'should evaluate the condition again once the throttle window has passed') }) + + it('should pause for a condition that exceeds the evaluation time budget and skip it afterwards', function () { + installSampler() + const sampler = getSampler() + const probes = [{ id: 'probe-1', samplingIndex: 0, nsBetweenSampling: 0n, condition: 'slow()' }] + const breakpointCondition = compileBreakpointCondition(probes) + const evaluate = (elapsedNs) => { + // eslint-disable-next-line no-new-func + return new Function('slow', `return ${breakpointCondition}`)(() => { + now += elapsedNs + return true + }) + } + + assert.strictEqual(evaluate(BigInt(EVALUATION_TIMEOUT_MS) * 1_000_000n), true, 'should sample within budget') + assert.strictEqual(sampler.takeConditionError('probe-1'), undefined) + + assert.strictEqual(evaluate(BigInt(EVALUATION_TIMEOUT_MS) * 1_000_000n + 1n), true, 'should pause for the error') + assert.strictEqual( + sampler.takeConditionError('probe-1'), + 'Condition evaluation exceeded its time budget of 10ms (took 10.0ms)' + ) + assert.strictEqual(evaluate(0n), false, 'should skip the condition while throttled') + assert.deepStrictEqual(drainGuardrailMetrics(), [ + ['events.skipped', ['event_type:log', 'reason:evaluationTimeout'], 1], + ]) + }) }) describe('runtime sampler', function () { @@ -371,6 +402,90 @@ describe('probe sampler', function () { assert.strictEqual(Atomics.load(sampledProbeIndexes, SAMPLED_PROBE_OVERFLOW_INDEX), 1) }) + it('should sample a matching condition evaluated within the time budget', function () { + const sampledProbeIndexes = installSampler() + const sampler = getSampler() + const budgetNs = BigInt(EVALUATION_TIMEOUT_MS) * 1_000_000n + + assert.strictEqual(sampler.conditionEvaluated(7, 'probe-1', now - budgetNs, true, 0n, false), true) + assert.strictEqual(Atomics.load(sampledProbeIndexes, SAMPLED_PROBE_INDEXES_START), 7) + assert.strictEqual(sampler.conditionEvaluated(8, 'probe-2', now - budgetNs, false, 0n, false), false) + assert.strictEqual(Atomics.load(sampledProbeIndexes, SAMPLED_PROBE_COUNT_INDEX), 1) + assert.deepStrictEqual(drainGuardrailMetrics(), []) + }) + + it('should apply the rate limits to matching conditions', function () { + installSampler() + const sampler = getSampler() + + assert.strictEqual(sampler.conditionEvaluated(7, 'probe-1', now, true, 200000n, false), true) + assert.strictEqual(sampler.conditionEvaluated(7, 'probe-1', now, true, 200000n, false), false) + assert.deepStrictEqual(drainGuardrailMetrics(), [ + ['events.skipped', ['event_type:log', 'reason:rateLimitProbe'], 1], + ]) + }) + + it('should report a condition that exceeds the time budget as an error, even if it matched', function () { + const sampledProbeIndexes = installSampler() + const sampler = getSampler() + const overBudgetNs = BigInt(EVALUATION_TIMEOUT_MS) * 1_000_000n + 500_000n + + assert.strictEqual(sampler.conditionEvaluated(7, 'probe-1', now - overBudgetNs, true, 0n, true), true) + assert.strictEqual(Atomics.load(sampledProbeIndexes, SAMPLED_PROBE_INDEXES_START), 7 | CONDITION_ERROR_FLAG) + assert.strictEqual( + sampler.takeConditionError('probe-1'), + 'Condition evaluation exceeded its time budget of 10ms (took 10.5ms)' + ) + }) + + it('should count hits skipped because of an exceeded time budget', function () { + installSampler() + const sampler = getSampler() + const overBudgetNs = BigInt(EVALUATION_TIMEOUT_MS) * 1_000_000n + 1n + + sampler.conditionEvaluated(7, 'probe-1', now - overBudgetNs, false, 0n, true) + assert.deepStrictEqual(drainGuardrailMetrics(), [], 'the error result itself is not a skip') + + assert.strictEqual(sampler.shouldEvaluateCondition('probe-1', true), false) + assert.strictEqual(sampler.shouldEvaluateCondition('probe-1', true), false) + assert.strictEqual(sampler.makeSampleDecision(7, 'probe-1', 0n, true), false) + assert.deepStrictEqual(drainGuardrailMetrics(), [ + ['events.skipped', ['event_type:snapshot', 'reason:evaluationTimeout'], 3], + ]) + + now += CONDITION_ERROR_THROTTLE_NS + assert.strictEqual(sampler.shouldEvaluateCondition('probe-1', true), true) + assert.deepStrictEqual(drainGuardrailMetrics(), []) + }) + + it('should not count hits skipped because of a condition error', function () { + installSampler() + const sampler = getSampler() + + sampler.conditionError(7, 'probe-1', new Error('boom')) + assert.strictEqual(sampler.shouldEvaluateCondition('probe-1', true), false) + assert.strictEqual(sampler.makeSampleDecision(7, 'probe-1', 0n, true), false) + + assert.deepStrictEqual(drainGuardrailMetrics(), []) + }) + + it('should throttle a probe whose evaluation timed out in the worker', function () { + installSampler() + const sampler = getSampler() + + sampler.evaluationTimedOut('probe-1') + + assert.strictEqual(sampler.makeSampleDecision(7, 'probe-1', 0n, false), false) + assert.strictEqual(sampler.shouldEvaluateCondition('probe-1', false), false) + assert.strictEqual(sampler.takeConditionError('probe-1'), undefined, 'the worker already reported the error') + assert.deepStrictEqual(drainGuardrailMetrics(), [ + ['events.skipped', ['event_type:log', 'reason:evaluationTimeout'], 2], + ]) + + now += CONDITION_ERROR_THROTTLE_NS + assert.strictEqual(sampler.makeSampleDecision(7, 'probe-1', 0n, false), true) + }) + it('should forget the recorded error and throttle when a probe is removed', function () { installSampler() const sampler = getSampler() @@ -404,7 +519,7 @@ describe('probe sampler', function () { * Install the runtime sampler for tests. */ function installSampler () { - return new Int32Array(installProbeSampler(guardrailMetrics)) + return new Int32Array(installProbeSampler(guardrailMetrics, samplerConfig)) } /**