feat(debugger): add an evaluation time budget

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: [],

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

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

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')
+    })
+  })
+})

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[];

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",

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
 }

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
 }

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
       }
     }`
 }