fix(profiling-node): Stop the trace lifecycle profiler when spans are unsampled

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;
@@ -95,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;
     }
@@ -125,7 +135,7 @@ class ContinuousProfiler {
       return;
     }
 
-    if (!this._chunkData) {
+    if (!this._isSessionRunning()) {
       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<string>();
+    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;
@@ -257,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();
   }
 
@@ -305,13 +326,40 @@ 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));
+      // 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();
+      });
     }, CHUNK_INTERVAL_MS);
 
     // Unref timeout so it doesn't keep the process alive.
     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.
+   */
+  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.

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,96 @@ 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('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 }) => {
+        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', () => {