From c0cf2d080eee82df8b4c0c9a17f10f062f8bdd3a Mon Sep 17 00:00:00 2001 From: s1gr1d <32902192+s1gr1d@users.noreply.github.com> Date: Fri, 9 Oct 2026 10:52:11 +0200 Subject: [PATCH 1/2] fix(profiling-node): Stop the trace lifecycle profiler when spans are unsampled --- packages/profiling-node/src/integration.ts | 62 ++++++- .../profiling-node/test/integration.test.ts | 173 ++++++++++++++++++ 2 files changed, 225 insertions(+), 10 deletions(-) diff --git a/packages/profiling-node/src/integration.ts b/packages/profiling-node/src/integration.ts index a158019ee036..7f3888413f4d 100644 --- a/packages/profiling-node/src/integration.ts +++ b/packages/profiling-node/src/integration.ts @@ -1,6 +1,15 @@ /* eslint-disable max-lines */ import type { Event, IntegrationFn, ProfileChunk, ProfilingIntegration } from '@sentry/core'; -import { consoleSandbox, debug, defineIntegration, getCurrentScope, getGlobalScope, uuid4 } from '@sentry/core'; +import { + consoleSandbox, + debug, + defineIntegration, + getCurrentScope, + getGlobalScope, + getRootSpan, + spanIsSampled, + uuid4, +} from '@sentry/core'; import type { NodeClient } from '@sentry/node'; import { CpuProfilerBindings, ProfileFormat } from '@sentry/node-cpu-profiler'; import { isMainThread } from 'worker_threads'; @@ -24,6 +33,7 @@ class ContinuousProfiler { private _profilerId: string | undefined; private _client: NodeClient | undefined = undefined; private _chunkData: ChunkData | undefined = undefined; + private _pendingChunkRestart: NodeJS.Immediate | undefined = undefined; private _profileLifecycle: 'manual' | 'trace' | undefined = undefined; private _sampled: boolean | undefined = undefined; private _sessionSamplingRate: number | undefined = undefined; @@ -125,7 +135,7 @@ class ContinuousProfiler { return; } - if (!this._chunkData) { + if (!this._chunkData && !this._pendingChunkRestart) { DEBUG_BUILD && debug.log('[Profiling] No profile session running, no-op.'); return; } @@ -151,19 +161,30 @@ class ContinuousProfiler { return; } - let activeSpanCounter = 0; - this._client.on('spanStart', _span => { - if (activeSpanCounter === 0) { + // Unsampled child spans emit `spanStart` but never `spanEnd`, so only sampled spans are tracked. + const activeSpanIds = new Set(); + this._client.on('spanStart', span => { + if (!spanIsSampled(span)) { + if (DEBUG_BUILD && span === getRootSpan(span)) { + debug.log('[Profiling] Not profiling trace because its root span was not sampled.'); + } + return; + } + if (activeSpanIds.size === 0) { this._startChunkProfiling(); } - activeSpanCounter++; + activeSpanIds.add(span.spanContext().spanId); }); - this._client.on('spanEnd', _span => { - if (activeSpanCounter === 1) { + this._client.on('spanEnd', span => { + const spanId = span.spanContext().spanId; + if (!activeSpanIds.has(spanId)) { + return; + } + activeSpanIds.delete(spanId); + if (activeSpanIds.size === 0) { this._stopChunkProfiling(); } - activeSpanCounter--; }); } @@ -194,6 +215,10 @@ class ContinuousProfiler { * Stops profiling of the current chunks and flushes the profile to Sentry */ private _stopChunkProfiling(): void { + // The chunk timer stops the current chunk before it schedules the next one, so a stop that lands + // in between must also cancel that restart, or profiling continues with nothing left to profile. + this._cancelPendingChunkRestart(); + if (!this._chunkData) { DEBUG_BUILD && debug.log('[Profiling] No chunk data found, no-op.'); return; @@ -305,13 +330,30 @@ class ContinuousProfiler { DEBUG_BUILD && debug.log(`[Profiling] Stopping profiling chunk: ${chunk.id}`); this._stopChunkProfiling(); DEBUG_BUILD && debug.log('[Profiling] Starting new profiling chunk.'); - setImmediate(this._restartChunkProfiling.bind(this)); + this._pendingChunkRestart = setImmediate(() => { + this._pendingChunkRestart = undefined; + this._restartChunkProfiling(); + }); }, CHUNK_INTERVAL_MS); // Unref timeout so it doesn't keep the process alive. chunk.timer.unref(); } + /** + * Cancels the next chunk if the chunk timer scheduled one that has not started yet. + */ + private _cancelPendingChunkRestart(): void { + if (!this._pendingChunkRestart) { + return; + } + + clearImmediate(this._pendingChunkRestart); + this._pendingChunkRestart = undefined; + DEBUG_BUILD && + debug.log('[Profiling] Profiling stopped before the next chunk started, cancelled the scheduled chunk.'); + } + /** * Attaches profiling information to spans that were started * during a profiling session. diff --git a/packages/profiling-node/test/integration.test.ts b/packages/profiling-node/test/integration.test.ts index b7c24525419d..9380eca90b32 100644 --- a/packages/profiling-node/test/integration.test.ts +++ b/packages/profiling-node/test/integration.test.ts @@ -1,4 +1,5 @@ import type { Transport } from '@sentry/core'; +import { debug } from '@sentry/core'; import * as Sentry from '@sentry/node'; import type { NodeClientOptions } from '@sentry/node/build/types/types'; import { CpuProfilerBindings } from '@sentry/node-cpu-profiler'; @@ -54,6 +55,21 @@ describe('ProfilingIntegration', () => { expect(stopProfilingSpy).toHaveBeenCalled(); }); + it('logs a no-op when stopping without a running profile session', () => { + const [client] = makeSpanProfilingClient({ + profileLifecycle: 'manual', + profileSessionSampleRate: 1, + }); + Sentry.setCurrentClient(client); + client.init(); + + const debugLogSpy = vi.spyOn(debug, 'log'); + + Sentry.profiler.stopProfiler(); + + expect(debugLogSpy).toHaveBeenCalledWith('[Profiling] No profile session running, no-op.'); + }); + it('calling start and stop while profile session is running does nothing', () => { const [client] = makeSpanProfilingClient({ profileLifecycle: 'manual', @@ -305,6 +321,90 @@ describe('ProfilingIntegration', () => { expect(stopProfilingSpy).toHaveBeenCalled(); }); + it('logs when it skips a trace because the root span is not sampled', () => { + const [client] = makeSpanProfilingClient({ + profileLifecycle: 'trace', + profileSessionSampleRate: 1, + tracesSampleRate: 0, + }); + + Sentry.setCurrentClient(client); + client.init(); + + const debugLogSpy = vi.spyOn(debug, 'log'); + + Sentry.startInactiveSpan({ name: 'GET /users/:id' }); + + expect(debugLogSpy).toHaveBeenCalledWith( + '[Profiling] Not profiling trace because its root span was not sampled.', + ); + }); + + it('does not log skipped unsampled child spans', () => { + const [client] = makeSpanProfilingClient({ + profileLifecycle: 'trace', + profileSessionSampleRate: 1, + tracesSampleRate: 0, + }); + + Sentry.setCurrentClient(client); + client.init(); + + const rootSpan = Sentry.startInactiveSpan({ name: 'GET /users/:id' }); + const debugLogSpy = vi.spyOn(debug, 'log'); + + Sentry.startInactiveSpan({ name: 'SELECT * FROM users', parentSpan: rootSpan }); + + expect(debugLogSpy).not.toHaveBeenCalledWith( + '[Profiling] Not profiling trace because its root span was not sampled.', + ); + }); + + it('does not start the profiler for unsampled spans', () => { + const [client] = makeSpanProfilingClient({ + profileLifecycle: 'trace', + profileSessionSampleRate: 1, + tracesSampleRate: 0, + }); + + Sentry.setCurrentClient(client); + client.init(); + + const startProfilingSpy = vi.spyOn(CpuProfilerBindings, 'startProfiling'); + + Sentry.startSpan({ name: 'root' }, () => { + Sentry.startSpan({ name: 'child' }, () => {}); + }); + + expect(startProfilingSpy).not.toHaveBeenCalled(); + }); + + it('stops the profiler after the last sampled span ends, ignoring unsampled spans', () => { + const [client] = makeSpanProfilingClient({ + profileLifecycle: 'trace', + profileSessionSampleRate: 1, + tracesSampler: ({ name }) => (name === 'sampled' ? 1 : 0), + }); + + Sentry.setCurrentClient(client); + client.init(); + + const startProfilingSpy = vi.spyOn(CpuProfilerBindings, 'startProfiling'); + const stopProfilingSpy = vi.spyOn(CpuProfilerBindings, 'stopProfiling'); + + Sentry.startSpan({ name: 'unsampled' }, () => { + Sentry.startSpan({ name: 'unsampled-child' }, () => {}); + }); + + Sentry.startSpan({ name: 'sampled' }, () => { + Sentry.startSpan({ name: 'sampled-child' }, () => {}); + expect(startProfilingSpy).toHaveBeenCalledTimes(1); + expect(stopProfilingSpy).not.toHaveBeenCalled(); + }); + + expect(stopProfilingSpy).toHaveBeenCalledTimes(1); + }); + describe('envelope', () => { beforeEach(() => { vi.useRealTimers(); @@ -345,6 +445,79 @@ describe('ProfilingIntegration', () => { }); }); }); + + describe('chunk restart', () => { + const lifecycles = [ + { + profileLifecycle: 'manual', + startProfiling: () => { + Sentry.profiler.startProfiler(); + return () => Sentry.profiler.stopProfiler(); + }, + }, + { + profileLifecycle: 'trace', + startProfiling: () => { + const span = Sentry.startInactiveSpan({ name: 'GET /users/:id' }); + return () => span.end(); + }, + }, + ] as const; + + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it.each(lifecycles)( + 'does not start a new chunk when $profileLifecycle profiling stops before the scheduled restart', + ({ profileLifecycle, startProfiling }) => { + const [client] = makeSpanProfilingClient({ profileLifecycle, profileSessionSampleRate: 1 }); + Sentry.setCurrentClient(client); + client.init(); + + const startProfilingSpy = vi.spyOn(CpuProfilerBindings, 'startProfiling'); + const stopProfilingSpy = vi.spyOn(CpuProfilerBindings, 'stopProfiling'); + const debugLogSpy = vi.spyOn(debug, 'log'); + const stopProfiling = startProfiling(); + vi.advanceTimersToNextTimer(); + expect(stopProfilingSpy).toHaveBeenCalledTimes(1); + + stopProfiling(); + vi.runOnlyPendingTimers(); + + expect(startProfilingSpy).toHaveBeenCalledTimes(1); + expect(debugLogSpy).toHaveBeenCalledWith( + '[Profiling] Profiling stopped before the next chunk started, cancelled the scheduled chunk.', + ); + }, + ); + + it.each(lifecycles)( + 'does not report a cancelled chunk when $profileLifecycle profiling stops after the restart', + ({ profileLifecycle, startProfiling }) => { + const [client] = makeSpanProfilingClient({ profileLifecycle, profileSessionSampleRate: 1 }); + Sentry.setCurrentClient(client); + client.init(); + + const startProfilingSpy = vi.spyOn(CpuProfilerBindings, 'startProfiling'); + const debugLogSpy = vi.spyOn(debug, 'log'); + const stopProfiling = startProfiling(); + vi.advanceTimersToNextTimer(); + vi.runOnlyPendingTimers(); + expect(startProfilingSpy).toHaveBeenCalledTimes(2); + + stopProfiling(); + + expect(debugLogSpy).not.toHaveBeenCalledWith( + '[Profiling] Profiling stopped before the next chunk started, cancelled the scheduled chunk.', + ); + }, + ); + }); }); describe('NODE_VERSION', () => { From 90458067cb494a1aa3538b0c4625b550ebd016cd Mon Sep 17 00:00:00 2001 From: s1gr1d <32902192+s1gr1d@users.noreply.github.com> Date: Fri, 9 Oct 2026 11:13:15 +0200 Subject: [PATCH 2/2] fix(profiling-node): Do not start an extra chunk between two chunks A startProfiler() call after the chunk timer stopped a chunk, but before the scheduled next chunk started, began a new chunk. The scheduled restart then stopped it almost at once and sent a very short chunk. Start and stop now share one check that treats this gap as a running session. Also move the comment that explains the deferred restart to the setImmediate call. --- packages/profiling-node/src/integration.ts | 18 ++++++++++++------ .../profiling-node/test/integration.test.ts | 17 +++++++++++++++++ 2 files changed, 29 insertions(+), 6 deletions(-) diff --git a/packages/profiling-node/src/integration.ts b/packages/profiling-node/src/integration.ts index 7f3888413f4d..0832bd379c11 100644 --- a/packages/profiling-node/src/integration.ts +++ b/packages/profiling-node/src/integration.ts @@ -105,7 +105,7 @@ class ContinuousProfiler { } private _startProfiler(): void { - if (this._chunkData !== undefined) { + if (this._isSessionRunning()) { DEBUG_BUILD && debug.log('[Profiling] Profile session already running, no-op.'); return; } @@ -135,7 +135,7 @@ class ContinuousProfiler { return; } - if (!this._chunkData && !this._pendingChunkRestart) { + if (!this._isSessionRunning()) { DEBUG_BUILD && debug.log('[Profiling] No profile session running, no-op.'); return; } @@ -282,10 +282,6 @@ class ContinuousProfiler { } this._flush(chunk); - // Depending on the profile and stack sizes, stopping the profile and converting - // the format may negatively impact the performance of the application. To avoid - // blocking for too long, enqueue the next chunk start inside the next macrotask. - // clear current chunk this._resetChunkData(); } @@ -330,6 +326,9 @@ class ContinuousProfiler { DEBUG_BUILD && debug.log(`[Profiling] Stopping profiling chunk: ${chunk.id}`); this._stopChunkProfiling(); DEBUG_BUILD && debug.log('[Profiling] Starting new profiling chunk.'); + // Depending on the profile and stack sizes, stopping the profile and converting + // the format may negatively impact the performance of the application. To avoid + // blocking for too long, enqueue the next chunk start inside the next macrotask. this._pendingChunkRestart = setImmediate(() => { this._pendingChunkRestart = undefined; this._restartChunkProfiling(); @@ -340,6 +339,13 @@ class ContinuousProfiler { chunk.timer.unref(); } + /** + * A session is also running in the gap after the chunk timer stopped one chunk and before the next one starts. + */ + private _isSessionRunning(): boolean { + return this._chunkData !== undefined || this._pendingChunkRestart !== undefined; + } + /** * Cancels the next chunk if the chunk timer scheduled one that has not started yet. */ diff --git a/packages/profiling-node/test/integration.test.ts b/packages/profiling-node/test/integration.test.ts index 9380eca90b32..cff99664dc78 100644 --- a/packages/profiling-node/test/integration.test.ts +++ b/packages/profiling-node/test/integration.test.ts @@ -496,6 +496,23 @@ describe('ProfilingIntegration', () => { }, ); + it('does not start a second chunk when manual profiling starts between two chunks', () => { + const [client] = makeSpanProfilingClient({ profileLifecycle: 'manual', profileSessionSampleRate: 1 }); + Sentry.setCurrentClient(client); + client.init(); + + const startProfilingSpy = vi.spyOn(CpuProfilerBindings, 'startProfiling'); + const stopProfilingSpy = vi.spyOn(CpuProfilerBindings, 'stopProfiling'); + Sentry.profiler.startProfiler(); + vi.advanceTimersToNextTimer(); + + Sentry.profiler.startProfiler(); + vi.runOnlyPendingTimers(); + + expect(startProfilingSpy).toHaveBeenCalledTimes(2); + expect(stopProfilingSpy).toHaveBeenCalledTimes(1); + }); + it.each(lifecycles)( 'does not report a cancelled chunk when $profileLifecycle profiling stops after the restart', ({ profileLifecycle, startProfiling }) => {