Start collecting async IDs in profiles (#5524)

* Upgrade to profiler 5.7.0 for asyncId collection capability

* Add a config option to disable async ID collection

* Alphabetically sort some long option lists

* Add async ID assertions to the integration test

* Only enable the feature for Node.js version >=22.10.0

Author: szegedi

integration-tests/profiler/codehotspots.js

@@ -6,13 +6,19 @@ const tracer = DDTrace.init()
 
 function busyLoop () {
   const start = process.hrtime.bigint()
+  let x = 0
   for (;;) {
     const now = process.hrtime.bigint()
     // Busy cycle for 100ms
     if (now - start > 100000000n) {
       break
     }
+    // Do something in addition to invoking hrtime
+    for (let i = 0; i < 1000; i++) {
+      x += Math.sqrt(Math.random() * 2 - 1)
+    }
   }
+  return x
 }
 
 let counter = 0

integration-tests/profiler/profiler.spec.js

@@ -326,9 +326,10 @@ describe('profiler', () => {
       //   'local root span id's
       // - samples with spans also must have a 'trace endpoint' label with values 'endpoint-0',
       //   'endpoint-1', or 'endpoint-2'
-      // - every occurrence of a span must have the same root span and endpoint
+      // - every occurrence of a span must have the same root span, endpoint, and asyncId
       const rootSpans = new Set()
       const endpoints = new Set()
+      const asyncIds = new Set()
       const spans = new Map()
       const strings = profile.stringTable
       const tsKey = strings.dedup('end_timestamp_ns')
@@ -338,11 +339,13 @@ describe('profiler', () => {
       const threadNameKey = strings.dedup('thread name')
       const threadIdKey = strings.dedup('thread id')
       const osThreadIdKey = strings.dedup('os thread id')
+      const asyncIdKey = strings.dedup('async id')
       const threadNameValue = strings.dedup('Main Event Loop')
       const nonJSThreadNameValue = strings.dedup('Non-JS threads')
 
+      const asyncIdWorks = require('semifies')(process.versions.node, '>=22.10.0')
       for (const sample of profile.sample) {
-        let ts, spanId, rootSpanId, endpoint, threadName, threadId, osThreadId
+        let ts, spanId, rootSpanId, endpoint, threadName, threadId, osThreadId, asyncId
         for (const label of sample.label) {
           switch (label.key) {
             case tsKey: ts = label.num; break
@@ -352,6 +355,12 @@ describe('profiler', () => {
             case threadNameKey: threadName = label.str; break
             case threadIdKey: threadId = label.str; break
             case osThreadIdKey: osThreadId = label.str; break
+            case asyncIdKey:
+              asyncId = label.num
+              if (asyncId === 0) {
+                asyncId = undefined
+              }
+              break
             default: assert.fail(`Unexpected label key ${strings.dedup(label.key)} ${encoded}`)
           }
         }
@@ -385,11 +394,27 @@ describe('profiler', () => {
             // 3 of them.
             continue
           }
-          const spanData = { rootSpanId, endpoint }
+          const spanData = { rootSpanId, endpoint, asyncId }
+          // Record async ID so we can verify we encountered 9 different values.
+          // Async ID can be sporadically missing if sampling hits an intrinsified
+          // function.
+          if (asyncId !== undefined) {
+            asyncIds.add(asyncId)
+          }
           const existingSpanData = spans.get(spanId)
           if (existingSpanData) {
-            // Span's root span and endpoint must be consistent across samples
-            assert.deepEqual(spanData, existingSpanData, encoded)
+            // Span's root span, endpoint, and async ID must be consistent
+            // across samples.
+            assert.equal(existingSpanData.rootSpanId, rootSpanId, encoded)
+            assert.equal(existingSpanData.endpoint, endpoint, encoded)
+            if (asyncIdWorks) {
+              // Account for asyncID sporadically missing
+              if (existingSpanData.asyncId === undefined) {
+                existingSpanData.asyncId = asyncId
+              } else if (asyncId !== undefined) {
+                assert.equal(existingSpanData.asyncId, asyncId, encoded)
+              }
+            }
           } else {
             // New span id, store span data
             spans.set(spanId, spanData)
@@ -407,9 +432,10 @@ describe('profiler', () => {
           }
         }
       }
-      // Need to have a total of 9 different spans, with 3 different root spans
-      // and 3 different endpoints.
+      // Need to have a total of 9 different spans, with 9 different async IDs,
+      // 3 different root spans, and 3 different endpoints.
       assert.equal(spans.size, 9, encoded)
+      assert.equal(asyncIds.size, asyncIdWorks ? 9 : 0, encoded)
       assert.equal(rootSpans.size, 3, encoded)
       assert.equal(endpoints.size, 3, encoded)
     })

package.json

@@ -89,7 +89,7 @@
     "@datadog/wasm-js-rewriter": "3.1.0",
     "@datadog/native-iast-taint-tracking": "3.3.0",
     "@datadog/native-metrics": "^3.1.0",
-    "@datadog/pprof": "5.6.0",
+    "@datadog/pprof": "5.7.0",
     "@datadog/sketches-js": "^2.1.0",
     "@isaacs/ttlcache": "^1.4.1",
     "@opentelemetry/api": ">=1.0.0 <1.9.0",

packages/dd-trace/src/profiling/config.js

@@ -15,13 +15,15 @@ const { GIT_REPOSITORY_URL, GIT_COMMIT_SHA } = require('../plugins/util/tags')
 const { tagger } = require('./tagger')
 const { isFalse, isTrue } = require('../util')
 const { getAzureTagsFromMetadata, getAzureAppMetadata } = require('../azure_metadata')
+const satisfies = require('semifies')
 
 class Config {
   constructor (options = {}) {
     const {
       DD_AGENT_HOST,
       DD_ENV,
       DD_INTERNAL_PROFILING_TIMELINE_SAMPLING_ENABLED, // used for testing
+      DD_PROFILING_ASYNC_ID_ENABLED,
       DD_PROFILING_CODEHOTSPOTS_ENABLED,
       DD_PROFILING_CPU_ENABLED,
       DD_PROFILING_DEBUG_SOURCE_MAPS,
@@ -179,6 +181,10 @@ class Config {
     this.timelineSamplingEnabled = isTrue(coalesce(options.timelineSamplingEnabled,
       DD_INTERNAL_PROFILING_TIMELINE_SAMPLING_ENABLED, true))
 
+    // Async ID gathering only works reliably on Node >= 22.10.0
+    this.asyncIdEnabled = isTrue(coalesce(options.asyncIdEnabled,
+      DD_PROFILING_ASYNC_ID_ENABLED, this.timelineEnabled && satisfies(process.versions.node, '>=22.10.0')))
+
     this.codeHotspotsEnabled = isTrue(coalesce(options.codeHotspotsEnabled,
       DD_PROFILING_CODEHOTSPOTS_ENABLED,
       DD_PROFILING_EXPERIMENTAL_CODEHOTSPOTS_ENABLED, samplingContextsAvailable))

packages/dd-trace/src/profiling/profilers/wall.js

@@ -70,12 +70,14 @@ function ensureChannelsActivated () {
 class NativeWallProfiler {
   constructor (options = {}) {
     this.type = 'wall'
-    this._samplingIntervalMicros = options.samplingInterval || 1e6 / 99 // 99hz
-    this._flushIntervalMillis = options.flushInterval || 60 * 1e3 // 60 seconds
+    this._asyncIdEnabled = !!options.asyncIdEnabled
     this._codeHotspotsEnabled = !!options.codeHotspotsEnabled
+    this._cpuProfilingEnabled = !!options.cpuProfilingEnabled
     this._endpointCollectionEnabled = !!options.endpointCollectionEnabled
+    this._flushIntervalMillis = options.flushInterval || 60 * 1e3 // 60 seconds
+    this._samplingIntervalMicros = options.samplingInterval || 1e6 / 99 // 99hz
     this._timelineEnabled = !!options.timelineEnabled
-    this._cpuProfilingEnabled = !!options.cpuProfilingEnabled
+    this._v8ProfilerBugWorkaroundEnabled = !!options.v8ProfilerBugWorkaroundEnabled
     // We need to capture span data into the sample context for either code hotspots
     // or endpoint collection.
     this._captureSpanData = this._codeHotspotsEnabled || this._endpointCollectionEnabled
@@ -84,7 +86,6 @@ class NativeWallProfiler {
     // timestamps require the sample contexts feature in the pprof wall profiler), or
     // cpu profiling is enabled.
     this._withContexts = this._captureSpanData || this._timelineEnabled || this._cpuProfilingEnabled
-    this._v8ProfilerBugWorkaroundEnabled = !!options.v8ProfilerBugWorkaroundEnabled
     this._mapper = undefined
     this._pprof = undefined
 
@@ -127,13 +128,14 @@ class NativeWallProfiler {
     }
 
     this._pprof.time.start({
-      intervalMicros: this._samplingIntervalMicros,
+      collectAsyncId: this._asyncIdEnabled,
+      collectCpuTime: this._cpuProfilingEnabled,
       durationMillis: this._flushIntervalMillis,
+      intervalMicros: this._samplingIntervalMicros,
+      lineNumbers: false,
       sourceMapper: this._mapper,
       withContexts: this._withContexts,
-      lineNumbers: false,
-      workaroundV8Bug: this._v8ProfilerBugWorkaroundEnabled,
-      collectCpuTime: this._cpuProfilingEnabled
+      workaroundV8Bug: this._v8ProfilerBugWorkaroundEnabled
     })
 
     if (this._withContexts) {

packages/dd-trace/test/profiling/profilers/wall.spec.js

@@ -58,7 +58,8 @@ describe('profilers/native/wall', () => {
         withContexts: false,
         lineNumbers: false,
         workaroundV8Bug: false,
-        collectCpuTime: false
+        collectCpuTime: false,
+        collectAsyncId: false
       })
   })
 
@@ -77,7 +78,8 @@ describe('profilers/native/wall', () => {
         withContexts: false,
         lineNumbers: false,
         workaroundV8Bug: false,
-        collectCpuTime: false
+        collectCpuTime: false,
+        collectAsyncId: false
       })
   })
 
@@ -173,7 +175,8 @@ describe('profilers/native/wall', () => {
         withContexts: false,
         lineNumbers: false,
         workaroundV8Bug: false,
-        collectCpuTime: false
+        collectCpuTime: false,
+        collectAsyncId: false
       })
   })
 

yarn.lock

@@ -383,10 +383,10 @@
     node-addon-api "^6.1.0"
     node-gyp-build "^3.9.0"
 
-"@datadog/pprof@5.6.0":
-  version "5.6.0"
-  resolved "https://registry.yarnpkg.com/@datadog/pprof/-/pprof-5.6.0.tgz#b6f5c566512ba5e55c6dbf46e9f0f020cfd5c6b5"
-  integrity sha512-x7yN0s4wMnRqv3PWQ6eXKH5XE5qvCOwWbOsXqpT2Irbsc7Wcl5w5JrJUcbPCdSJGihpIh6kAeIrS6w/ZCcHy2Q==
+"@datadog/pprof@5.7.0":
+  version "5.7.0"
+  resolved "https://registry.yarnpkg.com/@datadog/pprof/-/pprof-5.7.0.tgz#3dde6d0cce023091f30effc0aab0c896ad2d7fe3"
+  integrity sha512-+pTeElxHwNUQrqY11f6MUUJDk9pMTIvu0LZhEpDZPphq8WDNU9OBvqFFfX9YdQI/nLZAe4L8t2CEgeJJwzW5EQ==
   dependencies:
     delay "^5.0.0"
     node-gyp-build "<4.0"