From 02dd334c18cdcda6961566f292458d64e3a18c63 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Miguel=20=C3=81ngel?= Date: Sat, 5 Sep 2026 12:35:31 +0000 Subject: [PATCH 1/4] test(producer): pin unpinned drawElement stall retry --- .../src/services/renderOrchestrator.test.ts | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/packages/producer/src/services/renderOrchestrator.test.ts b/packages/producer/src/services/renderOrchestrator.test.ts index 5ce124b887..ca7579b04b 100644 --- a/packages/producer/src/services/renderOrchestrator.test.ts +++ b/packages/producer/src/services/renderOrchestrator.test.ts @@ -2584,6 +2584,21 @@ describe("shouldRetryViaPinnedFallback (widen the self-verify retry to generic c }); }); +describe("sequential drawElement renderer 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); + }); +}); + describe("shouldStreamParallelCapture (non-DE parallel streaming router)", () => { const eligible = { routerEnabled: true, From 722762e44c218d747a6adbc2a3b54eecb3b9d544 Mon Sep 17 00:00:00 2001 From: Vance Ingalls Date: Thu, 20 Aug 2026 23:39:37 -0700 Subject: [PATCH 2/4] fix(engine): bound drawElement frames so a wedged renderer falls back instead of failing (#3172) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(engine): bound drawElement frames so a wedged renderer falls back instead of failing A single drawElement frame could kill an entire render. On one comp (caption-editorial-emphasis) drawElementImage returns normally and the renderer then stops draining its task queue: the setTimeout(…, 0) that schedules toDataURL never fires, the capture page.evaluate never settles, and 60s later the stage watchdog fails the whole render. Deterministic on 152.0.7977.30, always the same frame. Root-cause detail in PRINFRA-488. Two gaps, both closed here. 1. Nothing below the 60s stage watchdog bounded a frame. Adds a per-frame deadline (HF_DE_FRAME_TIMEOUT_MS, default 15000, 0 disables) around the WHOLE frame operation, not just the drawElementImage call — the stall surfaces at whichever page round-trip comes next, and was observed at both the capture and the seek's background-image decode. Bounding one call missed it. Deliberately NO per-frame screenshot fallback for this error: once the renderer stops scheduling it is wedged for every subsequent round-trip on that page. Measured — the screenshot fallback blew the same deadline. The frame fails fast instead, so the recovery that actually works can run. 2. That recovery was ineligible. shouldRetryViaPinnedFallback only retried a generic capture failure when the worker count was PINNED by the inversion or the router; a comp that engaged drawElement on the ordinary single-worker path had no whole-render fallback at all. A renderer stall is now retryable on any routing — the failure is a property of drawElement itself, and the retry re-renders on a fresh page via screenshot. Reported as de_fallback_reason "de_renderer_stall" so it is distinguishable from capture_error in telemetry, and counted per-session as deFrameTimeouts. Verified end to end on the repro: previously exit 1 with "stalled: no frame progress for 60000ms"; now the deadline fires, the render retries via screenshot, and RENDER_OK with a valid 1920x1080 / 240-frame / 8.0s MP4. Tests cover the predicate both ways plus the cross-package error match. Engine 1,481 and producer 587 green (audioPadTrim.integration flakes only under full-suite parallel load — passes in isolation, and on clean HEAD it is green too, so it is not from this change). Refs PRINFRA-488 * fix(engine,producer,cli): count drawElement frame timeouts where they happen `session.deFrameTimeouts` was incremented inside `captureFrameCore`'s catch, but the deadline races that function from OUTSIDE it — `withFrameDeadline` is applied by `captureFrameToBuffer`, and `DeFrameTimeoutError` is constructed nowhere else. So the branch was unreachable: on a wedged renderer the counter stayed 0, the engine-side stall log never printed, and `CapturePerfSummary.deFrameTimeouts` reported 0 on every affected render. The end-to-end recovery worked throughout — `isDeRendererStallError` matches by name at the producer — only the observability was dead. Moved the increment and the log into an `onTimeout` hook that fires from the deadline itself, deleted the unreachable branch and the now-unused `isDeFrameTimeoutError`, and threaded the count out to `render_completed.de_frame_timeouts` so the rate is graphable apart from the other `capture_error` fallbacks. A stall always costs a whole-render re-run, which is why it deserves its own series. Also corrected the `fallbackReason` docstring, which still listed only `psnr | blank | oom | capture_error` after this branch added `de_renderer_stall`. `withFrameDeadline` is exported for a two-case fake-timer test: the deadline fires and calls `onTimeout` once, and a resolving inner promise passes its value through with no late timer. The first case fails if the counter moves back inside the work promise. (cherry picked from commit ec2b2b5b2ad74b53fcf2bacd7885d0237d1cbd30) --- packages/cli/src/commands/render.ts | 1 + packages/cli/src/telemetry/events.ts | 2 + .../frameCapture-frameDeadline.test.ts | 45 +++++++++ packages/engine/src/services/frameCapture.ts | 96 ++++++++++++++++++- packages/engine/src/types.ts | 7 ++ .../src/services/render/perfSummary.ts | 1 + .../src/services/renderOrchestrator.test.ts | 55 +++++++++++ .../src/services/renderOrchestrator.ts | 53 +++++++++- 8 files changed, 254 insertions(+), 6 deletions(-) create mode 100644 packages/engine/src/services/frameCapture-frameDeadline.test.ts 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/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/renderOrchestrator.test.ts b/packages/producer/src/services/renderOrchestrator.test.ts index ca7579b04b..f553f9ea8d 100644 --- a/packages/producer/src/services/renderOrchestrator.test.ts +++ b/packages/producer/src/services/renderOrchestrator.test.ts @@ -34,6 +34,7 @@ import { resolveParallelRouterRetryPlan, resetCaptureAttemptProgress, shouldRetryViaPinnedFallback, + isDeRendererStallError, countElementTags, envInt, isDeParallelRouterEnabled, @@ -2464,6 +2465,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({ diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index c7a373846d..94c38700a6 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,10 @@ 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 drawElement renderer stall is independent of routing and retries on + * any cohort. Encoder interruptions remain excluded so a host shutdown cannot + * be hidden behind same-host retry work. */ export function shouldRetryViaPinnedFallback(args: { isVerifyError: boolean; @@ -1849,12 +1860,34 @@ 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; }): boolean { if (args.isCancellation || args.isEncoderInterrupted) return false; if (args.isVerifyError) return true; + if (args.isDeRendererStall === 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"); +} + /** * 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 @@ -3600,6 +3633,7 @@ async function executeRenderPipeline(input: { // spawns on retry. See shouldRetryViaPinnedFallback for exactly // which errors qualify. const isVerifyError = isDrawElementVerificationError(err); + const isDeStall = isDeRendererStallError(err); const isCancellation = err instanceof RenderCancelledError || executionSignal?.aborted === true; if ( @@ -3609,6 +3643,7 @@ async function executeRenderPipeline(input: { isEncoderInterrupted: err instanceof EncoderInterruptedError, deWorkerInversion, deParallelRouter, + isDeRendererStall: isDeStall, }) ) throw err; @@ -3621,19 +3656,27 @@ 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" + : "[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" + : "capture failed on pinned worker count; retrying with forceScreenshot", ); const failedRouting = capturePlan.routing.kind; capturePlan = replanAfterFailure( From cb0d8e14d62947fe9c7749f7932f986b9cfc5312 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Miguel=20=C3=81ngel?= Date: Sat, 5 Sep 2026 18:06:35 +0000 Subject: [PATCH 3/4] fix(render): retry sequential screenshot stalls --- .../stages/captureStreamingStage.test.ts | 41 ++++++++++ .../render/stages/captureStreamingStage.ts | 75 ++++++++++++++----- .../src/services/renderOrchestrator.test.ts | 40 +++++++++- .../src/services/renderOrchestrator.ts | 52 +++++++++---- 4 files changed, 172 insertions(+), 36 deletions(-) diff --git a/packages/producer/src/services/render/stages/captureStreamingStage.test.ts b/packages/producer/src/services/render/stages/captureStreamingStage.test.ts index 2b552873ef..f6c66c0939 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 () => {}, @@ -356,6 +359,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..528b696e22 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,7 +703,7 @@ 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(); let stalled = false; @@ -813,7 +848,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 +856,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 f553f9ea8d..05d5256d7a 100644 --- a/packages/producer/src/services/renderOrchestrator.test.ts +++ b/packages/producer/src/services/renderOrchestrator.test.ts @@ -35,6 +35,7 @@ import { resetCaptureAttemptProgress, shouldRetryViaPinnedFallback, isDeRendererStallError, + isSequentialCaptureStallError, countElementTags, envInt, isDeParallelRouterEnabled, @@ -2639,7 +2640,7 @@ describe("shouldRetryViaPinnedFallback (widen the self-verify retry to generic c }); }); -describe("sequential drawElement renderer stall recovery", () => { +describe("sequential capture stall recovery", () => { it("retries a typed stall on an explicit unpinned one-worker route", () => { expect( shouldRetryViaPinnedFallback({ @@ -2652,6 +2653,43 @@ describe("sequential drawElement renderer stall recovery", () => { }), ).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)", () => { diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index 94c38700a6..bcf54956c4 100644 --- a/packages/producer/src/services/renderOrchestrator.ts +++ b/packages/producer/src/services/renderOrchestrator.ts @@ -1850,8 +1850,10 @@ export function resolveParallelRouterRetryPlan(args: { * that would delay honoring "stop" with a pointless resource spin-up/ * tear-down cycle. * - * A typed drawElement renderer stall is independent of routing and retries on - * any cohort. Encoder interruptions remain excluded so a host shutdown cannot + * 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: { @@ -1870,10 +1872,12 @@ export function shouldRetryViaPinnedFallback(args: { * 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) return true; + if (args.isDeRendererStall === true || args.isSequentialCaptureStall === true) return true; return args.deWorkerInversion === "inverted" || args.deParallelRouter === "routed"; } @@ -1888,6 +1892,21 @@ export function isDeRendererStallError(err: unknown): boolean { 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 @@ -3622,18 +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 ( @@ -3644,6 +3661,7 @@ async function executeRenderPipeline(input: { deWorkerInversion, deParallelRouter, isDeRendererStall: isDeStall, + isSequentialCaptureStall: isSequentialStall, }) ) throw err; @@ -3667,7 +3685,9 @@ async function executeRenderPipeline(input: { ? "[Render] drawElement self-verification failed; re-rendering via screenshot" : isDeStall ? "[Render] drawElement renderer stalled; re-rendering via screenshot" - : "[Render] capture failed on the pinned worker count; 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( @@ -3676,7 +3696,9 @@ async function executeRenderPipeline(input: { ? "drawElement self-verify failed; retrying with forceScreenshot" : isDeStall ? "drawElement renderer stalled; retrying with forceScreenshot" - : "capture failed on pinned worker count; 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( From 0cf62f9ae89ed105f501c18d81c70d63f1e6c392 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Miguel=20=C3=81ngel?= Date: Sat, 5 Sep 2026 19:14:51 +0000 Subject: [PATCH 4/4] fix(render): bound parallel worker capture phases --- .../src/services/parallelCoordinator.test.ts | 31 ++- .../src/services/parallelCoordinator.ts | 181 +++++++++++++++--- .../stages/captureStreamingStage.test.ts | 20 ++ .../render/stages/captureStreamingStage.ts | 30 ++- 4 files changed, 231 insertions(+), 31 deletions(-) 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/producer/src/services/render/stages/captureStreamingStage.test.ts b/packages/producer/src/services/render/stages/captureStreamingStage.test.ts index f6c66c0939..80ed36203b 100644 --- a/packages/producer/src/services/render/stages/captureStreamingStage.test.ts +++ b/packages/producer/src/services/render/stages/captureStreamingStage.test.ts @@ -78,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) => { @@ -276,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(); }); diff --git a/packages/producer/src/services/render/stages/captureStreamingStage.ts b/packages/producer/src/services/render/stages/captureStreamingStage.ts index 528b696e22..0dc8e76f54 100644 --- a/packages/producer/src/services/render/stages/captureStreamingStage.ts +++ b/packages/producer/src/services/render/stages/captureStreamingStage.ts @@ -706,6 +706,12 @@ export async function runCaptureStreamingStage( 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( () => { @@ -713,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(); @@ -731,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(); @@ -776,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;