Skip to content
Open
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 @@ -1700,6 +1700,7 @@ function trackRenderMetrics(
speedRatio,
captureAvgMs: perf?.captureAvgMs,
captureP50Ms: perf?.captureP50Ms,
subTimelineWait: perf?.subTimelineWait,
videoCount: perf?.videoCount,
capturePeakMs: perf?.capturePeakMs,
tmpPeakBytes: perf?.tmpPeakBytes,
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 @@ -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;
Expand Down Expand Up @@ -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,
Expand Down
66 changes: 66 additions & 0 deletions packages/engine/src/services/frameCapture-subTimelinePoll.test.ts
Original file line number Diff line number Diff line change
@@ -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");
});
});
90 changes: 67 additions & 23 deletions packages/engine/src/services/frameCapture.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -899,6 +909,7 @@ export async function createCaptureSession(
onBeforeCapture,
isInitialized: false,
browserConsoleBuffer: [],
scriptLoadFailures: [],
capturePerf: {
frames: 0,
seekMs: 0,
Expand Down Expand Up @@ -971,21 +982,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;
Expand Down Expand Up @@ -1121,11 +1117,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
Expand All @@ -1142,7 +1146,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
Expand All @@ -1156,8 +1181,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 || {};
Expand All @@ -1175,6 +1201,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(
Expand Down Expand Up @@ -1381,6 +1408,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({
Expand All @@ -1397,6 +1427,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({
Expand Down Expand Up @@ -1461,8 +1494,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");
Expand Down Expand Up @@ -1596,8 +1634,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");
Expand Down Expand Up @@ -3041,6 +3084,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.
Expand Down
2 changes: 2 additions & 0 deletions packages/engine/src/types.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
10 changes: 10 additions & 0 deletions packages/producer/src/services/render/perfSummary.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
2 changes: 2 additions & 0 deletions packages/producer/src/services/renderOrchestrator.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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[];
Expand Down
Loading