diff --git a/packages/cli/src/commands/render.ts b/packages/cli/src/commands/render.ts index f53af70355..83525a1c90 100644 --- a/packages/cli/src/commands/render.ts +++ b/packages/cli/src/commands/render.ts @@ -1550,6 +1550,7 @@ function trackRenderMetrics( deBlankRecaptures: perf?.drawElement?.blankRecaptures, deBoundaryFrames: perf?.drawElement?.boundaryFrames, deNcprFallbacks: perf?.drawElement?.ncprFallbacks, + deFrameTimeouts: perf?.drawElement?.frameTimeouts, compositionDurationMs, compositionWidth: perf?.resolution.width, compositionHeight: perf?.resolution.height, diff --git a/packages/cli/src/telemetry/events.ts b/packages/cli/src/telemetry/events.ts index 965c47f718..838b1cfc30 100644 --- a/packages/cli/src/telemetry/events.ts +++ b/packages/cli/src/telemetry/events.ts @@ -297,6 +297,7 @@ export function trackRenderComplete( deBlankRecaptures?: number; deBoundaryFrames?: number; deNcprFallbacks?: number; + deFrameTimeouts?: number; // "cli" when triggered by `hyperframes render` (default), "studio" when // triggered by a studio preview-server render (POST /api/projects/:id/render). source?: "cli" | "studio"; @@ -399,6 +400,7 @@ export function trackRenderComplete( de_blank_recaptures: props.deBlankRecaptures, de_boundary_frames: props.deBoundaryFrames, de_ncpr_fallbacks: props.deNcprFallbacks, + de_frame_timeouts: props.deFrameTimeouts, ...powerStateFields(), source: props.source ?? "cli", composition_duration_ms: props.compositionDurationMs, diff --git a/packages/engine/src/services/frameCapture-frameDeadline.test.ts b/packages/engine/src/services/frameCapture-frameDeadline.test.ts new file mode 100644 index 0000000000..427c09b443 --- /dev/null +++ b/packages/engine/src/services/frameCapture-frameDeadline.test.ts @@ -0,0 +1,45 @@ +/** + * Tests for the per-frame drawElement deadline (`withFrameDeadline`, PRINFRA-488). + * + * The deadline races the capture round-trip from OUTSIDE `captureFrameCore`, + * because puppeteer cannot abort an in-flight `page.evaluate`. That is exactly + * why the stall counter has to live in the `onTimeout` hook: a wedged renderer + * never returns, so no catch block inside the work promise ever runs. The first + * shipped version incremented `session.deFrameTimeouts` in that unreachable + * catch, so the counter — and the `CapturePerfSummary` field it feeds — read 0 + * on every stalled render. + */ + +import { describe, expect, it, vi } from "vitest"; +import { withFrameDeadline } from "./frameCapture.js"; + +describe("withFrameDeadline", () => { + it("rejects with DeFrameTimeoutError and fires onTimeout when work outlives the deadline", async () => { + vi.useFakeTimers(); + try { + const onTimeout = vi.fn(); + // Never settles — the wedged-renderer shape. + const raced = withFrameDeadline(new Promise(() => {}), "frame 7", 15_000, onTimeout); + const assertion = expect(raced).rejects.toThrow(/frame 7 exceeded 15000ms/); + await vi.advanceTimersByTimeAsync(15_000); + await assertion; + expect(onTimeout).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }); + + it("passes the value through and leaves onTimeout alone when work wins", async () => { + vi.useFakeTimers(); + try { + const onTimeout = vi.fn(); + const raced = withFrameDeadline(Promise.resolve("buffer"), "frame 7", 15_000, onTimeout); + await expect(raced).resolves.toBe("buffer"); + // Past the deadline: the cleared timer must not fire late. + await vi.advanceTimersByTimeAsync(30_000); + expect(onTimeout).not.toHaveBeenCalled(); + } finally { + vi.useRealTimers(); + } + }); +}); diff --git a/packages/engine/src/services/frameCapture.ts b/packages/engine/src/services/frameCapture.ts index 524154934d..7e9cd3713e 100644 --- a/packages/engine/src/services/frameCapture.ts +++ b/packages/engine/src/services/frameCapture.ts @@ -226,6 +226,13 @@ export interface CaptureSession { deVerifyInitMs?: number; /** Count of per-frame "No cached paint record" screenshot fallbacks (telemetry). */ deNcprFallbacks?: number; + /** + * Count of drawElement frame captures that blew `HF_DE_FRAME_TIMEOUT_MS` + * because the renderer stopped scheduling after drawElementImage returned + * (PRINFRA-488). Each one aborts the drawElement attempt so the whole render + * retries via screenshot. + */ + deFrameTimeouts?: number; /** * drawElement init passed every gate but stopped before verification + * canvas injection: the session has no video-frame injector yet (probe @@ -3415,6 +3422,69 @@ function isRecoverableDrawElementError(err: unknown): boolean { return isNoCachedPaintRecordError(err) || isCanvasNotInitializedError(err); } +/** + * Per-frame deadline for the drawElement capture round-trip. + * + * drawElementImage can return normally and then leave the renderer not draining + * its task queue: the `setTimeout(…, 0)` that drawAndEncode schedules to run + * `toDataURL` never fires, so the capture `page.evaluate` never settles. + * Reproduced deterministically on Chromium 152.0.7977.30, one comp, always the + * same frame (PRINFRA-488). Nothing below the render-level watchdog bounded + * this, so a single bad frame failed the ENTIRE render after a 60 s stall. + * + * This bounds the round-trip so the producer can discard the wedged page and + * retry the whole render on a fresh screenshot session. A per-frame screenshot + * cannot recover because the same page has stopped scheduling. Tune with + * `HF_DE_FRAME_TIMEOUT_MS`; 0 disables. + */ +const DE_FRAME_TIMEOUT_MS = Number(process.env.HF_DE_FRAME_TIMEOUT_MS ?? "15000"); + +class DeFrameTimeoutError extends Error { + constructor(label: string, ms: number) { + super(`drawElement ${label} exceeded ${ms}ms (renderer stopped scheduling; see PRINFRA-488)`); + this.name = "DeFrameTimeoutError"; + } +} + +/** + * Race `work` against a deadline. The losing promise is NOT cancellable — + * puppeteer cannot abort an in-flight `page.evaluate` — so its rejection is + * swallowed to avoid an unhandled rejection when it eventually settles (or + * never does). The orphaned round-trip keeps running in its Chrome worker; + * that worker is reclaimed by the outer retry rebuilding the page + * (`closeOrphanedProbeForRetry`), not by anything here. + * + * `onTimeout` fires exactly when the deadline wins, and is the ONLY place the + * stall is observable: because the deadline races `work` from outside, nothing + * inside `work` — including its own catch blocks — ever sees this error. + * + * Exported for the deadline unit test; `captureFrameToBuffer` is the only + * production caller. + */ +export async function withFrameDeadline( + work: Promise, + label: string, + ms: number, + onTimeout?: () => void, +): Promise { + if (!(ms > 0)) return work; + let timer: ReturnType | undefined; + const guard = new Promise((_resolve, reject) => { + timer = setTimeout(() => { + onTimeout?.(); + reject(new DeFrameTimeoutError(label, ms)); + }, ms); + }); + try { + return await Promise.race([work, guard]); + } finally { + if (timer) clearTimeout(timer); + void work.catch(() => { + /* orphaned round-trip — see doc above */ + }); + } +} + async function captureFrameCore( session: CaptureSession, frameIndex: number, @@ -3639,7 +3709,30 @@ export async function captureFrameToBuffer( frameIndex: number, time: number, ): Promise { - const { buffer, captureTimeMs } = await captureFrameCore(session, frameIndex, time); + const { buffer, captureTimeMs } = + session.captureMode === "drawelement" + ? await withFrameDeadline( + captureFrameCore(session, frameIndex, time), + `frame ${frameIndex}`, + DE_FRAME_TIMEOUT_MS, + () => { + // Deliberately NO per-frame screenshot fallback. When the renderer + // stops scheduling it is wedged for EVERY subsequent round-trip on + // that page — measured: the screenshot fallback blew the same + // deadline. Fail fast and let the producer re-render the whole comp + // on a fresh page via the screenshot path, the only recovery that + // works. Counted here rather than in captureFrameCore's catch: the + // deadline rejects from outside it, so that catch never runs. + session.deFrameTimeouts = (session.deFrameTimeouts ?? 0) + 1; + console.log( + `[engine] fast capture: frame ${frameIndex} — capture exceeded ` + + `${DE_FRAME_TIMEOUT_MS}ms; renderer stalled after drawElementImage ` + + `(PRINFRA-488). Failing the drawElement attempt so the whole render ` + + `retries via screenshot.`, + ); + }, + ) + : await captureFrameCore(session, frameIndex, time); return { buffer, captureTimeMs }; } @@ -4355,5 +4448,6 @@ export function getCapturePerfSummary(session: CaptureSession): CapturePerfSumma deVerifyInitMs: session.deVerifyInitMs ?? 0, deBoundaryFrames: session.clipBoundaryFrames?.size ?? 0, deNcprFallbacks: ncprFallbacks, + deFrameTimeouts: session.deFrameTimeouts ?? 0, }; } diff --git a/packages/engine/src/services/parallelCoordinator.test.ts b/packages/engine/src/services/parallelCoordinator.test.ts index 08b08ac993..9cc2c832f9 100644 --- a/packages/engine/src/services/parallelCoordinator.test.ts +++ b/packages/engine/src/services/parallelCoordinator.test.ts @@ -1,4 +1,4 @@ -import { describe, it, expect } from "vitest"; +import { describe, it, expect, vi } from "vitest"; import { calculateOptimalWorkers, computeWorkerSizing, @@ -12,11 +12,40 @@ import { shouldDisableBrowserPoolForParallelWorker, shouldVerifyWorkerGpu, synthesizeSilentWorkerExitError, + withParallelWorkerDeadline, resolveParallelDeVerifySamples, type WorkerResult, } from "./parallelCoordinator.js"; import type { EngineConfig } from "../config.js"; +describe("parallel worker phase deadline", () => { + it("fails a wedged operation with phase and browser diagnostics before the aggregate watchdog", async () => { + vi.useFakeTimers(); + try { + const raced = withParallelWorkerDeadline( + new Promise(() => {}), + { + workerId: 2, + phase: "frame_capture", + frameIndex: 0, + browserExecutable: "C:/Chrome/chrome.exe", + browserVersion: "Chrome/152.0.7977.30", + canvasDrawElement: true, + gpuBackend: "d3d11/nvidia", + }, + 30_000, + ); + const assertion = expect(raced).rejects.toThrow( + /worker=2.*phase=frame_capture.*frame=0.*Chrome\/152.*CanvasDrawElement=true.*gpu=d3d11\/nvidia/, + ); + await vi.advanceTimersByTimeAsync(30_000); + await assertion; + } finally { + vi.useRealTimers(); + } + }); +}); + describe("distributeFrames", () => { it("distributes frames evenly across workers", () => { const tasks = distributeFrames(100, 4, "/tmp/work"); diff --git a/packages/engine/src/services/parallelCoordinator.ts b/packages/engine/src/services/parallelCoordinator.ts index 41a641aca5..45098d2eab 100644 --- a/packages/engine/src/services/parallelCoordinator.ts +++ b/packages/engine/src/services/parallelCoordinator.ts @@ -86,6 +86,25 @@ export interface ParallelProgress { capturedFrames: number; activeWorkers: number; workerProgress: Map; + /** Latest lifecycle transition; absent on ordinary completed-frame updates. */ + latestWorkerPhase?: ParallelWorkerPhaseDiagnostic; +} + +export type ParallelWorkerPhase = + | "browser_launch" + | "browser_probe" + | "session_init" + | "frame_capture" + | "frame_encode"; + +export interface ParallelWorkerPhaseDiagnostic { + workerId: number; + phase: ParallelWorkerPhase; + frameIndex?: number; + browserExecutable: string; + browserVersion: string; + canvasDrawElement: boolean | "unknown"; + gpuBackend: string; } export interface WorkerSizingConfig extends Partial< @@ -479,25 +498,60 @@ export function shouldVerifyWorkerGpu(workerId: number, config?: Partial(promise: Promise, signal: AbortSignal | undefined): Promise { - if (!signal) return promise; - if (signal.aborted) return Promise.reject(new Error("Parallel worker cancelled")); +export function withParallelWorkerDeadline( + promise: Promise, + diagnostic: ParallelWorkerPhaseDiagnostic, + timeoutMs: number, + signal?: AbortSignal, +): Promise { + if (signal?.aborted) return Promise.reject(new Error("Parallel worker cancelled")); return new Promise((resolve, reject) => { - const onAbort = () => reject(new Error("Parallel worker cancelled")); - signal.addEventListener("abort", onAbort, { once: true }); + let timer: ReturnType | undefined; + const cleanup = () => { + if (timer) clearTimeout(timer); + signal?.removeEventListener("abort", onAbort); + }; + const onAbort = () => { + cleanup(); + reject(new Error("Parallel worker cancelled")); + }; + signal?.addEventListener("abort", onAbort, { once: true }); + if (timeoutMs > 0) { + timer = setTimeout(() => { + cleanup(); + const error = new Error( + `Parallel worker operation timeout exceeded after ${timeoutMs}ms: ` + + `worker=${diagnostic.workerId} phase=${diagnostic.phase} ` + + `frame=${diagnostic.frameIndex ?? "n/a"} ` + + `browser=${diagnostic.browserExecutable} version=${diagnostic.browserVersion} ` + + `CanvasDrawElement=${diagnostic.canvasDrawElement} gpu=${diagnostic.gpuBackend}`, + ); + error.name = "ParallelWorkerPhaseTimeoutError"; + reject(error); + }, timeoutMs); + timer.unref?.(); + } promise.then( (value) => { - signal.removeEventListener("abort", onAbort); + cleanup(); resolve(value); }, (error) => { - signal.removeEventListener("abort", onAbort); + cleanup(); reject(error); }, ); }); } +function resolveParallelWorkerTimeoutMs(enabled: boolean): number { + if (!enabled) return 0; + const raw = process.env.HF_DE_PARALLEL_PHASE_TIMEOUT_MS; + if (raw === "0") return 0; + const parsed = raw ? Number(raw) : Number.NaN; + return Number.isFinite(parsed) && parsed > 0 ? parsed : 30_000; +} + // fallow-ignore-next-line complexity async function captureFrameRange( session: CaptureSession, @@ -508,10 +562,27 @@ async function captureFrameRange( onFrameBuffer: | ((frameIndex: number, buffer: Buffer, session: CaptureSession) => Promise) | undefined, + phaseTimeoutMs: number, + diagnosticFor: (phase: ParallelWorkerPhase, frameIndex?: number) => ParallelWorkerPhaseDiagnostic, + onWorkerPhase: ((diagnostic: ParallelWorkerPhaseDiagnostic) => void) | undefined, ): Promise { let framesCaptured = 0; const outputOffset = task.outputFrameOffset ?? 0; const stride = task.frameStride ?? 1; + const runCaptureOperation = ( + phase: ParallelWorkerPhase, + frameIndex: number, + operation: () => Promise, + ): Promise => { + const diagnostic = diagnosticFor(phase, frameIndex); + if (framesCaptured === 0) onWorkerPhase?.(diagnostic); + return withParallelWorkerDeadline(operation(), diagnostic, phaseTimeoutMs, signal); + }; + const awaitEncode = (frameIndex: number, encodeResult: Promise): Promise => { + const diagnostic = diagnosticFor("frame_encode", frameIndex); + if (framesCaptured === 0) onWorkerPhase?.(diagnostic); + return withParallelWorkerDeadline(encodeResult, diagnostic, phaseTimeoutMs, signal); + }; // Depth-2 pipelined drawElement produce (HF_DE_PARALLEL_STREAM spike): frame // k's in-page worker encode overlaps frame k+stride's produce phase — the // same shape as the sequential worker-encode loop. Only engaged when the @@ -535,9 +606,8 @@ async function captureFrameRange( if (dbg && i < task.startFrame + dbgWin) { console.log(`[par:w${task.workerId}] +${Date.now() - dbgT0}ms produce ${i} start`); } - const { encodeResult } = await raceAgainstAbort( + const { encodeResult } = await runCaptureOperation("frame_capture", i, () => captureFrameToBufferPipelined(session, i - outputOffset, time), - signal, ); // Marks the promise "handled" for Node's unhandled-rejection detector // without affecting the real `await prev.encodeResult` below — if a @@ -554,7 +624,7 @@ async function captureFrameRange( `[par:w${task.workerId}] +${Date.now() - dbgT0}ms drain ${prev.idx} await-encode`, ); } - const buf = await prev.encodeResult; + const buf = await awaitEncode(prev.idx, prev.encodeResult); if (dbg && prev.idx < task.startFrame + dbgWin) { console.log( `[par:w${task.workerId}] +${Date.now() - dbgT0}ms drain ${prev.idx} encoded ${buf.length}B`, @@ -570,7 +640,7 @@ async function captureFrameRange( prev = { idx: i, encodeResult }; } if (prev) { - await onFrameBuffer(prev.idx, await prev.encodeResult, session); + await onFrameBuffer(prev.idx, await awaitEncode(prev.idx, prev.encodeResult), session); framesCaptured++; if (onFrameCaptured) onFrameCaptured(task.workerId, prev.idx); } @@ -582,13 +652,14 @@ async function captureFrameRange( const fileFrameIdx = i - outputOffset; if (onFrameBuffer) { - const { buffer } = await raceAgainstAbort( + const { buffer } = await runCaptureOperation("frame_capture", i, () => captureFrameToBuffer(session, fileFrameIdx, time), - signal, ); await onFrameBuffer(i, buffer, session); } else { - await raceAgainstAbort(captureFrame(session, fileFrameIdx, time), signal); + await runCaptureOperation("frame_capture", i, () => + captureFrame(session, fileFrameIdx, time), + ); } framesCaptured++; if (onFrameCaptured) onFrameCaptured(task.workerId, i); @@ -764,6 +835,7 @@ async function executeWorkerTask( config?: Partial, parallel?: boolean, onFailure?: (failure: CaptureFailure) => void, + onWorkerPhase?: (diagnostic: ParallelWorkerPhaseDiagnostic) => void, ): Promise { const startTime = Date.now(); let framesCaptured = 0; @@ -783,37 +855,76 @@ async function executeWorkerTask( const workerConfig: Partial | undefined = needsSeparateBrowsers ? { ...config, enableBrowserPool: false } : config; + const phaseTimeoutMs = resolveParallelWorkerTimeoutMs( + Boolean(parallel && onFrameBuffer && workerConfig?.useDrawElement), + ); + let browserVersion = "unknown"; + let canvasDrawElement: boolean | "unknown" = "unknown"; + let gpuBackend = "unknown"; + let browserExecutable = resolveHeadlessShellPath(workerConfig) ?? "system/default"; + const diagnosticFor = ( + phase: ParallelWorkerPhase, + frameIndex?: number, + ): ParallelWorkerPhaseDiagnostic => ({ + workerId: task.workerId, + phase, + frameIndex, + browserExecutable, + browserVersion, + canvasDrawElement, + gpuBackend, + }); + const runPhase = (phase: ParallelWorkerPhase, operation: () => Promise): Promise => { + const diagnostic = diagnosticFor(phase); + onWorkerPhase?.(diagnostic); + return withParallelWorkerDeadline(operation(), diagnostic, phaseTimeoutMs, signal); + }; try { - session = await createCaptureSession( - serverUrl, - task.outputDir, - captureOptions, - createBeforeCaptureHook(), - workerConfig, + session = await runPhase("browser_launch", () => + createCaptureSession( + serverUrl, + task.outputDir, + captureOptions, + createBeforeCaptureHook(), + workerConfig, + ), ); + const activeSession = session; + browserExecutable = activeSession.browser?.process?.()?.spawnfile || browserExecutable; logParDebug(() => `[par:w${task.workerId}] session created`); - // Worker-0-only SwiftShader assertion — see `shouldVerifyWorkerGpu` and #955. - if (shouldVerifyWorkerGpu(task.workerId, workerConfig)) { - await assertSwiftShader(session.page, readWebGlVendorInfoFromCanvas); - } - await initializeSession(session); + browserVersion = await runPhase( + "browser_probe", + async () => (await activeSession.browser?.version?.().catch(() => "unknown")) ?? "unknown", + ); + await runPhase("session_init", async () => { + // Worker-0-only SwiftShader assertion — see `shouldVerifyWorkerGpu` and #955. + if (shouldVerifyWorkerGpu(task.workerId, workerConfig)) { + await assertSwiftShader(activeSession.page, readWebGlVendorInfoFromCanvas); + } + await initializeSession(activeSession); + }); + canvasDrawElement = activeSession.captureMode === "drawelement"; + gpuBackend = activeSession.gpuRenderer ?? "unknown"; logParDebug( () => `[par:w${task.workerId}] init done (mode=${session?.captureMode} workerEncode=${session?.workerEncodeEnabled === true})`, ); framesCaptured = await captureFrameRange( - session, + activeSession, task, captureOptions, signal, onFrameCaptured, onFrameBuffer, + phaseTimeoutMs, + diagnosticFor, + onWorkerPhase, ); - await verifyDiskDrawElementSamples(session, task, Boolean(onFrameBuffer)); + await verifyDiskDrawElementSamples(activeSession, task, Boolean(onFrameBuffer)); - perf = getCapturePerfSummary(session); + perf = getCapturePerfSummary(activeSession); return { workerId: task.workerId, framesCaptured, @@ -893,6 +1004,7 @@ export async function executeParallelCapture( 0, ); const workerProgress = new Map(); + const workerPhases = new Map(); for (const task of tasks) workerProgress.set(task.workerId, 0); @@ -910,6 +1022,18 @@ export async function executeParallelCapture( }); } }; + const onWorkerPhase = (diagnostic: ParallelWorkerPhaseDiagnostic) => { + workerPhases.set(diagnostic.workerId, diagnostic); + if (!onProgress) return; + const capturedFrames = Array.from(workerProgress.values()).reduce((a, b) => a + b, 0); + onProgress({ + totalFrames, + capturedFrames, + activeWorkers: tasks.length, + workerProgress: new Map(workerProgress), + latestWorkerPhase: diagnostic, + }); + }; const parallel = tasks.length > 1; const deVerifySamples = resolveParallelDeVerifySamples( @@ -943,6 +1067,7 @@ export async function executeParallelCapture( config, parallel, onFailure, + onWorkerPhase, ), ), ); diff --git a/packages/engine/src/types.ts b/packages/engine/src/types.ts index 0bcfed349a..bd5214d860 100644 --- a/packages/engine/src/types.ts +++ b/packages/engine/src/types.ts @@ -361,6 +361,13 @@ export interface CapturePerfSummary { deBoundaryFrames: number; /** Per-frame "No cached paint record" screenshot fallbacks during capture. */ deNcprFallbacks: number; + /** + * Per-frame drawElement captures that blew the `HF_DE_FRAME_TIMEOUT_MS` + * deadline (renderer stopped scheduling after drawElementImage returned — + * PRINFRA-488). Each timeout aborts that attempt so the producer can retry the + * whole render on a fresh screenshot session. + */ + deFrameTimeouts: number; } // ── Global Augmentation ──────────────────────────────────────────────────────── diff --git a/packages/producer/src/services/render/perfSummary.ts b/packages/producer/src/services/render/perfSummary.ts index 29472da3d0..fcc4f68dbf 100644 --- a/packages/producer/src/services/render/perfSummary.ts +++ b/packages/producer/src/services/render/perfSummary.ts @@ -155,6 +155,7 @@ function aggregateDrawElement( blankRecaptures: drain?.blankRecaptures ?? 0, boundaryFrames: perfs.reduce((sum, p) => sum + (p.deBoundaryFrames ?? 0), 0), ncprFallbacks: perfs.reduce((sum, p) => sum + (p.deNcprFallbacks ?? 0), 0), + frameTimeouts: perfs.reduce((sum, p) => sum + (p.deFrameTimeouts ?? 0), 0), }; } diff --git a/packages/producer/src/services/render/stages/captureStreamingStage.test.ts b/packages/producer/src/services/render/stages/captureStreamingStage.test.ts index 2b552873ef..80ed36203b 100644 --- a/packages/producer/src/services/render/stages/captureStreamingStage.test.ts +++ b/packages/producer/src/services/render/stages/captureStreamingStage.test.ts @@ -6,6 +6,7 @@ import { createCapturePlan } from "../capturePlan.js"; type MinimalEngineConfig = { forceScreenshot: boolean; ffmpegStreamingTimeout: number; + lowMemoryMode?: boolean; }; const writeFrame = mock((_buffer: Buffer) => true); @@ -21,6 +22,7 @@ let failInitializeSession = false; let hangParallelUntilAbort = false; let hangSequentialUntilStall = false; let sessionWorkerEncodeEnabled = false; +let captureSessionMode: "drawelement" | "screenshot" = "drawelement"; let failPrepareCaptureSessionForReuse = false; let initializeSessionErrorMessage = "initialize failed"; const browserConsoleBuffer = ["[FrameCapture:ERROR] page.goto failed"]; @@ -59,6 +61,7 @@ mock.module("@hyperframes/engine", () => ({ browserConsoleBuffer, options: { captureBeyondViewport: false }, workerEncodeEnabled: sessionWorkerEncodeEnabled, + captureMode: captureSessionMode, }), createFrameReorderBuffer: () => ({ waitForFrame: async () => {}, @@ -75,8 +78,26 @@ mock.module("@hyperframes/engine", () => ({ _opts: unknown, _hook: unknown, signal?: AbortSignal, + onProgress?: (progress: unknown) => void, ) => { if (hangParallelUntilAbort) { + onProgress?.({ + totalFrames: 100, + capturedFrames: 0, + activeWorkers: 2, + workerProgress: new Map([ + [0, 0], + [1, 0], + ]), + latestWorkerPhase: { + workerId: 0, + phase: "session_init", + browserExecutable: "C:/Chrome/chrome.exe", + browserVersion: "Chrome/152.0.7977.30", + canvasDrawElement: true, + gpuBackend: "d3d11/nvidia", + }, + }); // Simulate a wedged worker: make no frame progress, then reject with the // pool's generic string once aborted (by the parent or the watchdog). await new Promise((_resolve, reject) => { @@ -273,6 +294,8 @@ describe("runCaptureStreamingStage", () => { // A stalled render must surface as a stall (→ pinned fallback), never as // the raw "[Parallel] Capture failed" or a cancellation. expect((caught as Error).message).toContain("stalled"); + expect((caught as Error).message).toContain("phase=session_init"); + expect((caught as Error).message).toContain("Chrome/152.0.7977.30"); // Parent signal never fired, so the orchestrator won't read this as a cancel. expect(input.abortSignal).toBeUndefined(); }); @@ -356,6 +379,44 @@ describe("runCaptureStreamingStage", () => { expect((caught as Error).message).toContain("stalled"); }); + it("reports the actual screenshot mode and closes a wedged low-memory session", async () => { + hangSequentialUntilStall = true; + captureSessionMode = "screenshot"; + closeCaptureSession.mockClear(); + const prev = process.env.HF_DE_STALL_MS; + process.env.HF_DE_STALL_MS = "50"; + const { runCaptureStreamingStage } = await import("./captureStreamingStage.js"); + const cfg = { + forceScreenshot: true, + ffmpegStreamingTimeout: 3_600_000, + lowMemoryMode: true, + }; + const baseInput = createInput(cfg); + const input = { + ...baseInput, + totalFrames: 10, + plan: { ...baseInput.plan, forceScreenshot: true }, + }; + + let caught: unknown; + try { + await runCaptureStreamingStage(input); + } catch (error) { + caught = error; + } finally { + hangSequentialUntilStall = false; + captureSessionMode = "drawelement"; + if (prev === undefined) delete process.env.HF_DE_STALL_MS; + else process.env.HF_DE_STALL_MS = prev; + } + + expect(caught).toBeInstanceOf(Error); + expect((caught as Error & { cause?: Error }).cause?.name).toBe("SequentialCaptureStallError"); + expect((caught as Error).message).toContain("Sequential screenshot capture stalled"); + expect((caught as Error).message).not.toContain("drawElement"); + expect(closeCaptureSession).toHaveBeenCalledTimes(1); + }); + it("still honors the pre-rename HF_DE_PARALLEL_STALL_MS env var for one release", async () => { hangSequentialUntilStall = true; const prevNew = process.env.HF_DE_STALL_MS; diff --git a/packages/producer/src/services/render/stages/captureStreamingStage.ts b/packages/producer/src/services/render/stages/captureStreamingStage.ts index bf8c850660..0dc8e76f54 100644 --- a/packages/producer/src/services/render/stages/captureStreamingStage.ts +++ b/packages/producer/src/services/render/stages/captureStreamingStage.ts @@ -81,28 +81,28 @@ import { encoderFailureError } from "../encoderInterruption.js"; import type { SdrStreamingCapturePlan } from "../capturePlan.js"; /** - * No-frame-progress watchdog for DE streaming capture. A worker (parallel - * path) or the single in-flight capture (sequential path, worker-encode or - * plain) can wedge mid-capture (a hung seek/screenshot at an early frame), + * No-frame-progress watchdog for streaming capture. A worker (parallel path) + * or the single in-flight capture (sequential path, worker-encode or plain) + * can wedge mid-capture (a hung seek/screenshot at an early frame), * which would otherwise sit until the per-frame CDP `protocolTimeout` * (~5 min) fires — a silent multi-minute hang that only THEN reaches the * pinned fallback. Trip well before that: if no NEW frame lands within this - * window, fail fast so the orchestrator re-renders via screenshot. Default + * window, fail fast so the orchestrator retries from a fresh session. Default * 60s ≫ any real per-frame budget (15–32 ms), so a legit slow frame won't * false-trip; a false trip only costs the (slower, never-wrong) screenshot * fallback. */ -const DEFAULT_DE_STALL_MS = 60_000; +const DEFAULT_CAPTURE_STALL_MS = 60_000; const DE_STALL_POLL_MS = 5_000; -function resolveDeStallTimeoutMs(): number { +function resolveCaptureStallTimeoutMs(): number { // HF_DE_PARALLEL_STALL_MS is the pre-rename name (this config used to guard // only the parallel path). Bridged for one release so an already-deployed // ops surface (runbook, ConfigMap, ...) tuning the old name doesn't // silently no-op; drop once nothing sets it anymore. const raw = process.env.HF_DE_STALL_MS ?? process.env.HF_DE_PARALLEL_STALL_MS; const parsed = raw ? Number(raw) : Number.NaN; - return Number.isFinite(parsed) && parsed > 0 ? parsed : DEFAULT_DE_STALL_MS; + return Number.isFinite(parsed) && parsed > 0 ? parsed : DEFAULT_CAPTURE_STALL_MS; } /** @@ -112,8 +112,8 @@ function resolveDeStallTimeoutMs(): number { * take no signal — a wedged call can't be cancelled, only raced. A tripped * guard abandons the in-flight capture (same "orphaned, never awaited" * contract as the worker-encode pipeline's encodeResult) and rejects so the - * caller fails fast to the pinned screenshot fallback instead of waiting out - * the ~5min CDP protocol timeout. + * caller fails fast to the exactly-once fresh-session fallback instead of + * waiting out the ~5min CDP protocol timeout. * * `signal` is read only at trip time to label the rejection, never to cancel * the race early — a parent abort during a wedge still has to wait out the @@ -121,21 +121,56 @@ function resolveDeStallTimeoutMs(): number { * must say "aborted", not "stalled", so downstream logs/telemetry don't * misreport a deliberate cancellation as a capture failure. */ +function captureModeLabel(mode: CaptureSession["captureMode"]): string { + if (mode === "drawelement") return "drawElement"; + if (mode === "beginframe") return "BeginFrame"; + return "screenshot"; +} + +class SequentialCaptureStallError extends Error { + readonly captureMode: CaptureSession["captureMode"]; + + constructor( + captureMode: CaptureSession["captureMode"], + stallTimeoutMs: number, + frameIndex: number, + totalFrames: number, + ) { + super( + `[Render] Sequential ${captureModeLabel(captureMode)} capture stalled: ` + + `no frame progress for ${stallTimeoutMs}ms (stuck at frame ${frameIndex}/${totalFrames}).`, + ); + this.name = "SequentialCaptureStallError"; + this.captureMode = captureMode; + } +} + function raceAgainstStall( promise: Promise, deadlineMs: number, - message: string, + input: { + captureMode: CaptureSession["captureMode"]; + frameIndex: number; + totalFrames: number; + stallTimeoutMs: number; + }, signal?: AbortSignal, ): Promise { return new Promise((resolve, reject) => { const timer = setTimeout( () => { reject( - new Error( - signal?.aborted - ? "[Render] Sequential drawElement capture aborted while a capture call was in flight." - : message, - ), + signal?.aborted + ? new Error( + `[Render] Sequential ${captureModeLabel(input.captureMode)} capture aborted ` + + `while a capture call was in flight (frame ${input.frameIndex}/${input.totalFrames}).`, + ) + : new SequentialCaptureStallError( + input.captureMode, + input.stallTimeoutMs, + input.frameIndex, + input.totalFrames, + ), ); }, Math.max(0, deadlineMs), @@ -391,13 +426,13 @@ async function runWorkerEncodePipelineLoop( const guard = createDrainFrameGuard({ log, stats, frameTime }); const guardFrame = (idx: number, buf: Buffer): Promise => guard(session, idx, buf); - const stallTimeoutMs = resolveDeStallTimeoutMs(); + const stallTimeoutMs = resolveCaptureStallTimeoutMs(); let lastProgressAt = Date.now(); const captureWithStallGuard = (idx: number, promise: Promise): Promise => raceAgainstStall( promise, stallTimeoutMs - (Date.now() - lastProgressAt), - `[Render] Sequential drawElement capture stalled: no frame progress for ${stallTimeoutMs}ms (stuck at frame ${idx}/${totalFrames}).`, + { captureMode: session.captureMode, frameIndex: idx, totalFrames, stallTimeoutMs }, abortSignal, ); @@ -668,9 +703,15 @@ export async function runCaptureStreamingStage( if (abortSignal.aborted) stallController.abort(); else abortSignal.addEventListener("abort", forwardParentAbort, { once: true }); } - const stallTimeoutMs = resolveDeStallTimeoutMs(); + const stallTimeoutMs = resolveCaptureStallTimeoutMs(); let lastCapturedFrames = 0; let lastProgressAt = Date.now(); + const workerPhases = new Map(); + const phaseSummary = () => + [...workerPhases.entries()] + .sort(([left], [right]) => left - right) + .map(([workerId, detail]) => `worker=${workerId} ${detail}`) + .join("; "); let stalled = false; const stallTimer = setInterval( () => { @@ -678,7 +719,8 @@ export async function runCaptureStreamingStage( stalled = true; const stallErr = new Error( `[Render] Parallel drawElement capture stalled: no frame progress for ${stallTimeoutMs}ms ` + - `(stuck at ${lastCapturedFrames}/${totalFrames}).`, + `(stuck at ${lastCapturedFrames}/${totalFrames}).` + + (workerPhases.size > 0 ? ` Last worker phases: ${phaseSummary()}.` : ""), ); reorderBuffer.abort(stallErr); stallController.abort(); @@ -696,6 +738,24 @@ export async function runCaptureStreamingStage( createRenderVideoFrameInjector, stallController.signal, (progress) => { + if (progress.latestWorkerPhase) { + const phase = progress.latestWorkerPhase; + const detail = + `phase=${phase.phase} frame=${phase.frameIndex ?? "n/a"} ` + + `browser=${phase.browserExecutable} version=${phase.browserVersion} ` + + `CanvasDrawElement=${phase.canvasDrawElement} gpu=${phase.gpuBackend}`; + workerPhases.set(phase.workerId, detail); + log.info("[Render] Parallel capture worker phase", { + workerId: phase.workerId, + phase: phase.phase, + frameIndex: phase.frameIndex, + browserExecutable: phase.browserExecutable, + browserVersion: phase.browserVersion, + canvasDrawElement: phase.canvasDrawElement, + gpuBackend: phase.gpuBackend, + }); + return; + } if (progress.capturedFrames > lastCapturedFrames) { lastCapturedFrames = progress.capturedFrames; lastProgressAt = Date.now(); @@ -741,7 +801,8 @@ export async function runCaptureStreamingStage( throw new Error( `[Render] Parallel drawElement capture stalled after ${stallTimeoutMs}ms with no ` + `frame progress (last frame ${lastCapturedFrames}/${totalFrames}); ` + - `falling back to screenshot.`, + `falling back to screenshot.` + + (workerPhases.size > 0 ? ` Last worker phases: ${phaseSummary()}.` : ""), ); } throw err; @@ -813,7 +874,7 @@ export async function runCaptureStreamingStage( abortSignal, ); } else { - const stallTimeoutMs = resolveDeStallTimeoutMs(); + const stallTimeoutMs = resolveCaptureStallTimeoutMs(); let lastProgressAt = Date.now(); for (let i = 0; i < totalFrames; i++) { assertNotAborted(); @@ -821,7 +882,7 @@ export async function runCaptureStreamingStage( const { buffer } = await raceAgainstStall( captureFrameToBuffer(session, i, time), stallTimeoutMs - (Date.now() - lastProgressAt), - `[Render] Sequential drawElement capture stalled: no frame progress for ${stallTimeoutMs}ms (stuck at frame ${i}/${totalFrames}).`, + { captureMode: session.captureMode, frameIndex: i, totalFrames, stallTimeoutMs }, abortSignal, ); await reorderBuffer.waitForFrame(i); diff --git a/packages/producer/src/services/renderOrchestrator.test.ts b/packages/producer/src/services/renderOrchestrator.test.ts index 5ce124b887..05d5256d7a 100644 --- a/packages/producer/src/services/renderOrchestrator.test.ts +++ b/packages/producer/src/services/renderOrchestrator.test.ts @@ -34,6 +34,8 @@ import { resolveParallelRouterRetryPlan, resetCaptureAttemptProgress, shouldRetryViaPinnedFallback, + isDeRendererStallError, + isSequentialCaptureStallError, countElementTags, envInt, isDeParallelRouterEnabled, @@ -2464,6 +2466,60 @@ describe("resolveParallelRouterRetryPlan (self-verify retry rollback)", () => { }); describe("shouldRetryViaPinnedFallback (widen the self-verify retry to generic capture failures, including OOM)", () => { + // PRINFRA-488: a wedged renderer must be retryable on ANY routing. Before this, + // a comp that engaged drawElement on the ordinary single-worker path had no + // whole-render fallback, so one stalled frame failed the entire render. + it("retries a drawElement renderer stall even with no pinned routing", () => { + expect( + shouldRetryViaPinnedFallback({ + isVerifyError: false, + isCancellation: false, + deWorkerInversion: undefined, + deParallelRouter: undefined, + isDeRendererStall: true, + }), + ).toBe(true); + }); + + it("still does NOT retry a generic capture failure with no pinned routing", () => { + expect( + shouldRetryViaPinnedFallback({ + isVerifyError: false, + isCancellation: false, + deWorkerInversion: undefined, + deParallelRouter: undefined, + isDeRendererStall: false, + }), + ).toBe(false); + }); + + it("never retries a cancellation, even for a renderer stall", () => { + expect( + shouldRetryViaPinnedFallback({ + isVerifyError: false, + isCancellation: true, + deWorkerInversion: undefined, + deParallelRouter: undefined, + isDeRendererStall: true, + }), + ).toBe(false); + }); + + it("recognizes the engine's stall error across the package boundary", () => { + const byName = new Error("whatever"); + byName.name = "DeFrameTimeoutError"; + expect(isDeRendererStallError(byName)).toBe(true); + expect( + isDeRendererStallError( + new Error( + "drawElement frame 50 exceeded 15000ms (renderer stopped scheduling; see PRINFRA-488)", + ), + ), + ).toBe(true); + expect(isDeRendererStallError(new Error("some other capture failure"))).toBe(false); + expect(isDeRendererStallError("not an error")).toBe(false); + }); + it("always retries a drawElement self-verify failure, pinned or not", () => { expect( shouldRetryViaPinnedFallback({ @@ -2584,6 +2640,58 @@ describe("shouldRetryViaPinnedFallback (widen the self-verify retry to generic c }); }); +describe("sequential capture stall recovery", () => { + it("retries a typed stall on an explicit unpinned one-worker route", () => { + expect( + shouldRetryViaPinnedFallback({ + isVerifyError: false, + isCancellation: false, + isEncoderInterrupted: false, + deWorkerInversion: undefined, + deParallelRouter: undefined, + isDeRendererStall: true, + }), + ).toBe(true); + }); + + it("retries a typed screenshot stall on an unpinned low-memory route", () => { + expect( + shouldRetryViaPinnedFallback({ + isVerifyError: false, + isCancellation: false, + isEncoderInterrupted: false, + deWorkerInversion: undefined, + deParallelRouter: undefined, + isSequentialCaptureStall: true, + }), + ).toBe(true); + }); + + it("does not retry a screenshot stall after parent cancellation", () => { + expect( + shouldRetryViaPinnedFallback({ + isVerifyError: false, + isCancellation: true, + isEncoderInterrupted: false, + deWorkerInversion: undefined, + deParallelRouter: undefined, + isSequentialCaptureStall: true, + }), + ).toBe(false); + }); + + it("recognizes a wrapped screenshot watchdog error across the stage boundary", () => { + expect( + isSequentialCaptureStallError( + new Error( + "[Render] Sequential screenshot capture stalled: no frame progress for 60000ms (stuck at frame 99/135).", + ), + ), + ).toBe(true); + expect(isSequentialCaptureStallError(new Error("ordinary screenshot failure"))).toBe(false); + }); +}); + describe("shouldStreamParallelCapture (non-DE parallel streaming router)", () => { const eligible = { routerEnabled: true, diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index c7a373846d..bcf54956c4 100644 --- a/packages/producer/src/services/renderOrchestrator.ts +++ b/packages/producer/src/services/renderOrchestrator.ts @@ -540,9 +540,9 @@ export interface RenderPerfSummary { * `fallbackReason` being set is the "any fallback fired" signal. */ selfVerifyFallback: boolean; - /** What tripped the fallback retry: psnr | blank | oom | capture_error. */ + /** What tripped the fallback retry: psnr | blank | oom | de_renderer_stall | capture_error. */ fallbackReason?: string; - /** The failing PSNR (dB) when `fallbackReason === "psnr"`; undefined for blank/oom/capture_error (no score exists). */ + /** The failing PSNR (dB) when `fallbackReason === "psnr"`; undefined for every other reason (no score exists). */ fallbackFailedDb?: number; /** Frame index the verification failure was detected at; set for both "psnr" and "blank" fallback reasons. */ fallbackFrameIndex?: number; @@ -556,6 +556,13 @@ export interface RenderPerfSummary { boundaryFrames: number; /** Per-frame "No cached paint record" screenshot fallbacks. */ ncprFallbacks: number; + /** + * Frames that blew `HF_DE_FRAME_TIMEOUT_MS` — a wedged renderer + * (PRINFRA-488). Distinct from the other fallback counters: this one always + * costs a whole-render re-run via screenshot, so its rate is worth graphing + * on its own rather than inside `capture_error`. + */ + frameTimeouts: number; }; /** * Render-host facts, captured from the orchestrator process. Lets fleet-wide @@ -1842,6 +1849,12 @@ export function resolveParallelRouterRetryPlan(args: { * before the outer catch's `RenderCancelledError` branch ends the render — * that would delay honoring "stop" with a pointless resource spin-up/ * tear-down cycle. + * + * A typed sequential capture stall is independent of routing and retries on + * any cohort. This includes low-memory screenshot capture: its failed stage + * closes the wedged session before the retry creates a fresh screenshot + * session. Encoder interruptions remain excluded so a host shutdown cannot + * be hidden behind same-host retry work. */ export function shouldRetryViaPinnedFallback(args: { isVerifyError: boolean; @@ -1849,12 +1862,51 @@ export function shouldRetryViaPinnedFallback(args: { isEncoderInterrupted?: boolean; deWorkerInversion: "inverted" | "reverted" | undefined; deParallelRouter: "routed" | "reverted" | undefined; + /** + * The drawElement capture wedged the renderer (PRINFRA-488). Retryable on ANY + * routing, not just a pinned one: the failure is a property of drawElement + * itself, and the retry re-renders on a fresh page via screenshot — the only + * recovery that works once the renderer stops scheduling. Without this a comp + * that engaged drawElement on the ordinary single-worker path (neither + * inverted nor routed) had NO whole-render fallback, so one wedged frame + * failed the entire render. + */ + isDeRendererStall?: boolean; + /** The producer's no-progress watchdog tripped around a sequential capture call. */ + isSequentialCaptureStall?: boolean; }): boolean { if (args.isCancellation || args.isEncoderInterrupted) return false; if (args.isVerifyError) return true; + if (args.isDeRendererStall === true || args.isSequentialCaptureStall === true) return true; return args.deWorkerInversion === "inverted" || args.deParallelRouter === "routed"; } +/** + * True for the drawElement per-frame deadline breach raised by the engine when + * the renderer stops scheduling after `drawElementImage` returns (PRINFRA-488). + * Matched on name+message rather than by class because the error crosses the + * engine/producer package boundary. + */ +export function isDeRendererStallError(err: unknown): boolean { + if (!(err instanceof Error)) return false; + return err.name === "DeFrameTimeoutError" || err.message.includes("renderer stopped scheduling"); +} + +/** + * True when the producer's sequential no-progress deadline won. The stage + * wraps its typed cause in CaptureStageError, so match both the inner name and + * the stable, mode-bearing outer message. + */ +export function isSequentialCaptureStallError(err: unknown): boolean { + if (!(err instanceof Error)) return false; + return ( + err.name === "SequentialCaptureStallError" || + /^\[Render\] Sequential (?:drawElement|BeginFrame|screenshot) capture stalled:/.test( + err.message, + ) + ); +} + /** * When a self-verify (or pinned-fallback) retry is triggered mid-capture, the * caller may still hold a live probe session that the failed stage was passed @@ -3589,17 +3641,16 @@ async function executeRenderPipeline(input: { try { streamingRes = await invokeStreaming(); } catch (err) { - // drawElement self-verification tripped (blank frame or PSNR breach - // vs the pre-injection ground truth), OR — when the inversion/router - // pinned a fixed worker count regardless of calibration — any other - // capture-stage failure (host contention timeout, worker crash, OOM) - // on that pinned path. Both restart the whole render on the same - // tested screenshot/parallel-SS baseline: slower, never wrong. The - // failed attempt's session was closed by the stage's finally; - // probeSession (if any) was consumed by it, so a fresh session - // spawns on retry. See shouldRetryViaPinnedFallback for exactly - // which errors qualify. + // drawElement self-verification or a sequential no-progress deadline + // restarts the whole render from a fresh screenshot session. When an + // inversion/router pinned the worker count, other capture-stage + // failures (host timeout, worker crash, OOM) can use that same tested + // baseline. The stage closes the failed session before throwing; + // probeSession (if any) was consumed by it. See + // shouldRetryViaPinnedFallback for exactly which errors qualify. const isVerifyError = isDrawElementVerificationError(err); + const isDeStall = isDeRendererStallError(err); + const isSequentialStall = isSequentialCaptureStallError(err); const isCancellation = err instanceof RenderCancelledError || executionSignal?.aborted === true; if ( @@ -3609,6 +3660,8 @@ async function executeRenderPipeline(input: { isEncoderInterrupted: err instanceof EncoderInterruptedError, deWorkerInversion, deParallelRouter, + isDeRendererStall: isDeStall, + isSequentialCaptureStall: isSequentialStall, }) ) throw err; @@ -3621,19 +3674,31 @@ async function executeRenderPipeline(input: { deFallbackFrameIndex = t.frameIndex; deFallbackThresholdDb = t.thresholdDb; } else { - deFallbackReason = isMemoryExhaustion ? "oom" : "capture_error"; + deFallbackReason = isMemoryExhaustion + ? "oom" + : isDeStall + ? "de_renderer_stall" + : "capture_error"; } log.warn( isVerifyError ? "[Render] drawElement self-verification failed; re-rendering via screenshot" - : "[Render] capture failed on the pinned worker count; re-rendering via screenshot", + : isDeStall + ? "[Render] drawElement renderer stalled; re-rendering via screenshot" + : isSequentialStall + ? "[Render] sequential capture stalled; retrying on a fresh screenshot session" + : "[Render] capture failed on the pinned worker count; re-rendering via screenshot", { error: err instanceof Error ? err.message : String(err) }, ); observability.checkpoint( "capture_streaming", isVerifyError ? "drawElement self-verify failed; retrying with forceScreenshot" - : "capture failed on pinned worker count; retrying with forceScreenshot", + : isDeStall + ? "drawElement renderer stalled; retrying with forceScreenshot" + : isSequentialStall + ? "sequential capture stalled; retrying with a fresh screenshot session" + : "capture failed on pinned worker count; retrying with forceScreenshot", ); const failedRouting = capturePlan.routing.kind; capturePlan = replanAfterFailure(