diff --git a/packages/profiling-node/src/integration.ts b/packages/profiling-node/src/integration.ts index c1a96015f0c4..2eb0a59142ae 100644 --- a/packages/profiling-node/src/integration.ts +++ b/packages/profiling-node/src/integration.ts @@ -17,7 +17,7 @@ import { CpuProfilerBindings } from './cpu_profiler'; import { DEBUG_BUILD } from './debug-build'; import { NODE_MAJOR, NODE_VERSION } from './nodeVersion'; import { MAX_PROFILE_DURATION_MS, maybeProfileSpan, stopSpanProfile } from './spanProfileUtils'; -import type { RawChunkCpuProfile, RawThreadCpuProfile } from './types'; +import type { RawThreadCpuProfile } from './types'; import { ProfileFormat } from './types'; import { PROFILER_THREAD_NAME } from './utils'; @@ -161,7 +161,7 @@ interface ChunkData { } class ContinuousProfiler { - private _profilerId = uuid4(); + private _profilerId: string | undefined; private _client: NodeClient | undefined = undefined; private _chunkData: ChunkData | undefined = undefined; @@ -172,15 +172,48 @@ class ContinuousProfiler { */ public initialize(client: NodeClient): void { this._client = client; + + // Attaches a listener to beforeSend which will add the threadId data to the event being sent. + // This adds a constant overhead to all events being sent which could be improved to only attach + // and detach the listener during a profiler session + this._client.on('beforeSendEvent', this._onBeforeSendThreadContextAssignment.bind(this)); } /** - * Recursively schedules chunk profiling to start and stop at a set interval. - * Once the user calls stop(), the current chunk will be stopped and flushed to Sentry and no new chunks will - * will be started. To restart continuous mode after calling stop(), the user must call start() again. + * Initializes a new profilerId session and schedules chunk profiling. * @returns void */ public start(): void { + if (!this._client) { + DEBUG_BUILD && logger.log('[Profiling] Failed to start, sentry client was never attached to the profiler.'); + return; + } + + // Flush any existing chunks before starting a new one. + this._chunkStop(); + + // Restart the profiler session + this._setupSpanChunkInstrumentation(); + this._chunkStart(); + } + + /** + * Stops the current chunk and flushes the profile to Sentry. + * @returns void + */ + public stop(): void { + if (!this._client) { + DEBUG_BUILD && logger.log('[Profiling] Failed to stop, sentry client was never attached to the profiler.'); + return; + } + this._chunkStop(); + this._teardownSpanChunkInstrumentation(); + } + + /** + * Stop profiler and initializes profiling of the next chunk + */ + private _chunkStart(): void { if (!this._client) { // The client is not attached to the profiler if the user has not enabled continuous profiling. // In this case, calling start() and stop() is a noop action.The reason this exists is because @@ -193,20 +226,16 @@ class ContinuousProfiler { logger.log( `[Profiling] Chunk with chunk_id ${this._chunkData.id} is still running, current chunk will be stopped a new chunk will be started.`, ); - this.stop(); + this._chunkStop(); } - const traceId = - getCurrentScope().getPropagationContext().traceId || getIsolationScope().getPropagationContext().traceId; - this._initializeChunk(traceId); - this._startChunkProfiling(this._chunkData!); + this._startChunkProfiling(); } /** - * Stops the current chunk and flushes the profile to Sentry. - * @returns void + * Stops profiling of the current chunks and flushes the profile to Sentry */ - public stop(): void { + private _chunkStop(): void { if (this._chunkData?.timer) { global.clearTimeout(this._chunkData.timer); this._chunkData.timer = undefined; @@ -223,12 +252,17 @@ class ContinuousProfiler { return; } - const profile = this._stopChunkProfiling(this._chunkData); + const profile = CpuProfilerBindings.stopProfiling(this._chunkData.id, ProfileFormat.CHUNK); if (!profile) { DEBUG_BUILD && logger.log(`[Profiling] _chunkiledStartTraceID to collect profile for: ${this._chunkData.id}`); return; } + if (!this._profilerId) { + DEBUG_BUILD && + logger.log('[Profiling] Profile chunk does not contain a valid profiler_id, this is a bug in the SDK'); + return; + } if (profile) { DEBUG_BUILD && logger.log(`[Profiling] Sending profile chunk ${this._chunkData.id}.`); } @@ -248,7 +282,7 @@ class ContinuousProfiler { if (!chunk) { DEBUG_BUILD && logger.log(`[Profiling] Failed to create profile chunk for: ${this._chunkData.id}`); - this._reset(); + this._resetChunkData(); return; } @@ -257,7 +291,7 @@ class ContinuousProfiler { // 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._reset(); + this._resetChunkData(); } /** @@ -287,29 +321,23 @@ class ContinuousProfiler { }); } - /** - * Stops the profile and clears chunk instrumentation from global scope - * @returns void - */ - private _stopChunkProfiling(chunk: ChunkData): RawChunkCpuProfile | null { - this._teardownSpanChunkInstrumentation(); - return CpuProfilerBindings.stopProfiling(chunk.id, ProfileFormat.CHUNK); - } - /** * Starts the profiler and registers the flush timer for a given chunk. * @param chunk */ - private _startChunkProfiling(chunk: ChunkData): void { - this._setupSpanChunkInstrumentation(); + private _startChunkProfiling(): void { + const traceId = + getCurrentScope().getPropagationContext().traceId || getIsolationScope().getPropagationContext().traceId; + const chunk = this._initializeChunk(traceId); + CpuProfilerBindings.startProfiling(chunk.id); DEBUG_BUILD && logger.log(`[Profiling] starting profiling chunk: ${chunk.id}`); chunk.timer = global.setTimeout(() => { DEBUG_BUILD && logger.log(`[Profiling] Stopping profiling chunk: ${chunk.id}`); - this.stop(); + this._chunkStop(); DEBUG_BUILD && logger.log('[Profiling] Starting new profiling chunk.'); - setImmediate(this.start.bind(this)); + setImmediate(this._chunkStart.bind(this)); }, CHUNK_INTERVAL_MS); // Unref timeout so it doesn't keep the process alive. @@ -323,21 +351,31 @@ class ContinuousProfiler { private _setupSpanChunkInstrumentation(): void { if (!this._client) { DEBUG_BUILD && - logger.log('[Profiling] Failed to collect profile, sentry client was never attached to the profiler.'); + logger.log( + '[Profiling] Failed to initialize span profiling, sentry client was never attached to the profiler.', + ); return; } + this._profilerId = uuid4(); getGlobalScope().setContext('profile', { profiler_id: this._profilerId, }); + } - this._client.on('beforeSendEvent', e => this._assignThreadIdContext(e)); + /** + * Assigns thread_id and thread name context to a profiled event if there is an active profiler session + */ + private _onBeforeSendThreadContextAssignment(event: Event): void { + if (!this._client || !this._profilerId) return; + this._assignThreadIdContext(event); } /** * Clear profiling information from global context when a profile is not running. */ private _teardownSpanChunkInstrumentation(): void { + this._profilerId = undefined; const globalScope = getGlobalScope(); globalScope.setContext('profile', {}); } @@ -345,18 +383,19 @@ class ContinuousProfiler { /** * Initializes new profile chunk metadata */ - private _initializeChunk(traceId: string): void { + private _initializeChunk(traceId: string): ChunkData { this._chunkData = { id: uuid4(), startTraceID: traceId, timer: undefined, }; + return this._chunkData; } /** * Assigns thread_id and thread name context to a profiled event. */ - private _assignThreadIdContext(event: Event): any { + private _assignThreadIdContext(event: Event): void { if (!event?.['contexts']?.['profile']) { return; } @@ -380,7 +419,7 @@ class ContinuousProfiler { /** * Resets the current chunk state. */ - private _reset(): void { + private _resetChunkData(): void { this._chunkData = undefined; } } diff --git a/packages/profiling-node/test/spanProfileUtils.test.ts b/packages/profiling-node/test/spanProfileUtils.test.ts index f65556f57ab4..fd2c95ec79e4 100644 --- a/packages/profiling-node/test/spanProfileUtils.test.ts +++ b/packages/profiling-node/test/spanProfileUtils.test.ts @@ -52,6 +52,12 @@ function makeContinuousProfilingClient(): [Sentry.NodeClient, Transport] { return [client, client.getTransport() as Transport]; } +function getProfilerId(): string { + return ( + Sentry.getClient()?.getIntegrationByName>('ProfilingIntegration') as any + )?._profiler?._profilerId; +} + function makeClientOptions( options: Omit, ): NodeClientOptions { @@ -394,7 +400,7 @@ describe('continuous profiling', () => { const integration = client?.getIntegrationByName>('ProfilingIntegration'); if (integration) { - integration._profiler.stop(); + Sentry.profiler.stopProfiler(); } jest.clearAllMocks(); @@ -432,14 +438,9 @@ describe('continuous profiling', () => { client.init(); const transportSpy = jest.spyOn(transport, 'send').mockReturnValue(Promise.resolve({})); - - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); jest.advanceTimersByTime(1000); - integration._profiler.stop(); + Sentry.profiler.stopProfiler(); jest.advanceTimersByTime(1000); const profile = transportSpy.mock.calls?.[0]?.[0]?.[1]?.[0]?.[1] as ProfileChunk; @@ -455,14 +456,10 @@ describe('continuous profiling', () => { client.init(); expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); + Sentry.profiler.startProfiler(); const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); - - expect(integration._profiler).toBeDefined(); + expect(integration?._profiler).toBeDefined(); }); it('starts a continuous profile', () => { @@ -473,11 +470,7 @@ describe('continuous profiling', () => { client.init(); expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); expect(startProfilingSpy).toHaveBeenCalledTimes(1); }); @@ -490,12 +483,9 @@ describe('continuous profiling', () => { client.init(); expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); - integration._profiler.start(); + Sentry.profiler.startProfiler(); + Sentry.profiler.startProfiler(); + expect(startProfilingSpy).toHaveBeenCalledTimes(2); expect(stopProfilingSpy).toHaveBeenCalledTimes(1); }); @@ -509,15 +499,46 @@ describe('continuous profiling', () => { client.init(); expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); + + jest.advanceTimersByTime(5001); + expect(stopProfilingSpy).toHaveBeenCalledTimes(1); + expect(startProfilingSpy).toHaveBeenCalledTimes(2); + }); + + it('chunks share the same profilerId', async () => { + const startProfilingSpy = jest.spyOn(CpuProfilerBindings, 'startProfiling'); + const stopProfilingSpy = jest.spyOn(CpuProfilerBindings, 'stopProfiling'); + + const [client] = makeContinuousProfilingClient(); + Sentry.setCurrentClient(client); + client.init(); + + expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); + Sentry.profiler.startProfiler(); + const profilerId = getProfilerId(); jest.advanceTimersByTime(5001); expect(stopProfilingSpy).toHaveBeenCalledTimes(1); expect(startProfilingSpy).toHaveBeenCalledTimes(2); + expect(getProfilerId()).toBe(profilerId); + }); + + it('explicit calls to stop clear profilerId', async () => { + const startProfilingSpy = jest.spyOn(CpuProfilerBindings, 'startProfiling'); + + const [client] = makeContinuousProfilingClient(); + Sentry.setCurrentClient(client); + client.init(); + + expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); + Sentry.profiler.startProfiler(); + const profilerId = getProfilerId(); + Sentry.profiler.stopProfiler(); + Sentry.profiler.startProfiler(); + + expect(getProfilerId()).toEqual(expect.any(String)); + expect(getProfilerId()).not.toBe(profilerId); }); it('stops a continuous profile after interval', async () => { @@ -529,11 +550,7 @@ describe('continuous profiling', () => { client.init(); expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); jest.advanceTimersByTime(5001); expect(stopProfilingSpy).toHaveBeenCalledTimes(1); @@ -548,15 +565,11 @@ describe('continuous profiling', () => { client.init(); expect(startProfilingSpy).not.toHaveBeenCalledTimes(1); - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); jest.advanceTimersByTime(1000); - integration._profiler.stop(); + Sentry.profiler.stopProfiler(); expect(stopProfilingSpy).toHaveBeenCalledTimes(1); jest.advanceTimersByTime(1000); @@ -603,14 +616,9 @@ describe('continuous profiling', () => { client.init(); const transportSpy = jest.spyOn(transport, 'send').mockReturnValue(Promise.resolve({})); - - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); jest.advanceTimersByTime(1000); - integration._profiler.stop(); + Sentry.profiler.stopProfiler(); jest.advanceTimersByTime(1000); expect(transportSpy.mock.calls?.[0]?.[0]?.[1]?.[0]?.[0]?.type).toBe('profile_chunk'); @@ -640,7 +648,7 @@ describe('continuous profiling', () => { integration._profiler.start(); const profiledTransaction = Sentry.startInactiveSpan({ forceTransaction: true, name: 'profile_hub' }); profiledTransaction.end(); - integration._profiler.stop(); + Sentry.profiler.stopProfiler(); expect(transportSpy.mock.calls?.[1]?.[0]?.[1]?.[0]?.[1]).toMatchObject({ contexts: { @@ -658,7 +666,7 @@ describe('continuous profiling', () => { }); }); -describe('span profiling mode', () => { +describe('continuous profiling does not start in span profiling mode', () => { it.each([ ['profilesSampleRate=1', makeClientOptions({ profilesSampleRate: 1 })], ['profilesSampler is defined', makeClientOptions({ profilesSampler: () => 1 })], @@ -699,7 +707,9 @@ describe('span profiling mode', () => { } integration._profiler.start(); - expect(logSpy).toHaveBeenLastCalledWith('[Profiling] Profiler was never attached to the client.'); + expect(logSpy).toHaveBeenLastCalledWith( + '[Profiling] Failed to start, sentry client was never attached to the profiler.', + ); }); }); describe('continuous profiling mode', () => { @@ -742,12 +752,7 @@ describe('continuous profiling mode', () => { } jest.spyOn(transport, 'send').mockReturnValue(Promise.resolve({})); - - const integration = client.getIntegrationByName>('ProfilingIntegration'); - if (!integration) { - throw new Error('Profiling integration not found'); - } - integration._profiler.start(); + Sentry.profiler.startProfiler(); const callCount = startProfilingSpy.mock.calls.length; expect(startProfilingSpy).toHaveBeenCalled();