Skip to content

Start collecting async IDs in profiles #5524

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 8 commits into from
Apr 8, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions integration-tests/profiler/codehotspots.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
40 changes: 33 additions & 7 deletions integration-tests/profiler/profiler.spec.js
Original file line number Diff line number Diff line change
Expand Up @@ -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')
Expand All @@ -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
Expand All @@ -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}`)
}
}
Expand Down Expand Up @@ -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)
Expand All @@ -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)
})
Expand Down
2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
6 changes: 6 additions & 0 deletions packages/dd-trace/src/profiling/config.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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))
Expand Down
18 changes: 10 additions & 8 deletions packages/dd-trace/src/profiling/profilers/wall.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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

Expand Down Expand Up @@ -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) {
Expand Down
9 changes: 6 additions & 3 deletions packages/dd-trace/test/profiling/profilers/wall.spec.js
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,8 @@ describe('profilers/native/wall', () => {
withContexts: false,
lineNumbers: false,
workaroundV8Bug: false,
collectCpuTime: false
collectCpuTime: false,
collectAsyncId: false
})
})

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

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

Expand Down
8 changes: 4 additions & 4 deletions yarn.lock
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
Loading