diff --git a/packages/utils/docs/profiler.md b/packages/utils/docs/profiler.md index a3740b875..e5249632c 100644 --- a/packages/utils/docs/profiler.md +++ b/packages/utils/docs/profiler.md @@ -6,6 +6,15 @@ The `Profiler` class provides a clean, type-safe API for performance monitoring that integrates seamlessly with Chrome DevTools. It supports both synchronous and asynchronous operations with smart defaults for custom track visualization, enabling developers to track performance bottlenecks and optimize application speed. +### Features + +- **Type-Safe API**: Fully typed UserTiming API for [Chrome DevTools Extensibility API](https://developer.chrome.com/docs/devtools/performance/extension) +- **Measure API**: Easy-to-use methods for measuring synchronous and asynchronous code execution times. +- **Custom Track Configuration**: Fully typed reusable configurations for custom track visualization. +- **Process buffered entries**: Captures and processes buffered profiling entries. +- **3rd Party Profiling**: Automatically processes third-party performance entries. +- **Clean measure names**: Automatically adds prefixes to measure names, as well as start/end postfix to marks, for better organization. + ## Getting started 1. If you haven't already, install [@code-pushup/utils](../../README.md). @@ -257,10 +266,23 @@ const saved = profiler.measure('save-user', () => saveToDb(user), { ## NodeJSProfiler -This profiler extends all options and API from Profiler with automatic process exit handling for buffered performance data. +### Features + +- **Crash-safe Write Ahead Log**: Ensures profiling data is saved even if the application crashes. +- **Recoverable Profiles**: Ability to resume profiling sessions after interruptions or crash. +- **Automatic Trace Generation**: Generates trace files compatible with Chrome DevTools for in-depth performance analysis. +- **Multiprocess Support**: Designed to handle profiling over sharded WAL. +- **Controllable over env vars**: Easily enable or disable profiling through environment variables. +This profiler extends all options and API from Profiler with automatic process exit handling for buffered performance data. The NodeJSProfiler automatically subscribes to performance observation and installs exit handlers that flush buffered data on process termination (signals, fatal errors, or normal exit). +### Exit Handlers + +The profiler automatically subscribes to process events (`exit`, `SIGINT`, `SIGTERM`, `SIGQUIT`, `uncaughtException`, `unhandledRejection`) during construction. When any of these occur, the handlers call `close()` to ensure buffered data is flushed. + +The `close()` method is idempotent and safe to call from exit handlers. It unsubscribes from exit handlers, closes the WAL sink, and unsubscribes from the performance observer, ensuring all buffered performance data is written before process termination. + ## Configuration ```ts diff --git a/packages/utils/mocks/sink.mock.ts b/packages/utils/mocks/sink.mock.ts index ecc280394..e61bd9146 100644 --- a/packages/utils/mocks/sink.mock.ts +++ b/packages/utils/mocks/sink.mock.ts @@ -51,4 +51,8 @@ export class MockTraceEventFileSink extends MockAppendableSink { repack = vi.fn((): void => {}); finalize = vi.fn((): void => {}); + + getPath = vi.fn((): string => { + return '/test/tmp/profiles/default/trace.default.jsonl'; + }); } diff --git a/packages/utils/src/lib/exit-process.int.test.ts b/packages/utils/src/lib/exit-process.int.test.ts index 5fccb57a3..d915f6317 100644 --- a/packages/utils/src/lib/exit-process.int.test.ts +++ b/packages/utils/src/lib/exit-process.int.test.ts @@ -1,7 +1,7 @@ import process from 'node:process'; -import { SIGNAL_EXIT_CODES, installExitHandlers } from './exit-process.js'; +import { SIGNAL_EXIT_CODES, subscribeProcessExit } from './exit-process.js'; -describe('installExitHandlers', () => { +describe('subscribeProcessExit', () => { const onError = vi.fn(); const onExit = vi.fn(); const processOnSpy = vi.spyOn(process, 'on'); @@ -25,7 +25,7 @@ describe('installExitHandlers', () => { }); it('should install event listeners for all expected events', () => { - expect(() => installExitHandlers({ onError, onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onError, onExit })).not.toThrow(); expect(processOnSpy).toHaveBeenCalledWith( 'uncaughtException', @@ -42,7 +42,7 @@ describe('installExitHandlers', () => { }); it('should call onError with error and kind for uncaughtException', () => { - expect(() => installExitHandlers({ onError })).not.toThrow(); + expect(() => subscribeProcessExit({ onError })).not.toThrow(); const testError = new Error('Test uncaught exception'); @@ -54,7 +54,7 @@ describe('installExitHandlers', () => { }); it('should call onError with reason and kind for unhandledRejection', () => { - expect(() => installExitHandlers({ onError })).not.toThrow(); + expect(() => subscribeProcessExit({ onError })).not.toThrow(); const testReason = 'Test unhandled rejection'; @@ -66,7 +66,7 @@ describe('installExitHandlers', () => { }); it('should call onExit and exit with code 0 for SIGINT', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); (process as any).emit('SIGINT'); @@ -79,7 +79,7 @@ describe('installExitHandlers', () => { }); it('should call onExit and exit with code 0 for SIGTERM', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); (process as any).emit('SIGTERM'); @@ -92,7 +92,7 @@ describe('installExitHandlers', () => { }); it('should call onExit and exit with code 0 for SIGQUIT', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); (process as any).emit('SIGQUIT'); @@ -105,7 +105,7 @@ describe('installExitHandlers', () => { }); it('should call onExit for successful process termination with exit code 0', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); (process as any).emit('exit', 0); @@ -116,7 +116,7 @@ describe('installExitHandlers', () => { }); it('should call onExit for failed process termination with exit code 1', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); (process as any).emit('exit', 1); diff --git a/packages/utils/src/lib/exit-process.ts b/packages/utils/src/lib/exit-process.ts index e2e3f89f8..07d611ea1 100644 --- a/packages/utils/src/lib/exit-process.ts +++ b/packages/utils/src/lib/exit-process.ts @@ -38,7 +38,20 @@ export type ExitHandlerOptions = { fatalExitCode?: number; }; -export function installExitHandlers(options: ExitHandlerOptions = {}): void { +/** + * + * @param options - Options for the exit handler + * @param options.onExit - Callback to be called when the process exits + * @param options.onError - Callback to be called when an error occurs + * @param options.exitOnFatal - Whether to exit the process on fatal errors + * @param options.exitOnSignal - Whether to exit the process on signals + * @param options.fatalExitCode - The exit code to use for fatal errors + * @returns A function to unsubscribe from the exit handlers + */ +// eslint-disable-next-line max-lines-per-function +export function subscribeProcessExit( + options: ExitHandlerOptions = {}, +): () => void { // eslint-disable-next-line functional/no-let let closedReason: CloseReason | undefined; const { @@ -57,7 +70,7 @@ export function installExitHandlers(options: ExitHandlerOptions = {}): void { onExit?.(code, reason); }; - process.on('uncaughtException', err => { + const uncaughtExceptionHandler = (err: unknown) => { onError?.(err, 'uncaughtException'); if (exitOnFatal) { close(fatalExitCode, { @@ -65,9 +78,9 @@ export function installExitHandlers(options: ExitHandlerOptions = {}): void { fatal: 'uncaughtException', }); } - }); + }; - process.on('unhandledRejection', reason => { + const unhandledRejectionHandler = (reason: unknown) => { onError?.(reason, 'unhandledRejection'); if (exitOnFatal) { close(fatalExitCode, { @@ -75,22 +88,39 @@ export function installExitHandlers(options: ExitHandlerOptions = {}): void { fatal: 'unhandledRejection', }); } - }); + }; - (['SIGINT', 'SIGTERM', 'SIGQUIT'] as const).forEach(signal => { - process.on(signal, () => { - close(SIGNAL_EXIT_CODES()[signal], { kind: 'signal', signal }); - if (exitOnSignal) { - // eslint-disable-next-line n/no-process-exit - process.exit(SIGNAL_EXIT_CODES()[signal]); - } - }); - }); + const signalHandlers = (['SIGINT', 'SIGTERM', 'SIGQUIT'] as const).map( + signal => { + const handler = () => { + close(SIGNAL_EXIT_CODES()[signal], { kind: 'signal', signal }); + if (exitOnSignal) { + // eslint-disable-next-line unicorn/no-process-exit,n/no-process-exit + process.exit(SIGNAL_EXIT_CODES()[signal]); + } + }; + process.on(signal, handler); + return { signal, handler }; + }, + ); - process.on('exit', code => { + const exitHandler = (code: number) => { if (closedReason) { return; } close(code, { kind: 'exit' }); - }); + }; + + process.on('uncaughtException', uncaughtExceptionHandler); + process.on('unhandledRejection', unhandledRejectionHandler); + process.on('exit', exitHandler); + + return () => { + process.removeListener('uncaughtException', uncaughtExceptionHandler); + process.removeListener('unhandledRejection', unhandledRejectionHandler); + process.removeListener('exit', exitHandler); + signalHandlers.forEach(({ signal, handler }) => { + process.removeListener(signal, handler); + }); + }; } diff --git a/packages/utils/src/lib/exit-process.unit.test.ts b/packages/utils/src/lib/exit-process.unit.test.ts index 6ca520cfe..3226e650c 100644 --- a/packages/utils/src/lib/exit-process.unit.test.ts +++ b/packages/utils/src/lib/exit-process.unit.test.ts @@ -1,8 +1,8 @@ import os from 'node:os'; import process from 'node:process'; -import { SIGNAL_EXIT_CODES, installExitHandlers } from './exit-process.js'; +import { SIGNAL_EXIT_CODES, subscribeProcessExit } from './exit-process.js'; -describe('exit-process tests', () => { +describe('subscribeProcessExit', () => { const onError = vi.fn(); const onExit = vi.fn(); const processOnSpy = vi.spyOn(process, 'on'); @@ -26,7 +26,7 @@ describe('exit-process tests', () => { }); it('should install event listeners for all expected events', () => { - expect(() => installExitHandlers({ onError, onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onError, onExit })).not.toThrow(); expect(processOnSpy).toHaveBeenCalledWith( 'uncaughtException', @@ -43,7 +43,7 @@ describe('exit-process tests', () => { }); it('should call onError with error and kind for uncaughtException', () => { - expect(() => installExitHandlers({ onError })).not.toThrow(); + expect(() => subscribeProcessExit({ onError })).not.toThrow(); const testError = new Error('Test uncaught exception'); @@ -55,7 +55,7 @@ describe('exit-process tests', () => { }); it('should call onError with reason and kind for unhandledRejection', () => { - expect(() => installExitHandlers({ onError })).not.toThrow(); + expect(() => subscribeProcessExit({ onError })).not.toThrow(); const testReason = 'Test unhandled rejection'; @@ -68,7 +68,7 @@ describe('exit-process tests', () => { it('should call onExit with correct code and reason for SIGINT', () => { expect(() => - installExitHandlers({ onExit, exitOnSignal: true }), + subscribeProcessExit({ onExit, exitOnSignal: true }), ).not.toThrow(); (process as any).emit('SIGINT'); @@ -84,7 +84,7 @@ describe('exit-process tests', () => { it('should call onExit with correct code and reason for SIGTERM', () => { expect(() => - installExitHandlers({ onExit, exitOnSignal: true }), + subscribeProcessExit({ onExit, exitOnSignal: true }), ).not.toThrow(); (process as any).emit('SIGTERM'); @@ -100,7 +100,7 @@ describe('exit-process tests', () => { it('should call onExit with correct code and reason for SIGQUIT', () => { expect(() => - installExitHandlers({ onExit, exitOnSignal: true }), + subscribeProcessExit({ onExit, exitOnSignal: true }), ).not.toThrow(); (process as any).emit('SIGQUIT'); @@ -116,7 +116,7 @@ describe('exit-process tests', () => { it('should not exit process when exitOnSignal is false', () => { expect(() => - installExitHandlers({ onExit, exitOnSignal: false }), + subscribeProcessExit({ onExit, exitOnSignal: false }), ).not.toThrow(); (process as any).emit('SIGINT'); @@ -131,7 +131,7 @@ describe('exit-process tests', () => { }); it('should not exit process when exitOnSignal is not set', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); (process as any).emit('SIGTERM'); @@ -145,7 +145,7 @@ describe('exit-process tests', () => { }); it('should call onExit with exit code and reason for normal exit', () => { - expect(() => installExitHandlers({ onExit })).not.toThrow(); + expect(() => subscribeProcessExit({ onExit })).not.toThrow(); const exitCode = 42; (process as any).emit('exit', exitCode); @@ -158,7 +158,7 @@ describe('exit-process tests', () => { it('should call onExit with fatal reason when exitOnFatal is true', () => { expect(() => - installExitHandlers({ onError, onExit, exitOnFatal: true }), + subscribeProcessExit({ onError, onExit, exitOnFatal: true }), ).not.toThrow(); const testError = new Error('Test uncaught exception'); @@ -176,7 +176,7 @@ describe('exit-process tests', () => { it('should use custom fatalExitCode when exitOnFatal is true', () => { expect(() => - installExitHandlers({ + subscribeProcessExit({ onError, onExit, exitOnFatal: true, @@ -199,7 +199,7 @@ describe('exit-process tests', () => { it('should call onExit with fatal reason for unhandledRejection when exitOnFatal is true', () => { expect(() => - installExitHandlers({ onError, onExit, exitOnFatal: true }), + subscribeProcessExit({ onError, onExit, exitOnFatal: true }), ).not.toThrow(); const testReason = 'Test unhandled rejection'; @@ -243,7 +243,7 @@ describe('exit-process tests', () => { it('should call onExit only once even when close is called multiple times', () => { expect(() => - installExitHandlers({ onExit, exitOnSignal: true }), + subscribeProcessExit({ onExit, exitOnSignal: true }), ).not.toThrow(); (process as any).emit('SIGINT'); diff --git a/packages/utils/src/lib/profiler/__snapshots__/comprehensive-stats-trace-events.jsonl b/packages/utils/src/lib/profiler/__snapshots__/comprehensive-stats-trace-events.jsonl new file mode 100644 index 000000000..5583ed827 --- /dev/null +++ b/packages/utils/src/lib/profiler/__snapshots__/comprehensive-stats-trace-events.jsonl @@ -0,0 +1,8 @@ +{"cat":"blink.user_timing","ph":"i","name":"stats-profiler:operation-1:start","pid":10001,"tid":1,"ts":1700000005000000,"args":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}} +{"cat":"blink.user_timing","ph":"b","name":"stats-profiler:operation-1","id2":{"local":"0x1"},"pid":10001,"tid":1,"ts":1700000005000001,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"e","name":"stats-profiler:operation-1","id2":{"local":"0x1"},"pid":10001,"tid":1,"ts":1700000005000002,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"i","name":"stats-profiler:operation-1:end","pid":10001,"tid":1,"ts":1700000005000003,"args":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}} +{"cat":"blink.user_timing","ph":"i","name":"stats-profiler:operation-2:start","pid":10001,"tid":1,"ts":1700000005000004,"args":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}} +{"cat":"blink.user_timing","ph":"b","name":"stats-profiler:operation-2","id2":{"local":"0x2"},"pid":10001,"tid":1,"ts":1700000005000005,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"e","name":"stats-profiler:operation-2","id2":{"local":"0x2"},"pid":10001,"tid":1,"ts":1700000005000006,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"i","name":"stats-profiler:operation-2:end","pid":10001,"tid":1,"ts":1700000005000007,"args":{"detail":"{\"devtools\":{\"track\":\"Stats\",\"dataType\":\"track-entry\"}}"}} diff --git a/packages/utils/src/lib/profiler/__snapshots__/custom-tracks-trace-events.jsonl b/packages/utils/src/lib/profiler/__snapshots__/custom-tracks-trace-events.jsonl new file mode 100644 index 000000000..43f83dbdb --- /dev/null +++ b/packages/utils/src/lib/profiler/__snapshots__/custom-tracks-trace-events.jsonl @@ -0,0 +1,4 @@ +{"cat":"blink.user_timing","ph":"i","name":"api-server:user-lookup:start","pid":10001,"tid":1,"ts":1700000005000000,"args":{"detail":"{\"devtools\":{\"track\":\"cache\",\"dataType\":\"track-entry\"}}"}} +{"cat":"blink.user_timing","ph":"b","name":"api-server:user-lookup","id2":{"local":"0x1"},"pid":10001,"tid":1,"ts":1700000005000001,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"cache\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"e","name":"api-server:user-lookup","id2":{"local":"0x1"},"pid":10001,"tid":1,"ts":1700000005000002,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"cache\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"i","name":"api-server:user-lookup:end","pid":10001,"tid":1,"ts":1700000005000003,"args":{"detail":"{\"devtools\":{\"track\":\"cache\",\"dataType\":\"track-entry\"}}"}} diff --git a/packages/utils/src/lib/profiler/__snapshots__/sharded-path-trace-events.jsonl b/packages/utils/src/lib/profiler/__snapshots__/sharded-path-trace-events.jsonl new file mode 100644 index 000000000..2a30bcd0a --- /dev/null +++ b/packages/utils/src/lib/profiler/__snapshots__/sharded-path-trace-events.jsonl @@ -0,0 +1,4 @@ +{"cat":"blink.user_timing","ph":"i","name":"write-test:test-operation:start","pid":10001,"tid":1,"ts":1700000005000000,"args":{"detail":"{\"devtools\":{\"track\":\"Test\",\"dataType\":\"track-entry\"}}"}} +{"cat":"blink.user_timing","ph":"b","name":"write-test:test-operation","id2":{"local":"0x1"},"pid":10001,"tid":1,"ts":1700000005000001,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"Test\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"e","name":"write-test:test-operation","id2":{"local":"0x1"},"pid":10001,"tid":1,"ts":1700000005000002,"args":{"data":{"detail":"{\"devtools\":{\"track\":\"Test\",\"dataType\":\"track-entry\"}}"}}} +{"cat":"blink.user_timing","ph":"i","name":"write-test:test-operation:end","pid":10001,"tid":1,"ts":1700000005000003,"args":{"detail":"{\"devtools\":{\"track\":\"Test\",\"dataType\":\"track-entry\"}}"}} diff --git a/packages/utils/src/lib/profiler/constants.ts b/packages/utils/src/lib/profiler/constants.ts index 768006791..c0e515787 100644 --- a/packages/utils/src/lib/profiler/constants.ts +++ b/packages/utils/src/lib/profiler/constants.ts @@ -3,9 +3,7 @@ * When set to 'true', profiling is enabled. When set to 'false' or unset, profiling is disabled. * * @example - * ```bash * CP_PROFILING=true npm run dev - * ``` */ export const PROFILER_ENABLED_ENV_VAR = 'CP_PROFILING'; @@ -14,8 +12,16 @@ export const PROFILER_ENABLED_ENV_VAR = 'CP_PROFILING'; * When set to 'true', profiler state transitions create performance marks for debugging. * * @example - * ```bash * CP_PROFILER_DEBUG=true npm run dev - * ``` */ export const PROFILER_DEBUG_ENV_VAR = 'CP_PROFILER_DEBUG'; + +/** + * Environment variable name for setting the Sharded WAL Coordinator ID. + * This ID is used to identify the coordinator instance in a sharded Write-Ahead Logging setup. + * + * @example + * CP_SHARDED_WAL_COORDINATOR_ID=coordinator-1 npm run dev + */ +export const SHARDED_WAL_COORDINATOR_ID_ENV_VAR = + 'CP_SHARDED_WAL_COORDINATOR_ID'; diff --git a/packages/utils/src/lib/profiler/profiler-node.int.test.ts b/packages/utils/src/lib/profiler/profiler-node.int.test.ts new file mode 100644 index 000000000..1b903ee5a --- /dev/null +++ b/packages/utils/src/lib/profiler/profiler-node.int.test.ts @@ -0,0 +1,317 @@ +import fs from 'node:fs'; +import path from 'node:path'; +import { + awaitObserverCallbackAndFlush, + omitTraceJson, +} from '@code-pushup/test-utils'; +import type { PerformanceEntryEncoder } from '../performance-observer.js'; +import { WAL_ID_PATTERNS } from '../wal.js'; +import { NodejsProfiler } from './profiler-node.js'; +import { entryToTraceEvents } from './trace-file-utils.js'; +import type { UserTimingTraceEvent } from './trace-file.type.js'; + +describe('NodeJS Profiler Integration', () => { + const traceEventEncoder: PerformanceEntryEncoder = + entryToTraceEvents; + + let nodejsProfiler: NodejsProfiler; + + beforeEach(() => { + performance.clearMarks(); + performance.clearMeasures(); + vi.stubEnv('CP_PROFILING', undefined!); + vi.stubEnv('CP_PROFILER_DEBUG', undefined!); + + // Clean up trace files from previous test runs + const traceFilesDir = path.join(process.cwd(), 'tmp', 'int', 'utils'); + // eslint-disable-next-line n/no-sync + if (fs.existsSync(traceFilesDir)) { + // eslint-disable-next-line n/no-sync + const files = fs.readdirSync(traceFilesDir); + // eslint-disable-next-line functional/no-loop-statements + for (const file of files) { + if (file.endsWith('.json') || file.endsWith('.jsonl')) { + // eslint-disable-next-line n/no-sync + fs.unlinkSync(path.join(traceFilesDir, file)); + } + } + } + + nodejsProfiler = new NodejsProfiler({ + prefix: 'test', + track: 'test-track', + encodePerfEntry: traceEventEncoder, + filename: path.join(process.cwd(), 'tmp', 'int', 'utils', 'trace.json'), + enabled: true, + }); + }); + + afterEach(() => { + if (nodejsProfiler && nodejsProfiler.state !== 'closed') { + nodejsProfiler.close(); + } + vi.stubEnv('CP_PROFILING', undefined!); + vi.stubEnv('CP_PROFILER_DEBUG', undefined!); + }); + + it('should initialize with sink opened when enabled', () => { + expect(nodejsProfiler.isEnabled()).toBeTrue(); + expect(nodejsProfiler.stats.walOpen).toBeTrue(); + }); + + it('should create performance entries and write to sink', () => { + expect(nodejsProfiler.measure('test-operation', () => 'success')).toBe( + 'success', + ); + }); + + it('should handle async operations', async () => { + await expect( + nodejsProfiler.measureAsync('async-test', async () => { + await new Promise(resolve => setTimeout(resolve, 1)); + return 'async-result'; + }), + ).resolves.toBe('async-result'); + }); + + it('should disable profiling and close sink', () => { + nodejsProfiler.setEnabled(false); + expect(nodejsProfiler.isEnabled()).toBeFalse(); + expect(nodejsProfiler.stats.walOpen).toBeFalse(); + + expect(nodejsProfiler.measure('disabled-test', () => 'success')).toBe( + 'success', + ); + }); + + it('should re-enable profiling correctly', () => { + nodejsProfiler.setEnabled(false); + expect(nodejsProfiler.stats.walOpen).toBeFalse(); + + nodejsProfiler.setEnabled(true); + + expect(nodejsProfiler.isEnabled()).toBeTrue(); + expect(nodejsProfiler.stats.walOpen).toBeTrue(); + + expect(nodejsProfiler.measure('re-enabled-test', () => 42)).toBe(42); + }); + + it('should support custom tracks', async () => { + const traceTracksFile = path.join( + process.cwd(), + 'tmp', + 'int', + 'utils', + 'trace-tracks.json', + ); + const profilerWithTracks = new NodejsProfiler({ + prefix: 'api-server', + track: 'HTTP', + tracks: { + db: { track: 'Database', color: 'secondary' }, + cache: { track: 'Cache', color: 'primary' }, + }, + encodePerfEntry: traceEventEncoder, + filename: traceTracksFile, + enabled: true, + }); + + expect(profilerWithTracks.filePath).toBe(traceTracksFile); + + expect( + profilerWithTracks.measure('user-lookup', () => 'user123', { + track: 'cache', + }), + ).toBe('user123'); + + await awaitObserverCallbackAndFlush(profilerWithTracks); + profilerWithTracks.close(); + + // eslint-disable-next-line n/no-sync + const content = fs.readFileSync(traceTracksFile, 'utf8'); + const normalizedContent = omitTraceJson(content); + await expect(normalizedContent).toMatchFileSnapshot( + '__snapshots__/custom-tracks-trace-events.jsonl', + ); + }); + + it('should capture buffered entries when buffered option is enabled', () => { + const bufferedProfiler = new NodejsProfiler({ + prefix: 'buffered-test', + track: 'Test', + encodePerfEntry: traceEventEncoder, + captureBufferedEntries: true, + filename: path.join( + process.cwd(), + 'tmp', + 'int', + 'utils', + 'trace-buffered.json', + ), + enabled: true, + }); + + const bufferedStats = bufferedProfiler.stats; + expect(bufferedStats.state).toBe('running'); + expect(bufferedStats.walOpen).toBeTrue(); + expect(bufferedStats.isSubscribed).toBeTrue(); + expect(bufferedStats.queued).toBe(0); + expect(bufferedStats.dropped).toBe(0); + expect(bufferedStats.written).toBe(0); + + bufferedProfiler.close(); + }); + + it('should return correct getStats with dropped and written counts', () => { + const statsProfiler = new NodejsProfiler({ + prefix: 'stats-test', + track: 'Stats', + encodePerfEntry: traceEventEncoder, + maxQueueSize: 2, + flushThreshold: 2, + filename: path.join( + process.cwd(), + 'tmp', + 'int', + 'utils', + 'trace-stats.json', + ), + enabled: true, + }); + + expect(statsProfiler.measure('test-op', () => 'result')).toBe('result'); + + const stats = statsProfiler.stats; + expect(stats.state).toBe('running'); + expect(stats.walOpen).toBeTrue(); + expect(stats.isSubscribed).toBeTrue(); + expect(typeof stats.queued).toBe('number'); + expect(typeof stats.dropped).toBe('number'); + expect(typeof stats.written).toBe('number'); + + statsProfiler.close(); + }); + + it('should provide comprehensive queue statistics via getStats', async () => { + const traceStatsFile = path.join( + process.cwd(), + 'tmp', + 'int', + 'utils', + 'trace-stats-comprehensive.json', + ); + const profiler = new NodejsProfiler({ + prefix: 'stats-profiler', + track: 'Stats', + encodePerfEntry: traceEventEncoder, + maxQueueSize: 3, + flushThreshold: 2, + filename: traceStatsFile, + enabled: true, + }); + + const initialStats = profiler.stats; + expect(initialStats.state).toBe('running'); + expect(initialStats.walOpen).toBeTrue(); + expect(initialStats.isSubscribed).toBeTrue(); + expect(initialStats.queued).toBe(0); + expect(initialStats.dropped).toBe(0); + expect(initialStats.written).toBe(0); + + profiler.measure('operation-1', () => 'result1'); + profiler.measure('operation-2', () => 'result2'); + await awaitObserverCallbackAndFlush(profiler); + // Each measure creates 4 events (start marker, begin span, end span, end marker) + // 2 measures × 4 events = 8 events written + expect(profiler.stats.written).toBe(8); + + profiler.setEnabled(false); + + const finalStats = profiler.stats; + expect(finalStats.state).toBe('idle'); + expect(finalStats.walOpen).toBeFalse(); + expect(finalStats.isSubscribed).toBeFalse(); + expect(finalStats.queued).toBe(0); + + profiler.flush(); + profiler.close(); + + // eslint-disable-next-line n/no-sync + const content = fs.readFileSync(traceStatsFile, 'utf8'); + const normalizedContent = omitTraceJson(content); + await expect(normalizedContent).toMatchFileSnapshot( + '__snapshots__/comprehensive-stats-trace-events.jsonl', + ); + }); + + describe('sharded path structure', () => { + it('should create sharded path structure when filename is not provided', () => { + const profiler = new NodejsProfiler({ + prefix: 'sharded-test', + track: 'Test', + encodePerfEntry: traceEventEncoder, + enabled: true, + }); + + const filePath = profiler.filePath; + expect(filePath).toContainPath('tmp/profiles'); + expect(filePath).toMatch(/\.jsonl$/); + + const pathParts = filePath.split(path.sep); + const groupIdDir = pathParts.at(-2); + const fileName = pathParts.at(-1); + + expect(groupIdDir).toMatch(WAL_ID_PATTERNS.GROUP_ID); + expect(fileName).toMatch(/^trace\.\d{8}-\d{6}-\d{3}(?:\.\d+){3}\.jsonl$/); + + const groupIdDirPath = path.dirname(filePath); + // eslint-disable-next-line n/no-sync + expect(fs.existsSync(groupIdDirPath)).toBeTrue(); + + profiler.close(); + }); + + it('should create correct folder structure for sharded paths', () => { + const profiler = new NodejsProfiler({ + prefix: 'folder-test', + track: 'Test', + encodePerfEntry: traceEventEncoder, + enabled: true, + }); + + const filePath = profiler.filePath; + const dirPath = path.dirname(filePath); + const groupId = path.basename(dirPath); + + expect(groupId).toMatch(WAL_ID_PATTERNS.GROUP_ID); + // eslint-disable-next-line n/no-sync + expect(fs.existsSync(dirPath)).toBeTrue(); + // eslint-disable-next-line n/no-sync + expect(fs.statSync(dirPath).isDirectory()).toBeTrue(); + + profiler.close(); + }); + + it('should write trace events to sharded path file', async () => { + const profiler = new NodejsProfiler({ + prefix: 'write-test', + track: 'Test', + encodePerfEntry: traceEventEncoder, + enabled: true, + }); + + profiler.measure('test-operation', () => 'result'); + + await awaitObserverCallbackAndFlush(profiler); + profiler.close(); + + const filePath = profiler.filePath; + // eslint-disable-next-line n/no-sync + const content = fs.readFileSync(filePath, 'utf8'); + const normalizedContent = omitTraceJson(content); + await expect(normalizedContent).toMatchFileSnapshot( + '__snapshots__/sharded-path-trace-events.jsonl', + ); + }); + }); +}); diff --git a/packages/utils/src/lib/profiler/profiler-node.ts b/packages/utils/src/lib/profiler/profiler-node.ts new file mode 100644 index 000000000..b668b2028 --- /dev/null +++ b/packages/utils/src/lib/profiler/profiler-node.ts @@ -0,0 +1,312 @@ +import path from 'node:path'; +import { isEnvVarEnabled } from '../env.js'; +import { subscribeProcessExit } from '../exit-process.js'; +import { + type PerformanceObserverOptions, + PerformanceObserverSink, +} from '../performance-observer.js'; +import { objectToEntries } from '../transform.js'; +import { errorToMarkerPayload } from '../user-timing-extensibility-api-utils.js'; +import type { + ActionTrackEntryPayload, + MarkerPayload, +} from '../user-timing-extensibility-api.type.js'; +import { + type AppendableSink, + WriteAheadLogFile, + getShardId, + getShardedGroupId, + getShardedPath, +} from '../wal.js'; +import { + PROFILER_DEBUG_ENV_VAR, + PROFILER_ENABLED_ENV_VAR, +} from './constants.js'; +import { Profiler, type ProfilerOptions } from './profiler.js'; +import { traceEventWalFormat } from './wal-json-trace.js'; + +/** + * Options for configuring a NodejsProfiler instance. + * + * Extends ProfilerOptions with a required sink parameter. + * + * @template Tracks - Record type defining available track names and their configurations + */ +export type NodejsProfilerOptions< + DomainEvents extends string | object, + Tracks extends Record, +> = ProfilerOptions & + Omit, 'sink'> & { + /** + * File path for the WriteAheadLogFile sink. + * If not provided, defaults to `trace.json` in the current working directory. + * + * @default path.join(process.cwd(), 'trace.json') + */ + filename?: string; + /** + * Name of the environment variable to check for debug mode. + * When the env var is set to 'true', profiler state transitions create performance marks for debugging. + * + * @default 'CP_PROFILER_DEBUG' + */ + debugEnvVar?: string; + }; + +/** + * Performance profiler with automatic process exit handling for buffered performance data. + * + * This class extends the base {@link Profiler} with automatic flushing of performance data + * when the process exits. It automatically creates a {@link WriteAheadLogFile} sink that buffers + * performance entries and ensures they are written out during process termination, even for unexpected exits. + * + * The sink uses a default codec for serializing performance data to JSON format, + * enabling compatibility with Chrome DevTools trace file format. + * + * The profiler automatically subscribes to the performance observer when enabled and installs + * exit handlers that flush buffered data on process termination (signals, fatal errors, or normal exit). + * + * @template DomainEvents - The type of domain-specific events encoded by the performance observer sink + * @template Tracks - Record type defining available track names and their configurations + */ +export class NodejsProfiler< + DomainEvents extends string | object, + Tracks extends Record = Record< + string, + ActionTrackEntryPayload + >, +> extends Profiler { + #sink: AppendableSink; + #performanceObserverSink: PerformanceObserverSink; + #state: 'idle' | 'running' | 'closed' = 'idle'; + #debug: boolean; + #unsubscribeExitHandlers: (() => void) | undefined; + + /** + * Creates a NodejsProfiler instance. + * A WriteAheadLogFile sink is automatically created for buffering performance data. + * @param options - Configuration options + */ + // eslint-disable-next-line max-lines-per-function + constructor(options: NodejsProfilerOptions) { + const { + encodePerfEntry, + captureBufferedEntries, + flushThreshold, + maxQueueSize, + enabled, + filename, + debugEnvVar = PROFILER_DEBUG_ENV_VAR, + ...profilerOptions + } = options; + const initialEnabled = enabled ?? isEnvVarEnabled(PROFILER_ENABLED_ENV_VAR); + super({ ...profilerOptions, enabled: initialEnabled }); + + const walFormat = traceEventWalFormat(); + this.#sink = new WriteAheadLogFile({ + file: + filename ?? + path.join( + process.cwd(), + getShardedPath({ + dir: 'tmp/profiles', + groupId: getShardedGroupId(), + shardId: getShardId(), + format: walFormat, + }), + ), + codec: walFormat.codec, + }) as AppendableSink; + this.#debug = isEnvVarEnabled(debugEnvVar); + + this.#performanceObserverSink = new PerformanceObserverSink({ + sink: this.#sink, + encodePerfEntry, + captureBufferedEntries, + flushThreshold, + maxQueueSize, + debugEnvVar, + }); + + this.#unsubscribeExitHandlers = subscribeProcessExit({ + onError: ( + error: unknown, + kind: 'uncaughtException' | 'unhandledRejection', + ) => { + this.#handleFatalError(error, kind); + }, + onExit: (_code: number) => { + this.close(); + }, + }); + + if (initialEnabled) { + this.#transition('running'); + } + } + + /** + * Returns whether debug mode is enabled for profiler state transitions. + * + * Debug mode is initially determined by the environment variable specified by `debugEnvVar` + * (defaults to 'CP_PROFILER_DEBUG') during construction, but can be changed at runtime + * using {@link setDebugMode}. When enabled, profiler state transitions create + * performance marks for debugging. + * + * @returns true if debug mode is enabled, false otherwise + */ + get debug(): boolean { + return this.#debug; + } + + /** + * Sets debug mode for profiler state transitions. + * + * When debug mode is enabled, profiler state transitions create performance marks + * for debugging. This allows runtime control of debug mode without needing to + * restart the application or change environment variables. + * + * @param enabled - Whether to enable debug mode + */ + setDebugMode(enabled: boolean): void { + this.#debug = enabled; + } + + /** + * Creates a performance marker for a profiler state transition. + * @param transition - The state transition that occurred + */ + #transitionMarker(transition: string): void { + const transitionMarkerPayload: MarkerPayload = { + dataType: 'marker', + color: 'primary', + tooltipText: `Profiler state transition: ${transition}`, + properties: [['Transition', transition], ...objectToEntries(this.stats)], + }; + this.marker(transition, transitionMarkerPayload); + } + + /** + * Handles fatal errors by marking them and shutting down the profiler. + * @param error - The error that occurred + * @param kind - The kind of fatal error (uncaughtException or unhandledRejection) + */ + #handleFatalError( + error: unknown, + kind: 'uncaughtException' | 'unhandledRejection', + ): void { + this.marker( + 'Fatal Error', + errorToMarkerPayload(error, { + tooltipText: `${kind} caused fatal error`, + }), + ); + this.close(); // Ensures buffers flush and sink finalizes + } + + /** + * Transitions the profiler to a new state, performing necessary setup/teardown operations. + * + * State transitions enforce lifecycle invariants: + * - `idle -> running`: Enables profiling, opens sink, and subscribes to performance observer + * - `running -> idle`: Disables profiling, unsubscribes, and closes sink (sink will be reopened on re-enable) + * - `running -> closed`: Disables profiling, unsubscribes, and closes sink (irreversible) + * - `idle -> closed`: Closes sink if it was opened (irreversible) + * + * @param next - The target state to transition to + * @throws {Error} If attempting to transition from 'closed' state or invalid transition + */ + #transition(next: 'idle' | 'running' | 'closed'): void { + if (this.#state === next) { + return; + } + if (this.#state === 'closed') { + throw new Error('Profiler already closed'); + } + + const transition = `${this.#state}->${next}`; + + switch (transition) { + case 'idle->running': + super.setEnabled(true); + this.#sink.open?.(); + this.#performanceObserverSink.subscribe(); + break; + + case 'running->idle': + case 'running->closed': + super.setEnabled(false); + this.#performanceObserverSink.unsubscribe(); + this.#sink.close?.(); + break; + + case 'idle->closed': + // Sink may have been opened before, close it + this.#sink.close?.(); + break; + + default: + throw new Error(`Invalid transition: ${this.#state} -> ${next}`); + } + + this.#state = next; + + if (this.#debug) { + this.#transitionMarker(transition); + } + } + + /** + * Closes profiler and releases resources. Idempotent, safe for exit handlers. + * **Exit Handler Usage**: Call only this method from process exit handlers. + */ + close(): void { + if (this.#state === 'closed') { + return; + } + this.#unsubscribeExitHandlers?.(); + this.#transition('closed'); + } + + /** @returns Current profiler state */ + get state(): 'idle' | 'running' | 'closed' { + return this.#state; + } + + /** @returns Whether profiler is in 'running' state */ + override isEnabled(): boolean { + return this.#state === 'running'; + } + + /** Enables profiling (start/stop) */ + override setEnabled(enabled: boolean): void { + if (enabled) { + this.#transition('running'); + } else { + this.#transition('idle'); + } + } + + /** @returns Queue statistics and profiling state for monitoring */ + get stats() { + return { + ...this.#performanceObserverSink.getStats(), + debug: this.#debug, + state: this.#state, + walOpen: !this.#sink.isClosed(), + }; + } + + /** Flushes buffered performance data to sink. */ + flush(): void { + if (this.#state === 'closed') { + return; // No-op if closed + } + this.#performanceObserverSink.flush(); + } + + /** @returns The file path of the WriteAheadLogFile sink */ + get filePath(): string { + return (this.#sink as WriteAheadLogFile).getPath(); + } +} diff --git a/packages/utils/src/lib/profiler/profiler-node.unit.test.ts b/packages/utils/src/lib/profiler/profiler-node.unit.test.ts new file mode 100644 index 000000000..5357adc37 --- /dev/null +++ b/packages/utils/src/lib/profiler/profiler-node.unit.test.ts @@ -0,0 +1,894 @@ +import path from 'node:path'; +import { performance } from 'node:perf_hooks'; +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { MockTraceEventFileSink } from '../../../mocks/sink.mock'; +import { subscribeProcessExit } from '../exit-process.js'; +import * as PerfObserverModule from '../performance-observer.js'; +import type { PerformanceEntryEncoder } from '../performance-observer.js'; +import type { + ActionTrackEntryPayload, + UserTimingDetail, +} from '../user-timing-extensibility-api.type.js'; +import * as WalModule from '../wal.js'; +import { NodejsProfiler, type NodejsProfilerOptions } from './profiler-node.js'; +import { Profiler } from './profiler.js'; + +vi.mock('../exit-process.js'); + +const simpleEncoder: PerformanceEntryEncoder = entry => { + if (entry.entryType === 'measure') { + return [`${entry.name}:${entry.duration.toFixed(2)}ms`]; + } + return []; +}; + +describe('NodejsProfiler', () => { + const getNodejsProfiler = ( + overrides?: Partial< + NodejsProfilerOptions> + >, + ) => { + const sink = new MockTraceEventFileSink(); + const mockFilePath = + overrides?.filename ?? + '/test/tmp/profiles/20240101-120000-000/trace.20240101-120000-000.12345.1.1.jsonl'; + vi.spyOn(sink, 'open'); + vi.spyOn(sink, 'close'); + vi.spyOn(sink, 'getPath').mockReturnValue(mockFilePath); + + // Mock WriteAheadLogFile constructor to return our mock sink + vi.spyOn(WalModule, 'WriteAheadLogFile').mockImplementation( + () => sink as any, + ); + + const mockPerfObserverSink = { + subscribe: vi.fn(), + unsubscribe: vi.fn(() => { + mockPerfObserverSink.flush(); + }), + isSubscribed: vi.fn().mockReturnValue(false), + encode: vi.fn(), + flush: vi.fn(), + getStats: vi.fn().mockReturnValue({ + isSubscribed: false, + queued: 0, + dropped: 0, + written: 0, + maxQueueSize: 10_000, + flushThreshold: 20, + addedSinceLastFlush: 0, + buffered: true, + }), + }; + vi.spyOn(PerfObserverModule, 'PerformanceObserverSink').mockReturnValue( + mockPerfObserverSink as any, + ); + + const profiler = new NodejsProfiler({ + prefix: 'test', + track: 'test-track', + encodePerfEntry: simpleEncoder, + ...overrides, + }); + + return { sink, perfObserverSink: mockPerfObserverSink, profiler }; + }; + + const originalEnv = process.env.CP_PROFILER_DEBUG; + + beforeEach(() => { + performance.clearMarks(); + performance.clearMeasures(); + // eslint-disable-next-line functional/immutable-data + delete process.env.CP_PROFILER_DEBUG; + // eslint-disable-next-line functional/immutable-data + delete process.env.CP_PROFILING; + }); + + afterEach(() => { + if (originalEnv === undefined) { + // eslint-disable-next-line functional/immutable-data + delete process.env.CP_PROFILER_DEBUG; + } else { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = originalEnv; + } + }); + + describe('initialization', () => { + it('should export NodejsProfiler class', () => { + expect(typeof NodejsProfiler).toBe('function'); + }); + + it('should have required static structure', () => { + const profiler = getNodejsProfiler().profiler; + expect(typeof profiler.measure).toBe('function'); + expect(typeof profiler.measureAsync).toBe('function'); + expect(typeof profiler.marker).toBe('function'); + expect(typeof profiler.close).toBe('function'); + expect(typeof profiler.state).toBe('string'); + expect(typeof profiler.setEnabled).toBe('function'); + }); + + it('should inherit from Profiler', () => { + expect(Object.getPrototypeOf(NodejsProfiler.prototype)).toBe( + Profiler.prototype, + ); + }); + + it('should initialize with sink opened when enabled is true', () => { + const { sink, perfObserverSink } = getNodejsProfiler({ enabled: true }); + expect(sink.isClosed()).toBe(false); + expect(sink.open).toHaveBeenCalledTimes(1); + expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); + }); + + it('should initialize with sink closed when enabled is false', () => { + const { sink, perfObserverSink } = getNodejsProfiler({ enabled: false }); + expect(sink.isClosed()).toBe(true); + expect(sink.open).not.toHaveBeenCalled(); + expect(perfObserverSink.subscribe).not.toHaveBeenCalled(); + }); + }); + + describe('state management', () => { + it.each([ + { + name: 'idle → running', + initial: false, + action: ( + p: NodejsProfiler>, + ) => p.setEnabled(true), + expected: { + state: 'running', + sinkOpen: 1, + sinkClose: 0, + subscribe: 1, + unsubscribe: 0, + }, + }, + { + name: 'running → idle', + initial: true, + action: ( + p: NodejsProfiler>, + ) => p.setEnabled(false), + expected: { + state: 'idle', + sinkOpen: 1, + sinkClose: 1, + subscribe: 1, + unsubscribe: 1, + }, + }, + { + name: 'idle → closed', + initial: false, + action: ( + p: NodejsProfiler>, + ) => p.close(), + expected: { + state: 'closed', + sinkOpen: 0, + sinkClose: 1, + subscribe: 0, + unsubscribe: 0, + }, + }, + { + name: 'running → closed', + initial: true, + action: ( + p: NodejsProfiler>, + ) => p.close(), + expected: { + state: 'closed', + sinkOpen: 1, + sinkClose: 1, + subscribe: 1, + unsubscribe: 1, + }, + }, + ])('should handle $name transition', ({ initial, action, expected }) => { + const { sink, perfObserverSink, profiler } = getNodejsProfiler({ + enabled: initial, + }); + + action(profiler); + + expect(profiler.state).toBe(expected.state); + expect(sink.open).toHaveBeenCalledTimes(expected.sinkOpen); + expect(sink.close).toHaveBeenCalledTimes(expected.sinkClose); + expect(perfObserverSink.subscribe).toHaveBeenCalledTimes( + expected.subscribe, + ); + expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes( + expected.unsubscribe, + ); + }); + + it('should expose state via getter', () => { + const profiler = getNodejsProfiler({ enabled: false }).profiler; + + expect(profiler.state).toBe('idle'); + + profiler.setEnabled(true); + expect(profiler.state).toBe('running'); + + profiler.setEnabled(false); + expect(profiler.state).toBe('idle'); + + profiler.close(); + expect(profiler.state).toBe('closed'); + }); + + it('should maintain state invariant: running ⇒ sink open + observer subscribed', () => { + const { sink, perfObserverSink, profiler } = getNodejsProfiler({ + enabled: false, + }); + + expect(profiler.state).toBe('idle'); + expect(sink.isClosed()).toBe(true); + expect(perfObserverSink.isSubscribed()).toBe(false); + + profiler.setEnabled(true); + expect(profiler.state).toBe('running'); + expect(sink.isClosed()).toBe(false); + expect(sink.open).toHaveBeenCalledTimes(1); + expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); + + profiler.setEnabled(false); + expect(profiler.state).toBe('idle'); + expect(sink.isClosed()).toBe(true); + expect(sink.close).toHaveBeenCalledTimes(1); + expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); + + profiler.setEnabled(true); + expect(profiler.state).toBe('running'); + expect(sink.isClosed()).toBe(false); + expect(sink.open).toHaveBeenCalledTimes(2); + expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(2); + }); + + it('#transition method should execute all operations in running->closed case', () => { + const { sink, perfObserverSink, profiler } = getNodejsProfiler({ + enabled: true, + }); + + const parentSetEnabledSpy = vi.spyOn(Profiler.prototype, 'setEnabled'); + + expect(profiler.state).toBe('running'); + + profiler.close(); + + expect(parentSetEnabledSpy).toHaveBeenCalledWith(false); + expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); + expect(sink.close).toHaveBeenCalledTimes(1); + expect(profiler.state).toBe('closed'); + + parentSetEnabledSpy.mockRestore(); + }); + + it('is idempotent for repeated operations', () => { + const { sink, perfObserverSink, profiler } = getNodejsProfiler({ + enabled: true, + }); + + profiler.setEnabled(true); + profiler.setEnabled(true); + profiler.flush(); + profiler.flush(); + profiler.close(); + profiler.close(); + + expect(sink.open).toHaveBeenCalledTimes(1); + expect(sink.close).toHaveBeenCalledTimes(1); + expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); + expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); + }); + + it('rejects all lifecycle changes after close', () => { + const { perfObserverSink, profiler } = getNodejsProfiler({ + enabled: false, + }); + + profiler.close(); + + expect(() => profiler.setEnabled(true)).toThrow( + 'Profiler already closed', + ); + expect(() => profiler.setEnabled(false)).toThrow( + 'Profiler already closed', + ); + + profiler.flush(); + expect(perfObserverSink.flush).not.toHaveBeenCalled(); + }); + + it('throws error for invalid state transition (defensive code)', () => { + const profiler = getNodejsProfiler({ enabled: true }).profiler; + + expect(profiler.state).toBe('running'); + + // Test invalid transition through public API - trying to transition to an invalid state + // Since we can't access private methods, we test that the profiler maintains valid state + // Invalid transitions are prevented by the type system and runtime checks + expect(() => { + // This should not throw since we're using the public API correctly + profiler.setEnabled(false); + profiler.setEnabled(true); + }).not.toThrow(); + }); + }); + + describe('profiling operations', () => { + it('should expose filePath getter', () => { + const { profiler } = getNodejsProfiler({ enabled: true }); + expect(profiler.filePath).toMatchPath( + '/test/tmp/profiles/20240101-120000-000/trace.20240101-120000-000.12345.1.1.jsonl', + ); + }); + + it('should use provided filename when specified', () => { + const customPath = path.join(process.cwd(), 'custom-trace.json'); + const { profiler } = getNodejsProfiler({ + filename: customPath, + }); + expect(profiler.filePath).toBe(customPath); + }); + + it('should use sharded path when filename is not provided', () => { + const { profiler } = getNodejsProfiler(); + const filePath = profiler.filePath; + expect(filePath).toMatchPath( + '/test/tmp/profiles/20240101-120000-000/trace.20240101-120000-000.12345.1.1.jsonl', + ); + }); + + it('should perform measurements when enabled', () => { + const { profiler } = getNodejsProfiler({ enabled: true }); + + const result = profiler.measure('test-op', () => 'success'); + expect(result).toBe('success'); + }); + + it('should skip sink operations when disabled', () => { + const { sink, profiler } = getNodejsProfiler({ enabled: false }); + + const result = profiler.measure('disabled-op', () => 'success'); + expect(result).toBe('success'); + + expect(sink.getWrittenItems()).toHaveLength(0); + }); + + it('get stats() getter should return current stats', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + + expect(profiler.stats).toStrictEqual({ + state: 'idle', + walOpen: false, + isSubscribed: false, + queued: 0, + dropped: 0, + written: 0, + maxQueueSize: 10_000, + flushThreshold: 20, + addedSinceLastFlush: 0, + buffered: true, + debug: false, + }); + }); + + it('flush() should flush when profiler is running', () => { + const { perfObserverSink, profiler } = getNodejsProfiler({ + enabled: true, + }); + + expect(profiler.state).toBe('running'); + + profiler.flush(); + + expect(perfObserverSink.flush).toHaveBeenCalledTimes(1); + }); + + it('should propagate errors from measure work function', () => { + const { profiler } = getNodejsProfiler({ enabled: true }); + + const error = new Error('Test error'); + expect(() => { + profiler.measure('error-test', () => { + throw error; + }); + }).toThrow(error); + }); + + it('should propagate errors from measureAsync work function', async () => { + const { profiler } = getNodejsProfiler({ enabled: true }); + + const error = new Error('Async test error'); + await expect(async () => { + await profiler.measureAsync('async-error-test', async () => { + throw error; + }); + }).rejects.toThrow(error); + }); + + it('should skip measurement when profiler is not active', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + + let workCalled = false; + const result = profiler.measure('inactive-test', () => { + workCalled = true; + return 'result'; + }); + + expect(workCalled).toBe(true); + expect(result).toBe('result'); + }); + + it('should skip async measurement when profiler is not active', async () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + + let workCalled = false; + const result = await profiler.measureAsync( + 'inactive-async-test', + async () => { + workCalled = true; + return 'async-result'; + }, + ); + + expect(workCalled).toBe(true); + expect(result).toBe('async-result'); + }); + + it('should skip marker when profiler is not active', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + + expect(() => { + profiler.marker('inactive-marker'); + }).not.toThrow(); + }); + + it('base Profiler behavior: should always be active in base profiler', () => { + // eslint-disable-next-line functional/immutable-data + delete process.env.CP_PROFILING; + const profiler = new Profiler({ + prefix: 'cp', + track: 'test-track', + }); + + expect(profiler.isEnabled()).toBe(false); + + let workCalled = false; + const result = profiler.measure('base-test', () => { + workCalled = true; + return 'base-result'; + }); + + expect(workCalled).toBe(true); + expect(result).toBe('base-result'); + + expect(() => { + profiler.marker('base-marker'); + }).not.toThrow(); + }); + }); + + describe('debug mode', () => { + it('should initialize debug flag to false when env var not set', () => { + const { profiler } = getNodejsProfiler(); + + const stats = profiler.stats; + expect(stats.debug).toBe(false); + }); + + it('should initialize debug flag from CP_PROFILER_DEBUG env var when set', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + + const { profiler } = getNodejsProfiler(); + + const stats = profiler.stats; + expect(stats.debug).toBe(true); + }); + + it('should expose debug flag via getter', () => { + const { profiler } = getNodejsProfiler(); + expect(profiler.debug).toBe(false); + + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler: debugProfiler } = getNodejsProfiler(); + expect(debugProfiler.debug).toBe(true); + }); + + it('should create transition marker when debug is enabled and transitioning to running', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler } = getNodejsProfiler({ enabled: false }); + + performance.clearMarks(); + + profiler.setEnabled(true); + + const marks = performance.getEntriesByType('mark'); + const transitionMark = marks.find(mark => mark.name === 'idle->running'); + expect(transitionMark).toBeDefined(); + expect(transitionMark?.name).toBe('idle->running'); + }); + + it('should not create transition marker when transitioning from running to idle (profiler disabled)', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler } = getNodejsProfiler({ enabled: true }); + + performance.clearMarks(); + + profiler.setEnabled(false); + + const marks = performance.getEntriesByType('mark'); + const transitionMark = marks.find(mark => mark.name === 'running->idle'); + expect(transitionMark).toBeUndefined(); + }); + + it('does not emit transition markers unless debug is enabled', () => { + const { profiler } = getNodejsProfiler(); + + performance.clearMarks(); + + profiler.setEnabled(true); + + expect( + performance + .getEntriesByType('mark') + .some(m => m.name.startsWith('idle->running')), + ).toBe(false); + }); + + it('should include stats in transition marker properties when transitioning to running', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler, perfObserverSink } = getNodejsProfiler({ + enabled: false, + }); + + perfObserverSink.getStats.mockReturnValue({ + isSubscribed: true, + queued: 5, + dropped: 2, + written: 10, + maxQueueSize: 10_000, + flushThreshold: 20, + addedSinceLastFlush: 3, + buffered: true, + }); + + performance.clearMarks(); + + profiler.setEnabled(true); + + const marks = performance.getEntriesByType('mark'); + const transitionMark = marks.find(mark => mark.name === 'idle->running'); + expect(transitionMark).toBeDefined(); + + expect(transitionMark?.name).toBe('idle->running'); + expect(transitionMark?.detail).toBeDefined(); + const detail = transitionMark?.detail as UserTimingDetail; + expect(detail.devtools).toBeDefined(); + expect(detail.devtools?.dataType).toBe('marker'); + expect(detail.devtools?.properties).toBeDefined(); + }); + + // eslint-disable-next-line vitest/max-nested-describe + describe('setDebugMode', () => { + it('should enable debug mode when called with true', () => { + const { profiler } = getNodejsProfiler(); + expect(profiler.debug).toBe(false); + + profiler.setDebugMode(true); + + expect(profiler.debug).toBe(true); + expect(profiler.stats.debug).toBe(true); + }); + + it('should disable debug mode when called with false', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler } = getNodejsProfiler(); + expect(profiler.debug).toBe(true); + + profiler.setDebugMode(false); + + expect(profiler.debug).toBe(false); + expect(profiler.stats.debug).toBe(false); + }); + + it('should create transition markers after enabling debug mode', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + expect(profiler.debug).toBe(false); + + performance.clearMarks(); + profiler.setEnabled(true); + expect( + performance + .getEntriesByType('mark') + .some(m => m.name.startsWith('idle->running')), + ).toBe(false); + + profiler.setEnabled(false); + profiler.setDebugMode(true); + performance.clearMarks(); + + profiler.setEnabled(true); + + const marks = performance.getEntriesByType('mark'); + const transitionMark = marks.find( + mark => mark.name === 'idle->running', + ); + expect(transitionMark).toBeDefined(); + expect(transitionMark?.name).toBe('idle->running'); + }); + + it('should stop creating transition markers after disabling debug mode', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler } = getNodejsProfiler({ enabled: false }); + expect(profiler.debug).toBe(true); + + profiler.setDebugMode(false); + performance.clearMarks(); + + profiler.setEnabled(true); + + expect( + performance + .getEntriesByType('mark') + .some(m => m.name.startsWith('idle->running')), + ).toBe(false); + }); + + it('should be idempotent when called multiple times with true', () => { + const { profiler } = getNodejsProfiler(); + expect(profiler.debug).toBe(false); + + profiler.setDebugMode(true); + profiler.setDebugMode(true); + profiler.setDebugMode(true); + + expect(profiler.debug).toBe(true); + expect(profiler.stats.debug).toBe(true); + }); + + it('should be idempotent when called multiple times with false', () => { + // eslint-disable-next-line functional/immutable-data + process.env.CP_PROFILER_DEBUG = 'true'; + const { profiler } = getNodejsProfiler(); + expect(profiler.debug).toBe(true); + + profiler.setDebugMode(false); + profiler.setDebugMode(false); + profiler.setDebugMode(false); + + expect(profiler.debug).toBe(false); + expect(profiler.stats.debug).toBe(false); + }); + + it('should work when profiler is in idle state', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + expect(profiler.state).toBe('idle'); + expect(profiler.debug).toBe(false); + + profiler.setDebugMode(true); + expect(profiler.debug).toBe(true); + expect(profiler.stats.debug).toBe(true); + }); + + it('should work when profiler is in running state', () => { + const { profiler } = getNodejsProfiler({ enabled: true }); + expect(profiler.state).toBe('running'); + expect(profiler.debug).toBe(false); + + profiler.setDebugMode(true); + expect(profiler.debug).toBe(true); + expect(profiler.stats.debug).toBe(true); + + performance.clearMarks(); + profiler.setEnabled(false); + profiler.setEnabled(true); + + const marks = performance.getEntriesByType('mark'); + const transitionMark = marks.find( + mark => mark.name === 'idle->running', + ); + expect(transitionMark).toBeDefined(); + }); + + it('should work when profiler is in closed state', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + profiler.close(); + expect(profiler.state).toBe('closed'); + expect(profiler.debug).toBe(false); + + profiler.setDebugMode(true); + expect(profiler.debug).toBe(true); + expect(profiler.stats.debug).toBe(true); + }); + + it('should toggle debug mode multiple times', () => { + const { profiler } = getNodejsProfiler({ enabled: false }); + + profiler.setDebugMode(true); + expect(profiler.debug).toBe(true); + + profiler.setDebugMode(false); + expect(profiler.debug).toBe(false); + + profiler.setDebugMode(true); + expect(profiler.debug).toBe(true); + + profiler.setDebugMode(false); + expect(profiler.debug).toBe(false); + }); + }); + }); + + describe('exit handlers', () => { + const mockSubscribeProcessExit = vi.mocked(subscribeProcessExit); + + let capturedOnError: + | (( + error: unknown, + kind: 'uncaughtException' | 'unhandledRejection', + ) => void) + | undefined; + let capturedOnExit: + | (( + code: number, + reason: import('../exit-process.js').CloseReason, + ) => void) + | undefined; + const createProfiler = ( + overrides?: Partial< + NodejsProfilerOptions> + >, + ) => { + const sink = new MockTraceEventFileSink(); + vi.spyOn(sink, 'open'); + vi.spyOn(sink, 'close'); + vi.spyOn(WalModule, 'WriteAheadLogFile').mockImplementation( + () => sink as any, + ); + return new NodejsProfiler({ + prefix: 'cp', + track: 'test-track', + encodePerfEntry: simpleEncoder, + ...overrides, + }); + }; + + let profiler: NodejsProfiler< + string, + Record + >; + + beforeEach(() => { + capturedOnError = undefined; + capturedOnExit = undefined; + + mockSubscribeProcessExit.mockImplementation(options => { + capturedOnError = options?.onError; + capturedOnExit = options?.onExit; + return vi.fn(); + }); + + performance.clearMarks(); + performance.clearMeasures(); + // eslint-disable-next-line functional/immutable-data + delete process.env.CP_PROFILING; + }); + + it('installs exit handlers on construction', () => { + expect(() => createProfiler()).not.toThrow(); + + expect(mockSubscribeProcessExit).toHaveBeenCalledWith({ + onError: expect.any(Function), + onExit: expect.any(Function), + }); + }); + + it('setEnabled toggles profiler state', () => { + profiler = createProfiler({ enabled: true }); + expect(profiler.isEnabled()).toBe(true); + + profiler.setEnabled(false); + expect(profiler.isEnabled()).toBe(false); + + profiler.setEnabled(true); + expect(profiler.isEnabled()).toBe(true); + }); + + it('marks fatal errors and shuts down profiler on uncaughtException', () => { + profiler = createProfiler({ enabled: true }); + + const testError = new Error('Test fatal error'); + capturedOnError?.call(profiler, testError, 'uncaughtException'); + + expect(performance.getEntriesByType('mark')).toStrictEqual([ + { + name: 'Fatal Error', + detail: { + devtools: { + color: 'error', + dataType: 'marker', + tooltipText: 'uncaughtException caused fatal error', + properties: [ + ['Error Type', 'Error'], + ['Error Message', 'Test fatal error'], + ], + }, + }, + duration: 0, + entryType: 'mark', + startTime: 0, + }, + ]); + }); + + it('marks fatal errors and shuts down profiler on unhandledRejection', () => { + profiler = createProfiler({ enabled: true }); + expect(profiler.isEnabled()).toBe(true); + + capturedOnError?.call( + profiler, + new Error('Test fatal error'), + 'unhandledRejection', + ); + + expect(performance.getEntriesByType('mark')).toStrictEqual([ + { + name: 'Fatal Error', + detail: { + devtools: { + color: 'error', + dataType: 'marker', + tooltipText: 'unhandledRejection caused fatal error', + properties: [ + ['Error Type', 'Error'], + ['Error Message', 'Test fatal error'], + ], + }, + }, + duration: 0, + entryType: 'mark', + startTime: 0, + }, + ]); + }); + + it('exit handler shuts down profiler', () => { + profiler = createProfiler({ enabled: true }); + const closeSpy = vi.spyOn(profiler, 'close'); + expect(profiler.isEnabled()).toBe(true); + + capturedOnExit?.(0, { kind: 'exit' }); + + expect(profiler.isEnabled()).toBe(false); + expect(closeSpy).toHaveBeenCalledTimes(1); + }); + + it('close() unsubscribes from exit handlers even when disabled', () => { + const unsubscribeFn = vi.fn(); + mockSubscribeProcessExit.mockReturnValue(unsubscribeFn); + + profiler = createProfiler({ enabled: false }); + expect(profiler.isEnabled()).toBe(false); + expect(mockSubscribeProcessExit).toHaveBeenCalled(); + + profiler.close(); + + expect(unsubscribeFn).toHaveBeenCalledTimes(1); + expect(profiler.isEnabled()).toBe(false); + }); + }); +}); diff --git a/packages/utils/src/lib/profiler/profiler.int.test.ts b/packages/utils/src/lib/profiler/profiler.int.test.ts index 0e98dc329..1ee4763d6 100644 --- a/packages/utils/src/lib/profiler/profiler.int.test.ts +++ b/packages/utils/src/lib/profiler/profiler.int.test.ts @@ -1,7 +1,5 @@ -import { MockTraceEventFileSink } from '../../../mocks/sink.mock.js'; -import type { PerformanceEntryEncoder } from '../performance-observer.js'; import type { ActionTrackEntryPayload } from '../user-timing-extensibility-api.type.js'; -import { NodejsProfiler, Profiler } from './profiler.js'; +import { Profiler } from './profiler.js'; describe('Profiler Integration', () => { let profiler: Profiler>; @@ -297,169 +295,3 @@ describe('Profiler Integration', () => { expect(performance.getEntriesByType('measure')).toHaveLength(0); }); }); - -describe('NodeJS Profiler Integration', () => { - const simpleEncoder: PerformanceEntryEncoder = entry => { - if (entry.entryType === 'measure') { - return [`${entry.name}:${entry.duration.toFixed(2)}ms`]; - } - return []; - }; - - let mockSink: MockTraceEventFileSink; - let nodejsProfiler: NodejsProfiler; - - beforeEach(() => { - mockSink = new MockTraceEventFileSink(); - - nodejsProfiler = new NodejsProfiler({ - prefix: 'test', - track: 'test-track', - sink: mockSink, - encodePerfEntry: simpleEncoder, - enabled: true, - }); - }); - - it('should initialize with sink opened when enabled', () => { - expect(mockSink.isClosed()).toBeFalse(); - expect(nodejsProfiler.isEnabled()).toBeTrue(); - expect(mockSink.open).toHaveBeenCalledOnce(); - }); - - it('should create performance entries and write to sink', () => { - expect(nodejsProfiler.measure('test-operation', () => 'success')).toBe( - 'success', - ); - }); - - it('should handle async operations', async () => { - await expect( - nodejsProfiler.measureAsync('async-test', async () => { - await new Promise(resolve => setTimeout(resolve, 1)); - return 'async-result'; - }), - ).resolves.toBe('async-result'); - }); - - it('should disable profiling and close sink', () => { - nodejsProfiler.setEnabled(false); - expect(nodejsProfiler.isEnabled()).toBeFalse(); - expect(mockSink.isClosed()).toBeTrue(); - expect(mockSink.close).toHaveBeenCalledOnce(); - - expect(nodejsProfiler.measure('disabled-test', () => 'success')).toBe( - 'success', - ); - - expect(mockSink.getWrittenItems()).toHaveLength(0); - }); - - it('should re-enable profiling correctly', () => { - nodejsProfiler.setEnabled(false); - nodejsProfiler.setEnabled(true); - - expect(nodejsProfiler.isEnabled()).toBeTrue(); - expect(mockSink.isClosed()).toBeFalse(); - expect(mockSink.open).toHaveBeenCalledTimes(2); - - expect(nodejsProfiler.measure('re-enabled-test', () => 42)).toBe(42); - }); - - it('should support custom tracks', () => { - const profilerWithTracks = new NodejsProfiler({ - prefix: 'api-server', - track: 'HTTP', - tracks: { - db: { track: 'Database', color: 'secondary' }, - cache: { track: 'Cache', color: 'primary' }, - }, - sink: mockSink, - encodePerfEntry: simpleEncoder, - }); - - expect( - profilerWithTracks.measure('user-lookup', () => 'user123', { - track: 'cache', - }), - ).toBe('user123'); - }); - - it('should capture buffered entries when buffered option is enabled', () => { - const bufferedProfiler = new NodejsProfiler({ - prefix: 'buffered-test', - track: 'Test', - sink: mockSink, - encodePerfEntry: simpleEncoder, - captureBufferedEntries: true, - enabled: true, - }); - - const bufferedStats = bufferedProfiler.stats; - expect(bufferedStats.state).toBe('running'); - expect(bufferedStats.walOpen).toBeTrue(); - expect(bufferedStats.isSubscribed).toBeTrue(); - expect(bufferedStats.queued).toBe(0); - expect(bufferedStats.dropped).toBe(0); - expect(bufferedStats.written).toBe(0); - - bufferedProfiler.setEnabled(false); - }); - - it('should return correct getStats with dropped and written counts', () => { - const statsProfiler = new NodejsProfiler({ - prefix: 'stats-test', - track: 'Stats', - sink: mockSink, - encodePerfEntry: simpleEncoder, - maxQueueSize: 2, - flushThreshold: 2, - enabled: true, - }); - - expect(statsProfiler.measure('test-op', () => 'result')).toBe('result'); - - const stats = statsProfiler.stats; - expect(stats.state).toBe('running'); - expect(stats.walOpen).toBeTrue(); - expect(stats.isSubscribed).toBeTrue(); - expect(typeof stats.queued).toBe('number'); - expect(typeof stats.dropped).toBe('number'); - expect(typeof stats.written).toBe('number'); - - statsProfiler.setEnabled(false); - }); - - it('should provide comprehensive queue statistics via getStats', () => { - const profiler = new NodejsProfiler({ - prefix: 'stats-profiler', - track: 'Stats', - sink: mockSink, - encodePerfEntry: simpleEncoder, - maxQueueSize: 3, - flushThreshold: 2, - enabled: true, - }); - - const initialStats = profiler.stats; - expect(initialStats.state).toBe('running'); - expect(initialStats.walOpen).toBeTrue(); - expect(initialStats.isSubscribed).toBeTrue(); - expect(initialStats.queued).toBe(0); - expect(initialStats.dropped).toBe(0); - expect(initialStats.written).toBe(0); - - profiler.measure('operation-1', () => 'result1'); - profiler.measure('operation-2', () => 'result2'); - profiler.flush(); - expect(profiler.stats.written).toBe(0); - - profiler.setEnabled(false); - - const finalStats = profiler.stats; - expect(finalStats.state).toBe('idle'); - expect(finalStats.walOpen).toBeFalse(); - expect(finalStats.isSubscribed).toBeFalse(); - expect(finalStats.queued).toBe(0); - }); -}); diff --git a/packages/utils/src/lib/profiler/profiler.ts b/packages/utils/src/lib/profiler/profiler.ts index 5d5910625..e2b2f3b88 100644 --- a/packages/utils/src/lib/profiler/profiler.ts +++ b/packages/utils/src/lib/profiler/profiler.ts @@ -2,11 +2,6 @@ import { performance } from 'node:perf_hooks'; import process from 'node:process'; import { threadId } from 'node:worker_threads'; import { isEnvVarEnabled } from '../env.js'; -import { - type PerformanceObserverOptions, - PerformanceObserverSink, -} from '../performance-observer.js'; -import { objectToEntries } from '../transform.js'; import { type ActionTrackConfigs, type MeasureCtxOptions, @@ -20,13 +15,8 @@ import type { ActionTrackEntryPayload, DevToolsColor, EntryMeta, - MarkerPayload, } from '../user-timing-extensibility-api.type.js'; -import type { AppendableSink } from '../wal.js'; -import { - PROFILER_DEBUG_ENV_VAR, - PROFILER_ENABLED_ENV_VAR, -} from './constants.js'; +import { PROFILER_ENABLED_ENV_VAR } from './constants.js'; /** * Generates a unique profiler ID based on performance time origin, process ID, thread ID, and instance count. @@ -248,203 +238,3 @@ export class Profiler { } } } - -/** - * Options for configuring a NodejsProfiler instance. - * - * Extends ProfilerOptions with a required sink parameter. - * - * @template Tracks - Record type defining available track names and their configurations - */ -export type NodejsProfilerOptions< - DomainEvents, - Tracks extends Record, -> = ProfilerOptions & - Omit, 'sink'> & { - /** - * Sink for buffering and flushing performance data - */ - sink: AppendableSink; - - /** - * Name of the environment variable to check for debug mode. - * When the env var is set to 'true', profiler state transitions create performance marks for debugging. - * - * @default 'CP_PROFILER_DEBUG' - */ - debugEnvVar?: string; - }; - -/** - * Performance profiler with automatic process exit handling for buffered performance data. - * - * This class extends the base {@link Profiler} with automatic flushing of performance data - * when the process exits. It accepts a {@link PerformanceObserverSink} that buffers performance - * entries and ensures they are written out during process termination, even for unexpected exits. - * - * The sink defines the output format for performance data, enabling flexible serialization - * to various formats such as DevTools TraceEvent JSON, OpenTelemetry protocol buffers, - * or custom domain-specific formats. - * - * The profiler automatically subscribes to the performance observer when enabled and installs - * exit handlers that flush buffered data on process termination (signals, fatal errors, or normal exit). - * - */ -export class NodejsProfiler< - DomainEvents, - Tracks extends Record = Record< - string, - ActionTrackEntryPayload - >, -> extends Profiler { - #sink: AppendableSink; - #performanceObserverSink: PerformanceObserverSink; - #state: 'idle' | 'running' | 'closed' = 'idle'; - #debug: boolean; - - /** - * Creates a NodejsProfiler instance. - * @param options - Configuration with required sink - */ - constructor(options: NodejsProfilerOptions) { - const { - sink, - encodePerfEntry, - captureBufferedEntries, - flushThreshold, - maxQueueSize, - enabled, - debugEnvVar = PROFILER_DEBUG_ENV_VAR, - ...profilerOptions - } = options; - const initialEnabled = enabled ?? isEnvVarEnabled(PROFILER_ENABLED_ENV_VAR); - super({ ...profilerOptions, enabled: initialEnabled }); - - this.#sink = sink; - this.#debug = isEnvVarEnabled(debugEnvVar); - - this.#performanceObserverSink = new PerformanceObserverSink({ - sink, - encodePerfEntry, - captureBufferedEntries, - flushThreshold, - maxQueueSize, - debugEnvVar, - }); - - if (initialEnabled) { - this.#transition('running'); - } - } - - /** - * Returns whether debug mode is enabled for profiler state transitions. - * - * Debug mode is determined by the environment variable specified by `debugEnvVar` - * (defaults to 'CP_PROFILER_DEBUG'). When enabled, profiler state transitions create - * performance marks for debugging. - * - * @returns true if debug mode is enabled, false otherwise - */ - get debug(): boolean { - return this.#debug; - } - - /** - * Creates a performance marker for a profiler state transition. - * @param transition - The state transition that occurred - */ - #transitionMarker(transition: string): void { - const transitionMarkerPayload: MarkerPayload = { - dataType: 'marker', - color: 'primary', - tooltipText: `Profiler state transition: ${transition}`, - properties: [['Transition', transition], ...objectToEntries(this.stats)], - }; - this.marker(transition, transitionMarkerPayload); - } - - #transition(next: 'idle' | 'running' | 'closed'): void { - if (this.#state === next) { - return; - } - if (this.#state === 'closed') { - throw new Error('Profiler already closed'); - } - - const transition = `${this.#state}->${next}`; - - switch (transition) { - case 'idle->running': - super.setEnabled(true); - this.#sink.open?.(); - this.#performanceObserverSink.subscribe(); - break; - - case 'running->idle': - case 'running->closed': - super.setEnabled(false); - this.#performanceObserverSink.unsubscribe(); - this.#sink.close?.(); - break; - - case 'idle->closed': - // No-op, was not open - break; - - default: - throw new Error(`Invalid transition: ${this.#state} -> ${next}`); - } - - this.#state = next; - - if (this.#debug) { - this.#transitionMarker(transition); - } - } - - /** - * Closes profiler and releases resources. Idempotent, safe for exit handlers. - * **Exit Handler Usage**: Call only this method from process exit handlers. - */ - close(): void { - this.#transition('closed'); - } - - /** @returns Current profiler state */ - get state(): 'idle' | 'running' | 'closed' { - return this.#state; - } - - /** @returns Whether profiler is in 'running' state */ - override isEnabled(): boolean { - return this.#state === 'running'; - } - - /** Enables profiling (start/stop) */ - override setEnabled(enabled: boolean): void { - if (enabled) { - this.#transition('running'); - } else { - this.#transition('idle'); - } - } - - /** @returns Queue statistics and profiling state for monitoring */ - get stats() { - return { - ...this.#performanceObserverSink.getStats(), - debug: this.#debug, - state: this.#state, - walOpen: !this.#sink.isClosed(), - }; - } - - /** Flushes buffered performance data to sink. */ - flush(): void { - if (this.#state === 'closed') { - return; // No-op if closed - } - this.#performanceObserverSink.flush(); - } -} diff --git a/packages/utils/src/lib/profiler/profiler.unit.test.ts b/packages/utils/src/lib/profiler/profiler.unit.test.ts index bd1661ffd..bf047e3fa 100644 --- a/packages/utils/src/lib/profiler/profiler.unit.test.ts +++ b/packages/utils/src/lib/profiler/profiler.unit.test.ts @@ -1,20 +1,10 @@ import { performance } from 'node:perf_hooks'; import { threadId } from 'node:worker_threads'; import { beforeEach, describe, expect, it, vi } from 'vitest'; -import { MockTraceEventFileSink } from '../../../mocks/sink.mock.js'; -import type { PerformanceEntryEncoder } from '../performance-observer.js'; -import * as PerfObserverModule from '../performance-observer.js'; -import type { - ActionTrackEntryPayload, - UserTimingDetail, -} from '../user-timing-extensibility-api.type.js'; -import { - NodejsProfiler, - type NodejsProfilerOptions, - Profiler, - type ProfilerOptions, - getProfilerId, -} from './profiler.js'; +import type { ActionTrackEntryPayload } from '../user-timing-extensibility-api.type.js'; +import { Profiler, type ProfilerOptions, getProfilerId } from './profiler.js'; + +vi.mock('../exit-process.js'); describe('getProfilerId', () => { it('should generate a unique id per process', () => { @@ -477,897 +467,3 @@ describe('Profiler', () => { ); }); }); - -const simpleEncoder: PerformanceEntryEncoder = entry => { - if (entry.entryType === 'measure') { - return [`${entry.name}:${entry.duration.toFixed(2)}ms`]; - } - return []; -}; - -describe('NodejsProfiler', () => { - const getNodejsProfiler = ( - overrides?: Partial< - NodejsProfilerOptions> - >, - ) => { - const sink = new MockTraceEventFileSink(); - - const mockPerfObserverSink = { - subscribe: vi.fn(), - unsubscribe: vi.fn(() => { - mockPerfObserverSink.flush(); - }), - isSubscribed: vi.fn().mockReturnValue(false), - encode: vi.fn(), - flush: vi.fn(), - getStats: vi.fn().mockReturnValue({ - isSubscribed: false, - queued: 0, - dropped: 0, - written: 0, - maxQueueSize: 10_000, - flushThreshold: 20, - addedSinceLastFlush: 0, - buffered: true, - }), - }; - vi.spyOn(PerfObserverModule, 'PerformanceObserverSink').mockReturnValue( - mockPerfObserverSink as any, - ); - - vi.spyOn(sink, 'open'); - vi.spyOn(sink, 'close'); - - const profiler = new NodejsProfiler({ - prefix: 'test', - track: 'test-track', - sink, - encodePerfEntry: simpleEncoder, - ...overrides, - }); - - return { sink, perfObserverSink: mockPerfObserverSink, profiler }; - }; - - const originalEnv = process.env.CP_PROFILER_DEBUG; - - beforeEach(() => { - performance.clearMarks(); - performance.clearMeasures(); - // eslint-disable-next-line functional/immutable-data - delete process.env.CP_PROFILER_DEBUG; - // eslint-disable-next-line functional/immutable-data - delete process.env.CP_PROFILING; - }); - - afterEach(() => { - if (originalEnv === undefined) { - // eslint-disable-next-line functional/immutable-data - delete process.env.CP_PROFILER_DEBUG; - } else { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = originalEnv; - } - }); - - it('should export NodejsProfiler class', () => { - expect(typeof NodejsProfiler).toBe('function'); - }); - - it('should have required static structure', () => { - const profiler = getNodejsProfiler().profiler; - expect(typeof profiler.measure).toBe('function'); - expect(typeof profiler.measureAsync).toBe('function'); - expect(typeof profiler.marker).toBe('function'); - expect(typeof profiler.close).toBe('function'); - expect(typeof profiler.state).toBe('string'); - expect(typeof profiler.setEnabled).toBe('function'); - }); - - it('should inherit from Profiler', () => { - expect(Object.getPrototypeOf(NodejsProfiler.prototype)).toBe( - Profiler.prototype, - ); - }); - - it('should initialize with sink opened when enabled is true', () => { - const { sink, perfObserverSink } = getNodejsProfiler({ enabled: true }); - expect(sink.isClosed()).toBe(false); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('should initialize with sink closed when enabled is false', () => { - const { sink, perfObserverSink } = getNodejsProfiler({ enabled: false }); - expect(sink.isClosed()).toBe(true); - expect(sink.open).not.toHaveBeenCalled(); - expect(perfObserverSink.subscribe).not.toHaveBeenCalled(); - }); - - it('should open sink and subscribe observer when enabling', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - profiler.setEnabled(true); - - expect(profiler.state).toBe('running'); - expect(sink.isClosed()).toBe(false); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('should close sink and unsubscribe observer when disabling', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - profiler.setEnabled(false); - - expect(profiler.isEnabled()).toBe(false); - expect(sink.isClosed()).toBe(true); - expect(sink.close).toHaveBeenCalledTimes(1); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - }); - - it('should be idempotent - no-op when setting same state', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - - profiler.setEnabled(true); - - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('should perform measurements when enabled', () => { - const { profiler } = getNodejsProfiler({ enabled: true }); - - const result = profiler.measure('test-op', () => 'success'); - expect(result).toBe('success'); - }); - - it('should skip sink operations when disabled', () => { - const { sink, profiler } = getNodejsProfiler({ enabled: false }); - - const result = profiler.measure('disabled-op', () => 'success'); - expect(result).toBe('success'); - - expect(sink.getWrittenItems()).toHaveLength(0); - }); - - it('should flush buffered performance data to sink', () => { - const { perfObserverSink, profiler } = getNodejsProfiler({ enabled: true }); - - profiler.flush(); - - expect(perfObserverSink.flush).toHaveBeenCalledTimes(1); - }); - - it('get stats() getter should return current stats', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - expect(profiler.stats).toStrictEqual({ - state: 'idle', - walOpen: false, - isSubscribed: false, - queued: 0, - dropped: 0, - written: 0, - maxQueueSize: 10_000, - flushThreshold: 20, - addedSinceLastFlush: 0, - buffered: true, - debug: false, - }); - }); - - it('state transitions: should handle full transition matrix: idle → running → idle → closed', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Initial state: idle - expect(sink.isClosed()).toBe(true); - expect(perfObserverSink.subscribe).not.toHaveBeenCalled(); - - // idle → running - profiler.setEnabled(true); - expect(profiler.state).toBe('running'); - expect(sink.isClosed()).toBe(false); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - - // running → idle - profiler.setEnabled(false); - expect(profiler.isEnabled()).toBe(false); - expect(sink.isClosed()).toBe(true); - expect(sink.close).toHaveBeenCalledTimes(1); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - - // idle → closed (terminal) - profiler.close(); - expect(sink.close).toHaveBeenCalledTimes(1); // No additional close since we're in idle - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); // No additional unsubscribe since we're in idle - expect(perfObserverSink.flush).toHaveBeenCalledTimes(1); // Flush was called during running->idle transition via unsubscribe - - // Verify closed state - operations should throw or be safe - expect(() => profiler.setEnabled(true)).toThrow('Profiler already closed'); - profiler.close(); // Should be idempotent - }); - - it('state transitions: should expose state via getter', () => { - const profiler = getNodejsProfiler({ enabled: false }).profiler; - - expect(profiler.state).toBe('idle'); - - profiler.setEnabled(true); - expect(profiler.state).toBe('running'); - - profiler.setEnabled(false); - expect(profiler.state).toBe('idle'); - - profiler.close(); - expect(profiler.state).toBe('closed'); - }); - - it('state transitions: should maintain state invariant: running ⇒ sink open + observer subscribed', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Initially idle - sink closed, observer not subscribed - expect(profiler.state).toBe('idle'); - expect(sink.isClosed()).toBe(true); - expect(perfObserverSink.isSubscribed()).toBe(false); - - // Enable - should open sink and subscribe observer - profiler.setEnabled(true); - expect(profiler.state).toBe('running'); - expect(sink.isClosed()).toBe(false); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - - // Disable - should close sink and unsubscribe observer - profiler.setEnabled(false); - expect(profiler.state).toBe('idle'); - expect(sink.close).toHaveBeenCalledTimes(1); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - - // Enable again - should open and subscribe again - profiler.setEnabled(true); - expect(profiler.state).toBe('running'); - expect(sink.isClosed()).toBe(false); - expect(sink.open).toHaveBeenCalledTimes(2); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(2); - }); - - it('state transitions: should handle running → closed transition', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Initial state: running - expect(profiler.state).toBe('running'); - - // running → closed - profiler.close(); - expect(perfObserverSink.flush).toHaveBeenCalledTimes(1); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - expect(sink.close).toHaveBeenCalledTimes(1); - }); - - it('state transitions: should prevent invalid transitions when closed', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - // idle → closed - profiler.close(); - - // Should throw for setEnabled(true) - expect(() => profiler.setEnabled(true)).toThrow('Profiler already closed'); - }); - - it('state transitions: should handle flush when closed (no-op)', () => { - const { perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Close profiler - profiler.close(); - - // flush should be no-op when closed - profiler.flush(); - expect(perfObserverSink.flush).not.toHaveBeenCalled(); - }); - - it('state transitions: should handle flush when running', () => { - const { perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Should flush when running - profiler.flush(); - expect(perfObserverSink.flush).toHaveBeenCalledTimes(1); - }); - - it('state transitions: should throw error when attempting to transition from closed state', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - // Close the profiler first - profiler.close(); - expect(profiler.state).toBe('closed'); - - // Attempting to enable from closed state should throw - expect(() => profiler.setEnabled(true)).toThrow('Profiler already closed'); - }); - - it('state transitions: should handle idle to closed transition without cleanup', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Ensure profiler is in idle state - expect(profiler.state).toBe('idle'); - expect(sink.isClosed()).toBe(true); - expect(perfObserverSink.subscribe).not.toHaveBeenCalled(); - - // Transition from idle to closed - profiler.close(); - - // Should change state to closed without any cleanup operations - expect(profiler.state).toBe('closed'); - expect(sink.close).not.toHaveBeenCalled(); - expect(perfObserverSink.unsubscribe).not.toHaveBeenCalled(); - }); - - it('state transitions: should handle running to closed transition with cleanup', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Ensure profiler is in running state - expect(profiler.state).toBe('running'); - expect(sink.isClosed()).toBe(false); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - - // Transition from running to closed - profiler.close(); - - // Should change state to closed and perform cleanup operations - expect(profiler.state).toBe('closed'); - expect(sink.close).toHaveBeenCalledTimes(1); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - }); - - it('state transitions: should close profiler and change state to closed', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - // Initially idle - expect(profiler.state).toBe('idle'); - - // Close should transition to closed - profiler.close(); - expect(profiler.state).toBe('closed'); - }); - - it('state transitions: should disable profiling when setEnabled(false) is called', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Initially running - expect(profiler.state).toBe('running'); - - // Call setEnabled(false) which should transition to idle - profiler.setEnabled(false); - - // Verify operations were performed - expect(profiler.state).toBe('idle'); - expect(sink.close).toHaveBeenCalledTimes(1); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - }); - - it('#transition method state transitions: should return early when transitioning to same state (idle->idle)', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Ensure profiler is in idle state - expect(profiler.state).toBe('idle'); - - // Try to transition to same state - should be no-op - profiler.setEnabled(true); // This calls transition('running') from idle - expect(profiler.state).toBe('running'); - - // Now try to transition to running again - should be no-op - profiler.setEnabled(true); // Should not change anything - - // Should still be running and operations should not be called again - expect(profiler.state).toBe('running'); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('#transition method state transitions: should return early when transitioning to same state (running->running)', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Ensure profiler is in running state - expect(profiler.state).toBe('running'); - - // Try to transition to same state - should be no-op - profiler.setEnabled(true); // Should be no-op - - // Should still be running and operations should not be called again - expect(profiler.state).toBe('running'); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('#transition method state transitions: should throw error when attempting to transition from closed state', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - // Close the profiler first - profiler.close(); - expect(profiler.state).toBe('closed'); - - // Attempting to enable from closed state should throw - expect(() => profiler.setEnabled(true)).toThrow('Profiler already closed'); - - // Attempting to disable from closed state should also throw (since setEnabled(false) calls transition('idle')) - expect(() => profiler.setEnabled(false)).toThrow('Profiler already closed'); - }); - - it('#transition method state transitions: should handle idle->running transition', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Enable from idle state - expect(profiler.state).toBe('idle'); - - profiler.setEnabled(true); - - expect(profiler.state).toBe('running'); - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('#transition method state transitions: should handle running->idle transition', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Disable from running state - expect(profiler.state).toBe('running'); - - profiler.setEnabled(false); - - expect(profiler.state).toBe('idle'); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - expect(sink.close).toHaveBeenCalledTimes(1); - }); - - it('#transition method state transitions: should handle idle->closed transition', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Close from idle state - expect(profiler.state).toBe('idle'); - - profiler.close(); - - expect(profiler.state).toBe('closed'); - // No cleanup operations should be called for idle->closed - expect(sink.close).not.toHaveBeenCalled(); - expect(perfObserverSink.unsubscribe).not.toHaveBeenCalled(); - }); - - it('#transition method state transitions: should handle running->closed transition', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Close from running state - expect(profiler.state).toBe('running'); - - profiler.close(); - - expect(profiler.state).toBe('closed'); - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - expect(sink.close).toHaveBeenCalledTimes(1); - }); - - it('#transition method state transitions: should execute all operations in running->closed case', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Spy on the parent class setEnabled method - const parentSetEnabledSpy = vi.spyOn(Profiler.prototype, 'setEnabled'); - - // Ensure profiler is in running state - expect(profiler.state).toBe('running'); - - // Trigger the running->closed transition - profiler.close(); - - // Verify all operations in the case are executed: - // 1. super.setEnabled(false) - calls parent setEnabled - expect(parentSetEnabledSpy).toHaveBeenCalledWith(false); - - // 2. this.#performanceObserverSink.unsubscribe() - expect(perfObserverSink.unsubscribe).toHaveBeenCalledTimes(1); - - // 3. this.#sink.close() - expect(sink.close).toHaveBeenCalledTimes(1); - - // 4. State is updated to 'closed' - expect(profiler.state).toBe('closed'); - - // Clean up spy - parentSetEnabledSpy.mockRestore(); - }); - - it('#transition method state transitions: should throw error for invalid transitions (default case)', () => { - const profiler = getNodejsProfiler({ enabled: false }).profiler; - - // We can't easily trigger the default case since the method signature - // restricts the possible transitions, but we can test that valid transitions work - // and invalid ones would be caught by TypeScript or would need runtime testing - - // For now, verify that all valid transitions work as expected - expect(profiler.state).toBe('idle'); - - profiler.setEnabled(true); - expect(profiler.state).toBe('running'); - - profiler.setEnabled(false); - expect(profiler.state).toBe('idle'); - - profiler.close(); - expect(profiler.state).toBe('closed'); - }); - - it('close() API: should close profiler from idle state', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - expect(profiler.state).toBe('idle'); - - profiler.close(); - - expect(profiler.state).toBe('closed'); - }); - - it('close() API: should close profiler from running state', () => { - const { profiler } = getNodejsProfiler({ enabled: true }); - - expect(profiler.state).toBe('running'); - - profiler.close(); - - expect(profiler.state).toBe('closed'); - }); - - it('close() API: should be idempotent - calling close multiple times', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - expect(profiler.state).toBe('idle'); - - profiler.close(); - expect(profiler.state).toBe('closed'); - - // Calling close again should be safe - profiler.close(); - expect(profiler.state).toBe('closed'); - }); - - it('debug flag and transition markers: should initialize debug flag to false when env var not set', () => { - const { profiler } = getNodejsProfiler(); - - const stats = profiler.stats; - expect(stats.debug).toBe(false); - }); - - it('debug flag and transition markers: should initialize debug flag from CP_PROFILER_DEBUG env var when set', () => { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = 'true'; - - const { profiler } = getNodejsProfiler(); - - const stats = profiler.stats; - expect(stats.debug).toBe(true); - }); - - it('debug flag and transition markers: should create transition marker when debug is enabled and transitioning to running', () => { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = 'true'; - const { profiler } = getNodejsProfiler({ enabled: false }); - - performance.clearMarks(); - - // Transition from idle to running (profiler becomes enabled) - profiler.setEnabled(true); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => mark.name === 'idle->running'); - expect(transitionMark).toBeDefined(); - expect(transitionMark?.name).toBe('idle->running'); - }); - - it('debug flag and transition markers: should not create transition marker when transitioning from running to idle (profiler disabled)', () => { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = 'true'; - const { profiler } = getNodejsProfiler({ enabled: true }); - - performance.clearMarks(); - - // Transition from running to idle (profiler becomes disabled before marker call) - profiler.setEnabled(false); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => mark.name === 'running->idle'); - // Marker won't be created because profiler is disabled before marker() is called - expect(transitionMark).toBeUndefined(); - }); - - it('debug flag and transition markers: should not create transition marker when transitioning from idle to closed (profiler never enabled)', () => { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = 'true'; - const { profiler } = getNodejsProfiler({ enabled: false }); - - performance.clearMarks(); - - // Transition from idle to closed (profiler was never enabled) - profiler.close(); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => mark.name === 'idle->closed'); - // Marker won't be created because profiler is not enabled - expect(transitionMark).toBeUndefined(); - }); - - it('debug flag and transition markers: should not create transition marker when debug is disabled', () => { - // eslint-disable-next-line functional/immutable-data - delete process.env.CP_PROFILER_DEBUG; - const { profiler } = getNodejsProfiler(); - - performance.clearMarks(); - - // Transition from idle to running - profiler.setEnabled(true); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => - mark.name.startsWith('idle->running'), - ); - expect(transitionMark).toBeUndefined(); - }); - - it('debug flag and transition markers: should not create transition marker when debug not set and env var not set', () => { - const { profiler } = getNodejsProfiler(); - - performance.clearMarks(); - - // Transition from idle to running - profiler.setEnabled(true); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => - mark.name.startsWith('idle->running'), - ); - expect(transitionMark).toBeUndefined(); - }); - - it('debug flag and transition markers: should create transition marker when debug enabled via env var', () => { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = 'true'; - // eslint-disable-next-line functional/immutable-data - delete process.env.CP_PROFILING; - - const { profiler } = getNodejsProfiler(); - - performance.clearMarks(); - - // Transition from idle to running - profiler.setEnabled(true); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => - mark.name.startsWith('idle->running'), - ); - expect(transitionMark).toBeDefined(); - }); - - it('debug flag and transition markers: should include stats in transition marker properties when transitioning to running', () => { - // eslint-disable-next-line functional/immutable-data - process.env.CP_PROFILER_DEBUG = 'true'; - const { profiler, perfObserverSink } = getNodejsProfiler({ - enabled: false, - }); - - perfObserverSink.getStats.mockReturnValue({ - isSubscribed: true, - queued: 5, - dropped: 2, - written: 10, - maxQueueSize: 10_000, - flushThreshold: 20, - addedSinceLastFlush: 3, - buffered: true, - }); - - performance.clearMarks(); - - // Transition to running (profiler becomes enabled, so marker will be created) - profiler.setEnabled(true); - - const marks = performance.getEntriesByType('mark'); - const transitionMark = marks.find(mark => mark.name === 'idle->running'); - expect(transitionMark).toBeDefined(); - - // Verify marker was created with correct name and includes stats in detail - expect(transitionMark?.name).toBe('idle->running'); - expect(transitionMark?.detail).toBeDefined(); - const detail = transitionMark?.detail as UserTimingDetail; - expect(detail.devtools).toBeDefined(); - expect(detail.devtools?.dataType).toBe('marker'); - expect(detail.devtools?.properties).toBeDefined(); - }); - - it('setEnabled override: should enable profiling when setEnabled(true)', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - expect(profiler.state).toBe('idle'); - - profiler.setEnabled(true); - - expect(profiler.state).toBe('running'); - }); - - it('setEnabled override: should disable profiling when setEnabled(false)', () => { - const { profiler } = getNodejsProfiler({ enabled: true }); - - expect(profiler.state).toBe('running'); - - profiler.setEnabled(false); - - expect(profiler.state).toBe('idle'); - }); - - it('flush() early return when closed: should return early when flush() called on closed profiler', () => { - const { perfObserverSink, profiler } = getNodejsProfiler({ - enabled: false, - }); - - // Close profiler - profiler.close(); - expect(profiler.state).toBe('closed'); - - // flush should be no-op when closed - profiler.flush(); - - // flush should not be called on the performance observer sink - expect(perfObserverSink.flush).not.toHaveBeenCalled(); - }); - - it('flush() early return when closed: should flush when profiler is running', () => { - const { perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - expect(profiler.state).toBe('running'); - - profiler.flush(); - - expect(perfObserverSink.flush).toHaveBeenCalledTimes(1); - }); - - it('should be idempotent - no-op when transitioning to same state', () => { - const { sink, perfObserverSink, profiler } = getNodejsProfiler({ - enabled: true, - }); - - // Already running, enable again should be no-op - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - - profiler.setEnabled(true); // Should be no-op - - expect(sink.open).toHaveBeenCalledTimes(1); - expect(perfObserverSink.subscribe).toHaveBeenCalledTimes(1); - }); - - it('should propagate errors from measure work function', () => { - const { profiler } = getNodejsProfiler({ enabled: true }); - - const error = new Error('Test error'); - expect(() => { - profiler.measure('error-test', () => { - throw error; - }); - }).toThrow(error); - }); - - it('should propagate errors from measureAsync work function', async () => { - const { profiler } = getNodejsProfiler({ enabled: true }); - - const error = new Error('Async test error'); - await expect(async () => { - await profiler.measureAsync('async-error-test', async () => { - throw error; - }); - }).rejects.toThrow(error); - }); - - it('should skip measurement when profiler is not active', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - let workCalled = false; - const result = profiler.measure('inactive-test', () => { - workCalled = true; - return 'result'; - }); - - expect(workCalled).toBe(true); - expect(result).toBe('result'); - }); - - it('should skip async measurement when profiler is not active', async () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - let workCalled = false; - const result = await profiler.measureAsync( - 'inactive-async-test', - async () => { - workCalled = true; - return 'async-result'; - }, - ); - - expect(workCalled).toBe(true); - expect(result).toBe('async-result'); - }); - - it('should skip marker when profiler is not active', () => { - const { profiler } = getNodejsProfiler({ enabled: false }); - - // Should not throw, just return early - expect(() => { - profiler.marker('inactive-marker'); - }).not.toThrow(); - }); - - it('base Profiler behavior: should always be active in base profiler', () => { - // eslint-disable-next-line functional/immutable-data - delete process.env.CP_PROFILING; - const profiler = new Profiler({ - prefix: 'cp', - track: 'test-track', - }); - - expect(profiler.isEnabled()).toBe(false); // Base profiler defaults to disabled - - // measure should always execute work - let workCalled = false; - const result = profiler.measure('base-test', () => { - workCalled = true; - return 'base-result'; - }); - - expect(workCalled).toBe(true); - expect(result).toBe('base-result'); - - // marker should always work - expect(() => { - profiler.marker('base-marker'); - }).not.toThrow(); - }); -}); diff --git a/packages/utils/src/lib/wal.ts b/packages/utils/src/lib/wal.ts index 627debe52..f0dc87a83 100644 --- a/packages/utils/src/lib/wal.ts +++ b/packages/utils/src/lib/wal.ts @@ -350,7 +350,10 @@ export function parseWalFormat( * * @returns true if this is the leader WAL process, false otherwise */ -export function isLeaderWal(envVarName: string, profilerID: string): boolean { +export function isCoordinatorProcess( + envVarName: string, + profilerID: string, +): boolean { return process.env[envVarName] === profilerID; } @@ -359,7 +362,10 @@ export function isLeaderWal(envVarName: string, profilerID: string): boolean { * This must be done as early as possible before any user code runs. * Sets envVarName to the current process ID if not already defined. */ -export function setLeaderWal(envVarName: string, profilerID: string): void { +export function setCoordinatorProcess( + envVarName: string, + profilerID: string, +): void { if (!process.env[envVarName]) { // eslint-disable-next-line functional/immutable-data process.env[envVarName] = profilerID; @@ -369,6 +375,14 @@ export function setLeaderWal(envVarName: string, profilerID: string): void { // eslint-disable-next-line functional/no-let let shardCount = 0; +/** + * Generates a unique sharded WAL ID based on performance time origin, process ID, thread ID, and instance count. + */ +function getShardedWalId() { + // eslint-disable-next-line functional/immutable-data + return `${Math.round(performance.timeOrigin)}.${process.pid}.${threadId}.${++ShardedWal.instanceCount}`; +} + /** * Generates a human-readable shard ID. * This ID is unique per process/thread/shard combination and used in the file name. @@ -475,24 +489,46 @@ export function getShardedFinalPath(opt: { */ export class ShardedWal { + static instanceCount = 0; + readonly #id: string = getShardedWalId(); readonly groupId = getShardedGroupId(); readonly #format: WalFormat; readonly #dir: string = process.cwd(); + readonly #isCoordinator: boolean; /** * Create a sharded WAL manager. + * + * @param opt.dir - Base directory to store shard files (defaults to process.cwd()) + * @param opt.format - WAL format configuration + * @param opt.groupId - Group ID for sharding (defaults to generated group ID) + * @param opt.coordinatorIdEnvVar - Environment variable name for storing coordinator ID (defaults to CP_SHARDED_WAL_COORDINATOR_ID) */ constructor(opt: { dir?: string; format: Partial>; groupId?: string; + coordinatorIdEnvVar: string; }) { - const { dir, format, groupId } = opt; + const { dir, format, groupId, coordinatorIdEnvVar } = opt; this.groupId = groupId ?? getShardedGroupId(); if (dir) { this.#dir = dir; } this.#format = parseWalFormat(format); + this.#isCoordinator = isCoordinatorProcess(coordinatorIdEnvVar, this.#id); + } + + /** + * Is this instance the coordinator? + * + * Coordinator status is determined from the coordinatorIdEnvVar environment variable. + * The coordinator handles finalization and cleanup of shard files. + * + * @returns true if this instance is the coordinator, false otherwise + */ + isCoordinator(): boolean { + return this.#isCoordinator; } shard(shardId: string = getShardId()) { diff --git a/packages/utils/src/lib/wal.unit.test.ts b/packages/utils/src/lib/wal.unit.test.ts index 1740258dd..4221d4f0f 100644 --- a/packages/utils/src/lib/wal.unit.test.ts +++ b/packages/utils/src/lib/wal.unit.test.ts @@ -1,8 +1,9 @@ import { vol } from 'memfs'; -import { beforeEach, describe, expect, it, vi } from 'vitest'; import { MEMFS_VOLUME } from '@code-pushup/test-utils'; +import { SHARDED_WAL_COORDINATOR_ID_ENV_VAR } from './profiler/constants.js'; import { type Codec, + type InvalidEntry, ShardedWal, WAL_ID_PATTERNS, WriteAheadLogFile, @@ -10,10 +11,10 @@ import { filterValidRecords, getShardId, getShardedGroupId, - isLeaderWal, + isCoordinatorProcess, parseWalFormat, recoverFromContent, - setLeaderWal, + setCoordinatorProcess, stringCodec, } from './wal.js'; @@ -183,38 +184,38 @@ describe('WriteAheadLogFile', () => { const w = wal('/test/a.log'); expect(w).toBeInstanceOf(WriteAheadLogFile); expect(w.getPath()).toBe('/test/a.log'); - expect(w.isClosed()).toBe(true); + expect(w.isClosed()).toBeTrue(); }); it('throws error when appending without opening', () => { const w = wal('/test/a.log'); - expect(w.isClosed()).toBe(true); + expect(w.isClosed()).toBeTrue(); expect(() => w.append('a')).toThrow('WAL not opened'); }); it('opens and closes correctly', () => { const w = wal('/test/a.log'); - expect(w.isClosed()).toBe(true); + expect(w.isClosed()).toBeTrue(); w.open(); - expect(w.isClosed()).toBe(false); + expect(w.isClosed()).toBeFalse(); w.close(); - expect(w.isClosed()).toBe(true); + expect(w.isClosed()).toBeTrue(); }); it('multiple open calls are idempotent', () => { const w = wal('/test/a.log'); - expect(w.isClosed()).toBe(true); + expect(w.isClosed()).toBeTrue(); w.open(); - expect(w.isClosed()).toBe(false); + expect(w.isClosed()).toBeFalse(); w.open(); - expect(w.isClosed()).toBe(false); + expect(w.isClosed()).toBeFalse(); w.open(); - expect(w.isClosed()).toBe(false); + expect(w.isClosed()).toBeFalse(); w.close(); - expect(w.isClosed()).toBe(true); + expect(w.isClosed()).toBeTrue(); }); it('append lines if opened', () => { @@ -496,8 +497,8 @@ describe('stringCodec', () => { it('should handle special JSON values', () => { const codec = stringCodec(); expect(codec.decode('null')).toBeNull(); - expect(codec.decode('true')).toBe(true); - expect(codec.decode('false')).toBe(false); + expect(codec.decode('true')).toBeTrue(); + expect(codec.decode('false')).toBeFalse(); expect(codec.decode('"quoted string"')).toBe('quoted string'); expect(codec.decode('42')).toBe(42); }); @@ -677,13 +678,13 @@ describe('parseWalFormat', () => { }); }); -describe('isLeaderWal', () => { +describe('isCoordinatorProcess', () => { it('should return true when env var matches current pid', () => { const profilerId = `${Math.round(performance.timeOrigin)}${process.pid}.1.0`; vi.stubEnv('TEST_LEADER_PID', profilerId); - const result = isLeaderWal('TEST_LEADER_PID', profilerId); - expect(result).toBe(true); + const result = isCoordinatorProcess('TEST_LEADER_PID', profilerId); + expect(result).toBeTrue(); }); it('should return false when env var does not match current profilerId', () => { @@ -691,28 +692,28 @@ describe('isLeaderWal', () => { vi.stubEnv('TEST_LEADER_PID', wrongProfilerId); const currentProfilerId = `${Math.round(performance.timeOrigin)}${process.pid}.1.0`; - const result = isLeaderWal('TEST_LEADER_PID', currentProfilerId); - expect(result).toBe(false); + const result = isCoordinatorProcess('TEST_LEADER_PID', currentProfilerId); + expect(result).toBeFalse(); }); it('should return false when env var is not set', () => { vi.stubEnv('NON_EXISTENT_VAR', undefined as any); const profilerId = `${Math.round(performance.timeOrigin)}${process.pid}.1.0`; - const result = isLeaderWal('NON_EXISTENT_VAR', profilerId); - expect(result).toBe(false); + const result = isCoordinatorProcess('NON_EXISTENT_VAR', profilerId); + expect(result).toBeFalse(); }); it('should return false when env var is empty string', () => { vi.stubEnv('TEST_LEADER_PID', ''); const profilerId = `${Math.round(performance.timeOrigin)}${process.pid}.1.0`; - const result = isLeaderWal('TEST_LEADER_PID', profilerId); - expect(result).toBe(false); + const result = isCoordinatorProcess('TEST_LEADER_PID', profilerId); + expect(result).toBeFalse(); }); }); -describe('setLeaderWal', () => { +describe('setCoordinatorProcess', () => { beforeEach(() => { // Clean up any existing TEST_ORIGIN_PID // eslint-disable-next-line functional/immutable-data @@ -723,7 +724,7 @@ describe('setLeaderWal', () => { expect(process.env['TEST_ORIGIN_PID']).toBeUndefined(); const profilerId = `${Math.round(performance.timeOrigin)}${process.pid}.1.0`; - setLeaderWal('TEST_ORIGIN_PID', profilerId); + setCoordinatorProcess('TEST_ORIGIN_PID', profilerId); expect(process.env['TEST_ORIGIN_PID']).toBe(profilerId); }); @@ -733,14 +734,14 @@ describe('setLeaderWal', () => { const newProfilerId = `${Math.round(performance.timeOrigin)}${process.pid}.2.0`; vi.stubEnv('TEST_ORIGIN_PID', existingProfilerId); - setLeaderWal('TEST_ORIGIN_PID', newProfilerId); + setCoordinatorProcess('TEST_ORIGIN_PID', newProfilerId); expect(process.env['TEST_ORIGIN_PID']).toBe(existingProfilerId); }); it('should set env var to profiler id', () => { const profilerId = `${Math.round(performance.timeOrigin)}${process.pid}.1.0`; - setLeaderWal('TEST_ORIGIN_PID', profilerId); + setCoordinatorProcess('TEST_ORIGIN_PID', profilerId); expect(process.env['TEST_ORIGIN_PID']).toBe(profilerId); }); @@ -758,6 +759,7 @@ describe('ShardedWal', () => { format: { baseName: 'test-wal', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); expect(sw).toBeInstanceOf(ShardedWal); @@ -770,6 +772,7 @@ describe('ShardedWal', () => { baseName: 'trace', walExtension: '.log', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); const shard = sw.shard('20231114-221320-000.1.2.3'); @@ -786,6 +789,7 @@ describe('ShardedWal', () => { baseName: 'trace', walExtension: '.log', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); const shard = sw.shard(); @@ -801,6 +805,7 @@ describe('ShardedWal', () => { format: { baseName: 'test-wal', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); const files = (sw as any).shardFiles(); expect(files).toEqual([]); @@ -812,6 +817,7 @@ describe('ShardedWal', () => { format: { baseName: 'test-wal', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); // Create the group directory (matches actual getShardedGroupId() output) vol.mkdirSync('/empty/20231114-221320-000', { recursive: true }); @@ -834,6 +840,7 @@ describe('ShardedWal', () => { baseName: 'trace', walExtension: '.log', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); const files = (sw as any).shardFiles(); @@ -858,6 +865,7 @@ describe('ShardedWal', () => { finalExtension: '.json', finalizer: records => `${JSON.stringify(records)}\n`, }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); // Create the group directory @@ -885,6 +893,7 @@ describe('ShardedWal', () => { finalExtension: '.json', finalizer: records => `${JSON.stringify(records)}\n`, }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); sw.finalize(); @@ -920,6 +929,7 @@ describe('ShardedWal', () => { codec: tolerantCodec, finalizer: records => `${JSON.stringify(records)}\n`, }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); sw.finalize(); @@ -945,6 +955,7 @@ describe('ShardedWal', () => { baseName: 'test', walExtension: '.log', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); expect(vol.toJSON()).toStrictEqual({ @@ -971,6 +982,7 @@ describe('ShardedWal', () => { baseName: 'test', walExtension: '.log', }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); vol.unlinkSync( @@ -994,6 +1006,7 @@ describe('ShardedWal', () => { finalizer: (records, opt) => `${JSON.stringify({ records, meta: opt })}\n`, }, + coordinatorIdEnvVar: SHARDED_WAL_COORDINATOR_ID_ENV_VAR, }); sw.finalize({ version: '1.0', compressed: true }); diff --git a/testing/test-utils/src/index.ts b/testing/test-utils/src/index.ts index 2b34c05b6..38ce50155 100644 --- a/testing/test-utils/src/index.ts +++ b/testing/test-utils/src/index.ts @@ -10,3 +10,5 @@ export * from './lib/utils/file-system.js'; export * from './lib/utils/create-npm-workshpace.js'; export * from './lib/utils/project-graph.js'; export * from './lib/utils/test-folder-setup.js'; +export * from './lib/utils/omit-trace-json.js'; +export * from './lib/utils/profiler.mock.js'; diff --git a/testing/test-utils/src/lib/utils/omit-trace-json.ts b/testing/test-utils/src/lib/utils/omit-trace-json.ts new file mode 100644 index 000000000..e45a72a51 --- /dev/null +++ b/testing/test-utils/src/lib/utils/omit-trace-json.ts @@ -0,0 +1,207 @@ +/** + * Normalizes trace JSONL files for deterministic snapshot testing. + * + * Replaces variable values (pid, tid, ts) with deterministic incremental values + * while preserving the original order of events. + * + * - Assigns incremental IDs to pid fields starting from 10001, 10002, etc. + * - Assigns incremental IDs to tid fields starting from 1, 2, etc. + * - Normalizes timestamps by sorting them first to determine incremental order, + * then mapping to incremental values starting from mocked epoch clock base, + * while preserving the original order of events in the output. + * + * @param jsonlContent - JSONL string content (one JSON object per line) or parsed JSON object/array + * @param baseTimestampUs - Base timestamp in microseconds to start incrementing from (default: 1_700_000_005_000_000) + * @returns Normalized JSONL string with deterministic pid, tid, and ts values + */ +export function omitTraceJson( + jsonlContent: string | object, + baseTimestampUs = 1_700_000_005_000_000, +): string { + if (typeof jsonlContent !== 'string') { + const eventsArray = Array.isArray(jsonlContent) + ? jsonlContent + : [jsonlContent]; + if (eventsArray.length === 0) { + return ''; + } + const events = eventsArray as TraceEvent[]; + return normalizeAndFormatEvents(events, baseTimestampUs); + } + + // Handle string input (JSONL format) + const trimmedContent = jsonlContent.trim(); + if (!trimmedContent) { + return jsonlContent; + } + + // Parse all events from JSONL + const events = trimmedContent + .split('\n') + .filter(Boolean) + .map(line => JSON.parse(line) as TraceEvent); + + if (events.length === 0) { + return jsonlContent; + } + + return normalizeAndFormatEvents(events, baseTimestampUs); +} + +/** + * Normalizes trace events and formats them as JSONL. + */ +function normalizeAndFormatEvents( + events: TraceEvent[], + baseTimestampUs: number, +): string { + if (events.length === 0) { + return ''; + } + + // Collect unique pid and tid values + type Accumulator = { + uniquePids: Set; + uniqueTids: Set; + timestamps: number[]; + uniqueLocalIds: Set; + }; + + const { uniquePids, uniqueTids, timestamps, uniqueLocalIds } = + events.reduce( + (acc, event) => { + const newUniquePids = new Set(acc.uniquePids); + const newUniqueTids = new Set(acc.uniqueTids); + const newUniqueLocalIds = new Set(acc.uniqueLocalIds); + + if (typeof event.pid === 'number') { + newUniquePids.add(event.pid); + } + if (typeof event.tid === 'number') { + newUniqueTids.add(event.tid); + } + + const newTimestamps = + typeof event.ts === 'number' + ? [...acc.timestamps, event.ts] + : acc.timestamps; + + // Collect id2.local values + if ( + event.id2 && + typeof event.id2 === 'object' && + 'local' in event.id2 && + typeof event.id2.local === 'string' + ) { + newUniqueLocalIds.add(event.id2.local); + } + + return { + uniquePids: newUniquePids, + uniqueTids: newUniqueTids, + timestamps: newTimestamps, + uniqueLocalIds: newUniqueLocalIds, + }; + }, + { + uniquePids: new Set(), + uniqueTids: new Set(), + timestamps: [] as number[], + uniqueLocalIds: new Set(), + }, + ); + + // Create mappings: original value -> normalized incremental value + const pidMap = new Map(); + const tidMap = new Map(); + const localIdMap = new Map(); + + // Sort unique values to ensure consistent mapping order + const sortedPids = [...uniquePids].sort((a, b) => a - b); + const sortedTids = [...uniqueTids].sort((a, b) => a - b); + const sortedLocalIds = [...uniqueLocalIds].sort(); + + // Map pids starting from 10001 + sortedPids.forEach((pid, index) => { + pidMap.set(pid, 10_001 + index); + }); + + // Map tids starting from 1 + sortedTids.forEach((tid, index) => { + tidMap.set(tid, 1 + index); + }); + + // Map local IDs starting from "0x1" + sortedLocalIds.forEach((localId, index) => { + localIdMap.set(localId, `0x${(index + 1).toString(16)}`); + }); + + // Sort timestamps to determine incremental order + const sortedTimestamps = [...timestamps].sort((a, b) => a - b); + + // Map timestamps incrementally starting from baseTimestampUs + const tsMap = sortedTimestamps.reduce((map, ts, index) => { + if (!map.has(ts)) { + return new Map(map).set(ts, baseTimestampUs + index); + } + return map; + }, new Map()); + + // Normalize events while preserving original order + const normalizedEvents = events.map(event => { + const pidUpdate = + typeof event.pid === 'number' && pidMap.has(event.pid) + ? { pid: pidMap.get(event.pid)! } + : {}; + + const tidUpdate = + typeof event.tid === 'number' && tidMap.has(event.tid) + ? { tid: tidMap.get(event.tid)! } + : {}; + + const tsUpdate = + typeof event.ts === 'number' && tsMap.has(event.ts) + ? { ts: tsMap.get(event.ts)! } + : {}; + + // Normalize id2.local if present + const id2Update = + event.id2 && + typeof event.id2 === 'object' && + 'local' in event.id2 && + typeof event.id2.local === 'string' && + localIdMap.has(event.id2.local) + ? { + id2: { + ...event.id2, + local: localIdMap.get(event.id2.local)!, + }, + } + : {}; + + return { + ...event, + ...pidUpdate, + ...tidUpdate, + ...tsUpdate, + ...id2Update, + }; + }); + + // Convert back to JSONL format + return `${normalizedEvents.map(event => JSON.stringify(event)).join('\n')}\n`; +} + +/** + * Trace event structure with pid, tid, ts, and id2.local fields. + */ +type TraceEvent = { + pid?: number; + tid?: number; + ts?: number; + id2?: { + local?: string; + [key: string]: unknown; + }; + [key: string]: unknown; +}; diff --git a/testing/test-utils/src/lib/utils/omit-trace-json.unit.test.ts b/testing/test-utils/src/lib/utils/omit-trace-json.unit.test.ts new file mode 100644 index 000000000..dbf5a079a --- /dev/null +++ b/testing/test-utils/src/lib/utils/omit-trace-json.unit.test.ts @@ -0,0 +1,235 @@ +import { omitTraceJson } from './omit-trace-json.js'; + +describe('omitTraceJson', () => { + it('should return empty string unchanged', () => { + expect(omitTraceJson('')).toBe(''); + }); + + it('should return whitespace-only string unchanged', () => { + expect(omitTraceJson(' \n\t ')).toBe(' \n\t '); + }); + + it('should return empty JSONL unchanged', () => { + expect(omitTraceJson('\n\n')).toBe('\n\n'); + }); + + it('should return minimal event unchanged', () => { + const input = '{"name":"test"}\n'; + expect(omitTraceJson(input)).toBe(input); + }); + + it('should normalize pid field starting from 10001', () => { + const result = omitTraceJson('{"pid":12345}\n'); + const parsed = JSON.parse(result.trim()); + expect(parsed.pid).toBe(10_001); + }); + + it('should normalize tid field starting from 1', () => { + const result = omitTraceJson('{"tid":999}\n'); + const parsed = JSON.parse(result.trim()); + expect(parsed.tid).toBe(1); + }); + + it('should normalize ts field with default baseTimestampUs', () => { + const result = omitTraceJson('{"ts":1234567890}\n'); + const parsed = JSON.parse(result.trim()); + expect(parsed.ts).toBe(1_700_000_005_000_000); + }); + + it('should normalize ts field with custom baseTimestampUs', () => { + const customBase = 2_000_000_000_000_000; + const result = omitTraceJson('{"ts":1234567890}\n', customBase); + const parsed = JSON.parse(result.trim()); + expect(parsed.ts).toBe(customBase); + }); + + it('should normalize id2.local field starting from 0x1', () => { + const result = omitTraceJson('{"id2":{"local":"0xabc123"}}\n'); + const parsed = JSON.parse(result.trim()); + expect(parsed.id2.local).toBe('0x1'); + }); + + it('should preserve event order when timestamps are out of order', () => { + const input = + '{"ts":300,"name":"third"}\n{"ts":100,"name":"first"}\n{"ts":200,"name":"second"}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].name).toBe('third'); + expect(events[1].name).toBe('first'); + expect(events[2].name).toBe('second'); + expect(events[0].ts).toBe(1_700_000_005_000_002); + expect(events[1].ts).toBe(1_700_000_005_000_000); + expect(events[2].ts).toBe(1_700_000_005_000_001); + }); + + it('should preserve event order when PIDs are out of order', () => { + const input = + '{"pid":300,"name":"third"}\n{"pid":100,"name":"first"}\n{"pid":200,"name":"second"}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].name).toBe('third'); + expect(events[1].name).toBe('first'); + expect(events[2].name).toBe('second'); + expect(events[0].pid).toBe(10_003); + expect(events[1].pid).toBe(10_001); + expect(events[2].pid).toBe(10_002); + }); + + it('should preserve event order when TIDs are out of order', () => { + const input = + '{"tid":30,"name":"third"}\n{"tid":10,"name":"first"}\n{"tid":20,"name":"second"}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].name).toBe('third'); + expect(events[1].name).toBe('first'); + expect(events[2].name).toBe('second'); + expect(events[0].tid).toBe(3); + expect(events[1].tid).toBe(1); + expect(events[2].tid).toBe(2); + }); + + it('should preserve event order with mixed out-of-order fields', () => { + const input = + '{"pid":500,"tid":5,"ts":5000,"name":"e"}\n{"pid":100,"tid":1,"ts":1000,"name":"a"}\n{"pid":300,"tid":3,"ts":3000,"name":"c"}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events.map(e => e.name)).toEqual(['e', 'a', 'c']); + expect(events[0].pid).toBe(10_003); + expect(events[1].pid).toBe(10_001); + expect(events[2].pid).toBe(10_002); + }); + + it('should not normalize non-number pid values', () => { + const input = '{"pid":"string"}\n{"pid":null}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].pid).toBe('string'); + expect(events[1].pid).toBeNull(); + }); + + it('should not normalize non-number tid values', () => { + const input = '{"tid":"string"}\n{"tid":null}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].tid).toBe('string'); + expect(events[1].tid).toBeNull(); + }); + + it('should not normalize non-number ts values', () => { + const input = '{"ts":"string"}\n{"ts":null}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].ts).toBe('string'); + expect(events[1].ts).toBeNull(); + }); + + it('should not normalize id2.local when id2 is missing', () => { + const input = '{"name":"test"}\n'; + const result = omitTraceJson(input); + const parsed = JSON.parse(result.trim()); + expect(parsed.id2).toBeUndefined(); + }); + + it('should not normalize id2.local when id2 is not an object', () => { + const input = '{"id2":"string"}\n{"id2":null}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].id2).toBe('string'); + expect(events[1].id2).toBeNull(); + }); + + it('should not normalize id2.local when local is missing', () => { + const input = '{"id2":{"other":"value"}}\n'; + const result = omitTraceJson(input); + const parsed = JSON.parse(result.trim()); + expect(parsed.id2.local).toBeUndefined(); + expect(parsed.id2.other).toBe('value'); + }); + + it('should not normalize id2.local when local is not a string', () => { + const input = '{"id2":{"local":123}}\n{"id2":{"local":null}}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].id2.local).toBe(123); + expect(events[1].id2.local).toBeNull(); + }); + + it('should map duplicate values to same normalized value', () => { + const input = '{"pid":100}\n{"pid":200}\n{"pid":100}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].pid).toBe(10_001); + expect(events[1].pid).toBe(10_002); + expect(events[2].pid).toBe(10_001); + }); + + it('should handle duplicate timestamps correctly', () => { + const input = '{"ts":1000}\n{"ts":2000}\n{"ts":1000}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + expect(events[0].ts).toBe(1_700_000_005_000_000); + expect(events[1].ts).toBe(1_700_000_005_000_002); + expect(events[2].ts).toBe(1_700_000_005_000_000); + }); + + it('should preserve other id2 properties when normalizing local', () => { + const input = + '{"id2":{"local":"0xabc","other":"value","nested":{"key":123}}}\n'; + const result = omitTraceJson(input); + const parsed = JSON.parse(result.trim()); + expect(parsed.id2.local).toBe('0x1'); + expect(parsed.id2.other).toBe('value'); + expect(parsed.id2.nested).toEqual({ key: 123 }); + }); + + it('should map multiple id2.local values to incremental hex', () => { + const input = + '{"id2":{"local":"0xabc"}}\n{"id2":{"local":"0xdef"}}\n{"id2":{"local":"0x123"}}\n'; + const result = omitTraceJson(input); + const events = result + .trim() + .split('\n') + .map(line => JSON.parse(line)); + const locals = events.map(e => e.id2.local).sort(); + expect(locals).toEqual(['0x1', '0x2', '0x3']); + }); + + it('should output valid JSONL with trailing newline', () => { + const result = omitTraceJson('{"pid":123}\n'); + expect(result).toMatch(/\n$/); + expect(() => JSON.parse(result.trim())).not.toThrow(); + }); +}); diff --git a/testing/test-utils/src/lib/utils/profiler.mock.ts b/testing/test-utils/src/lib/utils/profiler.mock.ts new file mode 100644 index 000000000..0ffa2f33d --- /dev/null +++ b/testing/test-utils/src/lib/utils/profiler.mock.ts @@ -0,0 +1,15 @@ +/** + * Helper function to wait for PerformanceObserver callback and flush profiler. + * + * This is a common pattern in profiler integration tests where we need to: + * 1. Wait for the PerformanceObserver callback to process entries (10ms delay) + * 2. Flush the profiler to write queued entries to the sink + * + * @param profiler - The profiler instance to flush + */ +export async function awaitObserverCallbackAndFlush< + T extends { flush(): void }, +>(profiler: T): Promise { + await new Promise(resolve => setTimeout(resolve, 10)); + profiler.flush(); +}