diff --git a/config/scripts/mobile-web-app-frame-budget-sweep.test.ts b/config/scripts/mobile-web-app-frame-budget-sweep.test.ts index 13d9bbc8b40..eee3d8268f6 100644 --- a/config/scripts/mobile-web-app-frame-budget-sweep.test.ts +++ b/config/scripts/mobile-web-app-frame-budget-sweep.test.ts @@ -131,6 +131,34 @@ function noiseDocument({ viewportMeta }: { viewportMeta: boolean }): string { return `${meta}${style}` } +/** One screencast frame: its encoded size, and when the browser captured it. */ +type CapturedFrame = { bytes: number; stamp: number | null } + +/** + * The frames this capture may be read from, which is the precondition the byte count needs. + * + * Two readings rather than an ordering. `rastered` is where the arrivals after the raster barrier + * begin, and `paintedAt` is the page's own clock at the moment its second animation frame ran after + * the noise was put on the canvas -- the clock `metadata.timestamp` is also on. A frame is admitted + * only if the browser captured it at or after that moment. + * + * Arrival order cannot stand in for it: frames do not reach the client in capture order. Measured on + * this rig at 20x CPU throttling, over six captures, every frame of the black canvas the resize left + * and every frame still in flight from the previous viewport was stamped 86 to 161 ms before the + * paint and yet arrived after the barrier, while every frame carrying the noise was stamped inside + * 150 ms after it. Admitting one of those stale frames is both readings this sweep has flaked on: a + * black 1400x1600 frame encodes to 13483 bytes, which is the 0.006 bytes/px of 2026-09-22, and a + * full frame of the previous and smaller viewport is the ~447 KB whose posted envelope was the + * 596462 that 2026-09-21 expected to be null. + */ +function framesCarryingTheNoise( + frames: CapturedFrame[], + rastered: number, + paintedAt: number +): CapturedFrame[] { + return frames.slice(rastered).filter((one) => one.stamp !== null && one.stamp >= paintedAt) +} + /** * A noise JPEG at the quality the pane ships, encoded by Chromium's screencast, in bytes. * @@ -177,13 +205,22 @@ async function screencastNoiseJpegBytes( canvas.style.height = `${height}px` }, frame) - const sizes: number[] = [] - const onFrame = (event: { data: string; sessionId: number }): void => { - sizes.push(Buffer.from(event.data, 'base64').length) + const frames: CapturedFrame[] = [] + const onFrame = (event: { + data: string + sessionId: number + metadata: { timestamp?: number } + }): void => { + frames.push({ + bytes: Buffer.from(event.data, 'base64').length, + // Seconds in the protocol, milliseconds here, so it compares against the page's own clock. + stamp: event.metadata.timestamp === undefined ? null : event.metadata.timestamp * 1000 + }) void session.send('Page.screencastFrameAck', { sessionId: event.sessionId }).catch(() => {}) } session.on('Page.screencastFrame', onFrame) - let painted = 0 + let rastered = 0 + let paintedAt = Number.POSITIVE_INFINITY try { await session.send('Page.startScreencast', { format: 'jpeg', @@ -194,9 +231,11 @@ async function screencastNoiseJpegBytes( }) // The noise is painted after the screencast is running, and through this same CDP session, so // the reply orders it against the frame events. Two animation frames are awaited inside it, so - // when it resolves the paint has been committed to the compositor. - await session.send('Runtime.evaluate', { + // when it resolves the paint has been committed to the compositor -- and it hands back the + // page's own clock at that moment, which is what says which frames carry this noise. + const painting = await session.send('Runtime.evaluate', { awaitPromise: true, + returnByValue: true, expression: `(async () => { const canvas = document.getElementById('noise') const context = canvas.getContext('2d') @@ -211,8 +250,10 @@ async function screencastNoiseJpegBytes( } context.putImageData(image, 0, 0) await new Promise((resolve) => requestAnimationFrame(() => requestAnimationFrame(resolve))) + return Date.now() })()` }) + paintedAt = Number(painting.result.value) // A commit is not a raster. The screencast hands over whatever the compositor has drawn so far, // so after a resize it emits frames at the full size carrying only the tiles rastered yet. @@ -223,12 +264,18 @@ async function screencastNoiseJpegBytes( // so it is the raster this wants rather than a longer wait, and over the same rounds with it // none read under the floor. Quality 0 because nothing reads its bytes; 17 ms a call. await session.send('Page.captureScreenshot', { format: 'jpeg', quality: 0 }) - painted = sizes.length + rastered = frames.length - // Nudged until a frame lands after that raster. Two are taken and the larger is used, so a - // capture already in flight when the barrier returned cannot be the one this measures. + // Nudged until two frames the browser captured after this capture's own paint have landed. Two + // are taken and the larger is used, so a part-rastered frame cannot be the one this measures, + // and they are counted by `framesCarryingTheNoise` rather than by arrival for the reason it + // carries: a frame in flight from the previous viewport arrives here too. const deadline = Date.now() + 20_000 - for (let nudge = 0; sizes.length - painted < 2 && Date.now() < deadline; nudge += 1) { + for ( + let nudge = 0; + framesCarryingTheNoise(frames, rastered, paintedAt).length < 2 && Date.now() < deadline; + nudge += 1 + ) { await session.send('Runtime.evaluate', { expression: `document.documentElement.style.background = ${nudge % 2 === 0 ? "'#000'" : "'#111'"}` }) @@ -238,15 +285,23 @@ async function screencastNoiseJpegBytes( await session.send('Page.stopScreencast').catch(() => {}) session.off('Page.screencastFrame', onFrame) } - const afterPaint = sizes.slice(painted) + const afterPaint = framesCarryingTheNoise(frames, rastered, paintedAt) if (afterPaint.length === 0) { // Never fall back to a frame from before the raster: that is the understatement this exists to - // rule out, and a silent one would look like a cheaper encoder. + // rule out, and a silent one would look like a cheaper encoder. Every frame is printed with how + // long after the paint the browser captured it, so a window that held only stale ones is legible + // rather than inferred. + const seen = JSON.stringify( + frames.map((one) => ({ + bytes: one.bytes, + afterPaintMs: one.stamp === null ? null : Math.round(one.stamp - paintedAt) + })) + ) throw new Error( - `no screencast frame after the noise was rastered for ${frame.width}x${frame.height}` + `no screencast frame carried the rastered noise for ${frame.width}x${frame.height}: ${seen}` ) } - return Math.max(...afterPaint) + return Math.max(...afterPaint.map((one) => one.bytes)) } function screencastFrame(image: Uint8Array, frame: { width: number; height: number }) { @@ -395,6 +450,27 @@ describeSweep('the frame budget across the viewport range', () => { } }, 120_000) + it('reads the frames this capture painted, never one left over from the last', () => { + // The four shapes measured on this rig at 20x CPU throttling, all arriving after the raster + // barrier: the black canvas the resize left, a full frame of the previous and larger viewport, + // and this capture's own two. Only the last two are this capture's, and the gap between the + // stale stamps and the paint was never under 86 ms. + const frames = [ + { bytes: 13_483, stamp: 914 }, + { bytes: 447_491, stamp: 939 }, + { bytes: 997_489, stamp: 1005 }, + { bytes: 997_489, stamp: 1024 } + ] + expect(framesCarryingTheNoise(frames, 0, 1000).map((one) => one.bytes)).toEqual([ + 997_489, 997_489 + ]) + // A frame the browser sent no capture time for is not admissible either: it cannot be told from + // the stale ones, and guessing it fresh is the understatement the gate exists to refuse. + expect(framesCarryingTheNoise([{ bytes: 997_489, stamp: null }], 0, 1000)).toEqual([]) + // And the arrivals before the raster barrier stay out, which is the other half of the reading. + expect(framesCarryingTheNoise(frames, 3, 1000).map((one) => one.bytes)).toEqual([997_489]) + }) + it('never asks for more density than native, anywhere in the range', () => { for (const viewport of VIEWPORTS) { expect(budgetedFrame(viewport).scale).toBeLessThanOrEqual( diff --git a/config/scripts/mobile-web-app-html-preview-render.test.mjs b/config/scripts/mobile-web-app-html-preview-render.test.mjs index deb47f5f8f0..48f97486487 100644 --- a/config/scripts/mobile-web-app-html-preview-render.test.mjs +++ b/config/scripts/mobile-web-app-html-preview-render.test.mjs @@ -761,7 +761,7 @@ for (const engine of ['chromium', 'webkit']) { () => false, stop.signal, { arm: 'arm sampling-probe', browserVersion: browser().version() }, - 25 + { sampleEveryMs: 25 } ) clearTimeout(timer) spy.mockRestore() @@ -772,6 +772,36 @@ for (const engine of ['chromium', 'webkit']) { expect(printed[0]).toContain('frames [') }, 60_000) + // The bound, driven once. An arm whose click misses its actionability window waits here for a + // record nobody will write, and before the bound existed it spent the case's whole budget and + // failed as a bare timeout. What this pins is the reason it fails with instead. + it('gives up on a navigation that is not coming, and names why', async (ctx) => { + void ctx + const page = await browser().newPage() + try { + const failed = await waitForRecordedNavigation( + page, + [], + () => false, + null, + { + arm: 'arm bound-probe', + browserVersion: browser().version(), + actError: 'locator.click: Timeout 2000ms exceeded' + }, + { boundMs: 50 } + ).catch((error) => String(error)) + // Which arm, how long it waited, what its click did, and what the frame last read -- the + // four a CI log has nothing else to go on for. + expect(failed).toContain('arm bound-probe') + expect(failed).toMatch(/waited \d+ms for the navigation it expects/) + expect(failed).toContain('Timeout 2000ms exceeded') + expect(failed).toContain('frames [') + } finally { + await page.close() + } + }, 60_000) + it('keeps the Preview/Source toggle, and Source shows the source', async (ctx) => { const read = await open(browser(), { signal: ctx.signal, diff --git a/config/scripts/mobile-web-app-preview-arm-driver.mjs b/config/scripts/mobile-web-app-preview-arm-driver.mjs index e82def32183..c09eb00be65 100644 --- a/config/scripts/mobile-web-app-preview-arm-driver.mjs +++ b/config/scripts/mobile-web-app-preview-arm-driver.mjs @@ -194,7 +194,10 @@ export async function openPreviewArm( frame: artifactFrame, browserVersion, arm, - describeRequests + describeRequests, + // Carried, not just recorded: an arm whose click threw is waiting for a record nobody will + // write, and the bounded wait says so rather than leaving a bare timeout. + actError }) const result = await readPreviewArm({ page, diff --git a/config/scripts/mobile-web-app-preview-frame-readiness.mjs b/config/scripts/mobile-web-app-preview-frame-readiness.mjs index f62eecb75c3..c50c4d390a3 100644 --- a/config/scripts/mobile-web-app-preview-frame-readiness.mjs +++ b/config/scripts/mobile-web-app-preview-frame-readiness.mjs @@ -254,14 +254,31 @@ export async function settleAfterMount(page, navigations, expectNavigation, sign return await settleWithoutNavigation(page) } +/** + * How long a navigation an arm expects may go unrecorded before the wait calls it absent. + * + * Measured rather than chosen. Across the four arms that wait for one, three runs each on both + * engines, all 24 readings were satisfied on the loop's first check at 0 ms, and so were 24 more + * taken while two full `config/scripts` suites ran beside them: the record lands during the reads + * that precede this wait. The slowest whole case in that loaded set -- four arms, end to end -- was + * 2859 ms, so this is about fifteen loaded arms' worth of margin over a reading of zero, and a + * twelfth of the smallest budget (120 s) the cases that take this path declare. + * + * That gap is the point. A click carries a 2 s actionability window, and an arm whose click missed + * it is waiting for a record nobody will write; before this bound existed that arm spent the case's + * whole budget and failed as a bare timeout with the click's own error swallowed. Now it fails here, + * inside its own case, saying which arm, how long, what the click did and what the frame last read. + */ +const NAVIGATION_RECORD_MS = 10_000 + /** * The moment the arm's navigation exists, for an arm that expects one. * - * No clock at all: the rig's `page.on('request')` subscription records a main-frame navigation as - * the browser dispatches it, so the oracles are read after the thing under test rather than after a - * wait, and the only bound is the case's own timeout through `ctx.signal`. The route beside it only - * refuses the navigation; it stopped counting anything when the record moved off interception. An arm whose click missed its target prints - * what it did record and lets the case fail as the timeout it is. + * No clock on the happy path: the rig's `page.on('request')` subscription records a main-frame + * navigation as the browser dispatches it, so the oracles are read after the thing under test rather + * than after a wait, and the first check of the loop is what every passing arm answers. The route + * beside it only refuses the navigation; it stopped counting anything when the record moved off + * interception. * * Measured, so it is not sold as more than it is: with this replaced by a no-op every arm still * passes, because the reads that follow are each a round trip and the record lands during them. It is @@ -274,29 +291,43 @@ export async function waitForRecordedNavigation( matches, signal, reading, - sampleEveryMs = 5000 + { sampleEveryMs = 5000, boundMs = NAVIGATION_RECORD_MS } = {} ) { + // The same evidence the images arm prints. A navigation arm that produced nothing is asking the + // same question of the same frame, and on CI this one fails on its own. + const read = async () => + await describePreviewFrame(page, reading?.frame, reading?.browserVersion) + .then(async (frameReading) => { + const evidence = await reading?.describeRequests?.(reading?.frame) + return evidence ? `${frameReading} | ${evidence}` : frameReading + }) + .catch((error) => `the reading itself failed: ${String(error).split('\n')[0]}`) // Sampled while waiting, for the same reason `untilAborted` samples: a reading taken at the abort // can lose its race with vitest's teardown and never reach the log. let latest = 'no reading was taken before the case ended' - let since = Date.now() + const started = Date.now() + let since = started + // What the click did is half the answer here, so it is named either way: an arm that clicked + // cleanly and got no navigation is the product's doing, one whose click threw is the rig's. + const absent = (waited, last) => + `${reading?.arm ?? 'arm unknown'} waited ${String(waited)}ms for the navigation it expects ` + + `and recorded ${JSON.stringify(navigations)}; its action ` + + `${reading?.actError ? `failed with ${JSON.stringify(reading.actError)}` : 'reported no error'}` + + ` | ${last}` while (!navigations.some((one) => matches(one))) { if (signal?.aborted) { - console.error( - `[html-preview-render] the arm produced no navigation of the kind it expects; recorded ${JSON.stringify(navigations)}: ${reading?.arm ?? 'arm unknown'} | ${latest}` - ) + console.error(`[html-preview-render] ${absent(Date.now() - started, latest)}`) return } + const waited = Date.now() - started + if (waited > boundMs) { + // Read here and not from the sample: the bound is shorter than the sampling interval, so an + // arm that fails on it would otherwise print the placeholder instead of the frame. + throw new Error(`[html-preview-render] ${absent(waited, await read())}`) + } if (Date.now() - since > sampleEveryMs) { since = Date.now() - latest = await describePreviewFrame(page, reading?.frame, reading?.browserVersion) - .then(async (frameReading) => { - // The same evidence the images arm prints. A navigation arm that produced nothing is - // asking the same question of the same frame, and on CI this one fails on its own. - const evidence = await reading?.describeRequests?.(reading?.frame) - return evidence ? `${frameReading} | ${evidence}` : frameReading - }) - .catch((error) => `the reading itself failed: ${String(error).split('\n')[0]}`) + latest = await read() } await page.waitForTimeout(10) }