feat: instrument Node↔C++ IPC metrics in EDOPro and add reproducible performance benchmarks

Author: diangogav

docs/node-cpp-ipc-performance-testing.md

@@ -0,0 +1,69 @@
+# Node.js ↔ C++ IPC performance testing
+
+This document adds reproducible local benchmarks for the child-process IPC channel.
+
+## Included scripts
+
+- `npm run perf:protocol`
+  - Microbenchmark for JSON serialization/parsing and length-prefixed frame encode/decode.
+- `npm run perf:ipc`
+  - End-to-end IPC benchmark using a child-process echo worker that mimics current transport:
+    - parent writes line-delimited JSON commands,
+    - child replies with `uint32_le + json` frames.
+
+## Environment variables
+
+### `perf:protocol`
+
+- `BENCH_ITERATIONS` (default `200000`)
+- `BENCH_PAYLOAD_BYTES` (default `256`)
+
+Example:
+
+```bash
+BENCH_ITERATIONS=500000 BENCH_PAYLOAD_BYTES=512 npm run perf:protocol
+```
+
+### `perf:ipc`
+
+- `BENCH_MESSAGES` (default `20000`)
+- `BENCH_CONCURRENCY` (default `512`)
+- `BENCH_PAYLOAD_BYTES` (default `128`)
+
+Example:
+
+```bash
+BENCH_MESSAGES=50000 BENCH_CONCURRENCY=1024 BENCH_PAYLOAD_BYTES=256 npm run perf:ipc
+```
+
+## Metrics reported
+
+- Throughput (`throughputMsgPerSec`)
+- End-to-end latency (`p50`, `p95`, `p99`)
+- Backpressure stats (`drainCount`, `totalDrainWaitMs`)
+
+## Suggested baseline workflow
+
+1. Run both scripts on current branch.
+2. Save JSON output artifacts.
+3. Apply protocol changes (e.g. bidirectional length-prefix framing).
+4. Repeat benchmarks with same env vars.
+5. Compare p95/p99 latency and throughput deltas.
+
+## Production metrics capture
+
+You can enable periodic IPC metrics logs per room by setting:
+
+```bash
+IPC_METRICS_ENABLED=true
+```
+
+When enabled, each active EDO room logs a structured `IPC_METRICS` event every 60 seconds with:
+
+- queue depth and max queue depth
+- commands enqueued/written and stdin write errors
+- drain count and total drain wait time
+- stdout chunk/bytes counts
+- processed frames, parse errors, and deferred ticks
+
+Use this in production/staging to collect real IPC behavior and share snapshots for analysis.

package.json

@@ -21,7 +21,9 @@
     "migrate-users": "ts-node-dev -r tsconfig-paths/register --respawn --poll --require dotenv/config src/utils/migrate-user-from-redis-to-postgres.ts",
     "migration:generate": "ts-node -r tsconfig-paths/register --require dotenv/config ./node_modules/typeorm/cli.js migration:generate -d ./src/evolution-types/src/data-source.ts ./src/evolution-types/src/migrations/$npm_config_name",
     "migration:run": "ts-node -r tsconfig-paths/register --require dotenv/config ./node_modules/typeorm/cli.js migration:run -d ./src/evolution-types/src/data-source.ts",
-    "migration:revert": "ts-node -r tsconfig-paths/register --require dotenv/config ./node_modules/typeorm/cli.js migration:revert -d ./src/evolution-types/src/data-source.ts"
+    "migration:revert": "ts-node -r tsconfig-paths/register --require dotenv/config ./node_modules/typeorm/cli.js migration:revert -d ./src/evolution-types/src/data-source.ts",
+    "perf:protocol": "ts-node -r tsconfig-paths/register src/utils/perf/benchmark-protocol.ts",
+    "perf:ipc": "ts-node -r tsconfig-paths/register src/utils/perf/benchmark-node-cpp-ipc.ts"
   },
   "keywords": [],
   "author": "",

src/edopro/room/domain/Room.ts

@@ -46,6 +46,22 @@ export enum Rule {
 	ALL,
 }
 
+type IpcMetricsSnapshot = {
+	uptimeMs: number;
+	queueDepth: number;
+	maxQueueDepth: number;
+	commandsEnqueued: number;
+	commandsWritten: number;
+	stdinWriteErrors: number;
+	drainCount: number;
+	totalDrainWaitMs: number;
+	stdoutChunks: number;
+	stdoutBytes: number;
+	framesProcessed: number;
+	parseErrors: number;
+	deferredProcessTicks: number;
+};
+
 export class DeckRules {
 	public readonly mainMin: number;
 	public readonly mainMax: number;
@@ -156,6 +172,22 @@ export class Room extends YgoRoom {
 	private readonly notifier: RoomClientNotifier;
 	private readonly pendingCppMessages: string[] = [];
 	private isWaitingCppDrain = false;
+	private ipcMetricsStartedAt = Date.now();
+	private ipcMetricsLogInterval: NodeJS.Timeout | null = null;
+	private lastDrainStartAt: bigint | null = null;
+	private ipcMetrics = {
+		maxQueueDepth: 0,
+		commandsEnqueued: 0,
+		commandsWritten: 0,
+		stdinWriteErrors: 0,
+		drainCount: 0,
+		totalDrainWaitNs: 0n,
+		stdoutChunks: 0,
+		stdoutBytes: 0,
+		framesProcessed: 0,
+		parseErrors: 0,
+		deferredProcessTicks: 0,
+	};
 
 	private constructor(attr: RoomAttr) {
 		super({
@@ -560,9 +592,12 @@ export class Room extends YgoRoom {
 		this.isWaitingCppDrain = false;
 		this.pendingCppMessages.length = 0;
 		this._duel.stdin.on("error", (error) => {
+			this.ipcMetrics.stdinWriteErrors += 1;
 			this.logger.error("Error writing to the child process");
 			this.logger.error(error);
 		});
+
+		this.startIpcMetricsReporting();
 	}
 
 	private get duel(): ChildProcessWithoutNullStreams | null {
@@ -797,9 +832,30 @@ export class Room extends YgoRoom {
 
 	public sendMessageToCpp(message: string): void {
 		this.pendingCppMessages.push(`${message}\n`);
+		this.ipcMetrics.commandsEnqueued += 1;
+		if (this.pendingCppMessages.length > this.ipcMetrics.maxQueueDepth) {
+			this.ipcMetrics.maxQueueDepth = this.pendingCppMessages.length;
+		}
 		this.flushCppMessageQueue();
 	}
 
+	public recordCppStdoutChunk(byteLength: number): void {
+		this.ipcMetrics.stdoutChunks += 1;
+		this.ipcMetrics.stdoutBytes += byteLength;
+	}
+
+	public recordCppFrameProcessed(): void {
+		this.ipcMetrics.framesProcessed += 1;
+	}
+
+	public recordCppParseError(): void {
+		this.ipcMetrics.parseErrors += 1;
+	}
+
+	public recordCppDeferredProcessTick(): void {
+		this.ipcMetrics.deferredProcessTicks += 1;
+	}
+
 	isFinished(): boolean {
 		return this.currentDuel?.isFinished ?? false;
 	}
@@ -880,6 +936,7 @@ export class Room extends YgoRoom {
 				this._replay.destroy();
 			}
 			this.roomTimer.stop();
+			this.stopIpcMetricsReporting();
 		});
 	}
 
@@ -983,18 +1040,69 @@ export class Room extends YgoRoom {
 
 			if (!writeSuccess) {
 				this.isWaitingCppDrain = true;
+				this.ipcMetrics.drainCount += 1;
+				this.lastDrainStartAt = process.hrtime.bigint();
 				duel.stdin.once("drain", () => {
+					if (this.lastDrainStartAt !== null) {
+						this.ipcMetrics.totalDrainWaitNs += process.hrtime.bigint() - this.lastDrainStartAt;
+						this.lastDrainStartAt = null;
+					}
 					this.isWaitingCppDrain = false;
 					this.flushCppMessageQueue();
 				});
 
 				return;
 			}
 
+			this.ipcMetrics.commandsWritten += 1;
 			this.pendingCppMessages.shift();
 		}
 	}
 
+
+	private startIpcMetricsReporting(): void {
+		if (process.env.IPC_METRICS_ENABLED !== "true") {
+			return;
+		}
+
+		if (this.ipcMetricsLogInterval) {
+			return;
+		}
+
+		this.ipcMetricsStartedAt = Date.now();
+		this.ipcMetricsLogInterval = setInterval(() => {
+			const snapshot = this.getIpcMetricsSnapshot();
+			this.logger.info("IPC_METRICS", snapshot);
+		}, 60_000);
+	}
+
+	private stopIpcMetricsReporting(): void {
+		if (!this.ipcMetricsLogInterval) {
+			return;
+		}
+
+		clearInterval(this.ipcMetricsLogInterval);
+		this.ipcMetricsLogInterval = null;
+	}
+
+	private getIpcMetricsSnapshot(): IpcMetricsSnapshot {
+		return {
+			uptimeMs: Date.now() - this.ipcMetricsStartedAt,
+			queueDepth: this.pendingCppMessages.length,
+			maxQueueDepth: this.ipcMetrics.maxQueueDepth,
+			commandsEnqueued: this.ipcMetrics.commandsEnqueued,
+			commandsWritten: this.ipcMetrics.commandsWritten,
+			stdinWriteErrors: this.ipcMetrics.stdinWriteErrors,
+			drainCount: this.ipcMetrics.drainCount,
+			totalDrainWaitMs: Number(this.ipcMetrics.totalDrainWaitNs) / 1e6,
+			stdoutChunks: this.ipcMetrics.stdoutChunks,
+			stdoutBytes: this.ipcMetrics.stdoutBytes,
+			framesProcessed: this.ipcMetrics.framesProcessed,
+			parseErrors: this.ipcMetrics.parseErrors,
+			deferredProcessTicks: this.ipcMetrics.deferredProcessTicks,
+		};
+	}
+
 	private extractDeckPoints(notes?: string): number | undefined {
 		if (!notes) {
 			return undefined;

src/edopro/room/domain/states/dueling/DuelingState.ts

@@ -94,6 +94,8 @@ type SwapMessage = {
 	team: number;
 };
 export class DuelingState extends RoomState {
+	private static readonly MAX_MESSAGES_PER_TICK = 1000;
+
 	constructor(
 		eventEmitter: EventEmitter,
 		private readonly logger: Logger,
@@ -258,10 +260,12 @@ export class DuelingState extends RoomState {
 		});
 
 		core.stdout.on("data", (data: Buffer) => {
+			this.room.recordCppStdoutChunk(data.length);
 			try {
 				this.jsonMessageProcessor.read(data);
 				this.processMessage();
 			} catch (error) {
+				this.room.recordCppParseError();
 				const payload = this.jsonMessageProcessor.payload;
 				this.logger.error(error as Error);
 				this.logger.info(`data: ${data.toString("hex")}`);
@@ -282,8 +286,15 @@ export class DuelingState extends RoomState {
 	}
 
 	private processMessage(): void {
-		while (this.jsonMessageProcessor.isMessageReady()) {
+		let processedMessages = 0;
+
+		while (
+			processedMessages < DuelingState.MAX_MESSAGES_PER_TICK &&
+			this.jsonMessageProcessor.isMessageReady()
+		) {
+			processedMessages++;
 			this.jsonMessageProcessor.process();
+			this.room.recordCppFrameProcessed();
 			const payload = this.jsonMessageProcessor.payload;
 			const message = JSON.parse(payload.data) as Message;
 
@@ -341,6 +352,15 @@ export class DuelingState extends RoomState {
 				this.handleCoreSwap(message as unknown as SwapMessage);
 			}
 		}
+
+		if (this.jsonMessageProcessor.isMessageReady()) {
+			this.room.recordCppDeferredProcessTick();
+			this.logger.info("Processing remaining core messages in next tick", {
+				roomId: this.room.id,
+				maxMessagesPerTick: DuelingState.MAX_MESSAGES_PER_TICK,
+			});
+			setImmediate(() => this.processMessage());
+		}
 	}
 
 	private handleCoreReplay(message: ReplayMessage) {