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

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions packages/cli/src/commands/render.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
2 changes: 2 additions & 0 deletions packages/cli/src/telemetry/events.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -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,
Expand Down
45 changes: 45 additions & 0 deletions packages/engine/src/services/frameCapture-frameDeadline.test.ts
Original file line number Diff line number Diff line change
@@ -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<string>(() => {}), "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();
}
});
});
96 changes: 95 additions & 1 deletion packages/engine/src/services/frameCapture.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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<T>(
work: Promise<T>,
label: string,
ms: number,
onTimeout?: () => void,
): Promise<T> {
if (!(ms > 0)) return work;
let timer: ReturnType<typeof setTimeout> | undefined;
const guard = new Promise<never>((_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,
Expand Down Expand Up @@ -3639,7 +3709,30 @@ export async function captureFrameToBuffer(
frameIndex: number,
time: number,
): Promise<CaptureBufferResult> {
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 };
}
Expand Down Expand Up @@ -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,
};
}
31 changes: 30 additions & 1 deletion packages/engine/src/services/parallelCoordinator.test.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
import { describe, it, expect } from "vitest";
import { describe, it, expect, vi } from "vitest";
import {
calculateOptimalWorkers,
computeWorkerSizing,
Expand All @@ -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<void>(() => {}),
{
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");
Expand Down
Loading
Loading