Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
142 changes: 116 additions & 26 deletions packages/utils/docs/profiler.md
Original file line number Diff line number Diff line change
Expand Up @@ -283,6 +283,31 @@ The profiler automatically subscribes to process events (`exit`, `SIGINT`, `SIGT

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.

### Profiler Lifecycle States

The NodeJSProfiler follows a state machine with three distinct states:

**State Machine Flow**

```
idle ⇄ running
↓ ↓
└──→ closed
```

- **idle**: Profiler is initialized but not actively collecting measurements. WAL sink is closed and performance observer is unsubscribed.
- **running**: Profiler is actively collecting performance measurements. WAL sink is open and performance observer is subscribed.
- **closed**: Profiler has been closed and all buffered data has been flushed to disk. Resources have been fully released. This state is irreversible.

**State Transitions:**

- `idle``running`: Occurs when `setEnabled(true)` is called. Enables profiling, opens WAL sink, and subscribes to performance observer.
- `running``idle`: Occurs when `setEnabled(false)` is called. Disables profiling, unsubscribes from performance observer, and closes WAL sink (sink will be reopened on re-enable).
- `running``closed`: Occurs when `close()` is called. Disables profiling, unsubscribes, closes sink, finalizes shards, and unsubscribes exit handlers (irreversible).
- `idle``closed`: Occurs when `close()` is called. Closes sink if it was opened, finalizes shards, and unsubscribes exit handlers (irreversible).

Once a state transition to `closed` occurs, there are no transitions back to previous states. This ensures data integrity and prevents resource leaks.

## Configuration

```ts
Expand All @@ -295,22 +320,87 @@ new NodejsProfiler<DomainEvents, Tracks>(options: NodejsProfilerOptions<DomainEv

**Options:**

| Property | Type | Default | Description |
| ------------------------ | --------------------------------------- | ---------- | ------------------------------------------------------------------------------- |
| `encodePerfEntry` | `PerformanceEntryEncoder<DomainEvents>` | _required_ | Function that encodes raw PerformanceEntry objects into domain-specific types |
| `captureBufferedEntries` | `boolean` | `true` | Whether to capture performance entries that occurred before observation started |
| `flushThreshold` | `number` | `20` | Threshold for triggering queue flushes based on queue length |
| `maxQueueSize` | `number` | `10_000` | Maximum number of items allowed in the queue before new entries are dropped |
| Property | Type | Default | Description |
| ------------------------ | --------------------------------------- | ---------------- | ------------------------------------------------------------------------------------- |
| `format` | `ProfilerFormat<DomainEvents>` | _required_ | WAL format configuration for sharded write-ahead logging, including `encodePerfEntry` |
| `measureName` | `string` | _auto-generated_ | Optional folder name for sharding. If not provided, a new group ID will be generated |
| `outDir` | `string` | `'tmp/profiles'` | Output directory for WAL shards and final files |
| `outBaseName` | `string` | _optional_ | Override the base name for WAL files (overrides format.baseName) |
| `format.encodePerfEntry` | `PerformanceEntryEncoder<DomainEvents>` | _required_ | Function that encodes raw PerformanceEntry objects into domain-specific types |
| `captureBufferedEntries` | `boolean` | `true` | Whether to capture performance entries that occurred before observation started |
| `flushThreshold` | `number` | `20` | Threshold for triggering queue flushes based on queue length |
| `maxQueueSize` | `number` | `10_000` | Maximum number of items allowed in the queue before new entries are dropped |

### Environment Variables

The NodeJSProfiler can be configured using environment variables, which override the corresponding options when not explicitly provided:

| Environment Variable | Type | Default | Description |
| -------------------------- | -------- | ---------------- | ---------------------------------------------------------------------------------------------------------------------------------- |
| `CP_PROFILING` | `string` | _unset_ | Enables or disables profiling globally. Set to `'true'` to enable, `'false'` or unset to disable. |
| `DEBUG` | `string` | _unset_ | Enables debug mode for profiler state transitions. When set to `'true'`, state transitions create performance marks for debugging. |
| `CP_PROFILER_OUT_DIR` | `string` | `'tmp/profiles'` | Output directory for WAL shards and final files. Overrides the `outDir` option. |
| `CP_PROFILER_MEASURE_NAME` | `string` | _auto-generated_ | Measure name used for sharding. Overrides the `measureName` option. If not provided, a new group ID will be generated. |

```bash
# Enable profiling with custom output directory
CP_PROFILING=true CP_PROFILER_OUT_DIR=/path/to/profiles npm run dev

# Enable profiling with debug mode and custom measure name
CP_PROFILING=true DEBUG=true CP_PROFILER_MEASURE_NAME=my-measure npm run dev
```

## API Methods

The NodeJSProfiler inherits all API methods from the base Profiler class and adds additional methods for queue management and WAL lifecycle control.

| Method | Description |
| ------------------------------------ | ------------------------------------------------------------------------------- |
| `getStats()` | Returns comprehensive queue statistics for monitoring and debugging. |
| `flush()` | Forces immediate writing of all queued performance entries to the WAL. |
| `setEnabled(enabled: boolean): void` | Controls profiling at runtime with automatic WAL/observer lifecycle management. |
| Method | Description |
| ------------------------------------ | ---------------------------------------------------------------------------------------- | --------- | ----------- |
| `stats` | Returns comprehensive queue statistics and profiling state for monitoring and debugging. |
| `state` | Returns current profiler state (`'idle' | 'running' | 'closed'`). |
| `close()` | Closes profiler and releases resources. Idempotent, safe for exit handlers. |
| `flush()` | Forces immediate writing of all queued performance entries to the WAL. |
| `setEnabled(enabled: boolean): void` | Controls profiling at runtime with automatic WAL/observer lifecycle management. |

### Profiler state

```ts
profiler.state: 'idle' | 'running' | 'closed'
```

Returns the current profiler state. Use this to check the profiler's lifecycle state without accessing the full stats object.

```ts
// Check current state
if (profiler.state === 'running') {
console.log('Profiler is actively collecting measurements');
} else if (profiler.state === 'idle') {
console.log('Profiler is initialized but not collecting');
} else {
console.log('Profiler has been closed');
}
```

### Closing the profiler

```ts
profiler.close(): void
```

Closes profiler and releases resources. This method is idempotent and safe to call from exit handlers. When called, it transitions the profiler to the `closed` state, which is irreversible. All buffered data is flushed, shards are finalized, and exit handlers are unsubscribed.

```ts
// Close profiler when done
profiler.close();

// Safe to call multiple times (idempotent)
profiler.close(); // No-op if already closed

// Check if closed
if (profiler.state === 'closed') {
console.log('Profiler resources have been released');
}
```

### Runtime control with Write Ahead Log lifecycle management

Expand All @@ -327,13 +417,23 @@ await performHeavyOperation();
profiler.setEnabled(true); // WAL reopens and observer resubscribes
```

### Queue statistics
### Profiler statistics

```ts
profiler.getStats(): {
enabled: boolean;
observing: boolean;
walOpen: boolean;
profiler.stats: {
profilerState: 'idle' | 'running' | 'closed';
debug: boolean;
sharderState: 'active' | 'finalized' | 'cleaned';
shardCount: number;
groupId: string;
isCoordinator: boolean;
isFinalized: boolean;
isCleaned: boolean;
finalFilePath: string;
shardFileCount: number;
shardFiles: string[];
shardOpen: boolean;
shardPath: string;
isSubscribed: boolean;
queued: number;
dropped: number;
Expand All @@ -345,16 +445,6 @@ profiler.getStats(): {
}
```

Returns comprehensive queue statistics for monitoring and debugging. Provides insight into the current state of the performance entry queue, useful for monitoring memory usage and processing throughput.

```ts
const stats = profiler.getStats();
console.log(`Enabled: ${stats.enabled}, WAL Open: ${stats.walOpen}, Observing: ${stats.observing}, Subscribed: ${stats.isSubscribed}, Queued: ${stats.queued}`);
if (stats.enabled && stats.walOpen && stats.observing && stats.isSubscribed && stats.queued > stats.flushThreshold) {
console.log('Queue nearing capacity, consider manual flush');
}
```

### Manual flushing

```ts
Expand Down
29 changes: 29 additions & 0 deletions packages/utils/mocks/README.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
# Mocks

## multiprocess-profiling

The `profiler-worker.mjs` script demonstrates multiprocess profiling by spawning N child processes that perform work and generate performance traces.

### Expected Output

**Console:**

- JSON object containing profiler statistics (profiler state, shard info, queue stats, etc.)

**Files:**

- A timestamped directory in `CP_PROFILER_OUT_DIR` (e.g., `20260131-210017-052/`)
- `trace.<timestamp>.<pid>.<shard>.jsonl` - WAL format trace files (one per process)
- `trace.<timestamp>.json` - Consolidated trace file in Chrome DevTools format

### Usage

```bash
CP_PROFILING=true DEBUG=true CP_PROFILER_OUT_DIR=/path/to/output npx tsx packages/utils/mocks/multiprocess-profiling/profiler-worker.mjs <numProcesses>
```

**Example:**

```bash
CP_PROFILING=true DEBUG=true CP_PROFILER_OUT_DIR=./tmp/int/utils npx tsx --tsconfig tsconfig.base.json packages/utils/mocks/multiprocess-profiling/profiler-worker.mjs 3
```
Original file line number Diff line number Diff line change
@@ -0,0 +1,16 @@
import { NodejsProfiler } from '../../src/lib/profiler/profiler-node.js';
import {
createBufferedEvents,
getProfilerConfig,
performDummyWork,
} from './utils.js';

(async () => {
await createBufferedEvents();

const profiler = new NodejsProfiler(getProfilerConfig());

await performDummyWork(profiler);

profiler.close();
})();
51 changes: 51 additions & 0 deletions packages/utils/mocks/multiprocess-profiling/profiler-worker.mjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,51 @@
import { spawn } from 'node:child_process';
import path from 'node:path';
import { fileURLToPath } from 'node:url';
import { NodejsProfiler } from '../../src/lib/profiler/profiler-node.js';
import { createBufferedEvents, getProfilerConfig } from './utils.js';

const [numProcesses] = process.argv.slice(2);

if (!numProcesses) {
console.error('Usage: node profiler-worker.mjs <numProcesses>');
process.exit(1);
}

const numProcs = parseInt(numProcesses, 10);
if (isNaN(numProcs) || numProcs < 1) {
console.error('numProcesses must be a positive integer');
process.exit(1);
}

const workerScriptPath = path.join(
fileURLToPath(path.dirname(import.meta.url)),
'./profiler-worker-child.mjs',
);

await createBufferedEvents();

const profiler = new NodejsProfiler(getProfilerConfig());

await profiler.measureAsync('profiler-worker', async () => {
const processes = Array.from({ length: numProcs }, (_, i) => {
return new Promise((resolve, reject) => {
const child = spawn('npx', ['tsx', workerScriptPath], {
stdio: 'pipe',
});

child.on('close', code => {
if (code === 0) {
resolve(code);
} else {
reject(new Error(`Process ${i + 1} exited with code ${code}`));
}
});

child.on('error', reject);
});
});
await Promise.all(processes);
});

profiler.close();
console.log(JSON.stringify(profiler.stats, null, 2));
98 changes: 98 additions & 0 deletions packages/utils/mocks/multiprocess-profiling/utils.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
import { NodejsProfiler } from '../../src/lib/profiler/profiler-node.js';
import type { NodejsProfilerOptions } from '../../src/lib/profiler/profiler-node.js';
import { entryToTraceEvents } from '../../src/lib/profiler/trace-file-utils.js';
import type { TraceEvent } from '../../src/lib/profiler/trace-file.type.js';
import { traceEventWalFormat } from '../../src/lib/profiler/wal-json-trace.js';
import {
asOptions,
markerPayload,
trackEntryPayload,
} from '../../src/lib/user-timing-extensibility-api-utils';
import type {
ActionTrackEntryPayload,
TrackMeta,
} from '../../src/lib/user-timing-extensibility-api.type.js';

export function getTrackConfig(): TrackMeta {
return {
track: `Track: ${process.pid}`,
trackGroup: 'Multiprocess',
};
}

/**
* Default profiler configuration for multiprocess profiling mocks
*/
export function getProfilerConfig(
options?: Partial<
NodejsProfilerOptions<TraceEvent, Record<string, ActionTrackEntryPayload>>
>,
): NodejsProfilerOptions<TraceEvent, Record<string, ActionTrackEntryPayload>> {
return {
format: {
...traceEventWalFormat(),
encodePerfEntry: entryToTraceEvents,
},
...getTrackConfig(),
...options,
};
}

/**
* Creates buffered performance marks and measures before profiler initialization
*/
export async function createBufferedEvents(): Promise<void> {
const bM1 = `buffered-mark-${process.pid}`;
performance.mark(bM1, asOptions(markerPayload({ color: 'tertiary' })));
const intervalDelay = Math.floor(Math.random() * 150) + 50;
await new Promise(resolve => setTimeout(resolve, intervalDelay));
performance.measure(`buffered-${process.pid}`, {
start: bM1,
...asOptions(
trackEntryPayload({
...getTrackConfig(),
color: 'tertiary',
}),
),
});
}

/**
* Performs dummy work with random intervals and work packages
*/
export async function performDummyWork(
profiler: NodejsProfiler<TraceEvent>,
): Promise<void> {
profiler.marker(`process-${process.pid}:process-start`, {
tooltipText: `Process ${process.pid} started`,
});

// Random number of intervals (2-5)
const numIntervals = Math.floor(Math.random() * 4) + 2;

for (let interval = 0; interval < numIntervals; interval++) {
// Random interval delay (50-200ms)
const intervalDelay = Math.floor(Math.random() * 150) + 50;
await new Promise(resolve => setTimeout(resolve, intervalDelay));

// Random number of work packages per interval (1-5)
const numWorkPackages = Math.floor(Math.random() * 5) + 1;

for (let pkg = 0; pkg < numWorkPackages; pkg++) {
// Random work size (100-5000 elements)
const workSize = Math.floor(Math.random() * 5000000);

profiler.measure(
`process-${process.pid}:interval-${interval}:work-${pkg}`,
() => {
const arr = Array.from({ length: workSize }, (_, i) => i);
return arr.reduce((sum, x) => sum + x * Math.random(), 0);
},
);
}
}

profiler.marker(`process-${process.pid}:process-end`, {
tooltipText: `Process ${process.pid} completed ${numIntervals} intervals`,
});
}
Loading
Loading