diff --git a/internal/interaction-harness/README.md b/internal/interaction-harness/README.md index acceed2eaa8ba..db603cf2f7054 100644 --- a/internal/interaction-harness/README.md +++ b/internal/interaction-harness/README.md @@ -640,22 +640,22 @@ sent with `Input.dispatchTouchEvent`. WebKit has no `isInputPending`. ## Engine limits (measured with Playwright 1.61) -| | Chromium 149 | WebKit 26.5 (Linux build) | -| ------------------------------------------------------ | ---------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| Trusted touch + pointer events, multi-touch | yes | yes (a `touchstart` lists only the fingers that landed in it; pointer events exact) | -| Page sees the scripted timestamps | yes, exactly | no: real dispatch time; pacing keeps velocities within ~1 ms on an idle runner; after a stall each step waits its gap, less 2 ms, after WebKit answered the one before, even with `onEvent`, so no gap can shrink; a play fails when its page read a resting finger where the script moves, a throw where the script rests, or fewer than two moves, or, given `releaseTolerance`, a release straying further from the script's (each read as Core's tracker reads it): `TouchLiftStallError` when `onEvent` held the lift back, `TouchPageStallError` when the page's listeners held an event, else `TouchPacingError`; the lift's `release` names what the page read | -| Sub-pixel touch positions | yes | no: integer CSS px | -| Native scroll, fling, pinch-zoom from injected touches | yes | no | -| Lifting one finger while others stay down | yes | pointer events right, but that `touchend` lists no remaining `touches`: skip with `PARTIAL_LIFT_SKIP` | -| Click synthesised from a touch | yes | only from `driver.tap` (WebKit's tap gesture), not from a raw touch sequence | -| Curve sampling, storyboards, input log | yes | yes | -| A CSS animation shorter than a gap between two frames | yes: a pending animation starts at the next frame, and runs then | no: it can start and finish inside the gap, and its start event, sent at the next frame, finds nothing to record; `waitForAnimation` names it | -| Screencast frame evidence (busy main thread) | yes | yes (WebKit's own screencast; frames keep coming while the main thread is blocked) | -| Rendering trace, long tasks | yes | no (Playwright exposes neither) | -| Compositor presentation record | yes | no: `stop()` resolves to `[]`; the busy verdict judges the screencast alone | -| Wheel steps, exact CSS px deltas (`webInput.ts`) | yes | desktop context only (`isMobile: false`): skip with `WHEEL_SKIP`; the step also moves the mouse there (a `pointermove`) and holds Control as a key | -| Pen strokes, pressure, scripted timestamps | yes | no: skip with `PEN_SKIP` | -| Pen over a native scroller | no pan: the pen takes the mouse pipeline, so a stroke scrolls nothing, raises no `pointercancel` and ends in a `click` | no: skip with `PEN_SKIP` | +| | Chromium 149 | WebKit 26.5 (Linux build) | +| ------------------------------------------------------ | ---------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Trusted touch + pointer events, multi-touch | yes | yes (a `touchstart` lists only the fingers that landed in it; pointer events exact) | +| Page sees the scripted timestamps | yes, exactly | no: real dispatch time; pacing keeps velocities within ~1 ms on an idle runner; after a stall each step waits its gap, less 2 ms, after WebKit answered the one before, even with `onEvent`, so no gap can shrink; a play fails when its page read a resting finger where the script moves, a throw where the script rests, or fewer than two moves, or, given `releaseTolerance`, a release straying further from the script's (each read as Core's tracker reads it): `TouchLiftStallError` when `onEvent` held the lift back, `TouchPageStallError` when the page's listeners held an event, `TouchStarvationError` when the page drew no frame across the late gap, else `TouchPacingError`; the lift's `release` names what the page read | +| Sub-pixel touch positions | yes | no: integer CSS px | +| Native scroll, fling, pinch-zoom from injected touches | yes | no | +| Lifting one finger while others stay down | yes | pointer events right, but that `touchend` lists no remaining `touches`: skip with `PARTIAL_LIFT_SKIP` | +| Click synthesised from a touch | yes | only from `driver.tap` (WebKit's tap gesture), not from a raw touch sequence | +| Curve sampling, storyboards, input log | yes | yes | +| A CSS animation shorter than a gap between two frames | yes: a pending animation starts at the next frame, and runs then | no: it can start and finish inside the gap, and its start event, sent at the next frame, finds nothing to record; `waitForAnimation` names it | +| Screencast frame evidence (busy main thread) | yes | yes (WebKit's own screencast; frames keep coming while the main thread is blocked) | +| Rendering trace, long tasks | yes | no (Playwright exposes neither) | +| Compositor presentation record | yes | no: `stop()` resolves to `[]`; the busy verdict judges the screencast alone | +| Wheel steps, exact CSS px deltas (`webInput.ts`) | yes | desktop context only (`isMobile: false`): skip with `WHEEL_SKIP`; the step also moves the mouse there (a `pointermove`) and holds Control as a key | +| Pen strokes, pressure, scripted timestamps | yes | no: skip with `PEN_SKIP` | +| Pen over a native scroller | no pan: the pen takes the mouse pipeline, so a stroke scrolls nothing, raises no `pointercancel` and ends in a `click` | no: skip with `PEN_SKIP` | What WebKit cannot show here — native scroll hand-off, flings, a finger lifting while another stays down, finger tracking under a busy main thread, and @@ -673,7 +673,11 @@ The error is `TouchLiftStallError` when `onEvent` alone carries the scripted gap past the stillness interval, however much a loaded runner stretched it. Record what the page did in a listener of its own, or let the script rest before the lift. A runner too loaded to dispatch in time stretches a -gesture the same way, and the play fails with `TouchPacingError`. A play whose +gesture the same way, and the play fails with `TouchPacingError`. When the +page also drew no frame for longer than `FRAME_STARVATION_MS` across that +gap, and no page work held the event, it fails with `TouchStarvationError`: +the runner starved the page, so judge the proof from a run with CI's CPU +limits. A play whose proof reads no release from the lift, such as a pinch's end, passes `releaseUnread`. diff --git a/internal/interaction-harness/src/frame-starvation.ts b/internal/interaction-harness/src/frame-starvation.ts new file mode 100644 index 0000000000000..128b249ad6faa --- /dev/null +++ b/internal/interaction-harness/src/frame-starvation.ts @@ -0,0 +1,16 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file frame-starvation.ts + * @input Nothing + * @output `FRAME_STARVATION_MS`, the gap between two frames past which a page + * counts as starved + * @position A leaf module. ./frames.ts re-exports it, and ./touch.ts reads it + * too. ./frames.ts imports ./touch.ts, so the constant lives apart from both. + */ + +/** + * A gap between two frames the page drew, ms, past which the page counts as + * starved: about three frames at 60 Hz. + */ +export const FRAME_STARVATION_MS = 50; diff --git a/internal/interaction-harness/src/frames.ts b/internal/interaction-harness/src/frames.ts index 7c158b399799e..fbf1302746681 100644 --- a/internal/interaction-harness/src/frames.ts +++ b/internal/interaction-harness/src/frames.ts @@ -28,8 +28,11 @@ */ import type {CDPSession, Locator, Page} from '@playwright/test'; +import {FRAME_STARVATION_MS} from './frame-starvation'; import {webkitPageSession} from './touch'; +export {FRAME_STARVATION_MS} from './frame-starvation'; + export interface CastFrame { /** Presentation time, epoch ms (the compositor's frame timestamp). */ readonly t: number; @@ -879,12 +882,6 @@ export function frameStats( }; } -/** - * A gap between two frames the page drew, ms, past which the page counts as - * starved: about three frames at 60 Hz. - */ -export const FRAME_STARVATION_MS = 50; - const framesDrawn = (count: number) => `${count} ${count === 1 ? 'frame' : 'frames'}`; diff --git a/internal/interaction-harness/src/harness.interaction.browser.spec.ts b/internal/interaction-harness/src/harness.interaction.browser.spec.ts index f3d3bdb581b83..f97f277ddeaf1 100644 --- a/internal/interaction-harness/src/harness.interaction.browser.spec.ts +++ b/internal/interaction-harness/src/harness.interaction.browser.spec.ts @@ -190,6 +190,46 @@ async function fixture(page: Page) { await page.goto('http://harness.test/'); } +/** + * Starts a chain of 4 ms timers in the test process. It records how late each + * woke, when, and how long the process ran while that timer waited. A runner + * whose CPU quota stalls the process wakes them late, as it wakes the touch + * pacer late. The process then runs little in the wait. Harness code that + * holds the process wakes them late too, but the process runs through the + * wait. + */ +function startWakeControl(): { + stop(): { + readonly at: number; + readonly lateMs: number; + readonly ranMs: number; + }[]; +} { + const wakes: {at: number; lateMs: number; ranMs: number}[] = []; + let timer: ReturnType | undefined; + const arm = () => { + const due = performance.now() + 4; + const cpu = process.cpuUsage(); + timer = setTimeout(() => { + const now = performance.now(); + const ran = process.cpuUsage(cpu); + wakes.push({ + at: now, + lateMs: now - due, + ranMs: (ran.user + ran.system) / 1000, + }); + arm(); + }, 4); + }; + arm(); + return { + stop() { + clearTimeout(timer); + return wakes; + }, + }; +} + /** * Waits until a cast holds `min` frames. A cast sends a frame only when the * screen changes, and a loaded runner sends fewer of them. Past `capMs` @@ -237,19 +277,22 @@ test.describe('touch input', () => { ); // One take: a fresh page, the script played, and the harness's record of // when each step left (`dispatchedAt`) and when its dispatch was answered. + // A control timer runs in the test process beside it. const take = async () => { await fixture(page); const driver = await touchDriver(page); const answeredAt: number[] = []; // Taken before the harness reads its own clock to schedule the script. const playStart = Date.now(); + const control = startWakeControl(); const played = await driver.play(script, { onEvent: () => { answeredAt.push(Date.now()); }, }); + const wakes = control.stop(); const log = await readInputLog(page); - return {played, answeredAt, playStart, log}; + return {played, answeredAt, playStart, wakes, log}; }; const checkInput = (log: readonly InputRecord[]) => { const moves = log.filter(r => r.type === 'pointermove'); @@ -292,81 +335,132 @@ test.describe('touch input', () => { // the dispatch (it answers only once the page has the event), so a driver // that holds the moves and sends them in a burst fails. // - // This take watches every step (`onEvent`), so each step leaves at its - // scripted time and none waits for WebKit's answer to the one before. + // This take watches every step (`onEvent`), so the test records when + // WebKit answered each step's dispatch. // - // The pacing is bounded from above too. The harness waits only while it - // is ahead of the script and sends a late step at once, so a move it - // waited for (it left more than 2 ms after the step before was answered) - // must leave on time (no more than 2 ms after its scripted time). A harness - // that paces slowly waits past every move's time: sending each step at - // twice its time leaves every move both waited for and late. A harness - // whose send itself outlasts the step's spacing never waits, so a move - // behind such a send is off pace too. A runner whose CPU quota holds the - // test process also wakes the harness late from a wait, or holds a send, - // on a few moves (in a container capped at 3 CPUs, where the quota stalls - // the process for about 100 ms at a time), so a take is off pace when more - // than half its moves are. It is re-taken once, and a second such take - // fails. Under CPU starvation (a 3-CPU cap with 16 workers, with the - // software compositor's threads matched to the cap by LP_NUM_THREADS), a - // pacer the cap throttles falls behind and need not wait, so the pacing - // check can miss a slow pacer there (sending each step at twice its time - // failed 8 of 20 runs), and the quota slows some sends past the step's - // spacing, which reads like a harness whose send is slow (the real test - // passed 40 of 40 there, re-taken 9 times). - for (const attempt of [1, 2] as const) { - const {played, answeredAt, playStart, log} = await take(); - const {moves} = checkInput(log); - const sentAt = played.map(step => step.dispatchedAt); - const moveSteps = played.flatMap((step, i) => - step.type === 'touchMove' ? [i] : [], + // The pacing is bounded from above too. A WebKit play keeps each gap, less + // ANSWER_SLACK_MS, after WebKit answered the step before (`pacedDeadline`), + // so a stall stretches the gesture. A move must leave no more than 2 ms + // after that paced deadline, and a step's send must not outlast the + // spacing to the next. A harness that sends each step at twice its time + // leaves every move later than that. One whose send is that slow stretches + // the next gap by the send, less ANSWER_SLACK_MS. A runner whose CPU quota + // stalls the test process also wakes the harness late, or holds a send. + // A chain of 4 ms control timers then wakes late too: when the harness + // woke, or while it sent. A control timer wakes no more than 4 ms less + // late than the harness in the same stall. So a move is the runner's when + // the control woke more than 2 ms late, and the move was at most 4 ms + // later. The test names such a move and does not fail. Harness code + // that holds the process delays the control timers too, but the process + // runs through that delay. So a control wake counts only when the process + // ran for less than half of how late the wake was. A take fails when more + // than half its moves are off pace while the control woke on time. + const {played, answeredAt, playStart, wakes, log} = await take(); + const {moves} = checkInput(log); + const sentAt = played.map(step => step.dispatchedAt); + const moveSteps = played.flatMap((step, i) => + step.type === 'touchMove' ? [i] : [], + ); + expect(moveSteps).toHaveLength(moves.length); + const timeOrigin = await page.evaluate(() => performance.timeOrigin); + for (const [m, i] of moveSteps.entries()) { + // Against the clock before play() started, not the start event's + // send, which can itself leave late. Date.now() counts whole + // milliseconds, hence the 1 ms. + expect(sentAt[i] - playStart).toBeGreaterThanOrEqual(played[i].t - 1); + // 2 ms of rounding between the two processes' clocks. + expect(timeOrigin + moves[m].timeStamp).toBeGreaterThanOrEqual( + sentAt[i] - 2, ); - expect(moveSteps).toHaveLength(moves.length); - const timeOrigin = await page.evaluate(() => performance.timeOrigin); - for (const [m, i] of moveSteps.entries()) { - // Against the clock before play() started, not the start event's - // send, which can itself leave late. Date.now() counts whole - // milliseconds, hence the 1 ms. - expect(sentAt[i] - playStart).toBeGreaterThanOrEqual(played[i].t - 1); - // 2 ms of rounding between the two processes' clocks. - expect(timeOrigin + moves[m].timeStamp).toBeGreaterThanOrEqual( - sentAt[i] - 2, - ); - expect(timeOrigin + moves[m].timeStamp).toBeLessThanOrEqual( - answeredAt[i] + 2, + expect(timeOrigin + moves[m].timeStamp).toBeLessThanOrEqual( + answeredAt[i] + 2, + ); + if (m > 0) { + expect(moves[m].timeStamp).toBeGreaterThanOrEqual( + moves[m - 1].timeStamp, ); - if (m > 0) { - expect(moves[m].timeStamp).toBeGreaterThanOrEqual( - moves[m - 1].timeStamp, - ); - } } - // Lateness against the latest the play clock can have started: the - // start event's send. - const waitedLate = moveSteps.filter( - i => - sentAt[i] - answeredAt[i - 1] > 2 && - sentAt[i] - sentAt[0] - played[i].t > 2, - ); - // A move behind a send that took longer than the step's spacing: a - // harness whose send itself is that slow never waits, and paces every - // move at the send's speed. - const slowSent = moveSteps.filter( - i => answeredAt[i - 1] - sentAt[i - 1] > played[i].t - played[i - 1].t, + } + // How late the control woke between two times, ms. With no wake in that + // span, the first wake after it. A wake whose process ran for half its + // delay or more counts as on time. The test process itself held it, not + // the runner. + const controlLateMs = (from: number, to: number) => { + const within = wakes.filter(wake => wake.at >= from && wake.at <= to); + const next = wakes.find(wake => wake.at > to); + return Math.max( + 0, + ...(within.length > 0 ? within : next == null ? [] : [next]).map( + wake => (wake.ranMs < wake.lateMs / 2 ? wake.lateMs : 0), + ), ); - const offPace = new Set([...waitedLate, ...slowSent]); - if (offPace.size <= moves.length / 2) { - return; - } - const lateMs = waitedLate.map(i => - Math.round(sentAt[i] - sentAt[0] - played[i].t), + }; + // Each move's paced deadline, from the latest the play clock can have + // started (the start event's send) and WebKit's answer to the step + // before. Both come from the clock the play paces on, which reads a + // fraction of a millisecond, as do the control's wakes. + const pacedSent = played.map(step => step.pacedSentAt); + const pacedReturned = played.map(step => step.pacedReturnedAt); + const offPace = moveSteps.flatMap((i, move) => { + const spacing = played[i].t - played[i - 1].t; + const deadline = Math.max( + pacedSent[0] + played[i].t, + pacedReturned[i - 1] + spacing - ANSWER_SLACK_MS, ); - const note = `take ${attempt}: ${offPace.size} of ${moves.length} moves off pace: ${waitedLate.length} left late after the harness waited for them${lateMs.length > 0 ? ` (${lateMs.join(', ')} ms late)` : ''}, ${slowSent.length} followed a send slower than the step`; - if (attempt === 2) { - throw new Error(`touch pacing: ${note}`); - } - testInfo.annotations.push({type: 'touch-retake', description: note}); + const lateMs = pacedSent[i] - deadline; + const sendMs = pacedReturned[i - 1] - pacedSent[i - 1]; + return [ + // The control wakes that a stall ending at the harness's own wake + // delayed too. + ...(lateMs > 2 + ? [ + { + move, + why: 'left late', + ms: lateMs, + runnerMs: controlLateMs(pacedSent[i] - 2, pacedSent[i] + 8), + }, + ] + : []), + ...(sendMs > spacing + ? [ + { + move, + why: 'followed a slow send', + ms: sendMs - ANSWER_SLACK_MS, + runnerMs: controlLateMs( + pacedSent[i - 1], + pacedReturned[i - 1] + 4, + ), + }, + ] + : []), + ]; + }); + const byRunner = (move: (typeof offPace)[number]) => + move.runnerMs > 2 && move.ms <= move.runnerMs + 4; + const runner = offPace.filter(byRunner); + const harness = offPace.filter(move => !byRunner(move)); + // A move can be off pace for both reasons: it counts once. + const countMoves = (list: typeof offPace) => + new Set(list.map(entry => entry.move)).size; + const describe = (list: typeof offPace) => + list + .map( + move => + `${move.why} by ${Math.round(move.ms)} ms (control ${Math.round(move.runnerMs)} ms late)`, + ) + .join(', '); + if (runner.length > 0) { + testInfo.annotations.push({ + type: 'touch-runner-late', + description: `${countMoves(runner)} of ${moves.length} moves were off pace while the runner woke a control timer as late: ${describe(runner)}`, + }); } + expect( + countMoves(harness), + `touch pacing: ${countMoves(harness)} of ${moves.length} moves off pace while the control woke on time: ${describe(harness)}`, + ).toBeLessThanOrEqual(moves.length / 2); }); test("a page whose pointer listener holds its main thread changes a paced flick's release itself: TouchPageStallError, never the runner's", async ({ diff --git a/internal/interaction-harness/src/touch.pacing.test.ts b/internal/interaction-harness/src/touch.pacing.test.ts index 9f93402653ecd..c786273dd0462 100644 --- a/internal/interaction-harness/src/touch.pacing.test.ts +++ b/internal/interaction-harness/src/touch.pacing.test.ts @@ -18,16 +18,18 @@ * the runner's. A scrolling surface's release also reads the interval * before them. A release or a hold on the other side of a play's boundary * from the script's is a fault. Each pacing error names the longest time - * the page drew no frame. + * the page drew no frame. A late gap that no page work explains, across + * which the page drew no frame, is the starved runner's. * @position Node unit tests beside the harness's browser self-tests. * * SYNC: When modified, update touch.ts (pacedDeadline, touchPacingFault, - * TouchPacingError, TouchPageStallError, TouchLiftStallError, + * TouchPacingError, TouchPageStallError, TouchStarvationError, + * TouchLiftStallError, * TOUCH_STILLNESS_MS, TOUCH_RELEASE_NEWEST_WEIGHT). */ import {describe, expect, it} from 'vitest'; -import type {TouchEventStep} from './scripts'; +import {pinch, toTouchEvents, type TouchEventStep} from './scripts'; import { ANSWER_SLACK_MS, pacedDeadline, @@ -39,6 +41,7 @@ import { TouchLiftStallError, TouchPacingError, TouchPageStallError, + TouchStarvationError, liftStallError, longestFrameGap, readHold, @@ -619,6 +622,116 @@ describe('touchPlayError', () => { }); }); +describe('touchPlayError on a starved runner', () => { + // The lift reaches the page 120 ms after the last move, step 5, where the + // script spaces 16 ms: the page reads a resting finger. + const lateLift = at([0, 16, 32, 48, 64, 80, 200]); + const quick = [0, 0, 0, 0, 0, 0, 0]; + // The page drew no frame from 78 ms to 230 ms, across the lift's gap. + const starved = [0, 16, 33, 48, 64, 78, 230]; + const errorFor = ( + arrivals: TouchArrival[], + frames: number[], + onEventMs = quick, + ) => { + const fault = touchPacingFault(FLICK, arrivals); + if (fault?.kind !== 'rest') { + throw new Error('expected the page to read a rest'); + } + return touchPlayError(FLICK, arrivals, fault, onEventMs, frames); + }; + + it('names the starved runner when the page drew no frame across the late gap, and no page work held the event', () => { + const error = errorFor(lateLift, starved); + expect(error).toBeInstanceOf(TouchStarvationError); + expect(error.message).toMatch( + /the page drew no frame for 152 ms across a 120 ms gap where the script spaces 16 ms, and the page read a resting finger/, + ); + expect(error.message).toMatch( + /the runner starved the page\. Judge the proof from a run with CI's CPU limits/, + ); + }); + + it("names the gesture's longest frame gap, as every pacing error does", () => { + const fault = touchPacingFault(FLICK, lateLift); + if (fault?.kind !== 'rest') { + throw new Error('expected the page to read a rest'); + } + const error = touchPlayError( + FLICK, + lateLift, + {...fault, frameGapMs: longestFrameGap(starved, lateLift)}, + quick, + starved, + ); + expect(error).toBeInstanceOf(TouchStarvationError); + expect(error.message).toMatch( + /the page drew no frame for 152 ms during the gesture/, + ); + }); + + it('keeps a dispatch that stalled while the page drew frames a TouchPacingError', () => { + const drawing = Array.from({length: 15}, (_, k) => 16 * k); + expect(errorFor(lateLift, drawing)).toBeInstanceOf(TouchPacingError); + }); + + it("reads the frames across the late gap, not the gesture's longest frame gap", () => { + // No frame for 70 ms at the start, then one every 16 ms across the lift. + const earlyGap = [0, 70, 86, 102, 118, 134, 150, 166, 182, 198, 214]; + expect(longestFrameGap(earlyGap, lateLift)).toBe(70); + expect(errorFor(lateLift, earlyGap)).toBeInstanceOf(TouchPacingError); + }); + + it("keeps a gap the page's listeners held the page's, though the page drew nothing", () => { + const heldLift = lateLift.map((a, i) => + i === 5 ? {...a, handledAt: a.stamp + 110} : a, + ); + expect(errorFor(heldLift, starved)).toBeInstanceOf(TouchPageStallError); + }); + + it('keeps a wait for the main thread a TouchPacingError that names the wait, though the page drew nothing', () => { + // A page task held the main thread 100 ms before the last move's listeners. + const waitedLift = lateLift.map((a, i) => + i === 5 ? {...a, startedAt: a.stamp + 100, handledAt: a.stamp + 104} : a, + ); + const error = errorFor(waitedLift, starved); + expect(error).toBeInstanceOf(TouchPacingError); + expect(error.message).toMatch( + /an event waited 100 ms for the main thread before the page's listeners began/, + ); + }); + + it('names the lift stall first when onEvent alone carries the gap past the stillness interval', () => { + expect(errorFor(lateLift, starved, [0, 0, 0, 0, 0, 70, 0])).toBeInstanceOf( + TouchLiftStallError, + ); + }); + + it("names the starved runner for a pinch's late lift too", () => { + const steps = toTouchEvents( + pinch({ + center: {x: 200, y: 300}, + fromDistance: 100, + toDistance: 200, + durationMs: 100, + hz: 60, + }), + ); + const lift = steps.length - 1; + // Every step at its scripted time, but the lift 60 ms late. + const arrivals = at(steps.map((step, i) => step.t + (i === lift ? 60 : 0))); + const fault = touchPacingFault(steps, arrivals); + if (fault?.kind !== 'rest') { + throw new Error('expected the page to read a rest'); + } + const lastMove = arrivals[lift - 1].stamp; + const frames = [0, 16, 33, 50, 66, 83, lastMove - 1, lastMove + 120]; + const error = touchPlayError(steps, arrivals, fault, [], frames); + expect(error).toBeInstanceOf(TouchStarvationError); + expect((error as TouchStarvationError).fault.late.index).toBe(lift); + }); +}); + describe('boundaries, the scroll release and frame evidence', () => { // The third move reaches the page 20 ms late; the moves after it keep the // script's 16 ms. diff --git a/internal/interaction-harness/src/touch.ts b/internal/interaction-harness/src/touch.ts index d5715cc0bd956..064a8ee10360d 100644 --- a/internal/interaction-harness/src/touch.ts +++ b/internal/interaction-harness/src/touch.ts @@ -44,6 +44,7 @@ */ import type {CDPSession, JSHandle, Page} from '@playwright/test'; +import {FRAME_STARVATION_MS} from './frame-starvation'; import { toTouchEvents, type Finger, @@ -136,9 +137,11 @@ export interface PlayOptions { * throws when the page's release strays further than that share. The error * is `TouchLiftStallError` when the play's own `onEvent` held the lift back. * It is `TouchPageStallError` when the page's own touch and pointer - * listeners held an event back, else `TouchPacingError` (see - * `touchPacingFault`). A `'spacing'` play also throws when the page received - * fewer touch events than it sent; any other play is then not judged. + * listeners held an event back. It is `TouchStarvationError` when the page + * drew no frame across the late gap and no page work held the event, else + * `TouchPacingError` (see `touchPacingFault`). A `'spacing'` play also + * throws when the page received fewer touch events than it sent; any other + * play is then not judged. */ readonly pacing?: TouchPacing; /** @@ -195,6 +198,13 @@ export interface PlayedEvent extends TouchEventStep { * the page has the event by then. */ readonly returnedAt: number; + /** + * When the event left, on the clock a play paces on: the test process's + * `performance.now()`, ms, to a fraction of a millisecond. + */ + readonly pacedSentAt: number; + /** When the dispatch command returned, on that same clock, ms. */ + readonly pacedReturnedAt: number; /** The timestamp handed to the engine, epoch ms (Chromium only). */ readonly timestamp: number | null; /** @@ -414,6 +424,15 @@ export interface TouchPacingFault { * dispatch can deliver a gesture's timing then. */ readonly frameGapMs?: number | null; + /** + * The gap that strays furthest past the script's: the step it ends at, and + * the gap as the page received it and as scripted, ms. + */ + readonly late?: { + readonly index: number; + readonly gapMs: number; + readonly scriptedGapMs: number; + }; /** * The widest gap that an event's wait for the main thread accounts for, * when the listeners alone do not, or null. The wait ends when the page's @@ -713,6 +732,19 @@ export function touchPacingFault( } } }); + const lateK = gapsMs.reduce( + (best, gap, k) => + gap - scriptedGapsMs[k] > gapsMs[best] - scriptedGapsMs[best] ? k : best, + 0, + ); + const late = + span.length > 0 + ? { + index: span[lateK], + gapMs: gapsMs[lateK], + scriptedGapMs: scriptedGapsMs[lateK], + } + : undefined; if (!releaseFault || reading == null) { return { kind: 'hold', @@ -722,6 +754,7 @@ export function touchPacingFault( scriptedGapsMs, heldByPage, waited, + late, threshold: boundaries.holdMs, holdMs: hold ?? undefined, }; @@ -743,6 +776,7 @@ export function touchPacingFault( scriptedGapsMs, heldByPage, waited, + late, threshold: strays ? undefined : releaseBound, }; } @@ -804,7 +838,8 @@ function describeReading(fault: TouchPacingFault): string { * and pointer listeners did not hold the events back: a dispatch stalled * before the page. When an event waited for the main thread before the page's * listeners began, the error says how long. Another page task, or a starved - * runner, held it there. + * runner, held it there. A gap with no wait, across which the page drew no + * frame, is `TouchStarvationError`. */ export class TouchPacingError extends Error { constructor(readonly fault: TouchPacingFault) { @@ -838,6 +873,30 @@ export class TouchPageStallError extends Error { } } +/** + * A paced play's page read a release that is not the script's, and the + * runner starved the page. Across the gap that strays furthest, the page drew + * no frame for longer than `FRAME_STARVATION_MS`. Neither its own listeners + * nor a page task held the event before it. No pacing reaches a page that + * draws nothing, so the play cannot judge the component. It fails by name, + * as a busy proof's `FrameStarvationError` does. Judge the proof from a run + * with CI's CPU limits. + */ +export class TouchStarvationError extends Error { + constructor( + readonly fault: TouchPacingFault & { + readonly late: NonNullable; + /** The longest time the page drew no frame across that gap, ms. */ + readonly starvedMs: number; + }, + ) { + super( + `touchDriver: the page drew no frame for ${fault.starvedMs.toFixed(0)} ms across a ${fault.late.gapMs.toFixed(0)} ms gap where the script spaces ${fault.late.scriptedGapMs.toFixed(0)} ms, and ${describeFault(fault)}. Neither the page's listeners nor a page task held the event: the runner starved the page. Judge the proof from a run with CI's CPU limits`, + ); + this.name = 'TouchStarvationError'; + } +} + /** * A play's lift reached the page more than the stillness interval after its * finger's last move, where the script throws. The scripted gap plus the time @@ -922,20 +981,41 @@ export function liftStallError( /** * The error a paced play's fault throws. The lift stall comes first, since * it is the more specific cause. Then a gap the page's own listeners held is - * the page's, and any other gap is the runner's. + * the page's. A starved page drew no frame for longer than + * `FRAME_STARVATION_MS` across the late gap. With no wait for the main + * thread, that fault is the starved runner's. Any other gap is a dispatch + * that stalled before the page. + * `frames` are the times the page drew a frame during the play. */ export function touchPlayError( steps: readonly TouchEventStep[], arrivals: readonly TouchArrival[], fault: TouchPacingFault, onEventMs: readonly number[], -): TouchLiftStallError | TouchPageStallError | TouchPacingError { - return ( - liftStallError(steps, arrivals, fault, onEventMs) ?? - (fault.heldByPage == null - ? new TouchPacingError(fault) - : new TouchPageStallError({...fault, heldByPage: fault.heldByPage})) - ); + frames: readonly number[] = [], +): + | TouchLiftStallError + | TouchPageStallError + | TouchStarvationError + | TouchPacingError { + const lift = liftStallError(steps, arrivals, fault, onEventMs); + if (lift != null) { + return lift; + } + if (fault.heldByPage != null) { + return new TouchPageStallError({...fault, heldByPage: fault.heldByPage}); + } + const {late} = fault; + const starvedMs = + late == null || late.index < 1 || fault.waited != null + ? null + : longestFrameGap(frames, [ + arrivals[late.index - 1], + arrivals[late.index], + ]); + return late != null && starvedMs != null && starvedMs > FRAME_STARVATION_MS + ? new TouchStarvationError({...fault, late, starvedMs}) + : new TouchPacingError(fault); } /** Records what the page saw of a paced play's touches (WebKit). */ @@ -1013,8 +1093,16 @@ async function playSteps( const dispatchedAt = Date.now(); const sentAt = performance.now(); await dispatch(step, timestamp); - previous = {sentAt, returnedAt: performance.now()}; - played.push({...step, dispatchedAt, returnedAt: Date.now(), timestamp}); + const answered = performance.now(); + previous = {sentAt, returnedAt: answered}; + played.push({ + ...step, + dispatchedAt, + returnedAt: Date.now(), + pacedSentAt: sentAt, + pacedReturnedAt: answered, + timestamp, + }); const watched = performance.now(); await onEvent?.(step, index); onEventMs.push(performance.now() - watched); @@ -1036,7 +1124,7 @@ async function playSteps( }); if (found != null) { const fault = {...found, frameGapMs: longestFrameGap(frames, arrivals)}; - throw touchPlayError(steps, arrivals, fault, onEventMs); + throw touchPlayError(steps, arrivals, fault, onEventMs, frames); } const reading = readRelease(steps, arrivals, release); if (reading != null) { @@ -1209,43 +1297,34 @@ export function touchArrivalsFrom(record: { /** * Records, for each touch event of a paced play, when it reached the page - * and when the page's own listeners had finished with it (`armInputRun`). + * and when the page's own listeners had finished with it. It also records + * the page's frames (`armInputRun`). */ function touchArrivalProbe(page: Page): TouchArrivalProbe { let armed: JSHandle | null = null; - let drawn: JSHandle<{times: number[]; stopped: boolean}> | null = null; return { async arm() { await armed?.evaluate(run => run.stop()); await armed?.dispose(); - await drawn?.evaluate(record => { - record.stopped = true; - }); - await drawn?.dispose(); - armed = await armInputRun(page, TOUCH_TYPES); - // When the page draws each frame, on the clock its events are stamped - // on. The harness's own frames run on the real timers: a frozen timer - // gate (story.ts) holds only the page's. - drawn = await page.evaluateHandle(() => { - const gate = ( - window as unknown as { - __harnessTimerGate?: {frame?: typeof requestAnimationFrame}; - } - ).__harnessTimerGate; - const frame = gate?.frame ?? window.requestAnimationFrame.bind(window); - const record = {times: [] as number[], stopped: false}; - // Resolves at the first frame, so a frame before the gesture is read. - return new Promise(resolve => { - const tick = (time: number) => { - if (!record.stopped) { - record.times.push(time); - resolve(record); - frame(tick); - } - }; - frame(tick); - }); - }); + armed = await armInputRun(page, TOUCH_TYPES, {frames: true}); + // Waits for the run's first frame, so the frames read one before the + // gesture. The harness's own frames run on the real timers: a frozen + // timer gate (story.ts) holds only the page's. + await armed.evaluate( + run => + new Promise(resolve => { + const gate = ( + window as unknown as { + __harnessTimerGate?: {frame?: typeof requestAnimationFrame}; + } + ).__harnessTimerGate; + const frame = + gate?.frame ?? window.requestAnimationFrame.bind(window); + const check = () => + run.frames.length > 0 ? resolve() : frame(check); + check(); + }), + ); }, async read() { if (armed == null) { @@ -1253,13 +1332,14 @@ function touchArrivalProbe(page: Page): TouchArrivalProbe { } const run = armed; armed = null; - const record = await run.evaluate(recorded => { + const {frames, ...record} = await run.evaluate(recorded => { recorded.stop(); return { eventTypes: recorded.eventTypes.slice(), pointerTypes: recorded.pointerTypes.slice(), stamps: recorded.stamps.slice(), handledAt: recorded.handledAt.slice(), + frames: recorded.frames.slice(), // Only a mark added before the page's scripts comes before every // page listener. Without it, the hold counts from the stamp. ...(recorded.startsFirst @@ -1268,15 +1348,6 @@ function touchArrivalProbe(page: Page): TouchArrivalProbe { }; }); await run.dispose(); - const frames = - drawn == null - ? [] - : await drawn.evaluate(recorded => { - recorded.stopped = true; - return recorded.times.slice(); - }); - await drawn?.dispose(); - drawn = null; return {arrivals: touchArrivalsFrom(record), frames}; }, }; diff --git a/packages/lab/src/NavigationStack/__tests__/NavigationStack.interaction.browser.spec.ts b/packages/lab/src/NavigationStack/__tests__/NavigationStack.interaction.browser.spec.ts index ad8cf870e5c46..9e6e6a23e8a28 100644 --- a/packages/lab/src/NavigationStack/__tests__/NavigationStack.interaction.browser.spec.ts +++ b/packages/lab/src/NavigationStack/__tests__/NavigationStack.interaction.browser.spec.ts @@ -52,9 +52,8 @@ import { toTouchEvents, touchArrivalsFrom, touchDriver, - TouchPacingError, touchPacingFault, - TouchPageStallError, + touchPlayError, touchStoryboard, traceRendering, trackMarker, @@ -1015,7 +1014,8 @@ async function flickFromTheEdge(page: Page, busyLiftMs?: number) { } // ~60 px of travel at ~1200 px/s: p + 0.35·v is well past half. const script = flick({x: left + 6, y: 400}, {velocity: {x: 1200, y: 0}}); - const run = await armInputRun(page, TOUCH_INPUT_TYPES); + // With the page's frames, so a starved runner's late move reads as such. + const run = await armInputRun(page, TOUCH_INPUT_TYPES, {frames: true}); // The page reads the release from when the moves arrive: pace on spacing. await driver.play(script, {pacing: 'spacing'}); await waitForRest(card(page, 'screen-General')); @@ -1024,8 +1024,9 @@ async function flickFromTheEdge(page: Page, busyLiftMs?: number) { } catch (error) { // A starved runner delivers the moves late, so the page reads a release // far from the script's. Past half of it, the run did not deliver the - // flick this test describes. It fails by name, as the page's when its own - // listeners held a move. + // flick this test describes. It fails by name. It is the page's when its + // own listeners held a move. It is the starved runner's when the page drew + // no frame across the late gap. const record = await run.evaluate(recorded => { recorded.stop(); return { @@ -1033,17 +1034,14 @@ async function flickFromTheEdge(page: Page, busyLiftMs?: number) { pointerTypes: recorded.pointerTypes.slice(), stamps: recorded.stamps.slice(), handledAt: recorded.handledAt.slice(), + frames: recorded.frames.slice(), }; }); - const fault = touchPacingFault( - toTouchEvents(script), - touchArrivalsFrom(record), - 0.5, - ); + const steps = toTouchEvents(script); + const arrivals = touchArrivalsFrom(record); + const fault = touchPacingFault(steps, arrivals, 0.5); if (fault != null) { - throw fault.heldByPage == null - ? new TouchPacingError(fault) - : new TouchPageStallError({...fault, heldByPage: fault.heldByPage}); + throw touchPlayError(steps, arrivals, fault, [], record.frames); } throw error; }