From e5e463c673fda374f9a17239c219b12d9768dc46 Mon Sep 17 00:00:00 2001 From: scamiv <6170744+scamiv@users.noreply.github.com> Date: Tue, 3 Feb 2026 23:01:17 +0100 Subject: [PATCH] Implement worker metrics and debugging events - Introduced WorkerMetricsEvent and SetWorkerDebugEvent to facilitate communication between the main thread and worker for performance monitoring. - Enhanced ClientGameRunner to emit worker metrics and handle debug configuration updates. - Updated PerformanceOverlay to display worker metrics and allow toggling of debug settings. - Refactored Canvas2DRendererProxy and TerritoryRendererProxy to improve rendering performance and manage render cooldowns. - Added profiling capabilities in Worker.worker.ts to track event loop lag, simulation delays, and message handling metrics. --- src/client/ClientGameRunner.ts | 8 + src/client/InputHandler.ts | 15 + .../canvas2d/Canvas2DRendererProxy.ts | 84 +- .../graphics/layers/PerformanceOverlay.ts | 210 ++++ .../graphics/webgpu/TerritoryRendererProxy.ts | 91 +- src/core/worker/Worker.worker.ts | 1108 +++++++++++------ src/core/worker/WorkerClient.ts | 54 +- src/core/worker/WorkerMessages.ts | 65 +- src/core/worker/WorkerTerritoryRenderer.ts | 156 ++- 9 files changed, 1373 insertions(+), 418 deletions(-) diff --git a/src/client/ClientGameRunner.ts b/src/client/ClientGameRunner.ts index c7886a6cf..af6adb694 100644 --- a/src/client/ClientGameRunner.ts +++ b/src/client/ClientGameRunner.ts @@ -34,7 +34,9 @@ import { InputHandler, MouseMoveEvent, MouseUpEvent, + SetWorkerDebugEvent, TickMetricsEvent, + WorkerMetricsEvent, } from "./InputHandler"; import { endGame, startGame, startTime } from "./LocalPersistantStats"; import { terrainMapFileLoader } from "./TerrainMapFileLoader"; @@ -221,6 +223,12 @@ async function createClientGame( lobbyConfig.clientID, ); await worker.initialize(); + worker.onWorkerMetrics((metrics) => { + eventBus.emit(new WorkerMetricsEvent(metrics)); + }); + eventBus.on(SetWorkerDebugEvent, (event: SetWorkerDebugEvent) => { + worker.setWorkerDebug(event.config); + }); const gameView = new GameView( worker, config, diff --git a/src/client/InputHandler.ts b/src/client/InputHandler.ts index 6ffc3b161..be6b9c14f 100644 --- a/src/client/InputHandler.ts +++ b/src/client/InputHandler.ts @@ -2,6 +2,7 @@ import { EventBus, GameEvent } from "../core/EventBus"; import { UnitType } from "../core/game/Game"; import { UnitView } from "../core/game/GameView"; import { UserSettings } from "../core/game/UserSettings"; +import type { WorkerMetricsMessage } from "../core/worker/WorkerMessages"; import { UIState } from "./graphics/UIState"; import { ReplaySpeedMultiplier } from "./utilities/ReplaySpeedMultiplier"; @@ -81,6 +82,20 @@ export class RefreshGraphicsEvent implements GameEvent {} export class TogglePerformanceOverlayEvent implements GameEvent {} +export class SetWorkerDebugEvent implements GameEvent { + constructor( + public readonly config: { + enabled: boolean; + intervalMs?: number; + includeTrace?: boolean; + }, + ) {} +} + +export class WorkerMetricsEvent implements GameEvent { + constructor(public readonly metrics: WorkerMetricsMessage) {} +} + export class ToggleStructureEvent implements GameEvent { constructor(public readonly structureTypes: UnitType[] | null) {} } diff --git a/src/client/graphics/canvas2d/Canvas2DRendererProxy.ts b/src/client/graphics/canvas2d/Canvas2DRendererProxy.ts index bae056f55..474627fb9 100644 --- a/src/client/graphics/canvas2d/Canvas2DRendererProxy.ts +++ b/src/client/graphics/canvas2d/Canvas2DRendererProxy.ts @@ -2,7 +2,6 @@ import { createCanvas } from "src/client/Utils"; import { Theme } from "../../../core/configuration/Config"; import { TileRef } from "../../../core/game/GameMap"; import { GameView } from "../../../core/game/GameView"; -import { generateID } from "../../../core/Util"; import { WorkerClient } from "../../../core/worker/WorkerClient"; import { InitRendererMessage, @@ -16,7 +15,6 @@ import { SetPaletteMessage, SetPatternsEnabledMessage, SetShaderSettingsMessage, - TickRendererMessage, ViewSize, ViewTransform, } from "../../../core/worker/WorkerMessages"; @@ -40,6 +38,8 @@ export class Canvas2DRendererProxy { private lastSentViewSize: ViewSize | null = null; private lastSentViewTransform: ViewTransform | null = null; private renderInFlight = false; + private renderSeq = 0; + private renderCooldownUntilMs = 0; private constructor( private readonly game: GameView, @@ -299,23 +299,27 @@ export class Canvas2DRendererProxy { } tick(): void { - const message: TickRendererMessage = { type: "tick_renderer" }; - this.sendToWorker(message); + // No-op: worker renderer ticks from worker-side game_update. } render(): void { if (this.failed) { return; } + if (performance.now() < this.renderCooldownUntilMs) { + return; + } if (this.renderInFlight) { return; } this.renderInFlight = true; - const renderId = `render_${generateID()}`; + const renderId = `render_${++this.renderSeq}`; + const sentAtWallMs = Date.now(); const message: RenderFrameMessage = { type: "render_frame" }; message.id = renderId; + message.sentAtWallMs = sentAtWallMs; if ( !this.lastSentViewSize || @@ -343,15 +347,81 @@ export class Canvas2DRendererProxy { worker.removeMessageHandler(renderId); return; } - this.renderInFlight = false; + + console.warn(`render_done timeout (${renderId})`); worker.removeMessageHandler(renderId); - }, 2000); + + this.renderInFlight = false; + this.renderCooldownUntilMs = performance.now() + 250; + this.lastSentViewSize = null; + this.lastSentViewTransform = null; + }, 15000); worker.addMessageHandler(renderId, (m: any) => { if (m?.type !== "render_done") { return; } clearTimeout(timeout); + const startedAt = typeof m.startedAt === "number" ? m.startedAt : NaN; + const endedAt = typeof m.endedAt === "number" ? m.endedAt : NaN; + const startedAtWallMs = + typeof m.startedAtWallMs === "number" ? m.startedAtWallMs : NaN; + const endedAtWallMs = + typeof m.endedAtWallMs === "number" ? m.endedAtWallMs : NaN; + const echoedSentAtWallMs = + typeof m.sentAtWallMs === "number" ? m.sentAtWallMs : sentAtWallMs; + if ( + Number.isFinite(startedAt) && + Number.isFinite(endedAt) && + Number.isFinite(startedAtWallMs) && + Number.isFinite(endedAtWallMs) && + Number.isFinite(echoedSentAtWallMs) + ) { + const queueMs = startedAtWallMs - echoedSentAtWallMs; + const renderMs = endedAt - startedAt; + const totalMs = endedAtWallMs - echoedSentAtWallMs; + const breakdown = + typeof m.renderCpuMs === "number" || + typeof m.renderGpuWaitMs === "number" || + typeof m.renderWaitPrevGpuMs === "number" || + typeof m.renderGetTextureMs === "number" + ? { + waitPrevGpuMs: + typeof m.renderWaitPrevGpuMs === "number" + ? Math.round(m.renderWaitPrevGpuMs) + : undefined, + waitPrevGpuTimedOut: + typeof m.renderWaitPrevGpuTimedOut === "boolean" + ? m.renderWaitPrevGpuTimedOut + : undefined, + cpuMs: + typeof m.renderCpuMs === "number" + ? Math.round(m.renderCpuMs) + : undefined, + getTextureMs: + typeof m.renderGetTextureMs === "number" + ? Math.round(m.renderGetTextureMs) + : undefined, + gpuWaitMs: + typeof m.renderGpuWaitMs === "number" + ? Math.round(m.renderGpuWaitMs) + : undefined, + gpuWaitTimedOut: + typeof m.renderGpuWaitTimedOut === "boolean" + ? m.renderGpuWaitTimedOut + : undefined, + } + : undefined; + if (totalMs > 1000 || queueMs > 1000 || renderMs > 1000) { + console.warn("worker render timing", { + id: renderId, + queueMs: Math.round(queueMs), + renderMs: Math.round(renderMs), + totalMs: Math.round(totalMs), + breakdown, + }); + } + } this.renderInFlight = false; }); } else { diff --git a/src/client/graphics/layers/PerformanceOverlay.ts b/src/client/graphics/layers/PerformanceOverlay.ts index ad27aeaa5..a5c0725b6 100644 --- a/src/client/graphics/layers/PerformanceOverlay.ts +++ b/src/client/graphics/layers/PerformanceOverlay.ts @@ -2,9 +2,12 @@ import { LitElement, css, html } from "lit"; import { customElement, property, state } from "lit/decorators.js"; import { EventBus } from "../../../core/EventBus"; import { UserSettings } from "../../../core/game/UserSettings"; +import type { WorkerMetricsMessage } from "../../../core/worker/WorkerMessages"; import { + SetWorkerDebugEvent, TickMetricsEvent, TogglePerformanceOverlayEvent, + WorkerMetricsEvent, } from "../../InputHandler"; import { translateText } from "../../Utils"; import { FrameProfiler } from "../FrameProfiler"; @@ -42,6 +45,18 @@ export class PerformanceOverlay extends LitElement implements Layer { @state() private isVisible: boolean = false; + @state() + private workerMetrics: WorkerMetricsMessage | null = null; + + @state() + private workerMetricsAgeMs: number = 0; + + @state() + private workerIncludeTrace: boolean = false; + + @state() + private workerIntervalMs: number = 1000; + @state() private isDragging: boolean = false; @@ -60,6 +75,7 @@ export class PerformanceOverlay extends LitElement implements Layer { private dragStart: { x: number; y: number } = { x: 0, y: 0 }; private tickExecutionTimes: number[] = []; private tickDelayTimes: number[] = []; + private lastWorkerMetricsWallMs: number = 0; private copyStatusTimeoutId: ReturnType | null = null; @@ -232,11 +248,24 @@ export class PerformanceOverlay extends LitElement implements Layer { this.eventBus.on(TickMetricsEvent, (event: TickMetricsEvent) => { this.updateTickMetrics(event.tickExecutionDuration, event.tickDelay); }); + this.eventBus.on(WorkerMetricsEvent, (event: WorkerMetricsEvent) => { + this.workerMetrics = event.metrics; + this.lastWorkerMetricsWallMs = Date.now(); + this.workerMetricsAgeMs = 0; + this.requestUpdate(); + }); } setVisible(visible: boolean) { this.isVisible = visible; FrameProfiler.setEnabled(visible); + this.eventBus.emit( + new SetWorkerDebugEvent({ + enabled: visible, + intervalMs: this.workerIntervalMs, + includeTrace: this.workerIncludeTrace, + }), + ); } private handleClose() { @@ -326,10 +355,21 @@ export class PerformanceOverlay extends LitElement implements Layer { // Update FrameProfiler enabled state when visibility changes if (wasVisible !== this.isVisible) { FrameProfiler.setEnabled(this.isVisible); + this.eventBus.emit( + new SetWorkerDebugEvent({ + enabled: this.isVisible, + intervalMs: this.workerIntervalMs, + includeTrace: this.workerIncludeTrace, + }), + ); } if (!this.isVisible) return; + if (this.lastWorkerMetricsWallMs > 0) { + this.workerMetricsAgeMs = Date.now() - this.lastWorkerMetricsWallMs; + } + const now = performance.now(); // Initialize timing on first call @@ -486,10 +526,99 @@ export class PerformanceOverlay extends LitElement implements Layer { executionSamples: [...this.tickExecutionTimes], delaySamples: [...this.tickDelayTimes], }, + worker: { + enabled: this.isVisible, + includeTrace: this.workerIncludeTrace, + intervalMs: this.workerIntervalMs, + lastMetricsAgeMs: this.workerMetricsAgeMs, + metrics: this.workerMetrics, + }, layers: this.layerBreakdown.map((layer) => ({ ...layer })), }; } + private getWorkerKeyStats(metrics: WorkerMetricsMessage | null): { + loopLagAvg: number; + loopLagMax: number; + simDelayAvg: number; + simDelayMax: number; + simExecAvg: number; + simExecMax: number; + rfQueueAvg: number | null; + rfQueueMax: number | null; + rfHandlerAvg: number | null; + rfHandlerMax: number | null; + traceLines: string[]; + } { + if (!metrics) { + return { + loopLagAvg: 0, + loopLagMax: 0, + simDelayAvg: 0, + simDelayMax: 0, + simExecAvg: 0, + simExecMax: 0, + rfQueueAvg: null, + rfQueueMax: null, + rfHandlerAvg: null, + rfHandlerMax: null, + traceLines: [], + }; + } + + const rfQueueAvg = metrics.msgQueueMsAvg?.["render_frame"]; + const rfQueueMax = metrics.msgQueueMsMax?.["render_frame"]; + const rfHandlerAvg = metrics.msgHandlerMsAvg?.["render_frame"]; + const rfHandlerMax = metrics.msgHandlerMsMax?.["render_frame"]; + const traceLines = + metrics.trace && metrics.trace.length > 0 ? metrics.trace.slice(-5) : []; + + return { + loopLagAvg: metrics.eventLoopLagMsAvg, + loopLagMax: metrics.eventLoopLagMsMax, + simDelayAvg: metrics.simPumpDelayMsAvg, + simDelayMax: metrics.simPumpDelayMsMax, + simExecAvg: metrics.simPumpExecMsAvg, + simExecMax: metrics.simPumpExecMsMax, + rfQueueAvg: typeof rfQueueAvg === "number" ? rfQueueAvg : null, + rfQueueMax: typeof rfQueueMax === "number" ? rfQueueMax : null, + rfHandlerAvg: typeof rfHandlerAvg === "number" ? rfHandlerAvg : null, + rfHandlerMax: typeof rfHandlerMax === "number" ? rfHandlerMax : null, + traceLines, + }; + } + + private formatMs(v: number | null | undefined, digits: number = 1): string { + if (v === null || v === undefined || !Number.isFinite(v)) return "—"; + return `${v.toFixed(digits)}ms`; + } + + private onWorkerTraceToggle(e: Event) { + const target = e.target as HTMLInputElement; + this.workerIncludeTrace = !!target.checked; + this.eventBus.emit( + new SetWorkerDebugEvent({ + enabled: this.isVisible, + intervalMs: this.workerIntervalMs, + includeTrace: this.workerIncludeTrace, + }), + ); + } + + private onWorkerIntervalChange(e: Event) { + const target = e.target as HTMLSelectElement; + const ms = Number.parseInt(target.value, 10); + if (!Number.isFinite(ms) || ms <= 0) return; + this.workerIntervalMs = ms; + this.eventBus.emit( + new SetWorkerDebugEvent({ + enabled: this.isVisible, + intervalMs: this.workerIntervalMs, + includeTrace: this.workerIncludeTrace, + }), + ); + } + private clearCopyStatusTimeout() { if (this.copyStatusTimeoutId !== null) { clearTimeout(this.copyStatusTimeoutId); @@ -550,6 +679,8 @@ export class PerformanceOverlay extends LitElement implements Layer { ? Math.max(...this.layerBreakdown.map((l) => l.avg)) : 1; + const worker = this.getWorkerKeyStats(this.workerMetrics); + return html`
${this.tickDelayAvg.toFixed(2)}ms (max: ${this.tickDelayMax}ms)
+
+
Worker
+
+ metrics age + ${this.formatMs(this.workerMetricsAgeMs, 0)} +
+
+ event loop lag (avg / max) + ${this.formatMs(worker.loopLagAvg)} / + ${this.formatMs(worker.loopLagMax, 0)} +
+
+ sim pump delay (avg / max) + ${this.formatMs(worker.simDelayAvg)} / + ${this.formatMs(worker.simDelayMax, 0)} +
+
+ sim pump exec (avg / max) + ${this.formatMs(worker.simExecAvg)} / + ${this.formatMs(worker.simExecMax, 0)} +
+
+ render_frame queue (avg / max) + ${this.formatMs(worker.rfQueueAvg, 0)} / + ${this.formatMs(worker.rfQueueMax, 0)} +
+
+ render_frame handler (avg / max) + ${this.formatMs(worker.rfHandlerAvg, 0)} / + ${this.formatMs(worker.rfHandlerMax, 0)} +
+
+ trace + + + + +
+ ${worker.traceLines.length + ? html`
+
+ ${worker.traceLines.join("\n")} +
+
` + : html``} +
${this.layerBreakdown.length ? html`
diff --git a/src/client/graphics/webgpu/TerritoryRendererProxy.ts b/src/client/graphics/webgpu/TerritoryRendererProxy.ts index 27ee30d25..cd08b14af 100644 --- a/src/client/graphics/webgpu/TerritoryRendererProxy.ts +++ b/src/client/graphics/webgpu/TerritoryRendererProxy.ts @@ -2,7 +2,6 @@ import { createCanvas } from "src/client/Utils"; import { Theme } from "../../../core/configuration/Config"; import { TileRef } from "../../../core/game/GameMap"; import { GameView } from "../../../core/game/GameView"; -import { generateID } from "../../../core/Util"; import { WorkerClient } from "../../../core/worker/WorkerClient"; import { InitRendererMessage, @@ -16,7 +15,6 @@ import { SetPaletteMessage, SetPatternsEnabledMessage, SetShaderSettingsMessage, - TickRendererMessage, ViewSize, ViewTransform, } from "../../../core/worker/WorkerMessages"; @@ -44,6 +42,8 @@ export class TerritoryRendererProxy { private lastSentViewSize: ViewSize | null = null; private lastSentViewTransform: ViewTransform | null = null; private renderInFlight = false; + private renderSeq = 0; + private renderCooldownUntilMs = 0; private constructor( private readonly game: GameView, @@ -386,25 +386,29 @@ export class TerritoryRendererProxy { } tick(): void { - const message: TickRendererMessage = { - type: "tick_renderer", - }; - this.sendToWorker(message); + // No-op: worker renderer ticks from worker-side game_update. + // Sending tick messages from the main thread duplicates GPU work and + // can stall Firefox badly under load. } render(): void { if (this.failed) { return; } + if (performance.now() < this.renderCooldownUntilMs) { + return; + } if (this.renderInFlight) { return; } this.renderInFlight = true; - const renderId = `render_${generateID()}`; + const renderId = `render_${++this.renderSeq}`; + const sentAtWallMs = Date.now(); const message: RenderFrameMessage = { type: "render_frame" }; message.id = renderId; + message.sentAtWallMs = sentAtWallMs; if ( !this.lastSentViewSize || @@ -432,15 +436,84 @@ export class TerritoryRendererProxy { worker.removeMessageHandler(renderId); return; } - this.renderInFlight = false; + + console.warn(`render_done timeout (${renderId})`); worker.removeMessageHandler(renderId); - }, 2000); + + // Recover from lost/blocked frames without flooding the worker. + this.renderInFlight = false; + this.renderCooldownUntilMs = performance.now() + 250; + + // Force a view resync on the next successful render. + this.lastSentViewSize = null; + this.lastSentViewTransform = null; + }, 15000); worker.addMessageHandler(renderId, (m: any) => { if (m?.type !== "render_done") { return; } clearTimeout(timeout); + const startedAt = typeof m.startedAt === "number" ? m.startedAt : NaN; + const endedAt = typeof m.endedAt === "number" ? m.endedAt : NaN; + const startedAtWallMs = + typeof m.startedAtWallMs === "number" ? m.startedAtWallMs : NaN; + const endedAtWallMs = + typeof m.endedAtWallMs === "number" ? m.endedAtWallMs : NaN; + const echoedSentAtWallMs = + typeof m.sentAtWallMs === "number" ? m.sentAtWallMs : sentAtWallMs; + if ( + Number.isFinite(startedAt) && + Number.isFinite(endedAt) && + Number.isFinite(startedAtWallMs) && + Number.isFinite(endedAtWallMs) && + Number.isFinite(echoedSentAtWallMs) + ) { + const queueMs = startedAtWallMs - echoedSentAtWallMs; + const renderMs = endedAt - startedAt; + const totalMs = endedAtWallMs - echoedSentAtWallMs; + const breakdown = + typeof m.renderCpuMs === "number" || + typeof m.renderGpuWaitMs === "number" || + typeof m.renderWaitPrevGpuMs === "number" || + typeof m.renderGetTextureMs === "number" + ? { + waitPrevGpuMs: + typeof m.renderWaitPrevGpuMs === "number" + ? Math.round(m.renderWaitPrevGpuMs) + : undefined, + waitPrevGpuTimedOut: + typeof m.renderWaitPrevGpuTimedOut === "boolean" + ? m.renderWaitPrevGpuTimedOut + : undefined, + cpuMs: + typeof m.renderCpuMs === "number" + ? Math.round(m.renderCpuMs) + : undefined, + getTextureMs: + typeof m.renderGetTextureMs === "number" + ? Math.round(m.renderGetTextureMs) + : undefined, + gpuWaitMs: + typeof m.renderGpuWaitMs === "number" + ? Math.round(m.renderGpuWaitMs) + : undefined, + gpuWaitTimedOut: + typeof m.renderGpuWaitTimedOut === "boolean" + ? m.renderGpuWaitTimedOut + : undefined, + } + : undefined; + if (totalMs > 1000 || queueMs > 1000 || renderMs > 1000) { + console.warn("worker render timing", { + id: renderId, + queueMs: Math.round(queueMs), + renderMs: Math.round(renderMs), + totalMs: Math.round(totalMs), + breakdown, + }); + } + } this.renderInFlight = false; }); } else { diff --git a/src/core/worker/Worker.worker.ts b/src/core/worker/Worker.worker.ts index 6c1b819ed..3b7e8915b 100644 --- a/src/core/worker/Worker.worker.ts +++ b/src/core/worker/Worker.worker.ts @@ -31,6 +31,7 @@ import { TileContextResultMessage, TransportShipSpawnResultMessage, WorkerMessage, + WorkerMetricsMessage, } from "./WorkerMessages"; import { WorkerTerritoryRenderer } from "./WorkerTerritoryRenderer"; @@ -44,6 +45,241 @@ let dirtyTiles: DirtyTileQueue | null = null; let dirtyTilesOverflow = false; let renderTileState: Uint16Array | null = null; +type WorkerDebugConfig = { + enabled: boolean; + intervalMs: number; + includeTrace: boolean; +}; + +class WorkerProfiler { + public config: WorkerDebugConfig = { + enabled: false, + intervalMs: 1000, + includeTrace: false, + }; + + private reportTimer: any = null; + private lastReportWallMs = 0; + + private eventLoopLagSum = 0; + private eventLoopLagCount = 0; + private eventLoopLagMax = 0; + + private simDelaySum = 0; + private simDelayCount = 0; + private simDelayMax = 0; + + private simExecSum = 0; + private simExecCount = 0; + private simExecMax = 0; + + private readonly msgCounts = new Map(); + private readonly msgHandlerSum = new Map(); + private readonly msgQueueSum = new Map(); + private readonly msgHandlerMax = new Map(); + private readonly msgQueueMax = new Map(); + + private traceRing: string[] = []; + private traceHead = 0; + private readonly traceCap = 160; + + start(): void { + if (this.reportTimer) return; + this.lastReportWallMs = Date.now(); + + // Event-loop lag sampler (low overhead). + let expected = Date.now() + 100; + setInterval(() => { + if (!this.config.enabled) return; + const now = Date.now(); + const lag = Math.max(0, now - expected); + expected = now + 100; + this.eventLoopLagSum += lag; + this.eventLoopLagCount++; + this.eventLoopLagMax = Math.max(this.eventLoopLagMax, lag); + }, 100); + + this.reportTimer = setInterval(() => this.report(), this.config.intervalMs); + } + + configure(next: Partial): void { + const prevInterval = this.config.intervalMs; + this.config = { + enabled: next.enabled ?? this.config.enabled, + intervalMs: Math.max( + 100, + (next.intervalMs ?? this.config.intervalMs) | 0, + ), + includeTrace: next.includeTrace ?? this.config.includeTrace, + }; + + if (this.config.enabled && !this.reportTimer) { + this.start(); + } + + if (this.reportTimer && this.config.intervalMs !== prevInterval) { + clearInterval(this.reportTimer); + this.reportTimer = setInterval( + () => this.report(), + this.config.intervalMs, + ); + } + } + + recordMessage(type: string, queueMs: number | null, handlerMs: number): void { + if (!this.config.enabled) return; + this.msgCounts.set(type, (this.msgCounts.get(type) ?? 0) + 1); + this.msgHandlerSum.set( + type, + (this.msgHandlerSum.get(type) ?? 0) + handlerMs, + ); + this.msgHandlerMax.set( + type, + Math.max(this.msgHandlerMax.get(type) ?? 0, handlerMs), + ); + if (queueMs !== null) { + this.msgQueueSum.set(type, (this.msgQueueSum.get(type) ?? 0) + queueMs); + this.msgQueueMax.set( + type, + Math.max(this.msgQueueMax.get(type) ?? 0, queueMs), + ); + } + + if (handlerMs > 25 || (queueMs !== null && queueMs > 250)) { + this.trace( + `${new Date().toISOString()} msg ${type} queue=${queueMs ?? "?"}ms handler=${Math.round(handlerMs)}ms`, + ); + } + } + + recordSimExec(execMs: number): void { + if (!this.config.enabled) return; + this.simExecSum += execMs; + this.simExecCount++; + this.simExecMax = Math.max(this.simExecMax, execMs); + if (execMs > 25) { + this.trace( + `${new Date().toISOString()} sim executeNextTick ${Math.round(execMs)}ms`, + ); + } + } + + recordSimDelay(delayMs: number): void { + if (!this.config.enabled) return; + this.simDelaySum += delayMs; + this.simDelayCount++; + this.simDelayMax = Math.max(this.simDelayMax, delayMs); + if (delayMs > 25) { + this.trace( + `${new Date().toISOString()} sim scheduleDelay ${Math.round(delayMs)}ms`, + ); + } + } + + trace(line: string): void { + if (!this.config.enabled || !this.config.includeTrace) return; + if (this.traceRing.length < this.traceCap) { + this.traceRing.push(line); + return; + } + this.traceRing[this.traceHead] = line; + this.traceHead = (this.traceHead + 1) % this.traceCap; + } + + private flushTrace(): string[] { + if (!this.config.includeTrace || this.traceRing.length === 0) { + return []; + } + if (this.traceRing.length < this.traceCap) { + return [...this.traceRing]; + } + return [ + ...this.traceRing.slice(this.traceHead), + ...this.traceRing.slice(0, this.traceHead), + ]; + } + + private report(): void { + if (!this.config.enabled) return; + const now = Date.now(); + const intervalMs = Math.max(1, now - this.lastReportWallMs); + this.lastReportWallMs = now; + + const toAvgRecord = ( + sumMap: Map, + countMap: Map, + ) => { + const out: Record = {}; + for (const [k, sum] of sumMap) { + const c = countMap.get(k) ?? 0; + if (c > 0) { + out[k] = sum / c; + } + } + return out; + }; + + const toMaxRecord = (maxMap: Map) => { + const out: Record = {}; + for (const [k, v] of maxMap) { + out[k] = v; + } + return out; + }; + + const msgCountsObj: Record = {}; + for (const [k, c] of this.msgCounts) { + msgCountsObj[k] = c; + } + + const metrics: WorkerMetricsMessage = { + type: "worker_metrics", + intervalMs, + eventLoopLagMsAvg: + this.eventLoopLagCount > 0 + ? this.eventLoopLagSum / this.eventLoopLagCount + : 0, + eventLoopLagMsMax: this.eventLoopLagMax, + simPumpDelayMsAvg: + this.simDelayCount > 0 ? this.simDelaySum / this.simDelayCount : 0, + simPumpDelayMsMax: this.simDelayMax, + simPumpExecMsAvg: + this.simExecCount > 0 ? this.simExecSum / this.simExecCount : 0, + simPumpExecMsMax: this.simExecMax, + msgCounts: msgCountsObj, + msgHandlerMsAvg: toAvgRecord(this.msgHandlerSum, this.msgCounts), + msgHandlerMsMax: toMaxRecord(this.msgHandlerMax), + msgQueueMsAvg: toAvgRecord(this.msgQueueSum, this.msgCounts), + msgQueueMsMax: toMaxRecord(this.msgQueueMax), + trace: this.config.includeTrace ? this.flushTrace() : undefined, + }; + + sendMessage(metrics); + + // Reset per-interval counters. + this.eventLoopLagSum = 0; + this.eventLoopLagCount = 0; + this.eventLoopLagMax = 0; + this.simDelaySum = 0; + this.simDelayCount = 0; + this.simDelayMax = 0; + this.simExecSum = 0; + this.simExecCount = 0; + this.simExecMax = 0; + this.msgCounts.clear(); + this.msgHandlerSum.clear(); + this.msgHandlerMax.clear(); + this.msgQueueSum.clear(); + this.msgQueueMax.clear(); + if (this.config.includeTrace) { + this.traceRing = []; + this.traceHead = 0; + } + } +} + +const profiler = new WorkerProfiler(); + let simPumpScheduled = false; function scheduleSimPump(): void { if (simPumpScheduled) { @@ -51,13 +287,17 @@ function scheduleSimPump(): void { } simPumpScheduled = true; + const scheduledAtWallMs = Date.now(); setTimeout(async () => { simPumpScheduled = false; if (!gameRunner) { return; } const gr = await gameRunner; + profiler.recordSimDelay(Date.now() - scheduledAtWallMs); + const execStart = performance.now(); gr.executeNextTick(); + profiler.recordSimExec(performance.now() - execStart); if (gr.hasPendingTurns()) { scheduleSimPump(); } @@ -140,7 +380,12 @@ function gameUpdate(gu: GameUpdateViewData | ErrorUpdate) { // Run compute passes at simulation tick cadence (not at render FPS). if (didWork) { - renderer.tick(); + const r: any = renderer as any; + if (typeof r.requestTick === "function") { + r.requestTick(); + } else { + renderer.tick(); + } } } @@ -156,408 +401,497 @@ function sendMessage(message: WorkerMessage) { ctx.addEventListener("message", async (e: MessageEvent) => { const message = e.data; + const queueMs = + typeof (message as any).sentAtWallMs === "number" + ? Date.now() - (message as any).sentAtWallMs + : null; + const handlerStart = performance.now(); - switch (message.type) { - case "heartbeat": - // Heartbeat is a high-frequency "wake up" signal from the main thread. - // Coalesce it and run simulation work in small slices to avoid backlog. - scheduleSimPump(); - break; - case "init": - try { - gameStartInfo = message.gameStartInfo; - myClientID = message.clientID; - gameRunner = createGameRunner( - message.gameStartInfo, - message.clientID, - mapLoader, - gameUpdate, - ).then((gr) => { - const numTiles = gr.game.width() * gr.game.height(); - // Capacity is bounded; on overflow we fall back to markAllDirty(). - dirtyTiles = new DirtyTileQueue(numTiles, Math.max(4096, numTiles)); - dirtyTilesOverflow = false; - renderTileState = new Uint16Array(gr.game.tileStateView()); - - gr.tileUpdateSink = (packedUpdate) => { - if (!dirtyTiles) { - return; - } - - const tile = Number(packedUpdate >> 16n) as TileRef; - const state = Number(packedUpdate & 0xffffn); - if (renderTileState) { - renderTileState[tile] = state; - } - const mark = (t: any) => { - if (!dirtyTiles!.mark(t)) { - dirtyTilesOverflow = true; - } - }; - mark(tile); - gr.game.forEachNeighbor(tile, (n) => mark(n)); - }; - - sendMessage({ - type: "initialized", - id: message.id, - } as InitializedMessage); - return gr; + try { + switch (message.type) { + case "set_worker_debug": + profiler.configure({ + enabled: message.enabled, + intervalMs: message.intervalMs, + includeTrace: message.includeTrace, }); - } catch (error) { - console.error("Failed to initialize game runner:", error); - throw error; - } - break; - - case "turn": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - - try { - const gr = await gameRunner; - gr.addTurn(message.turn); + break; + case "heartbeat": + // Heartbeat is a high-frequency "wake up" signal from the main thread. + // Coalesce it and run simulation work in small slices to avoid backlog. scheduleSimPump(); - } catch (error) { - console.error("Failed to process turn:", error); - throw error; - } - break; + break; + case "init": + try { + gameStartInfo = message.gameStartInfo; + myClientID = message.clientID; + gameRunner = createGameRunner( + message.gameStartInfo, + message.clientID, + mapLoader, + gameUpdate, + ).then((gr) => { + const numTiles = gr.game.width() * gr.game.height(); + // Capacity is bounded; on overflow we fall back to markAllDirty(). + dirtyTiles = new DirtyTileQueue(numTiles, Math.max(4096, numTiles)); + dirtyTilesOverflow = false; + renderTileState = new Uint16Array(gr.game.tileStateView()); - case "tile_context": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - try { - const gr = await gameRunner; - const tile = message.tile; - const hasOwner = gr.game.hasOwner(tile); - const ownerSmallId = hasOwner ? gr.game.ownerID(tile) : null; - let ownerId: PlayerID | null = null; - if (hasOwner) { - const owner = gr.game.owner(tile); - ownerId = owner && owner.isPlayer() ? owner.id() : null; + gr.tileUpdateSink = (packedUpdate) => { + if (!dirtyTiles) { + return; + } + + const tile = Number(packedUpdate >> 16n) as TileRef; + const state = Number(packedUpdate & 0xffffn); + if (renderTileState) { + renderTileState[tile] = state; + } + const mark = (t: any) => { + if (!dirtyTiles!.mark(t)) { + dirtyTilesOverflow = true; + } + }; + mark(tile); + gr.game.forEachNeighbor(tile, (n) => mark(n)); + }; + + sendMessage({ + type: "initialized", + id: message.id, + } as InitializedMessage); + return gr; + }); + } catch (error) { + console.error("Failed to initialize game runner:", error); + throw error; } - sendMessage({ - type: "tile_context_result", - id: message.id, - result: { - hasOwner, - ownerSmallId, - ownerId, - hasFallout: gr.game.hasFallout(tile), - isDefended: gr.game.isDefended(tile), - }, - } as TileContextResultMessage); - } catch (error) { - console.error("Failed to fetch tile context:", error); - throw error; - } - break; + break; - case "player_actions": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - - try { - const actions = (await gameRunner).playerActions( - message.playerID, - message.x, - message.y, - ); - sendMessage({ - type: "player_actions_result", - id: message.id, - result: actions, - } as PlayerActionsResultMessage); - } catch (error) { - console.error("Failed to check borders:", error); - throw error; - } - break; - case "player_profile": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - - try { - const profile = (await gameRunner).playerProfile(message.playerID); - sendMessage({ - type: "player_profile_result", - id: message.id, - result: profile, - } as PlayerProfileResultMessage); - } catch (error) { - console.error("Failed to check borders:", error); - throw error; - } - break; - case "player_border_tiles": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - - try { - const borderTiles = (await gameRunner).playerBorderTiles( - message.playerID, - ); - sendMessage({ - type: "player_border_tiles_result", - id: message.id, - result: borderTiles, - } as PlayerBorderTilesResultMessage); - } catch (error) { - console.error("Failed to get border tiles:", error); - throw error; - } - break; - case "attack_average_position": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - - try { - const averagePosition = (await gameRunner).attackAveragePosition( - message.playerID, - message.attackID, - ); - sendMessage({ - type: "attack_average_position_result", - id: message.id, - x: averagePosition ? averagePosition.x : null, - y: averagePosition ? averagePosition.y : null, - } as AttackAveragePositionResultMessage); - } catch (error) { - console.error("Failed to get attack average position:", error); - throw error; - } - break; - case "transport_ship_spawn": - if (!gameRunner) { - throw new Error("Game runner not initialized"); - } - - try { - const spawnTile = (await gameRunner).bestTransportShipSpawn( - message.playerID, - message.targetTile, - ); - sendMessage({ - type: "transport_ship_spawn_result", - id: message.id, - result: spawnTile, - } as TransportShipSpawnResultMessage); - } catch (error) { - console.error("Failed to spawn transport ship:", error); - } - break; - - case "init_renderer": - try { - if (!gameRunner || !gameStartInfo) { + case "turn": + if (!gameRunner) { throw new Error("Game runner not initialized"); } - const gr = await gameRunner; - (renderer as any)?.dispose?.(); - renderer = null; - - // Create theme based on darkMode flag from main thread - // (can't access userSettings in worker, so it's passed from main thread) - const theme: Theme = message.darkMode - ? new PastelThemeDark() - : new PastelTheme(); - - const cosmeticsByClientID = new Map(); - for (const p of gameStartInfo.players) { - cosmeticsByClientID.set( - p.clientID, - (p.cosmetics ?? {}) as PlayerCosmetics, - ); + try { + const gr = await gameRunner; + gr.addTurn(message.turn); + scheduleSimPump(); + } catch (error) { + console.error("Failed to process turn:", error); + throw error; } + break; - const backend = message.backend ?? "webgpu"; - renderer = - backend === "canvas2d" - ? new WorkerCanvas2DRenderer() - : new WorkerTerritoryRenderer(); - - renderTileState ??= new Uint16Array(gr.game.tileStateView()); - await renderer.init( - message.offscreenCanvas, - gr, - theme, - myClientID, - cosmeticsByClientID, - renderTileState, - ); - - sendMessage({ - type: "renderer_ready", - id: message.id, - ok: true, - } as RendererReadyMessage); - } catch (error) { - console.error("Failed to initialize renderer:", error); - sendMessage({ - type: "renderer_ready", - id: message.id, - ok: false, - error: error instanceof Error ? error.message : String(error), - } as RendererReadyMessage); - renderer = null; - } - break; - - case "set_patterns_enabled": - if (renderer) { - renderer.setPatternsEnabled(message.enabled); - renderer.tick(); - } - break; - - case "set_palette": - if (renderer) { - renderer.setPaletteFromBytes( - message.paletteWidth, - message.maxSmallId, - message.row0, - message.row1, - ); - renderer.tick(); - } - break; - - case "set_view_size": - if (renderer) { - renderer.setViewSize(message.width, message.height); - } - break; - - case "set_view_transform": - if (renderer) { - renderer.setViewTransform( - message.scale, - message.offsetX, - message.offsetY, - ); - } - break; - - case "set_alternative_view": - if (renderer) { - renderer.setAlternativeView(message.enabled); - } - break; - - case "set_highlighted_owner": - if (renderer) { - renderer.setHighlightedOwnerId(message.ownerSmallId); - } - break; - - case "set_shader_settings": - if (renderer) { - const r: any = renderer as any; - if (message.territoryShader) { - r.setTerritoryShader?.(message.territoryShader); + case "tile_context": + if (!gameRunner) { + throw new Error("Game runner not initialized"); } - if (message.territoryShaderParams0 && message.territoryShaderParams1) { - r.setTerritoryShaderParams?.( - message.territoryShaderParams0, - message.territoryShaderParams1, - ); - } - if (message.terrainShader) { - r.setTerrainShader?.(message.terrainShader); - } - if (message.terrainShaderParams0 && message.terrainShaderParams1) { - r.setTerrainShaderParams?.( - message.terrainShaderParams0, - message.terrainShaderParams1, - ); - } - if (message.preSmoothing) { - r.setPreSmoothing?.( - message.preSmoothing.enabled, - message.preSmoothing.shaderPath, - message.preSmoothing.params0, - ); - } - if (message.postSmoothing) { - r.setPostSmoothing?.( - message.postSmoothing.enabled, - message.postSmoothing.shaderPath, - message.postSmoothing.params0, - ); - } - } - break; - - case "mark_tile": - if (renderer) { - renderer.markTile(message.tile); - } - break; - - case "mark_all_dirty": - if (renderer) { - renderer.markAllDirty(); - renderer.tick(); - } - break; - - case "refresh_palette": - if (renderer) { - renderer.refreshPalette(); - renderer.tick(); - } - break; - - case "refresh_terrain": - if (renderer) { - renderer.refreshTerrain(); - } - break; - - case "tick_renderer": - if (renderer) { - const start = performance.now(); - renderer.tick(); - const computeMs = performance.now() - start; - sendMessage({ - type: "renderer_metrics", - computeMs, - }); - } - break; - - case "render_frame": - if (renderer) { - if ("viewSize" in message && message.viewSize) { - renderer.setViewSize(message.viewSize.width, message.viewSize.height); - } - if ("viewTransform" in message && message.viewTransform) { - renderer.setViewTransform( - message.viewTransform.scale, - message.viewTransform.offsetX, - message.viewTransform.offsetY, - ); - } - renderer.render(); - if (message.id) { + try { + const gr = await gameRunner; + const tile = message.tile; + const hasOwner = gr.game.hasOwner(tile); + const ownerSmallId = hasOwner ? gr.game.ownerID(tile) : null; + let ownerId: PlayerID | null = null; + if (hasOwner) { + const owner = gr.game.owner(tile); + ownerId = owner && owner.isPlayer() ? owner.id() : null; + } sendMessage({ - type: "render_done", + type: "tile_context_result", id: message.id, - } as RenderDoneMessage); + result: { + hasOwner, + ownerSmallId, + ownerId, + hasFallout: gr.game.hasFallout(tile), + isDefended: gr.game.isDefended(tile), + }, + } as TileContextResultMessage); + } catch (error) { + console.error("Failed to fetch tile context:", error); + throw error; } - } - break; + break; - default: - console.warn("Unknown message :", message); + case "player_actions": + if (!gameRunner) { + throw new Error("Game runner not initialized"); + } + + try { + const actions = (await gameRunner).playerActions( + message.playerID, + message.x, + message.y, + ); + sendMessage({ + type: "player_actions_result", + id: message.id, + result: actions, + } as PlayerActionsResultMessage); + } catch (error) { + console.error("Failed to check borders:", error); + throw error; + } + break; + case "player_profile": + if (!gameRunner) { + throw new Error("Game runner not initialized"); + } + + try { + const profile = (await gameRunner).playerProfile(message.playerID); + sendMessage({ + type: "player_profile_result", + id: message.id, + result: profile, + } as PlayerProfileResultMessage); + } catch (error) { + console.error("Failed to check borders:", error); + throw error; + } + break; + case "player_border_tiles": + if (!gameRunner) { + throw new Error("Game runner not initialized"); + } + + try { + const borderTiles = (await gameRunner).playerBorderTiles( + message.playerID, + ); + sendMessage({ + type: "player_border_tiles_result", + id: message.id, + result: borderTiles, + } as PlayerBorderTilesResultMessage); + } catch (error) { + console.error("Failed to get border tiles:", error); + throw error; + } + break; + case "attack_average_position": + if (!gameRunner) { + throw new Error("Game runner not initialized"); + } + + try { + const averagePosition = (await gameRunner).attackAveragePosition( + message.playerID, + message.attackID, + ); + sendMessage({ + type: "attack_average_position_result", + id: message.id, + x: averagePosition ? averagePosition.x : null, + y: averagePosition ? averagePosition.y : null, + } as AttackAveragePositionResultMessage); + } catch (error) { + console.error("Failed to get attack average position:", error); + throw error; + } + break; + case "transport_ship_spawn": + if (!gameRunner) { + throw new Error("Game runner not initialized"); + } + + try { + const spawnTile = (await gameRunner).bestTransportShipSpawn( + message.playerID, + message.targetTile, + ); + sendMessage({ + type: "transport_ship_spawn_result", + id: message.id, + result: spawnTile, + } as TransportShipSpawnResultMessage); + } catch (error) { + console.error("Failed to spawn transport ship:", error); + } + break; + + case "init_renderer": + try { + if (!gameRunner || !gameStartInfo) { + throw new Error("Game runner not initialized"); + } + const gr = await gameRunner; + + (renderer as any)?.dispose?.(); + renderer = null; + + // Create theme based on darkMode flag from main thread + // (can't access userSettings in worker, so it's passed from main thread) + const theme: Theme = message.darkMode + ? new PastelThemeDark() + : new PastelTheme(); + + const cosmeticsByClientID = new Map(); + for (const p of gameStartInfo.players) { + cosmeticsByClientID.set( + p.clientID, + (p.cosmetics ?? {}) as PlayerCosmetics, + ); + } + + const backend = message.backend ?? "webgpu"; + renderer = + backend === "canvas2d" + ? new WorkerCanvas2DRenderer() + : new WorkerTerritoryRenderer(); + + renderTileState ??= new Uint16Array(gr.game.tileStateView()); + await renderer.init( + message.offscreenCanvas, + gr, + theme, + myClientID, + cosmeticsByClientID, + renderTileState, + ); + + sendMessage({ + type: "renderer_ready", + id: message.id, + ok: true, + } as RendererReadyMessage); + } catch (error) { + console.error("Failed to initialize renderer:", error); + sendMessage({ + type: "renderer_ready", + id: message.id, + ok: false, + error: error instanceof Error ? error.message : String(error), + } as RendererReadyMessage); + renderer = null; + } + break; + + case "set_patterns_enabled": + if (renderer) { + renderer.setPatternsEnabled(message.enabled); + const r: any = renderer as any; + if (typeof r.requestTick === "function") { + r.requestTick(); + } else { + renderer.tick(); + } + } + break; + + case "set_palette": + if (renderer) { + renderer.setPaletteFromBytes( + message.paletteWidth, + message.maxSmallId, + message.row0, + message.row1, + ); + const r: any = renderer as any; + if (typeof r.requestTick === "function") { + r.requestTick(); + } else { + renderer.tick(); + } + } + break; + + case "set_view_size": + if (renderer) { + renderer.setViewSize(message.width, message.height); + } + break; + + case "set_view_transform": + if (renderer) { + renderer.setViewTransform( + message.scale, + message.offsetX, + message.offsetY, + ); + } + break; + + case "set_alternative_view": + if (renderer) { + renderer.setAlternativeView(message.enabled); + } + break; + + case "set_highlighted_owner": + if (renderer) { + renderer.setHighlightedOwnerId(message.ownerSmallId); + } + break; + + case "set_shader_settings": + if (renderer) { + const r: any = renderer as any; + if (message.territoryShader) { + r.setTerritoryShader?.(message.territoryShader); + } + if ( + message.territoryShaderParams0 && + message.territoryShaderParams1 + ) { + r.setTerritoryShaderParams?.( + message.territoryShaderParams0, + message.territoryShaderParams1, + ); + } + if (message.terrainShader) { + r.setTerrainShader?.(message.terrainShader); + } + if (message.terrainShaderParams0 && message.terrainShaderParams1) { + r.setTerrainShaderParams?.( + message.terrainShaderParams0, + message.terrainShaderParams1, + ); + } + if (message.preSmoothing) { + r.setPreSmoothing?.( + message.preSmoothing.enabled, + message.preSmoothing.shaderPath, + message.preSmoothing.params0, + ); + } + if (message.postSmoothing) { + r.setPostSmoothing?.( + message.postSmoothing.enabled, + message.postSmoothing.shaderPath, + message.postSmoothing.params0, + ); + } + } + break; + + case "mark_tile": + if (renderer) { + renderer.markTile(message.tile); + } + break; + + case "mark_all_dirty": + if (renderer) { + renderer.markAllDirty(); + const r: any = renderer as any; + if (typeof r.requestTick === "function") { + r.requestTick(); + } else { + renderer.tick(); + } + } + break; + + case "refresh_palette": + if (renderer) { + renderer.refreshPalette(); + const r: any = renderer as any; + if (typeof r.requestTick === "function") { + r.requestTick(); + } else { + renderer.tick(); + } + } + break; + + case "refresh_terrain": + if (renderer) { + renderer.refreshTerrain(); + } + break; + + case "tick_renderer": + if (renderer) { + const start = performance.now(); + renderer.tick(); + const computeMs = performance.now() - start; + sendMessage({ + type: "renderer_metrics", + computeMs, + }); + } + break; + + case "render_frame": + if (renderer) { + const id = message.id; + const startedAt = performance.now(); + const startedAtWallMs = Date.now(); + let renderWaitPrevGpuMs: number | undefined; + let renderCpuMs: number | undefined; + let renderGetTextureMs: number | undefined; + let renderGpuWaitMs: number | undefined; + let renderWaitPrevGpuTimedOut: boolean | undefined; + let renderGpuWaitTimedOut: boolean | undefined; + try { + if ("viewSize" in message && message.viewSize) { + renderer.setViewSize( + message.viewSize.width, + message.viewSize.height, + ); + } + if ("viewTransform" in message && message.viewTransform) { + renderer.setViewTransform( + message.viewTransform.scale, + message.viewTransform.offsetX, + message.viewTransform.offsetY, + ); + } + const r: any = renderer as any; + if (typeof r.renderAsync === "function") { + const breakdown = await r.renderAsync(); + if (breakdown) { + renderWaitPrevGpuMs = breakdown.waitPrevGpuMs; + renderCpuMs = breakdown.cpuMs; + renderGetTextureMs = breakdown.getTextureMs; + renderGpuWaitMs = breakdown.gpuWaitMs; + renderWaitPrevGpuTimedOut = breakdown.waitPrevGpuTimedOut; + renderGpuWaitTimedOut = breakdown.gpuWaitTimedOut; + } + } else { + renderer.render(); + } + } catch (error) { + console.error("render_frame failed:", error); + } finally { + const endedAt = performance.now(); + const endedAtWallMs = Date.now(); + if (id) { + sendMessage({ + type: "render_done", + id, + sentAtWallMs: + typeof (message as any).sentAtWallMs === "number" + ? (message as any).sentAtWallMs + : undefined, + startedAtWallMs, + endedAtWallMs, + startedAt, + endedAt, + renderWaitPrevGpuMs, + renderCpuMs, + renderGetTextureMs, + renderGpuWaitMs, + renderWaitPrevGpuTimedOut, + renderGpuWaitTimedOut, + } as RenderDoneMessage); + } + } + } + break; + + default: + console.warn("Unknown message :", message); + } + } finally { + profiler.recordMessage( + (message as any).type ?? "unknown", + queueMs, + performance.now() - handlerStart, + ); } }); diff --git a/src/core/worker/WorkerClient.ts b/src/core/worker/WorkerClient.ts index 469b9ab84..ee31cd712 100644 --- a/src/core/worker/WorkerClient.ts +++ b/src/core/worker/WorkerClient.ts @@ -9,7 +9,12 @@ import { TileRef } from "../game/GameMap"; import { ErrorUpdate, GameUpdateViewData } from "../game/GameUpdates"; import { ClientID, GameStartInfo, Turn } from "../Schemas"; import { generateID } from "../Util"; -import { TileContext, WorkerMessage } from "./WorkerMessages"; +import { + SetWorkerDebugMessage, + TileContext, + WorkerMessage, + WorkerMetricsMessage, +} from "./WorkerMessages"; export class WorkerClient { private worker: Worker; @@ -18,6 +23,7 @@ export class WorkerClient { private gameUpdateCallback?: ( update: GameUpdateViewData | ErrorUpdate, ) => void; + private workerMetricsCallback?: (metrics: WorkerMetricsMessage) => void; constructor( private gameStartInfo: GameStartInfo, @@ -45,6 +51,10 @@ export class WorkerClient { } break; + case "worker_metrics": + this.workerMetricsCallback?.(message); + break; + case "initialized": case "renderer_ready": default: @@ -78,6 +88,13 @@ export class WorkerClient { * Post a message to the worker with optional transferables. */ postMessage(message: any, transfer?: Transferable[]): void { + if ( + message && + typeof message === "object" && + typeof message.sentAtWallMs !== "number" + ) { + message.sentAtWallMs = Date.now(); + } if (transfer && transfer.length > 0) { this.worker.postMessage(message, transfer); return; @@ -85,6 +102,23 @@ export class WorkerClient { this.worker.postMessage(message); } + onWorkerMetrics(callback?: (metrics: WorkerMetricsMessage) => void): void { + this.workerMetricsCallback = callback; + } + + setWorkerDebug(config: { + enabled: boolean; + intervalMs?: number; + includeTrace?: boolean; + }): void { + this.postMessage({ + type: "set_worker_debug", + enabled: config.enabled, + intervalMs: config.intervalMs, + includeTrace: config.includeTrace, + } satisfies SetWorkerDebugMessage); + } + initialize(): Promise { return new Promise((resolve, reject) => { const messageId = generateID(); @@ -96,7 +130,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "init", id: messageId, gameStartInfo: this.gameStartInfo, @@ -125,14 +159,14 @@ export class WorkerClient { throw new Error("Worker not initialized"); } - this.worker.postMessage({ + this.postMessage({ type: "turn", turn, }); } sendHeartbeat() { - this.worker.postMessage({ + this.postMessage({ type: "heartbeat", }); } @@ -155,7 +189,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "player_profile", id: messageId, playerID: playerID, @@ -181,7 +215,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "player_border_tiles", id: messageId, playerID: playerID, @@ -211,7 +245,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "player_actions", id: messageId, playerID: playerID, @@ -247,7 +281,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "attack_average_position", id: messageId, playerID: playerID, @@ -277,7 +311,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "transport_ship_spawn", id: messageId, playerID: playerID, @@ -301,7 +335,7 @@ export class WorkerClient { } }); - this.worker.postMessage({ + this.postMessage({ type: "tile_context", id: messageId, tile, diff --git a/src/core/worker/WorkerMessages.ts b/src/core/worker/WorkerMessages.ts index ebb78b85b..3cda691c7 100644 --- a/src/core/worker/WorkerMessages.ts +++ b/src/core/worker/WorkerMessages.ts @@ -42,12 +42,19 @@ export type WorkerMessageType = | "tick_renderer" | "render_frame" | "render_done" + | "set_worker_debug" + | "worker_metrics" | "renderer_metrics"; // Base interface for all messages interface BaseWorkerMessage { type: WorkerMessageType; id?: string; + /** + * Cross-thread timestamp (Date.now()) set by the sender when enqueuing the + * message. Used for queue latency debugging. + */ + sentAtWallMs?: number; } export interface HeartbeatMessage extends BaseWorkerMessage { @@ -258,6 +265,36 @@ export interface RenderFrameMessage extends BaseWorkerMessage { // Renderer messages from worker to main thread export interface RenderDoneMessage extends BaseWorkerMessage { type: "render_done"; + /** + * Timestamp (performance.now()) in the worker right before starting work. + */ + startedAt?: number; + /** + * Timestamp (performance.now()) in the worker right after finishing work. + */ + endedAt?: number; + /** + * Echo of RenderFrameMessage.sentAtWallMs (if provided) so callers can + * compute queue/processing latency without storing state. + */ + sentAtWallMs?: number; + /** + * Timestamps (Date.now()) in the worker. Use these for cross-thread latency + * (Firefox may use a different time origin for performance.now()). + */ + startedAtWallMs?: number; + endedAtWallMs?: number; + + /** + * Optional breakdown from the worker's renderAsync implementation. + * All values are milliseconds. + */ + renderWaitPrevGpuMs?: number; + renderCpuMs?: number; + renderGetTextureMs?: number; + renderGpuWaitMs?: number; + renderWaitPrevGpuTimedOut?: boolean; + renderGpuWaitTimedOut?: boolean; } export interface RendererReadyMessage extends BaseWorkerMessage { @@ -271,6 +308,30 @@ export interface RendererMetricsMessage extends BaseWorkerMessage { computeMs: number; } +export interface SetWorkerDebugMessage extends BaseWorkerMessage { + type: "set_worker_debug"; + enabled: boolean; + intervalMs?: number; + includeTrace?: boolean; +} + +export interface WorkerMetricsMessage extends BaseWorkerMessage { + type: "worker_metrics"; + intervalMs: number; + eventLoopLagMsAvg: number; + eventLoopLagMsMax: number; + simPumpDelayMsAvg: number; + simPumpDelayMsMax: number; + simPumpExecMsAvg: number; + simPumpExecMsMax: number; + msgCounts: Record; + msgHandlerMsAvg: Record; + msgHandlerMsMax: Record; + msgQueueMsAvg: Record; + msgQueueMsMax: Record; + trace?: string[]; +} + // Union types for type safety export type MainThreadMessage = | HeartbeatMessage @@ -295,6 +356,7 @@ export type MainThreadMessage = | RefreshPaletteMessage | RefreshTerrainMessage | TickRendererMessage + | SetWorkerDebugMessage | RenderFrameMessage; // Message send from worker @@ -309,4 +371,5 @@ export type WorkerMessage = | TransportShipSpawnResultMessage | RenderDoneMessage | RendererReadyMessage - | RendererMetricsMessage; + | RendererMetricsMessage + | WorkerMetricsMessage; diff --git a/src/core/worker/WorkerTerritoryRenderer.ts b/src/core/worker/WorkerTerritoryRenderer.ts index 21d6398da..95139b1e4 100644 --- a/src/core/worker/WorkerTerritoryRenderer.ts +++ b/src/core/worker/WorkerTerritoryRenderer.ts @@ -28,6 +28,7 @@ export class WorkerTerritoryRenderer { private resources: GroundTruthData | null = null; private gameViewAdapter: GameViewAdapter | null = null; private ready = false; + private lastGpuWork: Promise | null = null; // Compute passes private computePasses: ComputePass[] = []; @@ -62,6 +63,10 @@ export class WorkerTerritoryRenderer { private postSmoothingEnabled = false; private defensePostRange: number; private patternsEnabled = false; + private tickPending = false; + private tickRunning = false; + private gpuWaitEnabled = true; + private readonly gpuWaitTimeoutMs = 250; /** * Initialize renderer with offscreen canvas and game data. @@ -548,9 +553,9 @@ export class WorkerTerritoryRenderer { * Perform one simulation tick. * Runs compute passes to update ground truth data. */ - tick(): void { + tick(): boolean { if (!this.ready || !this.device || !this.resources) { - return; + return false; } this.resources.updateTickTiming(performance.now() / 1000); @@ -579,7 +584,7 @@ export class WorkerTerritoryRenderer { (this.defendedStrengthPass?.needsUpdate() ?? false); if (!needsCompute) { - return; + return false; } const encoder = this.device.device.createCommandEncoder(); @@ -610,13 +615,61 @@ export class WorkerTerritoryRenderer { } this.device.device.queue.submit([encoder.finish()]); + return true; + } + + requestTick(): void { + this.tickPending = true; + if (this.tickRunning) { + return; + } + this.tickRunning = true; + void this.runTickLoop(); + } + + private async runTickLoop(): Promise { + try { + while (this.tickPending) { + this.tickPending = false; + + if (!this.ready || !this.device) { + return; + } + + if (this.gpuWaitEnabled && this.lastGpuWork) { + const r = await this.awaitGpuWork(this.lastGpuWork); + if (r.timedOut) { + this.gpuWaitEnabled = false; + } + this.lastGpuWork = null; + } + + const submitted = this.tick(); + const q: any = this.device.device.queue as any; + if (submitted && typeof q?.onSubmittedWorkDone === "function") { + const p = q.onSubmittedWorkDone() as Promise; + this.lastGpuWork = p.catch(() => {}); + if (this.gpuWaitEnabled) { + const r = await this.awaitGpuWork(this.lastGpuWork); + if (r.timedOut) { + this.gpuWaitEnabled = false; + this.lastGpuWork = null; + } else { + this.lastGpuWork = null; + } + } + } + } + } finally { + this.tickRunning = false; + } } /** * Render one frame. * Runs render passes to draw to the canvas. */ - render(): void { + render(onGetTextureMs?: (ms: number) => void): void { if ( !this.ready || !this.device || @@ -638,7 +691,11 @@ export class WorkerTerritoryRenderer { } const encoder = this.device.device.createCommandEncoder(); + const getTexStart = performance.now(); const swapchainView = this.device.context.getCurrentTexture().createView(); + if (onGetTextureMs) { + onGetTextureMs(performance.now() - getTexStart); + } if ( this.preSmoothingEnabled && @@ -692,4 +749,95 @@ export class WorkerTerritoryRenderer { this.device.device.queue.submit([encoder.finish()]); } + + async renderAsync(): Promise<{ + waitPrevGpuMs: number; + cpuMs: number; + getTextureMs: number; + gpuWaitMs: number; + waitPrevGpuTimedOut: boolean; + gpuWaitTimedOut: boolean; + } | null> { + if (!this.ready || !this.device) { + return null; + } + + let waitPrevGpuMs = 0; + let cpuMs = 0; + let getTextureMs = 0; + let gpuWaitMs = 0; + let waitPrevGpuTimedOut = false; + let gpuWaitTimedOut = false; + + if (this.gpuWaitEnabled && this.lastGpuWork) { + const t0 = performance.now(); + const r = await this.awaitGpuWork(this.lastGpuWork); + waitPrevGpuTimedOut = r.timedOut; + if (r.timedOut) { + this.gpuWaitEnabled = false; + } + waitPrevGpuMs = performance.now() - t0; + this.lastGpuWork = null; + } + + const cpuStart = performance.now(); + this.render((ms) => { + getTextureMs = ms; + }); + cpuMs = performance.now() - cpuStart; + + const q: any = this.device.device.queue as any; + if (typeof q?.onSubmittedWorkDone !== "function") { + this.lastGpuWork = null; + return { + waitPrevGpuMs, + cpuMs, + getTextureMs, + gpuWaitMs, + waitPrevGpuTimedOut, + gpuWaitTimedOut, + }; + } + + const gpuStart = performance.now(); + const p = q.onSubmittedWorkDone() as Promise; + this.lastGpuWork = p.catch(() => {}); + if (this.gpuWaitEnabled) { + const r = await this.awaitGpuWork(this.lastGpuWork); + gpuWaitTimedOut = r.timedOut; + if (r.timedOut) { + this.gpuWaitEnabled = false; + this.lastGpuWork = null; + } else { + this.lastGpuWork = null; + } + gpuWaitMs = performance.now() - gpuStart; + } + + return { + waitPrevGpuMs, + cpuMs, + getTextureMs, + gpuWaitMs, + waitPrevGpuTimedOut, + gpuWaitTimedOut, + }; + } + + private async awaitGpuWork( + work: Promise, + ): Promise<{ timedOut: boolean }> { + let timeoutId: any = null; + const timeout = new Promise<"timeout">((resolve) => { + timeoutId = setTimeout(() => resolve("timeout"), this.gpuWaitTimeoutMs); + }); + const result = await Promise.race([ + work.then(() => "done" as const), + timeout, + ]); + if (timeoutId !== null) { + clearTimeout(timeoutId); + } + return { timedOut: result === "timeout" }; + } }