diff --git a/integration-tests/profiler/profiler.spec.js b/integration-tests/profiler/profiler.spec.js index 05488a3a482..5952b8d03c3 100644 --- a/integration-tests/profiler/profiler.spec.js +++ b/integration-tests/profiler/profiler.spec.js @@ -21,20 +21,33 @@ if (process.platform !== 'win32') { } function checkProfiles (agent, proc, timeout, - expectedProfileTypes = DEFAULT_PROFILE_TYPES, expectBadExit = false, multiplicity = 1) { + expectedProfileTypes = DEFAULT_PROFILE_TYPES, expectBadExit = false, multiplicity = 1 +) { + return Promise.all([ + processExitPromise(proc, timeout, expectBadExit), + expectProfileMessagePromise(agent, timeout, expectedProfileTypes, multiplicity) + ]) +} + +function expectProfileMessagePromise (agent, timeout, + expectedProfileTypes = DEFAULT_PROFILE_TYPES, multiplicity = 1 +) { const fileNames = expectedProfileTypes.map(type => `${type}.pprof`) - const resultPromise = agent.assertMessageReceived(({ headers, payload, files }) => { - assert.propertyVal(headers, 'host', `127.0.0.1:${agent.port}`) - assert.propertyVal(files[0], 'originalname', 'event.json') - const event = JSON.parse(files[0].buffer.toString()) - assert.propertyVal(event, 'family', 'node') - assert.deepPropertyVal(event, 'attachments', fileNames) - for (const [index, fileName] of fileNames.entries()) { - assert.propertyVal(files[index + 1], 'originalname', fileName) + return agent.assertMessageReceived(({ headers, _, files }) => { + try { + assert.propertyVal(headers, 'host', `127.0.0.1:${agent.port}`) + assert.propertyVal(files[0], 'originalname', 'event.json') + const event = JSON.parse(files[0].buffer.toString()) + assert.propertyVal(event, 'family', 'node') + assert.deepPropertyVal(event, 'attachments', fileNames) + for (const [index, fileName] of fileNames.entries()) { + assert.propertyVal(files[index + 1], 'originalname', fileName) + } + } catch (e) { + e.message += ` ${JSON.stringify({ headers, files })}` + throw e } }, timeout, multiplicity) - - return Promise.all([processExitPromise(proc, timeout, expectBadExit), resultPromise]) } function processExitPromise (proc, timeout, expectBadExit = false) { @@ -73,6 +86,18 @@ async function getLatestProfile (cwd, pattern) { return { profile: Profile.decode(pprofUnzipped), encoded: pprofGzipped.toString('base64') } } +function expectTimeout (messagePromise, allowErrors = false) { + return messagePromise.then( + () => { + throw new Error('Received unexpected message') + }, (e) => { + if (e.message !== 'timeout' && (!allowErrors || !e.message.startsWith('timeout, additionally:'))) { + throw e + } + } + ) +} + async function gatherNetworkTimelineEvents (cwd, scriptFilePath, eventType, args) { const procStart = BigInt(Date.now() * 1000000) const proc = fork(path.join(cwd, scriptFilePath), args, { @@ -142,6 +167,7 @@ describe('profiler', () => { let sandbox let cwd let profilerTestFile + let ssiTestFile let oomTestFile let oomEnv let oomExecArgv @@ -151,6 +177,7 @@ describe('profiler', () => { sandbox = await createSandbox() cwd = sandbox.folder profilerTestFile = path.join(cwd, 'profiler/index.js') + ssiTestFile = path.join(cwd, 'profiler/ssi.js') oomTestFile = path.join(cwd, 'profiler/oom.js') oomExecArgv = ['--max-old-space-size=50'] }) @@ -355,19 +382,10 @@ describe('profiler', () => { DD_PROFILING_ENABLED: 1 } }) - const checkTelemetry = agent.assertTelemetryReceived(({ headers, payload }) => { - }, 1000, 'generate-metrics') + const checkTelemetry = agent.assertTelemetryReceived(_ => {}, 1000, 'generate-metrics') // SSI telemetry is not supposed to have been emitted when DD_INJECTION_ENABLED is absent, - // so throw if telemetry callback was invoked and do nothing if it timed out - const checkNoTelemetry = checkTelemetry.then( - () => { - throw new Error('Received unexpected metrics') - }, (e) => { - if (e.message !== 'timeout') { - throw e - } - }) - return Promise.all([checkProfiles(agent, proc, timeout), checkNoTelemetry]) + // so expect telemetry callback to time out + return Promise.all([checkProfiles(agent, proc, timeout), expectTimeout(checkTelemetry)]) }) it('records SSI telemetry on process exit', () => { @@ -469,4 +487,67 @@ describe('profiler', () => { }) } }) + + context('SSI heuristics', () => { + beforeEach(async () => { + agent = await new FakeAgent().start() + }) + + afterEach(async () => { + proc.kill() + await agent.stop() + }) + + describe('does not trigger for', () => { + it('does not trigger for a short-lived app that creates no spans', () => { + return heuristicsDoesNotTriggerFor([], false) + }) + + it('does not trigger for a short-lived app that creates a span', () => { + return heuristicsDoesNotTriggerFor(['create-span'], true) + }) + + it('does not trigger for a long-lived app that creates no spans', () => { + return heuristicsDoesNotTriggerFor(['long-lived'], false) + }) + }) + + it('triggers for long-lived span-creating app', () => { + return checkProfiles(agent, + forkSsi(['create-span', 'long-lived']), + timeout, + DEFAULT_PROFILE_TYPES, + false, + // Will receive 2 messages: first one is for the trace, second one is for the profile. We + // only need the assertions in checkProfiles to succeed for the one with the profile. + 2) + }) + }) + + function forkSsi (args) { + return fork(ssiTestFile, args, { + cwd, + env: { + DD_TRACE_AGENT_PORT: agent.port, + DD_INJECTION_ENABLED: 'profiling', + DD_PROFILING_SSI_SHORT_LIVED_THRESHOLD: '1300' + } + }) + } + + function heuristicsDoesNotTriggerFor (args, allowTraceMessage) { + proc = fork(ssiTestFile, args, { + cwd, + env: { + DD_TRACE_AGENT_PORT: agent.port, + DD_INJECTION_ENABLED: 'profiling', + DD_PROFILING_SSI_SHORT_LIVED_THRESHOLD: '1300' + } + }) + + return Promise.all([ + processExitPromise(proc, timeout, false), + expectTimeout(expectProfileMessagePromise(agent, 1500), allowTraceMessage) + ]) + } }) diff --git a/integration-tests/profiler/ssi.js b/integration-tests/profiler/ssi.js new file mode 100644 index 00000000000..de407d17e83 --- /dev/null +++ b/integration-tests/profiler/ssi.js @@ -0,0 +1,21 @@ +'use strict' + +const DDTrace = require('dd-trace') + +const tracer = DDTrace.init() + +async function run () { + const tasks = [] + if (process.argv.includes('create-span')) { + tasks.push(tracer.trace('woo', _ => { + return new Promise(setImmediate) + })) + } + if (process.argv.includes('long-lived')) { + const shortLivedThreshold = Number(process.env.DD_PROFILING_SSI_SHORT_LIVED_THRESHOLD) + tasks.push(new Promise(resolve => setTimeout(resolve, shortLivedThreshold + 200))) + } + await Promise.all(tasks) +} + +tracer.profilerStarted().then(run) diff --git a/packages/dd-trace/src/config.js b/packages/dd-trace/src/config.js index d76902f5ace..402f5275aba 100644 --- a/packages/dd-trace/src/config.js +++ b/packages/dd-trace/src/config.js @@ -490,6 +490,7 @@ class Config { this._setValue(defaults, 'profiling.sourceMap', true) this._setValue(defaults, 'profiling.ssi', false) this._setValue(defaults, 'profiling.heuristicsEnabled', false) + this._setValue(defaults, 'profiling.shortLivedThreshold', undefined) this._setValue(defaults, 'protocolVersion', '0.4') this._setValue(defaults, 'queryStringObfuscation', qsRegex) this._setValue(defaults, 'remoteConfig.enabled', true) @@ -560,6 +561,7 @@ class Config { DD_PROFILING_ENABLED, DD_PROFILING_EXPORTERS, DD_PROFILING_SOURCE_MAP, + DD_PROFILING_SSI_SHORT_LIVED_THRESHOLD, DD_REMOTE_CONFIGURATION_ENABLED, DD_REMOTE_CONFIG_POLL_INTERVAL_SECONDS, DD_RUNTIME_METRICS_ENABLED, @@ -670,6 +672,10 @@ class Config { if (DD_INJECTION_ENABLED.split(',').includes('profiling')) { this._setBoolean(env, 'profiling.heuristicsEnabled', true) } + if (DD_PROFILING_SSI_SHORT_LIVED_THRESHOLD) { + // This is only used in testing to not have to wait 30s + this._setValue(env, 'profiling.shortLivedThreshold', Number(DD_PROFILING_SSI_SHORT_LIVED_THRESHOLD)) + } } this._setString(env, 'protocolVersion', DD_TRACE_AGENT_PROTOCOL_VERSION)