From c86bd1441236224690c4b9e63ecb802c37f711ad Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Thu, 30 May 2024 14:32:58 +0200 Subject: [PATCH] PROF-9791: Use heuristics to start the profiler when requested through SSI (#4322) --- integration-tests/profiler/profiler.spec.js | 127 ++++++++++++++---- integration-tests/profiler/ssi.js | 24 ++++ packages/dd-trace/src/config.js | 17 ++- packages/dd-trace/src/profiler.js | 3 +- packages/dd-trace/src/profiling/config.js | 1 + packages/dd-trace/src/profiling/profiler.js | 2 +- .../{ssi-telemetry.js => ssi-heuristics.js} | 100 +++++++++----- .../profiling/ssi-telemetry-mock-profiler.js | 13 +- packages/dd-trace/src/proxy.js | 44 +++--- packages/dd-trace/test/config.spec.js | 9 +- ...lemetry.spec.js => ssi-heuristics.spec.js} | 89 +++++++----- 11 files changed, 308 insertions(+), 121 deletions(-) create mode 100644 integration-tests/profiler/ssi.js rename packages/dd-trace/src/profiling/{ssi-telemetry.js => ssi-heuristics.js} (60%) rename packages/dd-trace/test/profiling/{ssi-telemetry.spec.js => ssi-heuristics.spec.js} (65%) diff --git a/integration-tests/profiler/profiler.spec.js b/integration-tests/profiler/profiler.spec.js index 05488a3a482..de9ab5626ef 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('a short-lived app that creates no spans', () => { + return heuristicsDoesNotTriggerFor([], false) + }) + + it('a short-lived app that creates a span', () => { + return heuristicsDoesNotTriggerFor(['create-span'], true) + }) + + it('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: 'profiler', + DD_INTERNAL_PROFILING_LONG_LIVED_THRESHOLD: '1300' + } + }) + } + + function heuristicsDoesNotTriggerFor (args, allowTraceMessage) { + proc = fork(ssiTestFile, args, { + cwd, + env: { + DD_TRACE_AGENT_PORT: agent.port, + DD_INJECTION_ENABLED: 'profiler', + DD_INTERNAL_PROFILING_LONG_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..b184d64762b --- /dev/null +++ b/integration-tests/profiler/ssi.js @@ -0,0 +1,24 @@ +'use strict' + +const DDTrace = require('dd-trace') + +const tracer = DDTrace.init() + +async function run () { + const tasks = [] + // If launched with 'create-span', the app will create a span. + if (process.argv.includes('create-span')) { + tasks.push(tracer.trace('woo', _ => { + return new Promise(setImmediate) + })) + } + // If launched with 'long-lived', the app will remain alive long enough to + // be considered long-lived by profiler activation heuristics. + if (process.argv.includes('long-lived')) { + const longLivedThreshold = Number(process.env.DD_INTERNAL_PROFILING_LONG_LIVED_THRESHOLD) + tasks.push(new Promise(resolve => setTimeout(resolve, longLivedThreshold + 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 ecc4c8b0355..4df252aa10b 100644 --- a/packages/dd-trace/src/config.js +++ b/packages/dd-trace/src/config.js @@ -485,9 +485,12 @@ class Config { this._setValue(defaults, 'peerServiceMapping', {}) this._setValue(defaults, 'plugins', true) this._setValue(defaults, 'port', '8126') - this._setValue(defaults, 'profiling.enabled', false) + this._setValue(defaults, 'profiling.enabled', undefined) this._setValue(defaults, 'profiling.exporters', 'agent') this._setValue(defaults, 'profiling.sourceMap', true) + this._setValue(defaults, 'profiling.ssi', false) + this._setValue(defaults, 'profiling.heuristicsEnabled', false) + this._setValue(defaults, 'profiling.longLivedThreshold', undefined) this._setValue(defaults, 'protocolVersion', '0.4') this._setValue(defaults, 'queryStringObfuscation', qsRegex) this._setValue(defaults, 'remoteConfig.enabled', true) @@ -558,6 +561,7 @@ class Config { DD_PROFILING_ENABLED, DD_PROFILING_EXPORTERS, DD_PROFILING_SOURCE_MAP, + DD_INTERNAL_PROFILING_LONG_LIVED_THRESHOLD, DD_REMOTE_CONFIGURATION_ENABLED, DD_REMOTE_CONFIG_POLL_INTERVAL_SECONDS, DD_RUNTIME_METRICS_ENABLED, @@ -663,6 +667,17 @@ class Config { this._setBoolean(env, 'profiling.enabled', coalesce(DD_EXPERIMENTAL_PROFILING_ENABLED, DD_PROFILING_ENABLED)) this._setString(env, 'profiling.exporters', DD_PROFILING_EXPORTERS) this._setBoolean(env, 'profiling.sourceMap', DD_PROFILING_SOURCE_MAP && !isFalse(DD_PROFILING_SOURCE_MAP)) + if (DD_INJECTION_ENABLED) { + this._setBoolean(env, 'profiling.ssi', true) + if (DD_INJECTION_ENABLED.split(',').includes('profiler')) { + this._setBoolean(env, 'profiling.heuristicsEnabled', true) + } + if (DD_INTERNAL_PROFILING_LONG_LIVED_THRESHOLD) { + // This is only used in testing to not have to wait 30s + this._setValue(env, 'profiling.longLivedThreshold', Number(DD_INTERNAL_PROFILING_LONG_LIVED_THRESHOLD)) + } + } + this._setString(env, 'protocolVersion', DD_TRACE_AGENT_PROTOCOL_VERSION) this._setString(env, 'queryStringObfuscation', DD_TRACE_OBFUSCATION_QUERY_STRING_REGEXP) this._setBoolean(env, 'remoteConfig.enabled', coalesce( diff --git a/packages/dd-trace/src/profiler.js b/packages/dd-trace/src/profiler.js index 349f0438d7c..ce08a3d0f6f 100644 --- a/packages/dd-trace/src/profiler.js +++ b/packages/dd-trace/src/profiler.js @@ -9,7 +9,7 @@ process.once('beforeExit', () => { profiler.stop() }) module.exports = { start: config => { const { service, version, env, url, hostname, port, tags, repositoryUrl, commitSHA } = config - const { enabled, sourceMap, exporters } = config.profiling + const { enabled, sourceMap, exporters, heuristicsEnabled } = config.profiling const logger = { debug: (message) => log.debug(message), info: (message) => log.info(message), @@ -19,6 +19,7 @@ module.exports = { return profiler.start({ enabled, + heuristicsEnabled, service, version, env, diff --git a/packages/dd-trace/src/profiling/config.js b/packages/dd-trace/src/profiling/config.js index 615a728c968..18b85f7c447 100644 --- a/packages/dd-trace/src/profiling/config.js +++ b/packages/dd-trace/src/profiling/config.js @@ -65,6 +65,7 @@ class Config { DD_PROFILING_PPROF_PREFIX, '') this.enabled = enabled + this.heuristicsEnabled = options.heuristicsEnabled this.service = service this.env = env this.host = host diff --git a/packages/dd-trace/src/profiling/profiler.js b/packages/dd-trace/src/profiling/profiler.js index 2c0ebcd5584..17422c5f993 100644 --- a/packages/dd-trace/src/profiling/profiler.js +++ b/packages/dd-trace/src/profiling/profiler.js @@ -55,7 +55,7 @@ class Profiler extends EventEmitter { if (this._enabled) return true const config = this._config = new Config(options) - if (!config.enabled) return false + if (!config.enabled && !config.heuristicsEnabled) return false this._logger = config.logger this._enabled = true diff --git a/packages/dd-trace/src/profiling/ssi-telemetry.js b/packages/dd-trace/src/profiling/ssi-heuristics.js similarity index 60% rename from packages/dd-trace/src/profiling/ssi-telemetry.js rename to packages/dd-trace/src/profiling/ssi-heuristics.js index a67cba4793a..f4e10ea4628 100644 --- a/packages/dd-trace/src/profiling/ssi-telemetry.js +++ b/packages/dd-trace/src/profiling/ssi-heuristics.js @@ -2,28 +2,25 @@ const telemetryMetrics = require('../telemetry/metrics') const profilersNamespace = telemetryMetrics.manager.namespace('profilers') -const performance = require('perf_hooks').performance const dc = require('dc-polyfill') -const { isTrue, isFalse } = require('../util') -// If the process lived for less than 30 seconds, it's considered short-lived -const DEFAULT_SHORT_LIVED_THRESHOLD = 30000 +// If the process lives for at least 30 seconds, it's considered long-lived +const DEFAULT_LONG_LIVED_THRESHOLD = 30000 const EnablementChoice = { MANUALLY_ENABLED: Symbol('SSITelemetry.EnablementChoice.MANUALLY_ENABLED'), SSI_ENABLED: Symbol('SSITelemetry.EnablementChoice.SSI_ENABLED'), SSI_NOT_ENABLED: Symbol('SSITelemetry.EnablementChoice.SSI_NOT_ENABLED'), - DISABLED: Symbol('SSITelemetry.EnablementChoice.MANUALLY_DISABLED') + DISABLED: Symbol('SSITelemetry.EnablementChoice.DISABLED') } Object.freeze(EnablementChoice) -function getEnablementChoiceFromEnv () { - const { DD_PROFILING_ENABLED, DD_INJECTION_ENABLED } = process.env - if (DD_INJECTION_ENABLED === undefined || isFalse(DD_PROFILING_ENABLED)) { +function getEnablementChoiceFromConfig (config) { + if (config.ssi === false || config.enabled === false) { return EnablementChoice.DISABLED - } else if (DD_INJECTION_ENABLED.split(',').includes('profiling')) { + } else if (config.heuristicsEnabled === true) { return EnablementChoice.SSI_ENABLED - } else if (isTrue(DD_PROFILING_ENABLED)) { + } else if (config.enabled === true) { return EnablementChoice.MANUALLY_ENABLED } else { return EnablementChoice.SSI_NOT_ENABLED @@ -38,39 +35,38 @@ function enablementChoiceToTagValue (enablementChoice) { return 'ssi_enabled' case EnablementChoice.SSI_NOT_ENABLED: return 'not_enabled' - case EnablementChoice.MANUALLY_DISABLED: + case EnablementChoice.DISABLED: // Can't emit this one as a tag throw new Error('Invalid enablement choice') } } /** - * This class emits telemetry metrics about the profiler behavior under SSI. It will only emit metrics - * when the application closes, and will emit the following metrics: + * This class embodies the SSI profiler-triggering heuristics and also emits telemetry metrics about + * the profiler behavior under SSI. It emits the following metrics: * - `number_of_profiles`: The number of profiles that were submitted - * - `number_of_runtime_id`: The number of runtime IDs in the app (always 1 for Node.js) - * It will also add tags describing the state of heuristics triggers, the enablement choice, and whether - * actual profiles were sent (as opposed to mock profiles). There is a mock profiler that is activated - * when the profiler is not enabled, and it will emit mock profile submission events at the same cadence - * the profiler would, providing insight into how many profiles would've been emitted if SSI enabled - * profiling. Note that telemetry is per tracer instance, and each worker thread will have its own instance. + * - `number_of_runtime_id`: The number of runtime IDs in the app (always 1 for Node.js, emitted + * once when the tags won't change for the remaineder of of the app's lifetime.) + * It will also add tags describing the state of heuristics triggers, the enablement choice, and + * whether actual profiles were sent (as opposed to mock profiles). There is a mock profiler that is + * activated when the profiler is not enabled, and it will emit mock profile submission events at + * the same cadence the profiler would, providing insight into how many profiles would've been + * emitted if SSI enabled profiling. Note that heuristics (and thus telemetry) is per tracer + * instance, and each worker thread will have its own instance. */ -class SSITelemetry { - constructor ({ - enablementChoice = getEnablementChoiceFromEnv(), - shortLivedThreshold = DEFAULT_SHORT_LIVED_THRESHOLD - } = {}) { - if (!Object.values(EnablementChoice).includes(enablementChoice)) { - throw new Error('Invalid enablement choice') - } - if (typeof shortLivedThreshold !== 'number' || shortLivedThreshold <= 0) { - throw new Error('Short-lived threshold must be a positive number') +class SSIHeuristics { + constructor (config) { + this.enablementChoice = getEnablementChoiceFromConfig(config) + + const longLivedThreshold = config.longLivedThreshold || DEFAULT_LONG_LIVED_THRESHOLD + if (typeof longLivedThreshold !== 'number' || longLivedThreshold <= 0) { + throw new Error('Long-lived threshold must be a positive number') } - this.enablementChoice = enablementChoice - this.shortLivedThreshold = shortLivedThreshold + this.longLivedThreshold = longLivedThreshold this.hasSentProfiles = false this.noSpan = true + this.shortLived = true } enabled () { @@ -83,7 +79,10 @@ class SSITelemetry { // reference point, but the tracer initialization point is more relevant, as we couldn't be // collecting profiles earlier anyway. The difference is not particularly significant if the // tracer is initialized early in the process lifetime. - this.startTime = performance.now() + setTimeout(() => { + this.shortLived = false + this._maybeTriggered() + }, this.longLivedThreshold).unref() this._onSpanCreated = this._onSpanCreated.bind(this) this._onProfileSubmitted = this._onProfileSubmitted.bind(this) @@ -97,8 +96,31 @@ class SSITelemetry { } } + onTriggered (callback) { + switch (typeof callback) { + case 'undefined': + case 'function': + this.triggeredCallback = callback + process.nextTick(() => { + this._maybeTriggered() + }) + break + default: + throw new TypeError('callback must be a function or undefined') + } + } + + _maybeTriggered () { + if (!this.shortLived && !this.noSpan) { + if (typeof this.triggeredCallback === 'function') { + this.triggeredCallback.call(null) + } + } + } + _onSpanCreated () { this.noSpan = false + this._maybeTriggered() dc.unsubscribe('dd-trace:span:start', this._onSpanCreated) } @@ -121,7 +143,7 @@ class SSITelemetry { if (this.noSpan) { decision.push('no_span') } - if (performance.now() - this.startTime < this.shortLivedThreshold) { + if (this.shortLived) { decision.push('short_lived') } if (decision.length === 0) { @@ -138,8 +160,14 @@ class SSITelemetry { this._profileCount = profilersNamespace.count('ssi_heuristic.number_of_profiles', tags) this._runtimeIdCount = profilersNamespace.count('ssi_heuristic.number_of_runtime_id', tags) - if (!this._emittedRuntimeId && decision[0] === 'triggered') { - // Tags won't change anymore, so we can emit the runtime ID metric now + if ( + !this._emittedRuntimeId && + decision[0] === 'triggered' && + // When enablement choice is SSI_ENABLED, hasSentProfiles can transition from false to true when the + // profiler gets started and the first profile is submitted, so we have to wait for it. + (this.enablementChoice !== EnablementChoice.SSI_ENABLED || this.hasSentProfiles) + ) { + // Tags won't change anymore, so we can emit the runtime ID metric now. this._emittedRuntimeId = true this._runtimeIdCount.inc() } @@ -164,4 +192,4 @@ class SSITelemetry { } } -module.exports = { SSITelemetry, EnablementChoice } +module.exports = { SSIHeuristics, EnablementChoice } diff --git a/packages/dd-trace/src/profiling/ssi-telemetry-mock-profiler.js b/packages/dd-trace/src/profiling/ssi-telemetry-mock-profiler.js index 2a164e0851c..564046e383b 100644 --- a/packages/dd-trace/src/profiling/ssi-telemetry-mock-profiler.js +++ b/packages/dd-trace/src/profiling/ssi-telemetry-mock-profiler.js @@ -12,16 +12,11 @@ module.exports = { // Copied from packages/dd-trace/src/profiler.js const flushInterval = coalesce(config.interval, Number(DD_PROFILING_UPLOAD_PERIOD) * 1000, 65 * 1000) - function scheduleProfileSubmit () { - timerId = setTimeout(emitProfileSubmit, flushInterval) - } - - function emitProfileSubmit () { + timerId = setTimeout(() => { profileSubmittedChannel.publish() - scheduleProfileSubmit() - } - - scheduleProfileSubmit() + timerId.refresh() + }, flushInterval) + timerId.unref() }, stop: () => { diff --git a/packages/dd-trace/src/proxy.js b/packages/dd-trace/src/proxy.js index 7d47b059142..9480100e5b9 100644 --- a/packages/dd-trace/src/proxy.js +++ b/packages/dd-trace/src/proxy.js @@ -13,7 +13,7 @@ const AppsecSdk = require('./appsec/sdk') const dogstatsd = require('./dogstatsd') const NoopDogStatsDClient = require('./noop/dogstatsd') const spanleak = require('./spanleak') -const { SSITelemetry } = require('./profiling/ssi-telemetry') +const { SSIHeuristics } = require('./profiling/ssi-heuristics') const telemetryLog = require('dc-polyfill').channel('datadog:telemetry:log') class LazyModule { @@ -96,23 +96,21 @@ class Tracer extends NoopProxy { require('./serverless').maybeStartServerlessMiniAgent(config) } - const ssiTelemetry = new SSITelemetry() - ssiTelemetry.start() + const ssiHeuristics = new SSIHeuristics(config.profiling) + ssiHeuristics.start() if (config.profiling.enabled) { - // do not stop tracer initialization if the profiler fails to be imported - try { - const profiler = require('./profiler') - this._profilerStarted = profiler.start(config) - } catch (e) { - log.error(e) - telemetryLog.publish({ - message: e.message, - level: 'ERROR', - stack_trace: e.stack + this._profilerStarted = this._startProfiler(config) + } else if (config.profiling.ssi) { + const mockProfiler = require('./profiling/ssi-telemetry-mock-profiler') + mockProfiler.start(config) + + if (config.profiling.heuristicsEnabled) { + ssiHeuristics.onTriggered(() => { + mockProfiler.stop() + this._startProfiler(config) + ssiHeuristics.onTriggered() }) } - } else if (ssiTelemetry.enabled()) { - require('./profiling/ssi-telemetry-mock-profiler').start(config) } if (!this._profilerStarted) { this._profilerStarted = Promise.resolve(false) @@ -138,6 +136,22 @@ class Tracer extends NoopProxy { return this } + _startProfiler (config) { + // do not stop tracer initialization if the profiler fails to be imported + try { + return require('./profiler').start(config) + } catch (e) { + log.error(e) + if (telemetryLog.hasSubscribers) { + telemetryLog.publish({ + message: e.message, + level: 'ERROR', + stack_trace: e.stack + }) + } + } + } + _enableOrDisableTracing (config) { if (config.tracing !== false) { if (config.appsec.enabled) { diff --git a/packages/dd-trace/test/config.spec.js b/packages/dd-trace/test/config.spec.js index 69bae6a4ec5..c44a5efc3e3 100644 --- a/packages/dd-trace/test/config.spec.js +++ b/packages/dd-trace/test/config.spec.js @@ -290,9 +290,11 @@ describe('Config', () => { { name: 'peerServiceMapping', value: {}, origin: 'default' }, { name: 'plugins', value: true, origin: 'default' }, { name: 'port', value: '8126', origin: 'default' }, - { name: 'profiling.enabled', value: false, origin: 'default' }, + { name: 'profiling.enabled', value: undefined, origin: 'default' }, { name: 'profiling.exporters', value: 'agent', origin: 'default' }, + { name: 'profiling.heuristicsEnabled', value: false, origin: 'default' }, { name: 'profiling.sourceMap', value: true, origin: 'default' }, + { name: 'profiling.ssi', value: false, origin: 'default' }, { name: 'protocolVersion', value: '0.4', origin: 'default' }, { name: 'queryStringObfuscation', @@ -434,7 +436,8 @@ describe('Config', () => { process.env.DD_IAST_TELEMETRY_VERBOSITY = 'DEBUG' process.env.DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED = 'true' process.env.DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED = 'true' - process.env.DD_EXPERIMENTAL_PROFILING_ENABLED = 'true' + process.env.DD_PROFILING_ENABLED = 'true' + process.env.DD_INJECTION_ENABLED = 'profiler' process.env.DD_API_SECURITY_ENABLED = 'true' process.env.DD_API_SECURITY_REQUEST_SAMPLE_RATE = 1 process.env.DD_INSTRUMENTATION_INSTALL_ID = '68e75c48-57ca-4a12-adfc-575c4b05fcbe' @@ -562,6 +565,8 @@ describe('Config', () => { { name: 'peerServiceMapping', value: { c: 'cc', d: 'dd' }, origin: 'env_var' }, { name: 'port', value: '6218', origin: 'env_var' }, { name: 'profiling.enabled', value: true, origin: 'env_var' }, + { name: 'profiling.heuristicsEnabled', value: true, origin: 'env_var' }, + { name: 'profiling.ssi', value: true, origin: 'env_var' }, { name: 'protocolVersion', value: '0.5', origin: 'env_var' }, { name: 'queryStringObfuscation', value: '.*', origin: 'env_var' }, { name: 'remoteConfig.enabled', value: false, origin: 'env_var' }, diff --git a/packages/dd-trace/test/profiling/ssi-telemetry.spec.js b/packages/dd-trace/test/profiling/ssi-heuristics.spec.js similarity index 65% rename from packages/dd-trace/test/profiling/ssi-telemetry.spec.js rename to packages/dd-trace/test/profiling/ssi-heuristics.spec.js index 5e8d7df9d62..be46d3714f5 100644 --- a/packages/dd-trace/test/profiling/ssi-telemetry.spec.js +++ b/packages/dd-trace/test/profiling/ssi-heuristics.spec.js @@ -9,30 +9,31 @@ const telemetryManagerNamespace = sinon.stub() telemetryManagerNamespace.returns() const dc = require('dc-polyfill') +const Config = require('../../src/config') -describe('SSI Telemetry', () => { +describe('SSI Heuristics', () => { it('should be disabled without SSI even if the profiler is manually enabled', () => { delete process.env.DD_INJECTION_ENABLED process.env.DD_PROFILING_ENABLED = 'true' - testDisabledTelemetry() + testDisabledHeuristics() }) it('should be disabled when SSI is present but the profiler is manually disabled', () => { process.env.DD_INJECTION_ENABLED = 'tracing' process.env.DD_PROFILING_ENABLED = 'false' - testDisabledTelemetry() + testDisabledHeuristics() }) it('should be enabled when SSI is present', () => { process.env.DD_INJECTION_ENABLED = 'tracing' delete process.env.DD_PROFILING_ENABLED - testEnabledTelemetry('not_enabled') + return testEnabledHeuristics('not_enabled') }) it('should be enabled when SSI is present and profiling is manually enabled', () => { process.env.DD_INJECTION_ENABLED = 'tracing' process.env.DD_PROFILING_ENABLED = 'true' - testEnabledTelemetry('manually_enabled') + return testEnabledHeuristics('manually_enabled') }) }) @@ -54,7 +55,7 @@ function setupHarness () { } const namespaceFn = sinon.stub().returns(ssiMetricsNamespace) - const { SSITelemetry, EnablementChoice } = proxyquire('../src/profiling/ssi-telemetry', { + const { SSIHeuristics, EnablementChoice } = proxyquire('../src/profiling/ssi-heuristics', { '../telemetry/metrics': { manager: { namespace: namespaceFn @@ -67,24 +68,24 @@ function setupHarness () { runtimeIdCountInc: runtimeIdCount.inc, count: ssiMetricsNamespace.count } - return { stubs, SSITelemetry, EnablementChoice } + return { stubs, SSIHeuristics, EnablementChoice } } -function testDisabledTelemetry () { - const { stubs, SSITelemetry, EnablementChoice } = setupHarness() - const telemetry = new SSITelemetry() - telemetry.start() +function testDisabledHeuristics () { + const { stubs, SSIHeuristics, EnablementChoice } = setupHarness() + const heuristics = new SSIHeuristics(new Config().profiling) + heuristics.start() dc.channel('dd-trace:span:start').publish() dc.channel('datadog:profiling:profile-submitted').publish() dc.channel('datadog:profiling:mock-profile-submitted').publish() dc.channel('datadog:telemetry:app-closing').publish() - expect(telemetry.enablementChoice).to.equal(EnablementChoice.DISABLED) - expect(telemetry.enabled()).to.equal(false) + expect(heuristics.enablementChoice).to.equal(EnablementChoice.DISABLED) + expect(heuristics.enabled()).to.equal(false) // When it is disabled, the telemetry should not subscribe to any channel // so the preceding publishes should not have any effect. - expect(telemetry._profileCount).to.equal(undefined) - expect(telemetry.hasSentProfiles).to.equal(false) - expect(telemetry.noSpan).to.equal(true) + expect(heuristics._profileCount).to.equal(undefined) + expect(heuristics.hasSentProfiles).to.equal(false) + expect(heuristics.noSpan).to.equal(true) expect(stubs.count.notCalled).to.equal(true) } @@ -96,16 +97,25 @@ function executeTelemetryEnabledScenario ( heuristicDecision, longLived = false ) { - const { stubs, SSITelemetry } = setupHarness() - const telemetry = longLived ? new SSITelemetry({ shortLivedThreshold: 2 }) : new SSITelemetry() - telemetry.start() - expect(telemetry.enabled()).to.equal(true) + const { stubs, SSIHeuristics } = setupHarness() + const config = new Config() if (longLived) { - for (const now = new Date().getTime(); new Date().getTime() - now < 3;); + config.profiling.longLivedThreshold = 2 } - scenario(telemetry) + const heuristics = new SSIHeuristics(config.profiling) + heuristics.start() + expect(heuristics.enabled()).to.equal(true) - createAndCheckMetrics(stubs, profileCount, sentProfiles, enablementChoice, heuristicDecision) + function runScenarioAndCheck () { + scenario(heuristics) + createAndCheckMetrics(stubs, profileCount, sentProfiles, enablementChoice, heuristicDecision) + } + + if (longLived) { + return new Promise(resolve => setTimeout(resolve, 3)).then(runScenarioAndCheck) + } else { + runScenarioAndCheck() + } } function createAndCheckMetrics (stubs, profileCount, sentProfiles, enablementChoice, heuristicDecision) { @@ -124,13 +134,12 @@ function createAndCheckMetrics (stubs, profileCount, sentProfiles, enablementCho expect(stubs.runtimeIdCountInc.args.length).to.equal(1) } -function testEnabledTelemetry (enablementChoice) { +function testEnabledHeuristics (enablementChoice) { testNoOp(enablementChoice) testProfilesSent(enablementChoice) testMockProfilesSent(enablementChoice) testSpan(enablementChoice) - testLongLived(enablementChoice) - testTriggered(enablementChoice) + return testLongLived(enablementChoice).then(() => testTriggered(enablementChoice)) } function testNoOp (enablementChoice) { @@ -152,23 +161,37 @@ function testMockProfilesSent (enablementChoice) { } function testSpan (enablementChoice) { - executeTelemetryEnabledScenario(telemetry => { + executeTelemetryEnabledScenario(heuristics => { dc.channel('dd-trace:span:start').publish() - expect(telemetry.noSpan).to.equal(false) + expect(heuristics.noSpan).to.equal(false) dc.channel('datadog:profiling:profile-submitted').publish() }, 1, true, enablementChoice, 'short_lived') } function testLongLived (enablementChoice) { - executeTelemetryEnabledScenario(_ => { + let callbackInvoked = false + return executeTelemetryEnabledScenario(heuristics => { + heuristics.onTriggered(() => { + callbackInvoked = true + heuristics.onTriggered() + }) dc.channel('datadog:profiling:profile-submitted').publish() - }, 1, true, enablementChoice, 'no_span', true) + }, 1, true, enablementChoice, 'no_span', true).then(() => { + expect(callbackInvoked).to.equal(false) + }) } function testTriggered (enablementChoice) { - executeTelemetryEnabledScenario(telemetry => { + let callbackInvoked = false + return executeTelemetryEnabledScenario(heuristics => { + heuristics.onTriggered(() => { + callbackInvoked = true + heuristics.onTriggered() + }) dc.channel('dd-trace:span:start').publish() - expect(telemetry.noSpan).to.equal(false) + expect(heuristics.noSpan).to.equal(false) dc.channel('datadog:profiling:profile-submitted').publish() - }, 1, true, enablementChoice, 'triggered', true) + }, 1, true, enablementChoice, 'triggered', true).then(() => { + expect(callbackInvoked).to.equal(true) + }) }