mirror of
https://github.com/stablyai/orca.git
synced 2026-09-22 16:02:32 +00:00
test(config): the render rig's navigation wait is bounded, and the frame-budget sweep reads the frames its capture painted (#22177)
* test(config): the render rig's navigation wait is bounded and says why it gave up `waitForRecordedNavigation` ticked every 10 ms until the case's own timeout, so an arm whose click missed its 2 s actionability window waited for a record nobody would write and failed as a bare timeout with the click's error swallowed. Measured on this tree: with the click pointed at a selector that does not exist, both engines failed with `Test timed out in 120000ms` and no mention of the click. C8.1 round 1 saw the same shape at 240 s on CI and dropped a render arm for it. The bound is 10 s, sized from the rig rather than chosen: the four arms that take this path, three runs each on both engines, answered on the loop's first check at 0 ms in all 24 readings, and in 24 more taken while two full `config/scripts` suites ran beside them, where the slowest whole case was 2859 ms. Past it the wait throws naming the arm, how long it waited, what the click did and what the frame last read; the same case now fails in 14.4 s. The happy path is unchanged -- the first check still answers it, with no added wait. Claude-Session: https://claude.ai/code/session_01JNnE9qzUZMMnqpZWCqM3nb * test(config): the frame-budget sweep reads the frames its own capture painted The sweep decided which screencast frames carried the noise by counting arrivals after the raster barrier, and frames do not reach the client in capture order. Measured directly against Chromium through CDP at 1400x1600, six captures at 20x CPU throttling: 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 this capture's paint and still arrived after the barrier, while every frame carrying the noise was stamped inside 150 ms after it. A black 1400x1600 frame encodes to 13483 bytes, which is the 0.006 bytes/px read on 2026-09-22, and a full frame of a previous smaller viewport is the ~447 KB whose posted envelope was the 596462 that 2026-09-21 expected to be null. So the precondition is a reading rather than an ordering: the paint hands back the page's own clock, `Page.screencastFrame` carries the browser's capture time on that same clock, and only frames stamped at or after the paint are admitted. A frame with no capture time is not admissible either, since it cannot be told from a stale one. When none is admissible the error prints every frame with how long after the paint it was captured, instead of understating the budget in silence. The healthy reading is unchanged -- 0.55296 max, 0.54399 min over three idle runs and three under two concurrent config/scripts suites, against 0.55296 / 0.54399 before -- and so is the cost: 18.4 s against 18.1 s. Claude-Session: https://claude.ai/code/session_01JNnE9qzUZMMnqpZWCqM3nb
This commit is contained in:
Jinwoo Hong
@@ -131,6 +131,34 @@ function noiseDocument({ viewportMeta }: { viewportMeta: boolean }): string {
|
||||
return `<!doctype html><html><head>${meta}${style}</head><body><canvas id="noise"></canvas></body></html>`
|
||||
}
|
||||
|
||||
/** 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(
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user