fix(engine): fail-fast the sub-composition timeline wait when a script 404s

pollSubCompositionTimelines waits for every [data-composition-id] host to
register window.__timelines[id]. When the script carrying that registration
fails to load (404 / request failure), the registration can never arrive —
but the poll still burned the full playerReadyTimeout (45s), then warned and
shipped a silently animation-less render. Wild scale: the capture-setup
histogram over 30 days of local renders decays smoothly (402/503/364/282/191
per 5s bucket) then spikes to 705 at the 45s bucket — ~1,000 renders/month
across 402 distinct users, ~15 user-hours of pure waiting.

- Sessions now record failed SCRIPT resources (requestfailed + HTTP>=400
  response, listeners that already existed for diagnostics) in
  session.scriptLoadFailures.
- pollSubCompositionTimelines takes a failure getter and cuts the wait to a
  2s grace once any script failed, with a loud warning naming the URL(s).
  Late-registering fetch-async comps are unaffected: no script failure means
  the full timeout still applies, and a registration landing inside the
  grace window still wins (tested).
- Outcome telemetry: session.subTimelineWaitOutcome ("ready" | "timeout" |
  "script_failure") -> CapturePerfSummary -> RenderPerfSummary.subTimelineWait
  (worst across sessions) -> render_complete sub_timeline_wait, so the wild
  rate becomes directly trackable instead of setup-histogram forensics.

Validation: the discovery comp (0768f038, its animations.js unreachable)
drops from ~72s to 23.1s total — poll cut at 2.1s with the script named;
healthy comp reports "ready". Canary suite 7/7 (PSNRs identical). 4 new
poll unit tests; engine suite 907 passed (14 failures are PRE-EXISTING on
main at v0.7.42 — 18 fail on a clean checkout, stash A/B verified).
tsc/oxlint/oxfmt clean.

Corpus note: 258/1,762 corpus comps (14%) reference local scripts missing
from the corpus fetch — their historical eval INIT timings measured this
timeout, not the engine. Capture-stage ratios remain valid (both paths paid
it equally).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Vance Ingalls
2026-07-08 16:09:47 -07:00
co-authored by Claude Fable 5
parent 230cc5bf7d
commit 54359f3d6a
7 changed files with 150 additions and 23 deletions
+1
View File
@@ -1708,6 +1708,7 @@ function trackRenderMetrics(
speedRatio,
captureAvgMs: perf?.captureAvgMs,
captureP50Ms: perf?.captureP50Ms,
subTimelineWait: perf?.subTimelineWait,
videoCount: perf?.videoCount,
capturePeakMs: perf?.capturePeakMs,
tmpPeakBytes: perf?.tmpPeakBytes,
+2
View File
@@ -148,6 +148,7 @@ export function trackRenderComplete(
captureAvgMs?: number;
/** Warmup-robust per-frame capture median (basis for speedup estimates). */
captureP50Ms?: number;
subTimelineWait?: string;
/** <video> element count (speedup segmentation: injection comps read lower). */
videoCount?: number;
capturePeakMs?: number;
@@ -221,6 +222,7 @@ export function trackRenderComplete(
speed_ratio: props.speedRatio,
capture_avg_ms: props.captureAvgMs,
capture_p50_ms: props.captureP50Ms,
sub_timeline_wait: props.subTimelineWait,
video_count: props.videoCount,
capture_peak_ms: props.capturePeakMs,
peak_memory_mb: props.peakMemoryMb,
@@ -0,0 +1,66 @@
/**
* pollSubCompositionTimelines fail-fast contract: a script resource that
* failed to load can never register its `window.__timelines[id]`, so the
* poll must cut to the short grace window instead of burning the full
* playerReadyTimeout (measured wild: a 705-render spike at the 45s setup
* bucket over 30 days ~1% of local renders).
*/
import { describe, expect, it, vi } from "vitest";
import type { Page } from "puppeteer-core";
import { pollSubCompositionTimelines } from "./frameCapture.js";
function makeMockPage(evaluateResults: (expr: string) => unknown): Page {
return {
evaluate: vi.fn(async (expr: string) => evaluateResults(expr)),
} as unknown as Page;
}
describe("pollSubCompositionTimelines fail-fast", () => {
it("returns ready and forces a timeline rebind when timelines register", async () => {
const page = makeMockPage(() => true);
const outcome = await pollSubCompositionTimelines(page, 1_000, 10);
expect(outcome).toBe("ready");
// Second evaluate is the __hfForceTimelineRebind call.
expect((page.evaluate as ReturnType<typeof vi.fn>).mock.calls.length).toBe(2);
});
it("bails after the grace window when a script resource failed to load", async () => {
const page = makeMockPage((expr) =>
expr.includes("__hfForceTimelineRebind") ? undefined : false,
);
const started = Date.now();
const outcome = await pollSubCompositionTimelines(
page,
60_000, // full timeout must NOT be waited
10,
() => ["http://localhost/animations.js"],
50, // grace
);
expect(outcome).toBe("script_failure");
expect(Date.now() - started).toBeLessThan(5_000);
});
it("waits the full timeout when timelines are missing but no script failed", async () => {
const page = makeMockPage(() => false);
const outcome = await pollSubCompositionTimelines(page, 120, 10, () => []);
expect(outcome).toBe("timeout");
});
it("keeps waiting through the grace window when failures appear but timelines register late", async () => {
let calls = 0;
const page = makeMockPage((expr) => {
if (expr.includes("__hfForceTimelineRebind")) return undefined;
calls++;
return calls >= 3; // registers on the 3rd poll tick, inside the grace window
});
const outcome = await pollSubCompositionTimelines(
page,
60_000,
10,
() => ["http://localhost/late.js"],
10_000, // generous grace — registration lands first
);
expect(outcome).toBe("ready");
});
});
+67 -23
View File
@@ -95,6 +95,16 @@ export interface CaptureSession {
pageReleased?: boolean;
browserReleased?: boolean;
browserConsoleBuffer: string[];
/**
* Script resources that failed to load (request failure or HTTP >= 400).
* pollSubCompositionTimelines fail-fasts on these: a comp whose timeline
* script 404'd can never register window.__timelines[id], so waiting the
* full playerReadyTimeout (45s) buys nothing (~1% of wild local renders
* were hitting that wall a 705-render spike at the 45s setup bucket).
*/
scriptLoadFailures: string[];
/** Outcome of the sub-composition timeline wait: ready | timeout | script_failure. */
subTimelineWaitOutcome?: "ready" | "timeout" | "script_failure";
initTelemetry?: {
initDurationMs: number;
tweenCount: number;
@@ -929,6 +939,7 @@ export async function createCaptureSession(
onBeforeCapture,
isInitialized: false,
browserConsoleBuffer: [],
scriptLoadFailures: [],
capturePerf: {
frames: 0,
seekMs: 0,
@@ -1001,21 +1012,6 @@ export function formatConsoleDiagnostic(
return { text: `${prefix} ${text}`, suppressHostLog: false };
}
async function pollPageExpression(
page: Page,
expression: string,
timeoutMs: number,
intervalMs: number = 100,
): Promise<boolean> {
const deadline = Date.now() + timeoutMs;
while (Date.now() < deadline) {
const ready = Boolean(await page.evaluate(expression));
if (ready) return true;
await new Promise((resolve) => setTimeout(resolve, intervalMs));
}
return Boolean(await page.evaluate(expression));
}
const HF_READY_DIAGNOSTIC_EXPR = `(function() {
var hf = window.__hf;
var player = window.__player;
@@ -1151,11 +1147,19 @@ async function pollHfReady(page: Page, timeoutMs: number, intervalMs: number = 1
);
}
async function pollSubCompositionTimelines(
export async function pollSubCompositionTimelines(
page: Page,
timeoutMs: number,
intervalMs: number = 150,
): Promise<void> {
// Fail-fast hook: when a SCRIPT resource failed to load (404 / request
// failure), the timeline registration it carried can never arrive — the
// full-timeout wait buys nothing (measured: a 705-render spike at the 45s
// setup bucket in 30 days of wild local renders, ~1% of renders, each also
// shipping silently-broken animations). Once failures are present the poll
// is cut to `scriptFailureGraceMs` from its start.
getScriptLoadFailures?: () => readonly string[],
scriptFailureGraceMs: number = 2_000,
): Promise<"ready" | "timeout" | "script_failure"> {
// Hosts may opt out of the timeline wait with `data-no-timeline` —
// compositions driven purely by CSS animations / rAF (the render-compat
// contract) never register window.__timelines[id], and without the opt-out
@@ -1172,7 +1176,28 @@ async function pollSubCompositionTimelines(
}
return true;
})()`;
const ready = await pollPageExpression(page, expression, timeoutMs, intervalMs);
const start = Date.now();
const deadline = start + timeoutMs;
let ready = false;
let scriptFailureBail = false;
for (;;) {
ready = Boolean(await page.evaluate(expression));
if (ready) break;
const now = Date.now();
if (now >= deadline) break;
const failures = getScriptLoadFailures?.() ?? [];
if (failures.length > 0 && now - start >= scriptFailureGraceMs) {
scriptFailureBail = true;
console.warn(
`[FrameCapture] Sub-composition timeline wait cut short after ${now - start}ms: ` +
`script resource(s) failed to load (${failures.join(", ")}) — ` +
`the timeline registration they carry can never arrive. ` +
`Fix the script reference; the render proceeds without those animations.`,
);
break;
}
await new Promise((resolve) => setTimeout(resolve, intervalMs));
}
// Always force a timeline rebind once sub-composition timelines are
// confirmed present. The previous implementation only called rebind
// when the timeline count grew during the poll, which missed the case
@@ -1186,8 +1211,9 @@ async function pollSubCompositionTimelines(
window.__hfForceTimelineRebind();
}
})()`);
return "ready";
}
if (!ready) {
if (!scriptFailureBail) {
const missing = await page.evaluate(`(function() {
var hosts = document.querySelectorAll("[data-composition-id]");
var timelines = window.__timelines || {};
@@ -1205,6 +1231,7 @@ async function pollSubCompositionTimelines(
`Compositions intentionally driven without GSAP timelines (CSS animations / rAF) can mark the host with data-no-timeline to skip this wait.`,
);
}
return scriptFailureBail ? "script_failure" : "timeout";
}
async function pollVideosReady(
@@ -1411,6 +1438,9 @@ export async function initializeSession(session: CaptureSession): Promise<void>
});
page.on("requestfailed", (request) => {
if (request.resourceType() === "script") {
session.scriptLoadFailures.push(request.url());
}
appendBrowserDiagnostic(
session,
formatRequestFailureDiagnostic({
@@ -1427,6 +1457,9 @@ export async function initializeSession(session: CaptureSession): Promise<void>
if (status < 400) return;
const request = response.request();
if (request.resourceType() === "script") {
session.scriptLoadFailures.push(response.url());
}
appendBrowserDiagnostic(
session,
formatHttpErrorDiagnostic({
@@ -1491,8 +1524,13 @@ export async function initializeSession(session: CaptureSession): Promise<void>
await pollHfReady(page, pageReadyTimeout);
logInitPhase("pollHfReady complete");
await pollSubCompositionTimelines(page, pageReadyTimeout);
logInitPhase("pollSubCompositionTimelines complete");
session.subTimelineWaitOutcome = await pollSubCompositionTimelines(
page,
pageReadyTimeout,
undefined,
() => session.scriptLoadFailures,
);
logInitPhase(`pollSubCompositionTimelines complete (${session.subTimelineWaitOutcome})`);
await applyVideoMetadataHints(page, session.options.videoMetadataHints);
logInitPhase("applyVideoMetadataHints complete");
@@ -1626,8 +1664,13 @@ export async function initializeSession(session: CaptureSession): Promise<void>
throw err;
}
await pollSubCompositionTimelines(page, pageReadyTimeout);
logInitPhase("pollSubCompositionTimelines complete");
session.subTimelineWaitOutcome = await pollSubCompositionTimelines(
page,
pageReadyTimeout,
undefined,
() => session.scriptLoadFailures,
);
logInitPhase(`pollSubCompositionTimelines complete (${session.subTimelineWaitOutcome})`);
await applyVideoMetadataHints(page, session.options.videoMetadataHints);
logInitPhase("applyVideoMetadataHints complete");
@@ -3086,6 +3129,7 @@ export function getCapturePerfSummary(session: CaptureSession): CapturePerfSumma
avgBeforeCaptureMs: Math.round(session.capturePerf.beforeCaptureMs / frames),
avgScreenshotMs: Math.round(session.capturePerf.screenshotMs / frames),
p50TotalMs: medianOf(session.capturePerf.frameMs),
subTimelineWaitOutcome: session.subTimelineWaitOutcome,
staticDedupReused: session.staticDedupCount ?? 0,
staticDedupEnabled: session.staticDedupEnabled ?? false,
// armed ⟺ a non-empty static set survived verification; predicted === its size.
+2
View File
@@ -183,6 +183,8 @@ export interface CapturePerfSummary {
* averages). Basis for in-the-wild speedup estimates. 0 when no frames.
*/
p50TotalMs: number;
/** Sub-composition timeline wait outcome: ready | timeout | script_failure (absent pre-init). */
subTimelineWaitOutcome?: string;
/**
* Frames served from the static-dedup cache instead of a real seek+screenshot
* (opt-out HF_STATIC_DEDUP=false). 0 when dedup was off or never armed. NOT counted
@@ -189,6 +189,16 @@ export function buildRenderPerfSummary(input: {
input.totalFrames,
)
: undefined,
subTimelineWait: (() => {
const outcomes = input.dedupPerfs
.map((p) => p.subTimelineWaitOutcome)
.filter((o): o is string => !!o);
if (outcomes.length === 0) return undefined;
// Worst outcome wins: script_failure > timeout > ready.
if (outcomes.includes("script_failure")) return "script_failure";
if (outcomes.includes("timeout")) return "timeout";
return "ready";
})(),
captureP50Ms: (() => {
// Per-frame median from the engine's samples; when parallel workers
// report separately, take the busiest session's median.
@@ -322,6 +322,8 @@ export interface RenderPerfSummary {
* captured the most frames when parallel workers report separately.
*/
captureP50Ms?: number;
/** Worst sub-composition timeline wait outcome across sessions: ready | timeout | script_failure. */
subTimelineWait?: string;
capturePeakMs?: number;
captureCalibration?: {
sampledFrames: number[];