diff --git a/packages/cli/src/capture/captureCompositionFrame.ts b/packages/cli/src/capture/captureCompositionFrame.ts index 065bb610bc..495fd9186f 100644 --- a/packages/cli/src/capture/captureCompositionFrame.ts +++ b/packages/cli/src/capture/captureCompositionFrame.ts @@ -115,6 +115,7 @@ export interface OpenSettledCompositionPageOptions { // Runs after the page exists but before page.goto, so console/pageerror/ // request listeners can attach without missing load-time events. beforeNavigate?: (page: Page) => void | Promise; + onLoaded?: () => void; // Started before the project was bundled; used only if it was launched with the same arguments. prelaunched?: PrelaunchedBrowser; } @@ -331,6 +332,7 @@ export async function openSettledCompositionPage( await options.beforeNavigate?.(page); await gotoWhenSent(page, url, pageNavigationTimeoutMs(options.navigationTimeoutMs)); await assertWebGpuAdapterAvailable(page, requiresWebGpu, softwareWebGpu); + options.onLoaded?.(); const renderReadyTimedOut = !(await waitForCompositionSettle(page, options)); return { browser: chromeBrowser, page, renderReadyTimedOut }; } catch (err) { diff --git a/packages/cli/src/commands/check.test.ts b/packages/cli/src/commands/check.test.ts index a7cbf31343..dbf82183c3 100644 --- a/packages/cli/src/commands/check.test.ts +++ b/packages/cli/src/commands/check.test.ts @@ -1631,6 +1631,38 @@ describe("check pipeline", () => { ); }); + it("a deadline that fires in the overlap pass names that pass in its finding", async () => { + vi.useFakeTimers(); + try { + let aborted!: AbortSignal; + const driver = fakeDriver({ + collectOverlapGrid: vi.fn( + () => + new Promise((_, reject) => + aborted.addEventListener("abort", () => reject(aborted.reason)), + ), + ), + }); + const { deps } = dependencies(driver); + deps.runBrowserCheck = async (_project, options, motion, deadline) => { + aborted = deadline!.signal; + deadline!.start(); + return runAuditGrid(driver, options, motion, undefined, deadline!.enter); + }; + const pending = runCheckPipeline(PROJECT, DEFAULT_CHECK_OPTIONS, deps); + await vi.advanceTimersByTimeAsync(120_000); + const report = await pending; + const failure = report.runtime.findings.find( + (finding) => finding.code === "check_runtime_failure", + ); + expect(failure?.message).toMatch(/^Check did not finish within its deadline/); + expect(failure?.message).toContain("while running the overlap pass."); + expect(failure?.message).toContain("checking samples 0.0, running the overlap pass 120.0."); + } finally { + vi.useRealTimers(); + } + }); + it("--strict flips a warnings-only result from exit 0 to exit 1", async () => { const warningDriver = () => fakeDriver({ diff --git a/packages/cli/src/utils/checkBrowser.ts b/packages/cli/src/utils/checkBrowser.ts index 6751963ab1..74f88083cc 100644 --- a/packages/cli/src/utils/checkBrowser.ts +++ b/packages/cli/src/utils/checkBrowser.ts @@ -239,11 +239,13 @@ export async function runBrowserCheck( ): Promise { const { bundleWithLocalizedFonts } = await import("./bundleWithLocalizedFonts.js"); const html = await bundleWithLocalizedFonts(project.dir); + deadline?.enter("copies"); const { findings: drafts, failedPaths } = await preResolveHostileMediaProxies( project.dir, html, options.autoProxy, ); + deadline?.enter("launch"); const server = await serveStaticProjectHtml( project.dir, html, @@ -279,6 +281,7 @@ export async function runBrowserCheck( wireRuntimeListeners(page, drafts, clock); await deadline?.preparePage(page); }, + onLoaded: () => deadline?.enter("settle"), }); chromeBrowser = session.browser; const page = session.page; @@ -303,7 +306,7 @@ export async function runBrowserCheck( drafts.push(...blur); const sampleLog = sampleWindow(drafts); const driver = createPageDriver(page, clock, sampleLog); - const result = await runGrid(driver, options, motion, helpers); + const result = await runGrid(driver, options, motion, helpers, deadline?.enter); helperSession?.stop(); const helper = await helperOpen?.catch(() => undefined); const merged = helper ? mergeHelperDrafts(sampleLog, helper.sampleLog) : drafts; diff --git a/packages/cli/src/utils/checkDeadline.test.ts b/packages/cli/src/utils/checkDeadline.test.ts index b14a07894d..feec624181 100644 --- a/packages/cli/src/utils/checkDeadline.test.ts +++ b/packages/cli/src/utils/checkDeadline.test.ts @@ -93,3 +93,32 @@ it("closing before browser readiness prevents a later clock from starting", asyn expect(vi.getTimerCount()).toBe(0); expect(deadline.signal.aborted).toBe(false); }); + +it("an expired check names the phase it was in and the seconds each phase took", async () => { + vi.useFakeTimers(); + const deadline = new CheckDeadline(); + const outcome = deadline + .run(() => rejectOnAbort(deadline.signal)) + .catch((error: unknown) => error); + try { + deadline.enter("copies"); + await vi.advanceTimersByTimeAsync(247_000); + deadline.enter("launch"); + await vi.advanceTimersByTimeAsync(2_000); + deadline.start(); + await vi.advanceTimersByTimeAsync(3_000); + deadline.enter("settle"); + await vi.advanceTimersByTimeAsync(60_000); + deadline.enter("samples"); + await vi.advanceTimersByTimeAsync(50_000); + deadline.enter("overlap"); + await vi.advanceTimersByTimeAsync(7_000); + expect(((await outcome) as Error).message).toBe( + "Check did not finish within its deadline (120 s from when Chrome was ready), while running the overlap pass. " + + "Seconds per phase: making video copies 247.0 (before the deadline), starting Chrome 2.0 (before the deadline), " + + "loading the page 3.0, waiting for the page to be ready 60.0, checking samples 50.0, running the overlap pass 7.0.", + ); + } finally { + await deadline.close(); + } +}); diff --git a/packages/cli/src/utils/checkDeadline.ts b/packages/cli/src/utils/checkDeadline.ts index 7ba94cae70..097ff553d1 100644 --- a/packages/cli/src/utils/checkDeadline.ts +++ b/packages/cli/src/utils/checkDeadline.ts @@ -7,12 +7,27 @@ const CHECK_DEADLINE_MS = 120_000; const SCRIPT_START = "[hyperframes:script:start] "; const SCRIPT_FINISH = "[hyperframes:script:finish] "; +const PHASE_LABELS = { + copies: "making video copies", + launch: "starting Chrome", + load: "loading the page", + settle: "waiting for the page to be ready", + samples: "checking samples", + overlap: "running the overlap pass", + crops: "capturing finding crops", +} as const; +export type CheckPhase = keyof typeof PHASE_LABELS; +const BEFORE_DEADLINE: ReadonlySet = new Set(["copies", "launch"]); + export class CheckDeadlineError extends Error { - constructor(readonly sourceFile?: string) { + constructor( + readonly sourceFile?: string, + phases = "", + ) { super( - sourceFile === undefined - ? "Check did not finish within its deadline." - : `${sourceFile}: its script did not finish within the check deadline.`, + (sourceFile === undefined + ? "Check did not finish within its deadline" + : `${sourceFile}: its script did not finish within the check deadline`) + (phases || "."), ); } } @@ -29,6 +44,8 @@ export class CheckDeadline { private readonly expiry: Promise; private rejectExpiry!: (error: CheckDeadlineError) => void; private phase: "waiting" | "started" | "closed" = "waiting"; + private work: { phase: CheckPhase; since: number } | undefined; + private readonly spent = new Map(); constructor() { this.expiry = new Promise((_, reject) => { @@ -36,11 +53,34 @@ export class CheckDeadline { }); } + enter = (phase: CheckPhase): void => { + if (this.expired) return; + const now = Date.now(); + if (this.work) this.spend(this.work.phase, now - this.work.since); + this.work = { phase, since: now }; + this.spend(phase, 0); + }; + + private spend(phase: CheckPhase, ms: number): void { + this.spent.set(phase, (this.spent.get(phase) ?? 0) + ms); + } + + private describe(): string { + if (!this.work) return ""; + const open = Date.now() - this.work.since; + const parts = [...this.spent].map(([phase, ms]) => { + const seconds = ((phase === this.work?.phase ? ms + open : ms) / 1000).toFixed(1); + return `${PHASE_LABELS[phase]} ${seconds}${BEFORE_DEADLINE.has(phase) ? " (before the deadline)" : ""}`; + }); + return ` (${CHECK_DEADLINE_MS / 1000} s from when Chrome was ready), while ${PHASE_LABELS[this.work.phase]}. Seconds per phase: ${parts.join(", ")}.`; + } + start = (): void => { if (this.phase !== "waiting") return; this.phase = "started"; + this.enter("load"); this.timer = setTimeout(() => { - this.expired = new CheckDeadlineError(this.scripts.at(-1)); + this.expired = new CheckDeadlineError(this.scripts.at(-1), this.describe()); this.rejectExpiry(this.expired); this.abort.abort(this.expired); }, CHECK_DEADLINE_MS); diff --git a/packages/cli/src/utils/checkPipeline.ts b/packages/cli/src/utils/checkPipeline.ts index ecc1a9612b..b03eff4051 100644 --- a/packages/cli/src/utils/checkPipeline.ts +++ b/packages/cli/src/utils/checkPipeline.ts @@ -1,5 +1,5 @@ import { BrowserCleanupError } from "../browser/launch.js"; -import { CheckDeadline, CheckDeadlineError } from "./checkDeadline.js"; +import { CheckDeadline, CheckDeadlineError, type CheckPhase } from "./checkDeadline.js"; import { checkSnapshotDirectory, beginCheckSnapshots, @@ -514,6 +514,7 @@ async function collectGridSamples( grid: SampleGrid, motion: MotionPlan, helpers: Promise, + enter: (phase: CheckPhase) => void, ): Promise { const geometryEnabled = grid.captionSamples.length > 0 || grid.frameSamples.length > 0; const sets: SampleSets = { @@ -559,6 +560,7 @@ async function collectGridSamples( driver.markSamples?.("end"); const collected = emptyGridSamples(); for (const samples of perTime) appendGridSamples(collected, samples); + enter("overlap"); await collectMotionOverlapSamples( driver, grid, @@ -566,6 +568,7 @@ async function collectGridSamples( options.range, craftEnabled(driver, options), ); + enter("samples"); return collected; } @@ -1431,7 +1434,9 @@ export async function runAuditGrid( options: CheckOptions, motion: MotionSpecResolution, helpers: Promise = Promise.resolve([]), + enter: (phase: CheckPhase) => void = () => {}, ): Promise { + enter("samples"); await driver.initialize(options.contrast); const grid = await buildSampleGrid(driver, options); const plan = await planMotionSampling( @@ -1440,7 +1445,7 @@ export async function runAuditGrid( grid.duration, ); const seekLoopStart = Date.now(); - const collected = await collectGridSamples(driver, options, grid, plan, helpers); + const collected = await collectGridSamples(driver, options, grid, plan, helpers, enter); const seekLoopMs = Date.now() - seekLoopStart; let motionIssues = plan.preflightIssues; @@ -1693,6 +1698,7 @@ async function withFindingCrops( const cropRequests = selectFindingCropRequests(report); if (cropRequests.length === 0) return report; try { + deadline.enter("crops"); const findingFiles = await deadline.run(() => dependencies.captureFindingCrops(project, options, cropRequests, deadline), ); diff --git a/packages/cli/src/utils/checkTypes.ts b/packages/cli/src/utils/checkTypes.ts index ff7ec80717..1e3851dd18 100644 --- a/packages/cli/src/utils/checkTypes.ts +++ b/packages/cli/src/utils/checkTypes.ts @@ -7,6 +7,7 @@ import type { ProjectDir } from "./project.js"; import type { BrowserGpuMode } from "../browser/gpuPolicy.js"; import type { HdrAutoPromotion } from "@hyperframes/engine"; import type { PrelaunchedBrowser } from "../capture/captureCompositionFrame.js"; +import type { CheckPhase } from "./checkDeadline.js"; export interface CheckOptions { samples: number; @@ -325,6 +326,7 @@ export type RunAuditGrid = ( options: CheckOptions, motion: MotionSpecResolution, helpers?: Promise, + enter?: (phase: CheckPhase) => void, ) => Promise; export interface CheckSection {