diff --git a/internal/interaction-harness/README.md b/internal/interaction-harness/README.md index 31c5149c2d407..277fe72b9aff6 100644 --- a/internal/interaction-harness/README.md +++ b/internal/interaction-harness/README.md @@ -1,20 +1,22 @@ # @astryxdesign/interaction-harness Playwright instruments for touch interaction and animation proofs: real touch -input, curve sampling and storyboards. **Internal and unpublished.** Specs live -next to their component as `*.interaction.browser.spec.ts` and run under +input, frame evidence, curve sampling and storyboards. **Internal and +unpublished.** Specs live next to their component as +`*.interaction.browser.spec.ts` and run under [`playwright.interaction.config.ts`](../../playwright.interaction.config.ts) on a phone-sized touch screen (402 × 714 CSS px page, 402 × 874 screen, 3 device pixels per CSS px, touch, mobile viewport rules), in Chromium and WebKit. The harness proves its own instruments in -[`src/harness.interaction.browser.spec.ts`](src/harness.interaction.browser.spec.ts), -on fixture pages written inline. +[`src/harness.interaction.browser.spec.ts`](src/harness.interaction.browser.spec.ts): +every positive check has a negative control beside it (a rAF animation that +freezes, a `top` animation that lays out every frame). ## Running ```sh -pnpm storybook:build # component specs read stories from the built Storybook +pnpm storybook:build # the specs read stories from the built Storybook pnpm exec playwright install chromium webkit pnpm test:interaction --project chromium # everything, Chromium pnpm test:interaction # one spec, both engines @@ -31,6 +33,12 @@ under a rootful docker daemon the container runs as your user so its node internal/interaction-harness/scripts/webkit-container.mjs [playwright test args…] ``` +WebKit composites through Mesa's software GL there, which compiles each shader +the first time a page draws it (450–700 ms for the first frame of a blurred or +newly animated layer). The script keeps Mesa's shader cache on the host +(`~/.cache/astryx-webkit-shaders/`, or `ASTRYX_WEBKIT_SHADER_CACHE`), so +only the first run on a machine pays for them. + Evidence (storyboards, curve traces) is written to `test-results/interaction-evidence/` (override with `ASTRYX_INTERACTION_EVIDENCE`) and attached to the test report. It is never @@ -38,15 +46,18 @@ committed: a pull request links or attaches it. ## Instruments -| Module | What it gives a spec | -| --------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `scripts.ts` | Touch scripts as data: `tap`, `drag` (hold, rest), `flick` (exact final-move speed, velocity profiles), `holdThenDrag`, `pinch`, `rotate`, `path`, `merge` (a second finger mid-gesture), `releaseVelocity`, `toTouchEvents`. | -| `touch.ts` | `touchDriver(page).play(script)`: the script as real engine input. `installInputLog` / `readInputLog`: what the page received. | -| `curves.ts` | `holdAnimations`, `seekAnimations`, `sampleCurve` (presented transform / opacity at any t), `waitForAnimation`, `watchAnimations`, `waitForRest`, `releaseAnimations`. | -| `math.ts` | Oracles independent of the code under test: `cubicBezier`, `timingFunction`, `springStep` (SwiftUI response / dampingFraction, initial velocity), `projectDecay`, `rubberBand`, `parseTransform`, `compareCurve`, `timeline`. | -| `storyboard.ts` | `animationStoryboard` (seek to t = 0, 16.7, 33.3 … ms), `touchStoryboard` (a frame per scripted event): PNG contact sheet + JSON trace. | -| `output.ts` | `evidenceDir`, `writeEvidence`: where evidence goes and how it is attached to the report. | -| `story.ts` | `phone`, `withStorybook`, `openStory`, `frames`, and the timer gate (`installTimerGate`, `freezeTimers`, `thawTimers`). | +| Module | What it gives a spec | +| --------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `scripts.ts` | Touch scripts as data: `tap`, `drag` (hold, rest), `flick` (exact final-move speed, velocity profiles), `holdThenDrag`, `pinch`, `rotate`, `path`, `merge` (a second finger mid-gesture), `releaseVelocity`, `toTouchEvents`. | +| `touch.ts` | `touchDriver(page).play(script)`: the script as real engine input. `installInputLog` / `readInputLog`: what the page received. | +| `frames.ts` | `startScreencast` (timestamped composited frames), `markElement` (a marker chip or outline), `trackMarker` (marker box per frame), `sampleRects` (per-rAF rects), `frameStats`. | +| `busy.ts` | `blockMainThread(page, ms)` and `busyWindowProof(tracked, window)`: frames presented, frames that moved, longest stall, a verdict; `presented` adds the compositor's own frames. | +| `trace.ts` | `traceRendering(page, body)`: main-thread counts of UpdateLayoutTree / Layout / PrePaint / Paint / Layerize / UpdateLayer / ScrollLayer / HitTest, `countBetween`, long tasks; `installLongTaskLog` / `readLongTasks`; `startCompositorTrace`: when the compositor presents. | +| `curves.ts` | `holdAnimations`, `seekAnimations`, `sampleCurve` (presented transform / opacity at any t), `waitForAnimation`, `watchAnimations`, `waitForRest`, `releaseAnimations`. | +| `math.ts` | Oracles independent of the code under test: `cubicBezier`, `timingFunction`, `springStep` (SwiftUI response / dampingFraction, initial velocity), `projectDecay`, `rubberBand`, `parseTransform`, `compareCurve`, `timeline`. | +| `storyboard.ts` | `animationStoryboard` (seek to t = 0, 16.7, 33.3 … ms), `touchStoryboard` (a frame per scripted event), `castStoryboard` (real screencast frames): PNG contact sheet + JSON trace. | +| `output.ts` | `evidenceDir`, `writeEvidence`: where evidence goes and how it is attached to the report. | +| `story.ts` | `phone`, `withStorybook`, `openStory`, `frames`, and the timer gate (`installTimerGate`, `freezeTimers`, `thawTimers`). | ## The proofs @@ -60,6 +71,14 @@ dispatch latency, and the events go through the compositor's gesture detection the limits below. Read positions a frame after a move: Chromium delivers `pointermove` aligned to animation frames. +**Stories, not Storybook.** `openStory` turns Storybook's highlight module off +on every page it opens, and checks that its root element is absent. Left on, +the module observes `#storybook-root` and, on every insertion, reads the +computed style of every element on the page inside the inserting task (117 +reads and two forced style recalculations for one exit copy in a Button story), +so a proof would measure Storybook as well as the component. +`openStory(page, origin, id, args, {storybookHighlight: true})` keeps it on. + **Curve sampling.** Pause every running animation (CSS transitions and animations are Web Animations too), seek to a time, read `getComputedStyle`: the presented value at that exact time, independent of frame timing. Finished @@ -97,6 +116,110 @@ set): a short entrance no longer races the first look on a cold page. When the action may be the page's first contact with the harness, take `watchAnimations(locator)` before it and read `watch.started()` after. +**Busy main thread.** Mark the element, start the screencast, start the +animation, wait until it runs (`waitForAnimation`: an animation cannot start +while the thread is held), block the main thread for 1 s (`spec:AST-094` +FR5's verification row), stop. Always +start the gesture or animation first and block mid-flight, never before: +in headless Chromium a touch that starts while the main thread is busy does +not scroll or start a gesture even with only passive listeners (the input +waits for the main thread). Tracking a finger under a busy main thread is +therefore proven on the iOS simulator, not here. The +screencast is captured off the main thread, so a compositor animation shows a +new position every frame of the block, and a main-thread animation shows none +(nothing changed, so no frame is sent at all: `busyWindowProof` counts the +whole window as one stall). `settledWithin` (2 px) stops judging at the easing +tail: the screencast rounds to whole pixels, so a tail that still moves shows +plateaus within a pixel or two of rest. A judged part shorter than four of the +screencast's intervals fails: the animation under test was not moving during +the block. With +`during`, `blockMainThread` starts the loop from a task queued in the frame +that saw the animation, after that frame's rendering update: WebKit hands a +newly started animation to its compositor there, and a loop inside the rAF +callback would freeze even a compositor animation. Call it before the release +that starts a settle and await it after, so the page is already waiting when +the settle begins. An animation counts once it is no longer pending and has +run at least one frame: a `minProgressMs` under 16 is raised to 16, since one +created in the frame the page looks is not on the compositor yet. The `verdict` judges the +frames the screencast delivered, whatever its rate (a loaded machine's can +deliver one frame in five or six), and tolerates nothing a frozen animation +does: at least one frame in the judged part, no stall longer than three of the +screencast's intervals (two dropped frames), and at least 90% of the frames it +delivered in the judged part presenting a new position (one miss is always +allowed; a frame it did not deliver is a gap, for the stall check). Pass +`maxMedianFrameMs` (20 at 60 Hz) only in a proof that claims display rate. +`verdict.failures` names each miss with its numbers, and `summary` carries the +raw numbers for the report. Frames are judged in presentation order: a loaded +machine can deliver them out of order. `castStoryboard` turns the frames of the +block into a filmstrip. + +A just-started animation can reach the screen after the block began (50–100 ms +later in WebKit on a loaded machine). When the cast saw the element at rest +before the block (wait for `cast.frameCount()` to pass 0 before starting the +animation), judging starts at its first presented change: the judged part still +ends with the block and still needs four intervals, and `onScreenFromMs` and the +summary report when it came. An element already moving is judged from the +block's start. WebKit's casts are 2 px quantized: the frames come at the +viewport's size, but the page in them is captured at half resolution, so +positions move in 2 CSS px steps (Chromium's in 1). With under two steps of +motion per frame, a frame delivered a few ms early shows no step and reads as +not moved. The proof reports `stepPx` and `pxPerFrame` and notes motion under +two steps per frame, which never fails it. Move a proof's element at least two +steps a frame: the self-tests move 560 px in 1,600 ms, about 4.8 px a frame. + +On a loaded machine Chromium's screencast can skip frames the compositor +still presents. `startCompositorTrace(page)`, started with the screencast and +stopped after the block, records when the compositor presented each frame +(`Display::FrameDisplayed`); pass it as `presented`. A gap between two moved +frames with nothing delivered inside it is then measured between the +compositor's own frames: the frames it presented there count as presented +(`recorderSkipped`, in the summary), and a gap it did not present through is +a stall as before. A gap that opens or closes the judged part, or holds a +delivered frame that did not move, is judged from the screencast, so a +frozen element fails whatever else the compositor draws (a rAF animation's +block presents no compositor frame at all). With the record, the 90% counts the +compositor's frames from the first to the last moved frame; the gaps before and +after are the stall check's. WebKit has no such trace: +`stop()` resolves to `[]` and the screencast is judged alone. + +**No Layout / Paint.** `traceRendering` records a Chromium trace around the +interaction; `countBetween` counts the steady middle of an animation (its +first and last frames may commit). A transform/opacity animation does no +Layout or Paint there; a layout-property animation does one per frame. The +harness's own animation recorder stands down while the trace runs, since its +frame loop would make every frame a main-thread one, restyling each running +animation's target and laying out an anchored one: it reads only the element a +CSS animation or transition event names, once, when that animation starts, and +catches up afterwards. A `waitForRest` awaited inside the traced body stands +down too: it waits on timers for the scheduled ends of the element's curves +(looking `frames` times a frame apart before settling on none, so an +animation the action starts a frame or two later is waited for) and reads no +style until the trace ends (in the anchored fixture's steady middle, +24 Layouts before, 0 now). So do `waitForAnimation` and a watch's +`started()`: they take the element's animations from the recorder's log, +judge a started one by its own times, and reach the element through a handle, +since each `locator.evaluate` makes a main-thread frame (there too, 24 +Layouts before, 0 now). That holds for script animations and CSS +transitions. On a CSS `@keyframes` animation (and, unwatched, a cancelled CSS +transition), `waitForAnimation` and `started()` read the animation's timing, +which flushes its style and adds Layouts to the trace: wait on one with +`waitForRest`, or after the trace. Taking a watch (`watchAnimations`) inside +a trace reads the watched element's animations, which restyles it (and lays +out an anchored one), so a proof takes its traced watch before the window it +counts. The trace's `longTasks` are the page's own: only a +task the harness marked as its own read (`waitForAnimation` describing +keyframes, `blockMainThread` without `during`) is in `devtoolsTasks` instead, +and only when no page script ran inside it. A test's own `page.evaluate` stays a +long task, whether it calls page code directly or sets it off. + +With `{invalidations: true}`, `traceRendering` also records why each style +recalculation ran and on which element, every animation that ran and whether +it ran on the compositor, and when script ran. `countBetween(trace, from, to, +{skipCompositorAnimationUpdates: true})` then leaves out a pass Chrome makes on +its own for compositor animations: every recalculation since the previous pass +has the reason Animation, on an element with an animation on the compositor at +the time, with no script in between. + **Storyboards.** Deterministic: frames come from seeking held animations or from stepping scripted input, never from wall-clock capture. The JSON trace carries each frame's measurements and the spec asserts on it; the sheet is @@ -104,16 +227,18 @@ evidence. A component that finishes an animation from a timer (a transitionend backstop, a cleanup render) would do so behind a held storyboard's back: `installTimerGate` before the animation starts and `freezeTimers` while photographing. The page can still cancel a held callback, a held frame callback -gets the time it actually runs, and the harness's own frame waits are not held. +gets the time it actually runs, and the harness's own waits (its frame waits, +`blockMainThread` with `during`, `sampleRects`) are not held. An animation that repeats forever does not set a storyboard's default length; with nothing else to film, pass `times`. A touch filmstrip keeps the scripted event `timeStamp`s (Chromium), but a handler that reads `performance.now()` or `Date.now()` sees one event per photograph, about 100 ms apart, so a clock-timed release flings slower when filmed than when played: a storyboard -cannot show such a gesture; record it in real time instead. Chromium can return -an empty copy of the page's surface right after it changes ("Unable to capture -screenshot"); a storyboard takes that photograph again two frames later, up to -three attempts in all, and lists each retake under `recaptures` in the trace. +cannot show such a gesture; record it in real time instead, with +`startScreencast` and `castStoryboard`. Chromium can return an empty copy of +the page's surface right after it changes ("Unable to capture screenshot"); a +storyboard takes that photograph again two frames later, up to three attempts +in all, and lists each retake under `recaptures` in the trace. ## Engine limits (measured with Playwright 1.61) @@ -126,11 +251,15 @@ three attempts in all, and lists each retake under `recaptures` in the trace. | 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 | +| 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 | What WebKit cannot show here — native scroll hand-off, flings, a finger -lifting while another stays down, and anything iOS-only — needs Mobile Safari -itself, on a device or the iOS simulator. Skip such a proof on the driver's -flag, citing the reason: `test.skip(!driver.partialLifts, PARTIAL_LIFT_SKIP)`. +lifting while another stays down, finger tracking under a busy main thread, and +anything iOS-only — needs Mobile Safari itself, on a device or the iOS +simulator. Skip such a proof on the driver's flag, citing the reason: +`test.skip(!driver.partialLifts, PARTIAL_LIFT_SKIP)`. The WebKit input command is reached through Playwright's in-process server object, so it needs a locally launched browser (the default), not `connect()`. diff --git a/internal/interaction-harness/package.json b/internal/interaction-harness/package.json index 40cccb26ca206..942eccb9ed8d5 100644 --- a/internal/interaction-harness/package.json +++ b/internal/interaction-harness/package.json @@ -3,7 +3,7 @@ "version": "0.0.0", "private": true, "type": "module", - "description": "Internal: Playwright helpers for touch interaction and animation proofs (real touch input, curve sampling, storyboards). Never published.", + "description": "Internal: Playwright helpers for touch interaction and animation proofs (real touch input, frame evidence, curve sampling, storyboards). Never published.", "main": "./src/index.ts", "exports": { ".": "./src/index.ts", diff --git a/internal/interaction-harness/scripts/webkit-container.mjs b/internal/interaction-harness/scripts/webkit-container.mjs index cb20fd44aa725..11ef11bdfda80 100644 --- a/internal/interaction-harness/scripts/webkit-container.mjs +++ b/internal/interaction-harness/scripts/webkit-container.mjs @@ -16,10 +16,19 @@ * docker daemon the container runs as the invoking user (rootless podman and * rootless docker already map it), so the `test-results/` it writes into the * mounted checkout stay the host user's and the next host run can clear them. + * + * WebKit composites through Mesa's software GL in the image, which compiles + * each shader variant the first time a page draws it: 450–700 ms for the + * first frame of a blurred or newly animated layer, long enough for a short + * animation to end before it is ever presented. Mesa caches what it compiles, + * and the cache is kept on the host (`~/.cache/astryx-webkit-shaders/`, + * or `ASTRYX_WEBKIT_SHADER_CACHE`), so a run starts with every shader an + * earlier run compiled instead of paying for them in its first tests. */ import {spawnSync} from 'node:child_process'; import fs from 'node:fs'; import {createRequire} from 'node:module'; +import os from 'node:os'; import path from 'node:path'; import {fileURLToPath} from 'node:url'; @@ -42,6 +51,19 @@ if (engine == null) { process.exit(1); } const args = process.argv.slice(2); +// Where the container sees the host's shader cache (see the header). +const containerShaderCache = '/astryx-shader-cache'; +const shaderCache = + process.env.ASTRYX_WEBKIT_SHADER_CACHE ?? + path.join( + os.homedir(), + '.cache', + 'astryx-webkit-shaders', + image.replace(/[^\w.-]+/g, '_'), + ); +fs.mkdirSync(shaderCache, {recursive: true}); +// The harness self-test reads this marker inside the container. +fs.writeFileSync(path.join(shaderCache, 'ASTRYX-SHADER-CACHE'), `${image}\n`); const env = [ 'ASTRYX_STORYBOOK_DIR', 'ASTRYX_INTERACTION_EVIDENCE', @@ -79,6 +101,10 @@ const command = [ '--ipc=host', '-v', `${root}:${root}`, + '-v', + `${shaderCache}:${containerShaderCache}`, + '-e', + `MESA_SHADER_CACHE_DIR=${containerShaderCache}`, '-w', root, ...env, diff --git a/internal/interaction-harness/src/busy.skip.fixture.ts b/internal/interaction-harness/src/busy.skip.fixture.ts new file mode 100644 index 0000000000000..409886f12e6f8 --- /dev/null +++ b/internal/interaction-harness/src/busy.skip.fixture.ts @@ -0,0 +1,125 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file busy.skip.fixture.ts + * @input One recorded busy-main-thread run in headless Chromium under + * parallel load: a compositor coast through a 566 ms block + * @output `frames`: the screencast frames the marker was tracked in, as + * [ms after the block started, y in CSS px, or null where the marker was not + * found]; `presented`: when the compositor presented each frame + * (`Display::FrameDisplayed`), ms after the block started; `block`: the + * block's span on the same clock. The screencast skipped frames at about + * +366 and +466 ms while the compositor kept presenting every 16.7 ms. + * @position Fixture for busy.test.ts + */ + +export const block = {from: 0, to: 566.1}; + +export const frames: ReadonlyArray = [ + [-1145.8, null], + [-1114, null], + [-1063.9, null], + [-1031.1, null], + [-996.6, null], + [-964.3, null], + [-930.7, null], + [-896.7, null], + [-864, null], + [-830.6, null], + [-797.8, null], + [-762.7, null], + [-731.3, null], + [-686.5, null], + [-680.8, null], + [-651, null], + [-634.1, null], + [-620.7, null], + [-615.8, null], + [-514.4, null], + [-495, null], + [-472.4, null], + [-465.3, null], + [-448.5, null], + [-430.3, null], + [-414.8, null], + [-398.3, null], + [-379.5, null], + [-364.2, null], + [-348.3, null], + [-330.6, null], + [-315, null], + [-297.6, null], + [-281.9, null], + [-265.1, null], + [-247.6, null], + [-230.8, null], + [-215.3, null], + [-198.6, null], + [-181, null], + [-165.3, null], + [-147.7, null], + [-132, null], + [-115.4, null], + [-98.5, null], + [-81.2, 504], + [-65.2, 500], + [-48.5, 496], + [-30.9, 491], + [-15.2, 487], + [1.3, 484], + [32.8, 480], + [49.8, 476], + [66.3, 473], + [82.8, 469], + [99.7, 466], + [116.1, 463], + [132.9, 460], + [149.5, 457], + [166.3, 454], + [182.9, 451], + [199.4, 448], + [216.2, 446], + [232.8, 443], + [249.4, 441], + [266.1, 438], + [282.7, 436], + [299.5, 434], + [316, 432], + [332.7, 430], + [349.5, 428], + [366.1, 426], + [433.1, 418], + [449.7, 417], + [466.2, 415], + [516.2, 411], + [532.8, 409], + [549.5, 408], + [566.2, 407], + [650.6, 401], + [666.2, 400], + [682.9, 399], + [699.6, 398], + [716.3, 397], + [816.1, 391], + [832.8, 391], + [849.5, 390], + [866.2, 389], + [882.9, 388], + [899.5, 388], + [916.1, 387], + [1033.8, 383], + [1050.1, 383], + [1066.7, 382], + [1083.3, 382], + [1099.5, 381], + [1117.3, 381], + [1134.2, 380], + [1149.5, 380], +]; + +export const presented: readonly number[] = [ + -98.7, -81.3, -65.3, -48.7, -31.1, -15.3, 1.3, 32.5, 49.6, 66.1, 82.7, 99.6, + 115.9, 132.6, 149.3, 166.1, 182.6, 199.3, 216, 232.6, 249.3, 266, 282.6, + 299.2, 315.8, 332.6, 349.3, 366, 381.5, 398.3, 415.1, 432.9, 449.6, 466.1, + 481.5, 498.3, 516, 532.6, 549.4, 566.1, 581.7, 598.4, 615, 631.6, 650.3, 666, +]; diff --git a/internal/interaction-harness/src/busy.test.ts b/internal/interaction-harness/src/busy.test.ts new file mode 100644 index 0000000000000..64b981a442c9e --- /dev/null +++ b/internal/interaction-harness/src/busy.test.ts @@ -0,0 +1,524 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file busy.test.ts + * @input Synthetic tracked frames (no browser) + * @output The busy-main-thread verdict's limits: dropped frames a loaded + * machine produces pass, a frozen animation fails every criterion, a window + * with nothing moving to judge fails, and out-of-order frames are judged in + * presentation order. + * @position Unit test of ./busy and ./frames' ordering; the browser proof + * with a real compositor animation and a rAF control is in + * harness.interaction.browser.spec.ts. + */ + +import {describe, expect, it} from 'vitest'; +import {busyWindowProof} from './busy'; +import * as skip from './busy.skip.fixture'; +import {inPresentationOrder, type TrackedFrame} from './frames'; + +const FRAME = 1000 / 60; +const BLOCK = {from: 1000, to: 1700}; + +/** A marker moving 3 px per frame from t = 800 to 1900, minus `dropped` frame indices. */ +function moving(dropped: readonly number[] = []): TrackedFrame[] { + const frames: TrackedFrame[] = []; + for (let i = 0; 800 + i * FRAME <= 1900; i += 1) { + if (dropped.includes(i)) { + continue; + } + frames.push({ + t: 800 + i * FRAME, + box: {x: 0, y: 3 * i, width: 10, height: 10}, + } as TrackedFrame); + } + return frames; +} + +/** Index of the first frame at or after `t`. */ +const at = (t: number) => Math.ceil((t - 800) / FRAME); + +/** `moving()` with each frame in `repeats` presenting the previous frame's position. */ +function repeating(repeats: readonly number[]): TrackedFrame[] { + return moving().map((f, i) => + repeats.includes(i) + ? ({...f, box: {...f.box!, y: 3 * (i - 1)}} as TrackedFrame) + : f, + ); +} + +/** A marker moving 3 px per frame from t = 800 to 1900, frames `intervals` apart in turn. */ +function cadenced(intervals: readonly number[]): TrackedFrame[] { + const frames: TrackedFrame[] = []; + for (let i = 0, t = 800; t <= 1900; i += 1) { + frames.push({ + t, + box: {x: 0, y: 3 * i, width: 10, height: 10}, + } as TrackedFrame); + t += intervals[i % intervals.length]; + } + return frames; +} + +describe('busyWindowProof verdict', () => { + it('passes a compositor animation with every frame', () => { + const proof = busyWindowProof(moving(), BLOCK); + expect(proof.verdict.failures).toEqual([]); + expect(proof.longestStallFrames).toBe(1); + }); + + it('passes one and two consecutive dropped frames (3 intervals)', () => { + const k = at(1300); + expect(busyWindowProof(moving([k]), BLOCK).verdict.failures).toEqual([]); + const two = busyWindowProof(moving([k, k + 1]), BLOCK); + expect(two.longestStallFrames).toBe(3); + expect(two.verdict.failures).toEqual([]); + }); + + it('fails three consecutive dropped frames', () => { + const k = at(1300); + const proof = busyWindowProof(moving([k, k + 1, k + 2]), BLOCK); + expect(proof.longestStallFrames).toBe(4); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('fails when more than 10% of the delivered frames do not move', () => { + const k = at(1050); + // 39 frames delivered: up to 3 may show no new position (10% = 3.9). + const scattered = [0, 12, 24].map(d => k + d); + expect( + busyWindowProof(repeating(scattered), BLOCK).verdict.failures, + ).toEqual([]); + const many = [0, 6, 12, 18, 24].map(d => k + d); + expect( + busyWindowProof(repeating(many), BLOCK).verdict.failures.join('\n'), + ).toMatch(/expected frames moved/); + }); + + it('judges a frame the screencast did not deliver as a gap for the stall check, not a miss', () => { + // The same five frames, not delivered: two-interval gaps, and every + // delivered frame moved. + const k = at(1050); + const many = [0, 6, 12, 18, 24].map(d => k + d); + const proof = busyWindowProof(moving(many), BLOCK); + expect(proof.verdict.failures).toEqual([]); + expect(proof.deliveredFrames).toBe(proof.moved); + }); + + it('judges an irregular cast on the frames it delivered', () => { + // A cast cycling 11.7, 11.7 and 17 ms: its median interval would expect + // 56 frames where it delivered 49, every one moved. + const proof = busyWindowProof(cadenced([11.7, 11.7, 17]), BLOCK); + expect(proof.verdict.failures).toEqual([]); + expect(proof.deliveredFrames).toBe(49); + expect(proof.moved).toBe(49); + // Still a stall where it delivers nothing for four frames, and still a + // miss where five delivered frames show no new position. + const gap = cadenced([11.7, 11.7, 17]).filter( + f => f.t < 1300 || f.t > 1360, + ); + expect(busyWindowProof(gap, BLOCK).verdict.failures.join('\n')).toMatch( + /longest stall/, + ); + const unmoved = cadenced([11.7, 11.7, 17]).map((f, i, all) => + [20, 26, 32, 38, 44].includes(i) + ? ({...f, box: {...all[i - 1].box!}} as TrackedFrame) + : f, + ); + expect(busyWindowProof(unmoved, BLOCK).verdict.failures.join('\n')).toMatch( + /expected frames moved/, + ); + }); + + it('lets a short window miss a frame, not three', () => { + // 150 ms judged: nine frames delivered, one miss allowed (10% would be 0.9). + const short = {from: 1000, to: 1190}; + const k = at(1040); + expect(busyWindowProof(repeating([k]), short).verdict.failures).toEqual([]); + expect( + busyWindowProof( + repeating([k, k + 3, k + 6]), + short, + ).verdict.failures.join('\n'), + ).toMatch(/expected frames moved/); + }); + + it('fails a frozen animation on every criterion', () => { + // Frames before and after the block only: nothing changed during it. + const frozen = moving().filter(f => f.t < BLOCK.from || f.t > BLOCK.to); + const proof = busyWindowProof(frozen, BLOCK); + expect(proof.changed).toBe(0); + expect(proof.verdict.pass).toBe(false); + expect(proof.verdict.failures.join('\n')).toMatch(/no frame presented/); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + expect(proof.verdict.failures.join('\n')).toMatch(/expected frames moved/); + }); + + it('fails a window in which the animation under test was not moving', () => { + // Settled before the block: the judgment ends where it starts. + const settled = moving().map(f => + f.t < 950 + ? f + : ({...f, box: {...f.box!, y: 3 * at(950)}} as TrackedFrame), + ); + const before = busyWindowProof(settled, BLOCK, {settledWithin: 2}); + expect(before.verdict.pass).toBe(false); + expect(before.verdict.failures.join('\n')).toMatch( + /judged = -?\d+ frames < 4: the animation under test was not moving/, + ); + // Settled 40 ms into the block: two frames, too few to judge. + const early = moving().map(f => + f.t < 1040 + ? f + : ({...f, box: {...f.box!, y: 3 * at(1040)}} as TrackedFrame), + ); + expect( + busyWindowProof(early, BLOCK, {settledWithin: 2}).verdict.failures.join( + '\n', + ), + ).toMatch(/frames < 4: the animation under test was not moving/); + }); + + it('judges the frames a slower screencast delivers by default, and display rate only when asked', () => { + // One frame in six, as a loaded machine's screencast delivers: every + // delivered frame moved, so the default verdict passes. + const sixth = moving().filter((_, i) => i % 6 === 0); + expect(busyWindowProof(sixth, BLOCK).verdict.failures).toEqual([]); + // Half rate fails only a proof that claims display rate. + const odd = moving().filter((_, i) => i % 2 === 1); + expect(busyWindowProof(odd, BLOCK).verdict.pass).toBe(true); + expect( + busyWindowProof(odd, BLOCK, {maxMedianFrameMs: 20}).verdict.failures.join( + '\n', + ), + ).toMatch(/median frame interval/); + }); +}); + +describe('busyWindowProof settledWithin', () => { + it('ends the judgment at a rounded easing tail, which would read as a stall', () => { + // An ease-out to y = 24 as the screencast reports it: whole pixels, so the + // tail repeats values while it still moves. + const ys = [ + 120, 100, 82, 67, 55, 46, 39, 34, 30, 28, 27, 26, 26, 26, 25, 25, 24, 24, + 24, 24, + ]; + const frames = ys.map( + (y, i) => + ({ + t: 1000 + i * FRAME, + box: {x: 0, y, width: 10, height: 10}, + }) as TrackedFrame, + ); + const window = {from: 1000, to: 1000 + ys.length * FRAME}; + const loose = busyWindowProof(frames, window, { + settledWithin: 2, + marginMs: 0, + }); + expect(loose.verdict.failures).toEqual([]); + const strict = busyWindowProof(frames, window, { + settledWithin: 1, + marginMs: 0, + }); + expect(strict.longestStallFrames).toBeGreaterThanOrEqual(3); + }); + + it('takes the end value from settledAt over a stale last frame', () => { + // The tail reaches y = 24, then the last frame shows a stale 100 (WebKit + // presents the last committed position once an accelerated animation + // ends while the main thread is still blocked). + const ys = [ + 120, 100, 82, 67, 55, 46, 39, 34, 30, 28, 27, 26, 25, 24, 24, 24, 100, + ]; + const frames = ys.map( + (y, i) => + ({ + t: 1000 + i * FRAME, + box: {x: 0, y, width: 10, height: 10}, + }) as TrackedFrame, + ); + const window = {from: 1000, to: 1000 + ys.length * FRAME}; + const stale = busyWindowProof(frames, window, { + settledWithin: 2, + marginMs: 0, + }); + expect(stale.verdict.pass).toBe(false); + const fromPage = busyWindowProof(frames, window, { + settledWithin: 2, + settledAt: 24, + marginMs: 0, + }); + expect(fromPage.verdict.failures).toEqual([]); + expect(fromPage.judged.to).toBe(frames[11].t); + }); +}); + +/** Seen at rest at t = 900, then on screen from `start`, moving 3 px a frame. */ +function startingAt(start: number): TrackedFrame[] { + const frames = [ + {t: 900, box: {x: 0, y: 0, width: 10, height: 10}} as TrackedFrame, + ]; + for (let i = 1; start + (i - 1) * FRAME <= 1900; i += 1) { + frames.push({ + t: start + (i - 1) * FRAME, + box: {x: 0, y: 3 * i, width: 10, height: 10}, + } as TrackedFrame); + } + return frames; +} + +describe('busyWindowProof on-screen start', () => { + it('judges a just-started animation from its first presented change when it was seen at rest before the block, and reports when', () => { + // On screen 87 ms into the block: four intervals after the judged part's start. + const proof = busyWindowProof(startingAt(1087), BLOCK); + expect(proof.verdict.failures).toEqual([]); + expect(proof.onScreenFromMs).toBeCloseTo(87, 5); + expect(proof.judged.from).toBeCloseTo(1087, 5); + expect(proof.summary).toMatch( + /on screen from \+87 ms \(nothing moved before the block\)/, + ); + }); + + it('still fails an animation that was already moving and stalls at the block start', () => { + const k = at(1020); + const proof = busyWindowProof(moving([k, k + 1, k + 2, k + 3]), BLOCK); + expect(proof.onScreenFromMs).toBeNull(); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('still fails a stall at the start when no frame before the block shows it at rest', () => { + const unseen = startingAt(1087).filter(f => f.t >= BLOCK.from); + const proof = busyWindowProof(unseen, BLOCK); + expect(proof.onScreenFromMs).toBeNull(); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('still fails a start the block itself delays until it ends', () => { + const proof = busyWindowProof(startingAt(1720), BLOCK); + expect(proof.onScreenFromMs).toBeNull(); + expect(proof.verdict.failures.join('\n')).toMatch(/no frame presented/); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('still fails a start that leaves fewer than minJudgedFrames inside the block', () => { + const proof = busyWindowProof(startingAt(1640), BLOCK); + expect(proof.onScreenFromMs).toBeCloseTo(640, 5); + expect(proof.verdict.failures.join('\n')).toMatch( + /frames < 4: the animation under test was not moving/, + ); + }); +}); + +describe('busyWindowProof position step', () => { + it("reports the cast's position step and motion per frame, and notes motion under two steps without failing", () => { + // 2.4 px a frame on a 2 px grid, as WebKit's casts report positions. + const grid = moving().map( + (f, i) => + ({ + ...f, + box: {...f.box!, y: 2 * Math.round((2.4 * i) / 2)}, + }) as TrackedFrame, + ); + const coarse = busyWindowProof(grid, BLOCK); + expect(coarse.stepPx).toBe(2); + expect(coarse.pxPerFrame).toBeCloseTo(2.4, 1); + expect(coarse.notes.join('\n')).toMatch( + /under two of the cast's 2 px position steps/, + ); + expect(coarse.summary).toMatch(/2\.4 px\/frame in 2 px steps; note: /); + expect(coarse.verdict.failures).toEqual([]); + // 3 px a frame in whole pixels: resolvable, nothing to note. + const fine = busyWindowProof(moving(), BLOCK); + expect(fine.stepPx).toBe(1); + expect(fine.pxPerFrame).toBeCloseTo(3, 1); + expect(fine.notes).toEqual([]); + }); +}); + +/** The compositor presenting every frame from `from` to `to`, minus `gaps` ([from, to] spans). */ +function drawn( + gaps: ReadonlyArray = [], + from = 700, + to = 2000, +): number[] { + const draws: number[] = []; + for (let t = from; t <= to; t += FRAME) { + if (!gaps.some(([a, b]) => t > a && t < b)) { + draws.push(t); + } + } + return draws; +} + +const skipFrames = (): TrackedFrame[] => + skip.frames.map( + ([t, y]) => + ({ + t, + box: y == null ? null : {x: 0, y, width: 10, height: 10}, + }) as TrackedFrame, + ); + +describe('busyWindowProof with the compositor record', () => { + it('with a compositor record, judges a sparse cast from its first to its last moved frame', () => { + // One screencast frame in six, as on a loaded machine, with the compositor + // presenting every frame: the frames before the first and after the last + // moved one are the stall check's, not misses. + const sparse = moving().filter((_, i) => i % 6 === 0); + expect( + busyWindowProof(sparse, BLOCK, {presented: drawn()}).verdict.failures, + ).toEqual([]); + }); + + it('with a compositor record and an on-screen start, counts the frames it credits as skipped in what it judges', () => { + // On screen 87 ms into the block, then four delivered frames that show + // no new position: that fails on a full cast. + const misses = [15, 20, 25, 30]; + const missing = startingAt(1087).map((f, i, all) => + misses.includes(i) + ? ({...f, box: {...all[i - 1].box!}} as TrackedFrame) + : f, + ); + const full = busyWindowProof(missing, BLOCK, {presented: drawn()}); + expect(full.verdict.failures.join('\n')).toMatch(/expected frames moved/); + // The screencast skipping the five frames after the on-screen frame + // changes nothing: the compositor presented them, and they are judged. + const skip = (frames: TrackedFrame[]) => + frames.filter((_, i) => i < 2 || i > 6); + const skipped = busyWindowProof(skip(missing), BLOCK, { + presented: drawn(), + }); + expect(skipped.recorderSkipped).toBe(5); + expect(skipped.verdict.failures.join('\n')).toMatch( + /expected frames moved/, + ); + // And a run with no misses never reads as more than every frame moved. + const clean = busyWindowProof(skip(startingAt(1087)), BLOCK, { + presented: drawn(), + }); + expect(clean.verdict.failures).toEqual([]); + expect(clean.movedFraction).toBeLessThanOrEqual(1); + }); + + it('reads frames the screencast skipped while the compositor presented them as presented: a recorded run that fails without the record', () => { + const frames = skipFrames(); + const alone = busyWindowProof(frames, skip.block, {settledWithin: 1}); + expect(alone.verdict.failures.join('\n')).toMatch( + /longest stall 6\d\.\d ms = 4 intervals > 3/, + ); + // Every frame the screencast delivered moved: only the stall remains, + // which the record resolves. + expect(alone.verdict.failures.join('\n')).not.toMatch( + /expected frames moved/, + ); + const proof = busyWindowProof(frames, skip.block, { + settledWithin: 1, + presented: skip.presented, + }); + expect(proof.verdict.failures).toEqual([]); + expect(proof.recorderSkipped).toBe(5); + expect(proof.longestStallFrames).toBeLessThanOrEqual(2); + expect(proof.summary).toMatch( + /the screencast skipped 5 frames the compositor presented \(at \+3\d\d ms, \+4\d\d ms\)/, + ); + }); + + it('counts a gap the compositor drew through as skipped, and one it did not draw through as a stall', () => { + const k = at(1300); + const gap: [number, number] = [ + 800 + (k - 1) * FRAME, + 800 + (k + 4) * FRAME, + ]; + const frames = moving([k, k + 1, k + 2, k + 3]); + expect(busyWindowProof(frames, BLOCK).verdict.pass).toBe(false); + const skipped = busyWindowProof(frames, BLOCK, {presented: drawn()}); + expect(skipped.verdict.failures).toEqual([]); + expect(skipped.recorderSkipped).toBe(4); + const stalled = busyWindowProof(frames, BLOCK, {presented: drawn([gap])}); + expect(stalled.recorderSkipped).toBe(0); + expect(stalled.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('still fails an element that does not move while the compositor presents for something else', () => { + const frozen = moving().map(f => + f.t >= BLOCK.from && f.t <= BLOCK.to + ? ({...f, box: {...f.box!, y: 3 * at(BLOCK.from)}} as TrackedFrame) + : f, + ); + const proof = busyWindowProof(frozen, BLOCK, {presented: drawn()}); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + expect(proof.verdict.failures.join('\n')).toMatch(/expected frames moved/); + }); + + it('still fails a frozen animation, whether or not the compositor presents during the block', () => { + const frozen = moving().filter(f => f.t < BLOCK.from || f.t > BLOCK.to); + for (const presented of [drawn([[BLOCK.from, BLOCK.to]]), drawn()]) { + const proof = busyWindowProof(frozen, BLOCK, {presented}); + expect(proof.verdict.failures.join('\n')).toMatch(/no frame presented/); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + } + }); + + it('keeps a gap a stall when the screencast delivered a frame inside it that did not move', () => { + const k = at(1300); + const frames = moving([k, k + 1, k + 3]).map(f => + f.t > 800 + (k + 1.5) * FRAME && f.t < 800 + (k + 2.5) * FRAME + ? ({...f, box: {...f.box!, y: 3 * (k - 1)}} as TrackedFrame) + : f, + ); + const proof = busyWindowProof(frames, BLOCK, {presented: drawn()}); + expect(proof.recorderSkipped).toBe(0); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('still counts single dropped frames the compositor did not present as missed', () => { + const k = at(1050); + const drops = [0, 6, 12, 18, 24, 30].map(d => k + d); + const frames = moving(drops); + const gaps = drops.map( + i => + [800 + (i - 0.5) * FRAME, 800 + (i + 0.5) * FRAME] as [number, number], + ); + expect( + busyWindowProof(frames, BLOCK, { + presented: drawn(gaps), + }).verdict.failures.join('\n'), + ).toMatch(/expected frames moved/); + expect( + busyWindowProof(frames, BLOCK, {presented: drawn()}).verdict.failures, + ).toEqual([]); + }); + + it('judges a gap at the edge of the judged part from the screencast alone', () => { + // Nothing delivered for the block's first 90 ms: a stall at its start, + // whatever the compositor drew, since no moved frame opens the gap. + const frames = moving().filter( + f => f.t < BLOCK.from || f.t > BLOCK.from + 90, + ); + const proof = busyWindowProof(frames, BLOCK, {presented: drawn()}); + expect(proof.recorderSkipped).toBe(0); + expect(proof.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + it('treats an empty record as no record, and says so', () => { + const frames = moving([at(1300), at(1300) + 1, at(1300) + 2, at(1300) + 3]); + const proof = busyWindowProof(frames, BLOCK, {presented: []}); + expect(proof.verdict.failures).toEqual( + busyWindowProof(frames, BLOCK).verdict.failures, + ); + expect(proof.summary).toMatch(/no compositor frames recorded/); + }); +}); + +describe('inPresentationOrder', () => { + it('sorts frames delivered out of order, so motion stays monotonic', () => { + const frames = moving(); + const k = at(1040); + const shuffled = [...frames]; + [shuffled[k], shuffled[k + 1]] = [shuffled[k + 1], shuffled[k]]; + expect(busyWindowProof(shuffled, BLOCK).monotonic).toBe(false); + const proof = busyWindowProof(inPresentationOrder(shuffled), BLOCK); + expect(proof.monotonic).toBe(true); + expect(proof.verdict.failures).toEqual([]); + }); +}); diff --git a/internal/interaction-harness/src/busy.ts b/internal/interaction-harness/src/busy.ts new file mode 100644 index 0000000000000..208500c41e1c3 --- /dev/null +++ b/internal/interaction-harness/src/busy.ts @@ -0,0 +1,575 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file busy.ts + * @input Uses a Playwright `Page` + * @output `blockMainThread` — a synchronous busy loop on the page's main thread + * that reports exactly when it ran — and `busyWindowProof`, which reads frame + * evidence for that window. + * @position The busy-main-thread proof: an animation that runs on the + * compositor keeps advancing at display rate while JavaScript holds the main + * thread; one driven from the main thread (rAF, style writes, layout + * properties) freezes for the whole block. Pair it with ./frames + * (`startScreencast` + `trackMarker`), which observes off the main thread. + * + * SYNC: Keep the README's busy-main-thread section equal to this contract. + */ + +import type {Locator, Page} from '@playwright/test'; +import {frameStats, type FrameStats, type TrackedFrame} from './frames'; + +export interface BusyWindow { + /** Epoch ms when the loop started and ended, on the page's own clock. */ + readonly from: number; + readonly to: number; +} + +/** + * Holds the page's main thread for `ms` (a synchronous loop: no task, frame, + * rAF, event or microtask runs meanwhile). Resolves with the window it held. + * + * Block MID-FLIGHT only: start the gesture or animation first. A touch that + * starts while the main thread is busy does not scroll or begin a gesture in + * headless Chromium, even with only passive listeners, and an animation that + * has not started cannot start (see `waitForAnimation`). Finger tracking + * under a busy main thread is a simulator proof, not a Playwright one. + * + * With `during`, the page itself waits until an animation on that element (or + * inside it) has run `minProgressMs`, then blocks from a task it queues in + * that frame. A round trip from the test would start the block later the + * busier the machine is, leaving less of a short animation to judge. The task + * runs after the frame's rendering update, which is where WebKit hands a newly + * started animation to its compositor: a loop inside the rAF callback itself + * holds that hand-off, and even a compositor animation freezes. To catch a + * settle near its start, call it before the release that starts the settle and + * await it after: the page is already waiting when the animation begins. Any + * animation inside `during` counts, so pick an element that runs nothing + * else meanwhile. + * + * An animation counts once it is no longer pending and has run at least one + * frame (`minProgressMs` below 16 ms is raised to 16). One created in the + * frame the page looks is still pending, not yet on the compositor + * (Chromium), and in WebKit its start time resolves before its layer is + * flushed: a block that started on it froze it. + */ +/** One display frame, ms: the least progress `blockMainThread` waits for. */ +const ONE_FRAME_MS = 16; + +export async function blockMainThread( + page: Page, + ms: number, + { + during, + minProgressMs = 16, + timeout = 5_000, + }: {during?: Locator; minProgressMs?: number; timeout?: number} = {}, +): Promise { + const minProgress = Math.max(minProgressMs, ONE_FRAME_MS); + if (during == null) { + return page.evaluate(duration => { + // The harness's own work: a trace sets it apart (trace.ts HARNESS_READ). + console.timeStamp('harness-read'); + const from = performance.timeOrigin + performance.now(); + const end = performance.now() + duration; + let spins = 0; + while (performance.now() < end) { + spins += 1; + } + return {from, to: performance.timeOrigin + performance.now(), spins}; + }, ms); + } + return during.evaluate( + (element, {duration, minProgress, wait}) => + new Promise((resolve, reject) => { + // The harness's own waits run on the real timers: a frozen timer gate + // (story.ts) holds only the page's. + const gate = ( + window as unknown as { + __harnessTimerGate?: { + frame?: typeof requestAnimationFrame; + timeout?: typeof setTimeout; + }; + } + ).__harnessTimerGate; + const frame = gate?.frame ?? window.requestAnimationFrame.bind(window); + const later = gate?.timeout ?? window.setTimeout.bind(window); + const deadline = performance.now() + wait; + const tick = () => { + const running = element + .getAnimations({subtree: true}) + .some( + a => + a.playState === 'running' && + !a.pending && + Number(a.currentTime ?? 0) >= minProgress, + ); + if (running) { + // The same loop as above, from a task queued in the frame that saw + // the animation: it runs once that frame's rendering update has + // handed the animation to the compositor. + later(() => { + const from = performance.timeOrigin + performance.now(); + const end = performance.now() + duration; + while (performance.now() < end) { + // Busy: nothing else runs. + } + resolve({from, to: performance.timeOrigin + performance.now()}); + }, 0); + } else if (performance.now() > deadline) { + reject(new Error('blockMainThread: no animation started')); + } else { + frame(tick); + } + }; + frame(tick); + }), + {duration: ms, minProgress, wait: timeout}, + ); +} + +export interface BusyVerdict { + readonly pass: boolean; + /** Each criterion the window missed, with its measured value and limit. */ + readonly failures: readonly string[]; +} + +export interface BusyProof extends FrameStats { + readonly window: BusyWindow; + /** + * The part of the window judged: inside the margins, up to `settledWithin`, + * and from `onScreenFromMs` when that is set. + */ + readonly judged: {readonly from: number; readonly to: number}; + /** + * When the tracked value was seen at rest before the judged part (a frame + * there, no change in the 250 ms before it: a just-started animation not on + * screen yet), ms after the window's start of its first presented change + * inside the block, where judging starts; null otherwise. + */ + readonly onScreenFromMs: number | null; + /** + * The cast's position step, CSS px: the largest of 0.5, 1 and 2 that every + * tracked position is a multiple of (WebKit's casts are 2: see the README). + */ + readonly stepPx: number; + /** The tracked value's mean motion per screencast interval in the judged part, px. */ + readonly pxPerFrame: number; + /** Facts worth reading beside the verdict, which never fail it. */ + readonly notes: readonly string[]; + /** + * With a compositor record (`presented`): frames the screencast skipped + * between two moved frames while the compositor presented them, which are + * neither stalls nor misses; 0 without one. + */ + readonly recorderSkipped: number; + /** + * The compositor's frame interval around the window, ms, from `presented`; + * null without a usable record (the screencast alone is judged). + */ + readonly compositorFrameMs: number | null; + /** + * The screencast's frame interval, from the frames around the window as well + * as inside it (a short window has few intervals; a frozen one has none). + */ + readonly cadenceMs: number; + /** + * Whole frame intervals in the judged part at the measured cadence (the + * compositor's, when recorded): the `minJudgedFrames` floor reads it. + */ + readonly expectedFrames: number; + /** Frames the screencast delivered in the judged part, with the marker found. */ + readonly deliveredFrames: number; + /** + * Longest time inside the window with no presented change, the window's own + * edges included. A frozen animation presents no new frame at all (nothing + * on screen changed, so the compositor sends none): its stall is the whole + * window. + */ + readonly longestStallMs: number; + /** Where the longest stall starts, ms after the window's start. */ + readonly longestStallAtMs: number; + /** + * `longestStallMs` in screencast intervals, rounded: 1 is no frame missed, + * 2 is one dropped frame. Rounding absorbs timestamp jitter. + */ + readonly longestStallFrames: number; + /** + * Frames in the window that presented a new position (the first compared + * with the last frame before the window). + */ + readonly moved: number; + /** + * `moved` (and `recorderSkipped`) over the frames judged: the frames the + * screencast delivered in the judged part, or with a compositor record the + * compositor's frames from the first to the last moved frame; + * `expectedFrames` when nothing moved or was delivered. + */ + readonly movedFraction: number; + /** The judgment against the limits (see `busyWindowProof`). */ + readonly verdict: BusyVerdict; + /** One line with the raw numbers, for an annotation or a failure message. */ + readonly summary: string; +} + +/** + * Frame evidence for a busy window: how many frames the screencast presented + * inside it, how many of them moved the tracked axis, and the longest stall. + * The window is trimmed by `marginMs` at both ends so the frame the block + * started on and the one it ended on are not counted. + * + * The verdict judges the frames the screencast delivered, whatever its rate + * (a loaded machine's screencast can deliver one frame in five or six), and + * tolerates nothing a main-thread animation does (it presents no frame for + * the whole block). It passes when: + * - the judged part presented at least one frame, and, only when a proof + * claims display rate and passes `maxMedianFrameMs`, their median interval + * is at most that; + * - no stall spans more than `maxStallFrames` screencast intervals; + * - at least `minMovedFraction` of the frames judged moved the tracked axis + * (a short window may still miss one): the frames the screencast delivered + * in the judged part, so an irregular cast is judged on what it delivered + * and a frame it did not deliver is a gap for the stall check, not a miss; + * with a compositor record, the compositor's frames from the first to the + * last moved frame (the gaps before and after are the stall check's); + * - the judged part spans at least `minJudgedFrames` frames. Fewer means the + * animation under test was not moving during the block (it settled before + * the block, or the block caught another animation), so there is nothing to + * judge, and that fails rather than passes. + * + * A just-started animation can reach the screen after the block began (its + * hand-off to the compositor lags under load: 50–100 ms in WebKit). When the + * tracked value was seen at rest before the judged part (a frame there, and no + * change in the 250 ms before it), judging starts at its first presented + * change inside the block, which the + * proof reports as `onScreenFromMs`. The judged part still ends with the + * block and the `minJudgedFrames` floor applies to it, so a start the block + * itself delays fails; an animation that was already moving is judged from + * the block's start, and a stall there fails as before. + * + * `stepPx` and `pxPerFrame` say whether a frame's motion is resolvable at + * all: under two position steps per frame, a frame delivered early can show + * no step and read as not moved, which the proof notes (never a failure). + * + * A loaded machine's screencast can skip frames the compositor still presents + * (Chromium). Given the compositor's record (`presented`, from + * `startCompositorTrace`), a gap between two moved frames with no frame + * delivered inside it is measured between the compositor's own frames: it is + * a stall only where the compositor presented nothing, and the frames it did + * present there are neither stalls nor misses (`recorderSkipped`). A gap + * that opens or closes the judged part, or holds a delivered frame that did + * not move, is judged from the screencast as before, so a frozen element + * fails whatever else the compositor draws. + */ +export function busyWindowProof( + tracked: readonly TrackedFrame[], + window: BusyWindow, + { + axis = 'y', + marginMs = 20, + settledWithin, + settledAt, + maxMedianFrameMs = Infinity, + maxStallFrames = 3, + minMovedFraction = 0.9, + minJudgedFrames = 4, + presented, + }: { + axis?: 'x' | 'y' | 'width' | 'height'; + marginMs?: number; + /** + * Opt-in, for a proof that claims display rate: the most the median frame + * interval may be, ms (20 at 60 Hz). Off by default, since it measures the + * screencast's own rate as much as the animation. + */ + maxMedianFrameMs?: number; + /** The most screencast intervals one stall may span (3 = two dropped frames). */ + maxStallFrames?: number; + /** + * The least fraction of the expected frames that must move. One missed + * frame is always allowed, so a window of under ten frames is not judged + * stricter than a long one. + */ + minMovedFraction?: number; + /** The fewest whole frame intervals the judged part of the window may span. */ + minJudgedFrames?: number; + /** + * Stop judging once the value is within this many px of where it ends. + * The screencast reports whole CSS pixels, so an easing tail that still + * moves shows plateaus (26, 26, 26 against a final 24) that would read + * as a stall: 2 is the usual value. + */ + settledWithin?: number; + /** + * Where the value ends, for `settledWithin`: read it from the page once the + * animation has ended (`waitForRest`). Defaults to the last frame's value, + * which can be stale: once an accelerated animation ends while the main + * thread is still blocked, WebKit presents the layer's last committed + * position until the main thread commits the end state. + */ + settledAt?: number; + /** + * When the compositor presented each frame, epoch ms on the page clock + * (`startCompositorTrace`; Chromium). Empty or absent, the screencast is + * judged alone. + */ + presented?: readonly number[]; + } = {}, +): BusyProof { + let end = window.to - marginMs; + if (settledWithin != null) { + const valued = tracked.flatMap(f => + f.box == null ? [] : [{t: f.t, value: f.box[axis]}], + ); + const final = + settledAt ?? (valued.length > 0 ? valued[valued.length - 1].value : null); + const arrived = valued.find( + f => + f.t >= window.from && + final != null && + Math.abs(f.value - final) <= settledWithin, + ); + if (arrived != null) { + end = Math.min(end, arrived.t); + } + } + const inner = {from: window.from + marginMs, to: end}; + const values = tracked + .filter(f => f.t >= inner.from && f.t <= inner.to) + .map(f => ({t: f.t, value: f.box == null ? null : f.box[axis]})); + const before = [...tracked].reverse().find(f => f.t < inner.from); + let previous: number | null = before?.box == null ? null : before.box[axis]; + const inWindow: number[] = []; + for (const v of values) { + if ( + v.value != null && + previous != null && + Math.abs(v.value - previous) > 0.25 + ) { + inWindow.push(v.t); + } + if (v.value != null) { + previous = v.value; + } + } + // Seen at rest before the judged part (a frame there, and no change in the + // 250 ms before it): the first presented change is the animation's on-screen + // start, and judging starts there. With no frame before, nothing is known, + // and the window is judged from its start. + const prior = tracked.filter(f => f.box != null && f.t < inner.from); + let leadFrom = 0; + prior.forEach((f, i) => { + if (f.t < inner.from - 250) { + leadFrom = i; + } + }); + const lead = prior.flatMap(f => (f.box == null ? [] : [f.box[axis]])); + const movedBefore = lead.some( + (value, i) => i > leadFrom && Math.abs(value - lead[i - 1]) > 0.25, + ); + const onScreenFrom = + prior.length > 0 && !movedBefore && inWindow.length > 0 + ? inWindow[0] + : null; + const judged = {from: onScreenFrom ?? inner.from, to: inner.to}; + const changes = inWindow.filter(t => t > judged.from || onScreenFrom == null); + const edges = [judged.from, ...changes, judged.to]; + const around = tracked + .filter(f => f.t >= inner.from - 250 && f.t <= inner.to + 250) + .map(f => f.t); + const intervals = around + .slice(1) + .map((t, i) => t - around[i]) + .sort((a, b) => a - b); + const stats = frameStats( + tracked.map(f => ({t: f.t, value: f.box == null ? null : f.box[axis]})), + judged, + ); + const cadence = + intervals.length >= 4 + ? intervals[Math.floor(intervals.length / 2)] + : stats.medianFrameMs || 1000 / 60; + // The compositor's own frames, when recorded: its interval, from the frames + // around the judged part. + const draws = [...(presented ?? [])] + .filter(t => t >= judged.from - 250 && t <= judged.to + 250) + .sort((a, b) => a - b); + const drawIntervals = draws + .slice(1) + .map((t, i) => t - draws[i]) + .sort((a, b) => a - b); + const compositorFrameMs = + drawIntervals.length >= 4 + ? drawIntervals[Math.floor(drawIntervals.length / 2)] + : null; + const changed = new Set(inWindow); + const delivered = tracked + .filter(f => f.box != null && f.t > judged.from && f.t < judged.to) + .map(f => f.t); + // Each gap between presented changes, in intervals of the channel that saw + // it: the screencast's, or, for a gap between two moved frames with no + // frame delivered inside it, the compositor's own longest interval there. + const gaps = edges.slice(1).map((to, i) => { + const from = edges[i]; + const ms = to - from; + if ( + compositorFrameMs == null || + !changed.has(from) || + !changed.has(to) || + delivered.some(t => t > from && t < to) + ) { + return {from, ms, frames: Math.round(ms / cadence), skipped: 0}; + } + const span = draws.filter( + t => t > from - compositorFrameMs / 2 && t < to + compositorFrameMs / 2, + ); + const longest = + span.length >= 2 + ? Math.min(ms, Math.max(...span.slice(1).map((t, j) => t - span[j]))) + : ms; + const frames = Math.round(longest / compositorFrameMs); + return { + from, + ms: longest, + frames, + skipped: Math.max(0, Math.round(ms / compositorFrameMs) - frames), + }; + }); + const longestGap = gaps.reduce((a, b) => + b.frames > a.frames || (b.frames === a.frames && b.ms > a.ms) ? b : a, + ); + const longestStallMs = longestGap.ms; + // Where the longest stall starts, from the start of the window. + const longestStallAtMs = longestGap.from - window.from; + const longestStallFrames = longestGap.frames; + const skips = gaps.filter(g => g.skipped > 0); + const recorderSkipped = skips.reduce((sum, g) => sum + g.skipped, 0); + // With a compositor record, frames count in its intervals, and the frames + // it presented where the screencast skipped are presented frames. + const expectedFrames = Math.floor( + (judged.to - judged.from) / (compositorFrameMs ?? cadence), + ); + const moved = changes.length; + // The frames judged for motion: the screencast's own frames in the judged + // part (each `changes` entry is one of them), or, with a compositor record, + // the compositor's frames from the first to the last moved frame (the gaps + // before and after them are the stall check's). After an on-screen start + // they count from the on-screen frame, which `changes` leaves out, so the + // frames credited as skipped after it are judged too. A part that moved + // nothing, or delivered nothing, is judged against its span, so a frozen + // animation misses here too. + const deliveredFrames = tracked.filter( + f => + f.box != null && + (onScreenFrom == null ? f.t >= judged.from : f.t > judged.from) && + f.t <= judged.to, + ).length; + const judgedFrames = + compositorFrameMs != null + ? changes.length > 0 + ? Math.round( + (changes[changes.length - 1] - (onScreenFrom ?? changes[0])) / + compositorFrameMs, + ) + (onScreenFrom == null ? 1 : 0) + : expectedFrames + : deliveredFrames === 0 + ? expectedFrames + : deliveredFrames; + const movedFraction = (moved + recorderSkipped) / Math.max(1, judgedFrames); + // The cast's position step, and the motion per interval it has to resolve. + const positions = tracked.flatMap(f => (f.box == null ? [] : [f.box[axis]])); + const stepPx = + [2, 1, 0.5].find(step => + positions.every(p => Math.abs(p / step - Math.round(p / step)) < 0.01), + ) ?? 0.5; + const judgedValues = tracked.flatMap(f => + f.box != null && f.t >= judged.from && f.t <= judged.to + ? [{t: f.t, value: f.box[axis]}] + : [], + ); + const first = judgedValues[0]; + const last = judgedValues[judgedValues.length - 1]; + const pxPerFrame = + first == null || last == null || last.t <= first.t + ? 0 + : Math.abs(last.value - first.value) / ((last.t - first.t) / cadence); + const notes: string[] = []; + if (presented != null && compositorFrameMs == null) { + notes.push( + 'no compositor frames recorded around the window: judged from the screencast alone', + ); + } + if (recorderSkipped > 0) { + notes.push( + `the screencast skipped ${recorderSkipped} frames the compositor presented (at ${skips.map(g => `+${(g.from - window.from).toFixed(0)} ms`).join(', ')})`, + ); + } + if (pxPerFrame > 0 && pxPerFrame < 2 * stepPx) { + notes.push( + `${pxPerFrame.toFixed(1)} px/frame is under two of the cast's ${stepPx} px position steps: a frame delivered early can show no step and read as not moved`, + ); + } + const failures: string[] = []; + if (stats.frames === 0) { + failures.push('no frame presented in the judged part'); + } else if (stats.medianFrameMs > maxMedianFrameMs) { + failures.push( + `median frame interval ${stats.medianFrameMs.toFixed(1)} ms > ${maxMedianFrameMs} ms (${stats.frames} frames presented)`, + ); + } + if (longestStallFrames > maxStallFrames) { + failures.push( + `longest stall ${longestStallMs.toFixed(1)} ms = ${longestStallFrames} intervals > ${maxStallFrames}`, + ); + } + if (expectedFrames < minJudgedFrames) { + failures.push( + `${(judged.to - judged.from).toFixed(0)} ms judged = ${expectedFrames} frames < ${minJudgedFrames}: the animation under test was not moving during the block`, + ); + } + const allowedMisses = Math.max( + 1, + Math.floor((1 - minMovedFraction) * judgedFrames + 1e-9), + ); + if (judgedFrames - moved - recorderSkipped > allowedMisses) { + failures.push( + `${moved} of ${judgedFrames} expected frames moved${recorderSkipped > 0 ? ` (and ${recorderSkipped} the screencast skipped)` : ''} (${(movedFraction * 100).toFixed(0)}% < ${(minMovedFraction * 100).toFixed(0)}%)`, + ); + } + const onScreenFromMs = + onScreenFrom == null ? null : onScreenFrom - window.from; + const summary = + `${(judged.to - judged.from).toFixed(0)} ms judged at ${cadence.toFixed(1)} ms/frame: ${stats.frames} frames presented, ` + + `${moved}/${judgedFrames} moved${recorderSkipped > 0 ? ` and ${recorderSkipped} skipped by the screencast` : ''} (${(movedFraction * 100).toFixed(0)}%), ` + + `median ${stats.medianFrameMs.toFixed(1)} ms, ` + + `longest stall ${longestStallMs.toFixed(1)} ms (${longestStallFrames} intervals) at +${longestStallAtMs.toFixed(0)} ms, ` + + `${stats.monotonic ? 'monotonic' : 'not monotonic'}, ` + + `${pxPerFrame.toFixed(1)} px/frame in ${stepPx} px steps` + + (compositorFrameMs == null + ? '' + : `, compositor presenting every ${compositorFrameMs.toFixed(1)} ms`) + + (onScreenFromMs == null + ? '' + : `, on screen from +${onScreenFromMs.toFixed(0)} ms (nothing moved before the block)`) + + notes.map(note => `; note: ${note}`).join(''); + return { + ...stats, + window, + judged, + onScreenFromMs, + stepPx, + pxPerFrame, + notes, + recorderSkipped, + compositorFrameMs, + cadenceMs: cadence, + longestStallMs, + longestStallAtMs, + expectedFrames, + deliveredFrames, + longestStallFrames, + moved, + movedFraction, + verdict: {pass: failures.length === 0, failures}, + summary, + }; +} diff --git a/internal/interaction-harness/src/curves.ts b/internal/interaction-harness/src/curves.ts index 69b9908066f62..9eff0abfb9da9 100644 --- a/internal/interaction-harness/src/curves.ts +++ b/internal/interaction-harness/src/curves.ts @@ -134,17 +134,61 @@ function animationRecorder(): void { return entry.startedAt == null && entry.animation.playState !== 'idle'; }); }; + // While a rendering trace runs (traceRendering sets + // `__harnessRenderingTrace`), the recorder stands down. Its per-frame + // callback would make every frame a main-thread frame, in which Blink + // restyles each running animation's target, a composited one included (and + // lays out an anchored one), and document.getAnimations() flushes style: + // exactly what the trace counts. So it runs no frame callback, and a CSS + // animation or transition event reads only the animations of the element it + // names, once, at that animation's start (one that ends inside the trace is + // otherwise never seen). The animate() wrapper below still records script + // animations (it reads no style), and traceRendering resumes the recorder + // once the trace ends. + const tracing = () => + (window as unknown as {__harnessRenderingTrace?: boolean}) + .__harnessRenderingTrace === true; + let looping = false; const tick = () => { + if (tracing()) { + looping = false; + return; + } record(); frame(tick); }; + const loop = () => { + if (!looping) { + looping = true; + frame(tick); + } + }; // What already runs when the recorder starts (a spinner on a page the // harness touches for the first time) is seen now, before any watch arms; // first seen a frame later, it would read as started by the watched action. + // (A recorder that starts during a trace reads once here, then waits.) record(); - frame(tick); + loop(); for (const type of ['animationstart', 'transitionrun', 'transitionstart']) { - document.addEventListener(type, record, true); + document.addEventListener( + type, + event => { + if (!tracing()) { + record(); + return; + } + const target = event.target; + if (target instanceof Element) { + // A pseudo-element's animation (`::backdrop`) is in the subtree. + const pseudo = (event as AnimationEvent | TransitionEvent) + .pseudoElement; + for (const animation of target.getAnimations({subtree: !!pseudo})) { + remember(animation); + } + } + }, + true, + ); } // A script animation is recorded as it is made: WebKit can start and finish // a short one between two frames of a fresh page. @@ -159,12 +203,36 @@ function animationRecorder(): void { }; w.__harnessAnimations = { log, - record, + // A read from outside the recorder (a wait's poll) stands down while a + // trace runs, as the frame loop does: document.getAnimations() flushes + // style. CSS start events and the animate() wrapper still log what + // starts, and resume() catches up. + record: () => { + if (!tracing()) { + record(); + } + }, + // Catches up on what started during a trace, then runs its frames again. + resume: () => { + record(); + loop(); + }, // Record first, then stamp strictly after the newest entry: a step that // changed style just before has its transition created by that read, - // and it started before the arm. - arm: () => { - record(); + // and it started before the arm. While a trace runs the page-wide read + // stands down, as record() does; the watched element's own animations + // are still read, which resolves its pending style change. That read + // restyles the element (and lays out an anchored one) in the task that + // takes the watch, so a traced proof takes its watch before the window + // it counts (README: No Layout / Paint). + arm: (element?: Element) => { + if (!tracing()) { + record(); + } else if (element != null) { + for (const animation of element.getAnimations({subtree: true})) { + remember(animation); + } + } const newest = log.length === 0 ? 0 : log[log.length - 1].seenAt; armedAt = Math.max(performance.now(), newest + 0.001); return armedAt; @@ -197,10 +265,47 @@ async function installCurveEnd(page: Page): Promise { await page.evaluate(() => { const w = window as unknown as { __harnessCurveEnd?: (animation: Animation) => number; + __harnessTiming?: ( + effect: AnimationEffect | null | undefined, + ) => ComputedEffectTiming | null; + }; + // An effect's timing as getComputedTiming() reports it. Inside a rendering + // trace it is worked out from getTiming() instead: getComputedTiming() + // updates a running animation on demand, which restyles its target in the + // next frame (and lays out an anchored one), exactly what a trace counts. + w.__harnessTiming ??= effect => { + if (effect == null) { + return null; + } + if ( + (window as unknown as {__harnessRenderingTrace?: boolean}) + .__harnessRenderingTrace !== true + ) { + return effect.getComputedTiming(); + } + const timing = effect.getTiming(); + const duration = + typeof timing.duration === 'number' ? timing.duration : 0; + const iterations = Number(timing.iterations ?? 1); + const delay = Number(timing.delay ?? 0); + const endDelay = Number(timing.endDelay ?? 0); + const activeDuration = + duration === 0 || iterations === 0 ? 0 : duration * iterations; + const derived: ComputedEffectTiming = { + ...timing, + duration, + iterations, + delay, + endDelay, + activeDuration, + endTime: Math.max(delay + activeDuration + endDelay, 0), + }; + return derived; }; if (w.__harnessCurveEnd) { return; } + const timingOf = w.__harnessTiming; const timingKeys = new Set([ 'offset', 'computedOffset', @@ -216,7 +321,7 @@ async function installCurveEnd(page: Page): Promise { ); w.__harnessCurveEnd = animation => { const effect = animation.effect as KeyframeEffect | null; - const timing = effect?.getComputedTiming(); + const timing = timingOf(effect); const delay = Number(timing?.delay ?? 0); const active = Number(timing?.activeDuration ?? 0); if ( @@ -826,6 +931,38 @@ export interface ActiveAnimation { readonly finishedAt: number | null; } +/** + * Runs `fn` on `locator`'s element: through the locator, or, `quietly`, + * through a handle to the element it matches now (none yet: `[]`). Each + * locator.evaluate makes a main-thread frame, which a trace counts; + * `elementHandles()` and a handle's evaluate make none. + */ +async function readElement( + locator: Locator, + quietly: boolean, + fn: (element: Element, arg: A) => R[], + arg: A, + timeout: number, +): Promise { + const run = fn as unknown as (element: Element, arg: unknown) => R[]; + if (!quietly) { + return locator.evaluate(run, arg as unknown, {timeout}); + } + const handles = await locator.elementHandles(); + try { + if (handles.length > 1) { + throw new Error( + `waitForAnimation: ${String(locator)} matches ${handles.length} elements`, + ); + } + return handles.length === 0 + ? [] + : await handles[0].evaluate(run, arg as unknown); + } finally { + await Promise.all(handles.map(handle => handle.dispose())); + } +} + /** * Runs a locator read within the wait's own deadline. A locator waits for * its element with no timeout of its own, so one the page removed (an exit @@ -876,6 +1013,15 @@ async function withinTimeout( * recorder keeps one entry per `Animation` object, so an animation reversed * or replayed mid-run is misread: a watch taken before the reversal rejects, * and an unwatched wait returns at once with a curve dated before it. + * + * Started inside a `traceRendering` body, it stands down as the recorder + * does, so it adds no frame the trace counts: it takes the element's + * animations from the recorder's log, judges a started one by its own times, + * and reaches the element through a handle to what the locator matches at + * each look. That holds for script animations and CSS transitions. On a CSS + * `@keyframes` animation (and, unwatched, a cancelled CSS transition) it reads + * the animation's timing, which flushes its style and adds Layouts to the + * trace: wait on one with `waitForRest`, or after the trace. */ export async function waitForAnimation( locator: Locator, @@ -891,17 +1037,34 @@ export async function waitForAnimation( } = {}, ): Promise { const deadline = Date.now() + timeout; - await installCurveEnd(locator.page()); + const page = locator.page(); + await installCurveEnd(page); + // Inside a rendering trace the wait stands down (see the page function), + // and it reads the element through handles: each locator.evaluate makes a + // main-thread frame (a Layout of an anchored element), where a handle's + // evaluate adds none. + const traced = await page.evaluate( + () => + (window as unknown as {__harnessRenderingTrace?: boolean}) + .__harnessRenderingTrace === true, + ); for (;;) { const read = await withinTimeout( 'waitForAnimation', locator, deadline, evaluateTimeout => - locator.evaluate( + readElement( + locator, + traced, (element, {minProgress, since: watchedFrom}) => { + // The harness's own read: a trace sets it apart (trace.ts HARNESS_READ). + console.timeStamp('harness-read'); const w = window as unknown as { __harnessCurveEnd: (a: Animation) => number; + __harnessTiming: ( + effect: AnimationEffect | null | undefined, + ) => ComputedEffectTiming | null; __harnessAnimations: { log: { animation: Animation; @@ -916,6 +1079,13 @@ export async function waitForAnimation( }; const curveEnd = w.__harnessCurveEnd; const recorder = w.__harnessAnimations; + // Inside a rendering trace the wait stands down as the recorder does: + // record() reads nothing, the animations come from the recorder's log + // rather than getAnimations(), and a started one runs by its own + // times, since playState flushes a CSS animation's style. + const traced = + (window as unknown as {__harnessRenderingTrace?: boolean}) + .__harnessRenderingTrace === true; recorder.record(); const describe = ( a: Animation, @@ -923,7 +1093,7 @@ export async function waitForAnimation( recordedStart: number | null, ) => { const effect = a.effect as KeyframeEffect | null; - const timing = effect?.getComputedTiming(); + const timing = w.__harnessTiming(effect); // The recorded start stands in once the page has cancelled it. A // run going backward began at its end: its startTime is where its // current time would reach 0, a whole run later. @@ -994,24 +1164,36 @@ export async function waitForAnimation( // finished must not answer for it. Only document-timeline animations // count, as for holdAnimations: a scroll- or view-timeline one moves // only when something scrolls and never progresses on its own. + const runs = (a: Animation) => { + if (!(a.timeline instanceof DocumentTimeline)) { + return false; + } + if (!traced || a.startTime == null) { + return a.playState === 'running'; + } + const time = Number(a.currentTime ?? 0); + return a.playbackRate < 0 + ? time > 0 + : time < Number(w.__harnessTiming(a.effect)?.endTime ?? 0); + }; + const onElement = () => + recorder.log.filter( + e => inside(e.animation) || e.ancestors.includes(element), + ); const live = ( - watchedFrom == null + watchedFrom == null && !traced ? element.getAnimations({subtree: true}) - : recorded + : (watchedFrom == null ? onElement() : recorded) .filter(e => e.finishedAt == null) .map(e => e.animation) - ).filter( - a => - a.playState === 'running' && - a.timeline instanceof DocumentTimeline, - ); + ).filter(runs); const running = live.filter(a => a.startTime != null); // Progress along the curve, on the timeline: a delay presents nothing // (going backward, the end delay plays first), a run going backward // (`reverse()`) progresses from its end, and a faster rate presents // more curve per ms. const progressed = running.filter(a => { - const timing = a.effect?.getComputedTiming(); + const timing = w.__harnessTiming(a.effect); const time = Number(a.currentTime ?? 0); const local = a.playbackRate < 0 @@ -1036,13 +1218,20 @@ export async function waitForAnimation( return e.finishedAt; } const a = e.animation; - if (a.playState !== 'finished' || a.startTime == null) { + if (a.startTime == null) { + return null; + } + const end = Number(w.__harnessTiming(a.effect)?.endTime ?? 0); + // Traced, by its own times; otherwise by its state. + const time = Number(a.currentTime ?? 0); + const done = traced + ? a.playbackRate < 0 + ? time <= 0 + : time >= end + : a.playState === 'finished'; + if (!done) { return null; } - const end = Number( - (a.effect as KeyframeEffect | null)?.getComputedTiming() - .endTime ?? 0, - ); return a.playbackRate < 0 ? Number(a.startTime) : Number(a.startTime) + end / Math.abs(a.playbackRate || 1); @@ -1052,7 +1241,7 @@ export async function waitForAnimation( .map(e => describe(e.animation, finishedAt(e), e.startedAt)); }, {minProgress: minProgressMs, since: since ?? null}, - {timeout: evaluateTimeout}, + evaluateTimeout, ), ); const found = read ?? []; @@ -1072,13 +1261,31 @@ export async function waitForAnimation( } } -/** Marks now as the point later waits count animations from. */ -async function armRecorder(page: Page): Promise { - return page.evaluate(() => - ( - window as unknown as {__harnessAnimations: {arm: () => number}} - ).__harnessAnimations.arm(), - ); +/** + * Marks now as the point later waits count animations from. With a locator, + * its element's pending style change is resolved first, also inside a trace + * (reached through a handle, which adds no main-thread frame). + */ +async function armRecorder(page: Page, locator?: Locator): Promise { + const handles = locator == null ? [] : await locator.elementHandles(); + try { + if (handles.length === 1) { + return await handles[0].evaluate(element => + ( + window as unknown as { + __harnessAnimations: {arm: (element?: Element) => number}; + } + ).__harnessAnimations.arm(element as Element), + ); + } + return await page.evaluate(() => + ( + window as unknown as {__harnessAnimations: {arm: () => number}} + ).__harnessAnimations.arm(), + ); + } finally { + await Promise.all(handles.map(handle => handle.dispose())); + } } export interface AnimationWatch { @@ -1096,7 +1303,9 @@ export interface AnimationWatch { /** * Starts watching `locator`'s element before an action, so the animation the * action starts is caught even when it ends before the test looks (a short - * entrance on a cold page): + * entrance on a cold page). Taking the watch reads the element's animations, + * which restyles it, inside a rendering trace too: take a traced watch before + * the window the proof counts: * * const watch = await watchAnimations(sheet); * await driver.play(tap(button)); @@ -1106,7 +1315,7 @@ export async function watchAnimations( locator: Locator, ): Promise { await installCurveEnd(locator.page()); - const since = await armRecorder(locator.page()); + const since = await armRecorder(locator.page(), locator); return { started: options => waitForAnimation(locator, {...options, since}), }; @@ -1125,6 +1334,16 @@ export async function watchAnimations( * forward run under a linear or cubic-bézier effect easing); under any other * easing or direction, waitForRest waits the hold out, and a hold longer than * `timeout` rejects with "still moving". + * + * While a rendering trace runs (`traceRendering`), it stands down as the + * animation recorder does: a per-frame callback would make every frame a + * main-thread frame, which the trace counts. It then waits on timers for the + * scheduled ends of the curves on the element instead (a run going backward, + * until it finishes), reading no style, so + * motion that no animation drives (a script writing styles) is not seen until + * the trace ends. Finding no animation, it looks again `frames` times a frame + * apart before settling, so one the action starts a few frames later is + * waited for. */ export async function waitForRest( locator: Locator, @@ -1157,15 +1376,94 @@ export async function waitForRest( backdrop, ].join(' | '); }; - // The page's real frames, even while a timer gate holds its callbacks. - const frame = + // The page's real frames and timers, even while a timer gate holds + // its callbacks: a frozen gate never holds the wait itself. + const gate = ( + window as unknown as { + __harnessTimerGate?: { + frame: typeof requestAnimationFrame; + timeout?: typeof setTimeout; + }; + } + ).__harnessTimerGate; + const frame = gate?.frame ?? requestAnimationFrame; + const timeout = gate?.timeout ?? setTimeout; + // Set by traceRendering while it traces (see the recorder above). + const tracing = () => + (window as unknown as {__harnessRenderingTrace?: boolean}) + .__harnessRenderingTrace === true; + const settle = () => { + // Later waits count animations from here. ( - window as unknown as { - __harnessTimerGate?: {frame: typeof requestAnimationFrame}; - } - ).__harnessTimerGate?.frame ?? requestAnimationFrame; - let last = read(); + window as unknown as {__harnessAnimations?: {arm: () => number}} + ).__harnessAnimations?.arm(); + resolve(); + }; + let last = ''; let still = 0; + const frames = () => { + last = read(); + still = 0; + frame(tick); + }; + // While traced: one look at the animations, then a timer to the latest + // scheduled curve end. One not started yet is looked at again a frame + // later; a trace that has ended hands over to the per-frame check. + // Finding nothing settles only after `frames` looks a frame apart, as + // the per-frame check needs `frames` still frames: an animation the + // action starts a frame or two later is still waited for. + let idle = 0; + const scheduled = () => { + let wait = 0; + for (const a of element.getAnimations({subtree: true})) { + // A scroll- or view-timeline animation moves only when something + // scrolls: it has no scheduled end to wait for (holdAnimations + // skips it the same way). + if (!(a.timeline instanceof DocumentTimeline)) { + continue; + } + if ( + a.pending || + (a.playState === 'running' && a.startTime == null) + ) { + wait = Math.max(wait, 16); + } else if (a.playState === 'running') { + // The curve's time left through the playback rate: forward, to + // its (held) end; backward (`reverse()`), to local time 0, + // where it finishes, as the untraced path waits it out. + const rate = a.playbackRate || 1; + const at = Number(a.currentTime ?? 0); + const left = + rate > 0 ? (curveEnd(a) - at) / rate : at / -rate; + wait = Math.max(wait, left); + } + } + if (wait <= 0) { + idle += 1; + if (idle >= need) { + settle(); + return; + } + wait = 16; + } else { + idle = 0; + } + const room = deadline - performance.now(); + timeout( + () => { + if (performance.now() > deadline) { + reject( + new Error('waitForRest: still moving at the deadline'), + ); + } else if (tracing()) { + scheduled(); + } else { + frames(); + } + }, + Math.min(wait, Math.max(0, room)) + 1, + ); + }; const tick = () => { const now = read(); const moving = element.getAnimations({subtree: true}).some( @@ -1182,20 +1480,20 @@ export async function waitForRest( still = !moving && now === last ? still + 1 : 0; last = now; if (still >= need) { - // Later waits count animations from here. - ( - window as unknown as { - __harnessAnimations?: {arm: () => number}; - } - ).__harnessAnimations?.arm(); - resolve(); + settle(); } else if (performance.now() > deadline) { reject(new Error(`waitForRest: still moving (${now})`)); + } else if (tracing()) { + scheduled(); } else { frame(tick); } }; - frame(tick); + if (tracing()) { + scheduled(); + } else { + frames(); + } }), {ms: timeout, need: frames}, {timeout: evaluateTimeout}, diff --git a/internal/interaction-harness/src/frames.ts b/internal/interaction-harness/src/frames.ts new file mode 100644 index 0000000000000..83841d259c17f --- /dev/null +++ b/internal/interaction-harness/src/frames.ts @@ -0,0 +1,531 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file frames.ts + * @input Uses a Playwright `Page`, a `Locator` for the element under test, and + * the engine's screencast (Chromium CDP `Page.startScreencast`; WebKit's + * `Screencast` domain) + * @output `startScreencast` (timestamped composited frames), `markElement` + * (a marker outline the frames can find), `trackMarker` (per-frame marker + * box), `sampleRects` (per-rAF rect sampling), `frameStats`. + * @position Frame evidence for motion proofs. The screencast is captured off + * the page's main thread, from what the compositor presents, so it keeps + * delivering frames while a script blocks the main thread: that is what makes + * the busy-main-thread proof possible. Rect sampling is the cheap path when + * the main thread is free. + * + * Marker tracking needs no image library: frames are decoded and scanned in a + * scratch page of the same browser (createImageBitmap + canvas), so the + * harness adds no dependency. + * + * SYNC: Keep the README's frame-evidence section equal to what this measures. + */ + +import type {CDPSession, Locator, Page} from '@playwright/test'; +import {webkitPageSession} from './touch'; + +export interface CastFrame { + /** Presentation time, epoch ms (the compositor's frame timestamp). */ + readonly t: number; + /** Base64 PNG/JPEG. */ + readonly data: string; + readonly format: 'png' | 'jpeg'; + /** CSS px of the viewport the frame shows. */ + readonly viewportWidth: number; + readonly viewportHeight: number; +} + +export interface Screencast { + /** + * Frames captured so far: wait for the first one to know the cast saw the + * page before an animation starts (`busyWindowProof` then knows its at-rest + * position). + */ + frameCount(): number; + /** Stops and returns every frame captured, in order. */ + stop(): Promise; +} + +export interface ScreencastOptions { + /** Lossless frames by default: marker colours survive PNG, not JPEG. */ + readonly format?: 'png' | 'jpeg'; + readonly quality?: number; + /** + * Keep one presented frame in this many (default 1, every frame): a slower + * evidence channel, like a loaded machine's screencast, for proving that a + * verdict does not depend on the screencast's rate. + */ + readonly everyNthFrame?: number; +} + +/** + * Starts capturing composited frames. Chromium delivers one per presented + * frame (16.7 ms at 60 Hz), timestamped by the compositor; WebKit's own + * screencast delivers one per composited update (about every 14 ms in the + * Linux build), stamped on CLOCK_MONOTONIC and rebased here onto the wall + * clock by that clock's measured offset, so both engines share the page's + * timeline. Both keep delivering while the page's main thread is blocked, and + * neither sends a frame when nothing on screen changed. + */ +export async function startScreencast( + page: Page, + options: ScreencastOptions = {}, +): Promise { + const name = page.context().browser()?.browserType().name(); + const viewport = page.viewportSize() ?? {width: 0, height: 0}; + if (name === 'chromium') { + return chromiumScreencast(page, viewport, options); + } + if (name === 'webkit') { + return webkitScreencast(page, viewport, options); + } + throw new Error( + `startScreencast: unsupported browser ${name ?? '(unknown)'}`, + ); +} + +async function chromiumScreencast( + page: Page, + viewport: {width: number; height: number}, + {format = 'png', quality = 90, everyNthFrame = 1}: ScreencastOptions, +): Promise { + const cdp: CDPSession = await page.context().newCDPSession(page); + const frames: CastFrame[] = []; + const onFrame = (frame: { + data: string; + sessionId: number; + metadata: {timestamp?: number; deviceWidth: number; deviceHeight: number}; + }) => { + frames.push({ + t: (frame.metadata.timestamp ?? Date.now() / 1000) * 1000, + data: frame.data, + format, + viewportWidth: frame.metadata.deviceWidth || viewport.width, + viewportHeight: frame.metadata.deviceHeight || viewport.height, + }); + cdp + .send('Page.screencastFrameAck', {sessionId: frame.sessionId}) + .catch(() => {}); + }; + cdp.on('Page.screencastFrame', onFrame); + // One CSS px per frame px keeps decoding cheap; everyNthFrame 1 = every presented frame. + await cdp.send('Page.startScreencast', { + format, + quality, + maxWidth: viewport.width, + maxHeight: viewport.height, + everyNthFrame, + }); + return { + frameCount: () => frames.length, + async stop() { + await cdp.send('Page.stopScreencast'); + cdp.off('Page.screencastFrame', onFrame); + await cdp.detach().catch(() => {}); + return inPresentationOrder(frames); + }, + }; +} + +async function webkitScreencast( + page: Page, + viewport: {width: number; height: number}, + {quality = 90, everyNthFrame = 1}: ScreencastOptions, +): Promise { + const session = webkitPageSession(page); + const frames: CastFrame[] = []; + let generation = 0; + let delivered = 0; + const onFrame = (payload: unknown) => { + const frame = payload as {data: string; timestamp: number}; + // WebKit's screencast has no everyNthFrame: keep one frame in N here. + delivered += 1; + if ((delivered - 1) % everyNthFrame !== 0) { + session + .send('Screencast.screencastFrameAck', {generation}) + .catch(() => {}); + return; + } + frames.push({ + // WebKit stamps frames in seconds on the monotonic clock; rebased below. + t: frame.timestamp * 1000, + data: frame.data, + format: 'jpeg', + viewportWidth: viewport.width, + viewportHeight: viewport.height, + }); + session.send('Screencast.screencastFrameAck', {generation}).catch(() => {}); + }; + session.on('Screencast.screencastFrame', onFrame); + const started = (await session.send('Screencast.startScreencast', { + width: viewport.width, + height: viewport.height, + toolbarHeight: 0, + quality, + })) as {generation: number}; + generation = started.generation; + // WebKit stamps frames in seconds on CLOCK_MONOTONIC, which this process + // shares: rebase them by the wall clock's offset from that clock, sampled + // together. (Taking the first frame as the start shifted every frame earlier + // by however long that frame took to come, 60–100 ms on a busy page.) + const wallMinusMonotonic = Date.now() - Number(process.hrtime.bigint()) / 1e6; + return { + frameCount: () => frames.length, + async stop() { + await session.send('Screencast.stopScreencast'); + session.off?.('Screencast.screencastFrame', onFrame); + if (frames.length === 0) { + return frames; + } + return inPresentationOrder(frames).map(f => ({ + ...f, + t: f.t + wallMinusMonotonic, + })); + }, + }; +} + +/** + * Frames sorted by their presentation timestamp. A loaded machine can deliver + * screencast frames out of order (a frame stamped 35 ms arriving after one + * stamped 46 ms); judged in arrival order, a steadily moving element would + * appear to step backwards. + */ +export function inPresentationOrder( + frames: readonly T[], +): T[] { + return [...frames].sort((a, b) => a.t - b.t); +} + +/** The marker colour: magenta never occurs in Astryx themes. */ +export const MARKER_RGB: readonly [number, number, number] = [255, 0, 255]; + +export interface MarkerOptions { + readonly rgb?: readonly [number, number, number]; + /** + * `chip` (default): a small square child pinned inside the element's + * top-left corner, above every sibling (z-index max), so nothing the + * component paints can cover it. The element must be its containing block: + * a static element is made `position: relative` while marked. + * `outline`: an inset outline on the element itself (no DOM insertion), for + * elements that cannot take a child; children with their own layers can + * cover parts of it. + */ + readonly mode?: 'chip' | 'outline'; + /** Chip size or outline width, CSS px. */ + readonly size?: number; + /** Chip inset from the element's top-left corner, CSS px. */ + readonly inset?: number; +} + +/** + * Marks the element so screencast frames can find it: the mark moves, scales + * and fades with the element's own layer and never changes its layout. + * Returns an undo. + */ +export async function markElement( + locator: Locator, + options: MarkerOptions = {}, +): Promise<() => Promise> { + const { + rgb = MARKER_RGB, + mode = 'chip', + size = mode === 'chip' ? 16 : 6, + inset = 8, + } = options; + const id = `m${Math.random().toString(36).slice(2, 8)}`; + await locator.evaluate( + (element, {id: markerId, color, size: px, inset: offset, mode: kind}) => { + const el = element as HTMLElement; + el.setAttribute('data-harness-marker', markerId); + if (kind === 'outline') { + const style = document.createElement('style'); + style.setAttribute('data-harness-marker-style', markerId); + style.textContent = `[data-harness-marker="${markerId}"]{outline:${px}px solid rgb(${color.join(',')}) !important;outline-offset:-${px}px !important;}`; + document.head.append(style); + return; + } + if (getComputedStyle(el).position === 'static') { + el.setAttribute('data-harness-marker-position', el.style.position); + el.style.position = 'relative'; + } + const chip = document.createElement('div'); + chip.setAttribute('data-harness-marker-chip', markerId); + chip.setAttribute('aria-hidden', 'true'); + chip.style.cssText = `position:absolute;top:${offset}px;left:${offset}px;width:${px}px;height:${px}px;background:rgb(${color.join(',')});z-index:2147483647;pointer-events:none;`; + el.append(chip); + }, + {id, color: [...rgb], size, inset, mode}, + ); + return async () => { + await locator.page().evaluate(markerId => { + const el = document.querySelector( + `[data-harness-marker="${markerId}"]`, + ); + if (el?.hasAttribute('data-harness-marker-position')) { + el.style.position = + el.getAttribute('data-harness-marker-position') ?? ''; + el.removeAttribute('data-harness-marker-position'); + } + el?.removeAttribute('data-harness-marker'); + document + .querySelector(`[data-harness-marker-chip="${markerId}"]`) + ?.remove(); + document + .querySelector(`[data-harness-marker-style="${markerId}"]`) + ?.remove(); + }, id); + }; +} + +export interface Box { + readonly x: number; + readonly y: number; + readonly width: number; + readonly height: number; +} + +export interface TrackedFrame { + /** Epoch ms. */ + readonly t: number; + /** The marker's bounding box in CSS px, or null when it is not on screen. */ + readonly box: Box | null; + /** Marker pixels found (a fading element finds fewer at the same tolerance). */ + readonly pixels: number; +} + +/** + * Finds the marker in every frame. Decoding runs in a scratch page of the same + * browser, so neither the page under test nor Node needs an image decoder. + */ +export async function trackMarker( + page: Page, + frames: readonly CastFrame[], + { + rgb = MARKER_RGB, + tolerance = 40, + }: {rgb?: readonly [number, number, number]; tolerance?: number} = {}, +): Promise { + const scratch = await page.context().newPage(); + try { + const out: TrackedFrame[] = []; + // Batches keep each evaluate payload moderate. + for (let i = 0; i < frames.length; i += 12) { + const batch = frames.slice(i, i + 12); + const boxes = await scratch.evaluate( + async ({batch: items, color, tol}) => { + const results: { + box: {x: number; y: number; width: number; height: number} | null; + pixels: number; + }[] = []; + for (const item of items) { + const blob = await ( + await fetch(`data:image/${item.format};base64,${item.data}`) + ).blob(); + const bitmap = await createImageBitmap(blob); + const canvas = new OffscreenCanvas(bitmap.width, bitmap.height); + const context = canvas.getContext('2d'); + if (context == null) { + throw new Error('no 2d context'); + } + context.drawImage(bitmap, 0, 0); + const {data, width, height} = context.getImageData( + 0, + 0, + bitmap.width, + bitmap.height, + ); + let minX = Infinity; + let minY = Infinity; + let maxX = -Infinity; + let maxY = -Infinity; + let pixels = 0; + for (let y = 0; y < height; y += 1) { + for (let x = 0; x < width; x += 1) { + const o = (y * width + x) * 4; + if ( + Math.abs(data[o] - color[0]) <= tol && + Math.abs(data[o + 1] - color[1]) <= tol && + Math.abs(data[o + 2] - color[2]) <= tol + ) { + pixels += 1; + if (x < minX) { + minX = x; + } + if (x > maxX) { + maxX = x; + } + if (y < minY) { + minY = y; + } + if (y > maxY) { + maxY = y; + } + } + } + } + const scale = width / item.viewportWidth; + results.push({ + box: + pixels === 0 + ? null + : { + x: minX / scale, + y: minY / scale, + width: (maxX - minX + 1) / scale, + height: (maxY - minY + 1) / scale, + }, + pixels, + }); + } + return results; + }, + { + batch: batch.map(f => ({ + data: f.data, + format: f.format, + viewportWidth: f.viewportWidth, + })), + color: [...rgb], + tol: tolerance, + }, + ); + boxes.forEach((result, k) => + out.push({t: batch[k].t, box: result.box, pixels: result.pixels}), + ); + } + return out; + } finally { + await scratch.close(); + } +} + +export interface RectSample { + /** Epoch ms of the rAF callback. */ + readonly t: number; + readonly box: Box | null; + readonly transform: string; + readonly opacity: number; +} + +/** + * Samples the element's rect, transform and opacity on every animation frame + * for `durationMs`. Main-thread sampling: it stops while the main thread is + * blocked, which is the point of the screencast path above. + */ +export async function sampleRects( + locator: Locator, + durationMs: number, +): Promise { + return locator.evaluate( + (element, duration) => + new Promise< + { + t: number; + box: {x: number; y: number; width: number; height: number} | null; + transform: string; + opacity: number; + }[] + >(resolve => { + // The harness's own waits run on the real timers: a frozen timer gate + // (story.ts) holds only the page's. + const gate = ( + window as unknown as { + __harnessTimerGate?: { + frame?: typeof requestAnimationFrame; + }; + } + ).__harnessTimerGate; + const frame = gate?.frame ?? window.requestAnimationFrame.bind(window); + const samples: { + t: number; + box: {x: number; y: number; width: number; height: number} | null; + transform: string; + opacity: number; + }[] = []; + const end = performance.now() + duration; + const tick = (now: number) => { + const rect = element.getBoundingClientRect(); + const style = getComputedStyle(element); + samples.push({ + t: performance.timeOrigin + now, + box: {x: rect.x, y: rect.y, width: rect.width, height: rect.height}, + transform: style.transform, + opacity: Number(style.opacity), + }); + if (now < end) { + frame(tick); + } else { + resolve(samples); + } + }; + frame(tick); + }), + durationMs, + ); +} + +export interface FrameStats { + readonly frames: number; + /** Frames whose tracked value differs from the frame before. */ + readonly changed: number; + /** Longest stretch without a change inside the window (an open stall at its end included), ms. */ + readonly longestStallMs: number; + /** Median spacing between frames, ms. */ + readonly medianFrameMs: number; + readonly monotonic: boolean; + readonly first: number | null; + readonly last: number | null; +} + +/** Summarises per-frame values (e.g. the marker's y) inside a time window. */ +export function frameStats( + samples: readonly {readonly t: number; readonly value: number | null}[], + window: {readonly from: number; readonly to: number} = { + from: -Infinity, + to: Infinity, + }, + epsilon = 0.25, +): FrameStats { + const inside = samples.filter( + s => s.t >= window.from && s.t <= window.to && s.value != null, + ) as {t: number; value: number}[]; + let changed = 0; + let increasing = 0; + let decreasing = 0; + let stallStart = inside[0]?.t ?? 0; + let longestStallMs = 0; + for (let i = 1; i < inside.length; i += 1) { + const delta = inside[i].value - inside[i - 1].value; + if (Math.abs(delta) > epsilon) { + changed += 1; + if (delta > 0) { + increasing += 1; + } else { + decreasing += 1; + } + longestStallMs = Math.max(longestStallMs, inside[i].t - stallStart); + stallStart = inside[i].t; + } + } + // A stall still open when the window closes counts too: a frozen animation never changes at all. + if (inside.length > 0) { + longestStallMs = Math.max( + longestStallMs, + inside[inside.length - 1].t - stallStart, + ); + } + const gaps = inside + .slice(1) + .map((s, i) => s.t - inside[i].t) + .sort((a, b) => a - b); + return { + frames: inside.length, + changed, + longestStallMs, + medianFrameMs: gaps.length ? gaps[Math.floor(gaps.length / 2)] : 0, + monotonic: increasing === 0 || decreasing === 0, + first: inside[0]?.value ?? null, + last: inside[inside.length - 1]?.value ?? null, + }; +} diff --git a/internal/interaction-harness/src/harness.interaction.browser.spec.ts b/internal/interaction-harness/src/harness.interaction.browser.spec.ts index 7e47af95b2c81..3a7b35279c5d1 100644 --- a/internal/interaction-harness/src/harness.interaction.browser.spec.ts +++ b/internal/interaction-harness/src/harness.interaction.browser.spec.ts @@ -3,32 +3,51 @@ /** * @file harness.interaction.browser.spec.ts * @input Fixture pages written inline (no Storybook), real Chromium/WebKit - * @output Proof that each harness instrument measures what it claims: - * scripted timestamps reach the page; a flick flings natively (Chromium); - * a second finger and a pinch arrive as distinct pointers; sampled curves - * match the oracles; the animation-state waits report a running transition - * and its end, and judge rest by presented values even while an animation - * holds its end, and a watch taken on first contact ignores an animation - * already running and keeps the start of one the page cancels when it ends; individual transform properties are sampled; a sample at + * @output Proof that each harness instrument measures what it claims, with a + * negative control beside every positive one: scripted timestamps reach the + * page; a flick flings natively (Chromium); a second finger and a pinch + * arrive as distinct pointers; the screencast shows a compositor animation + * advancing through a blocked main thread while a rAF animation freezes; + * the trace counts zero Layout for a transform animation and one per frame + * for a `top` animation, and none from the harness's own animation recorder + * while an anchored element's composited animation runs (a page that asks + * for a frame every frame lays it out in each); the long-task log records + * the page's own long task but not a DevTools evaluate, which the trace + * counts; sampled curves + * match the oracles, individual transform properties included; a sample at * an end reports the time it was read at; holding takes only running * document-timeline animations, each at its own offset, holds each where it * was read, adds a second hold to the held set without moving the first - * hold's times, drops one the page cancels, and releases only them; - * storyboards write a sheet and a trace that follows the curve, an endless - * animation does not set their length, and a photograph Chromium returns - * empty is taken again two frames later; a touch filmstrip keeps scripted - * event times while a handler clock sees its pacing; the timer gate holds a - * component timer until the filmstrip is done, drops callbacks the page - * cancels, stamps held frames with the time they run, and leaves the - * harness its own frames. + * hold's times, drops one the page cancels, and releases only them; the + * animation-state waits report a running transition and its end, and judge + * rest by presented values even while an animation holds its end, and a + * watch taken on first contact ignores an animation already running and + * keeps the start of one the page cancels when it ends, and the recorder + * reads only at CSS starts while a rendering trace runs and catches up + * after it; + * storyboards write a + * sheet and a trace that follows the curve, an endless animation does not + * set their length, and a photograph Chromium returns empty is taken again + * two frames later; a touch filmstrip keeps scripted event times while a + * handler clock sees its pacing; the timer gate holds a component timer + * until the filmstrip is done, drops callbacks the page cancels, stamps held + * frames with the time they run, and leaves the harness its own frames; a + * cast filmstrip keeps exactly the presented frames of its window, labelled + * from its zero, as PNG. * @position The harness's own test. A component spec trusts these * instruments; this file is why it may. */ +import fs from 'node:fs'; +import path from 'node:path'; import {expect, test, type Page} from '@playwright/test'; import { animationStoryboard, + castStoryboard, + blockMainThread, + busyWindowProof, compareCurve, + countBetween, cubicBezier, curveOf, drag, @@ -37,28 +56,46 @@ import { freezeTimers, holdAnimations, installInputLog, + installLongTaskLog, installTimerGate, + markElement, merge, parseTransform, PARTIAL_LIFT_SKIP, pinch, readInputLog, + readLongTasks, releaseAnimations, sampleCurve, + sampleRects, seekAnimations, springStep, + startCompositorTrace, + startScreencast, Storyboard, tap, thawTimers, timeline, touchDriver, touchStoryboard, + traceRendering, + trackMarker, waitForAnimation, waitForRest, watchAnimations, withFinger, } from './index'; +// An element positioned against an anchor: a composited animation of it lays +// out in every main-thread frame, so it shows any per-frame main-thread work. +const ANCHORED = ` + +
`; + const FIXTURE = ` +
`; + +async function busyFixture(page: Page) { + await page.route('http://busy.test/', route => + route.fulfill({contentType: 'text/html', body: BUSY_FIXTURE}), + ); + await page.goto('http://busy.test/'); +} + // A real navigation (not setContent, whose document.open() erases the window // listeners the input log installs). async function fixture(page: Page) { @@ -242,6 +297,894 @@ test.describe('touch input', () => { }); }); +test.describe('frame evidence', () => { + test('a compositor animation advances every frame through a blocked main thread; a rAF one freezes, whatever the screencast rate', async ({ + page, + }, testInfo) => { + await busyFixture(page); + const box = page.locator('#box'); + await markElement(box, {mode: 'outline'}); + + const run = async (driver: 'compositor' | 'raf', everyNthFrame = 1) => { + await box.evaluate((el, how) => { + el.getAnimations().forEach(a => a.cancel()); + el.style.transform = 'none'; + if (how === 'compositor') { + el.animate( + [{transform: 'translateY(0px)'}, {transform: 'translateY(560px)'}], + {duration: 1600, easing: 'linear'}, + ); + } else { + const start = performance.now(); + const step = (now: number) => { + const p = Math.min(1, (now - start) / 1600); + el.style.transform = `translateY(${560 * p}px)`; + if (p < 1) { + requestAnimationFrame(step); + } + }; + requestAnimationFrame(step); + } + }, driver); + const cast = await startScreencast(page, {everyNthFrame}); + await page.waitForTimeout(200); + const window = await blockMainThread(page, 700); + await page.waitForTimeout(200); + const tracked = await trackMarker(page, await cast.stop()); + return busyWindowProof(tracked, window, {axis: 'y'}); + }; + + const compositor = await run('compositor'); + testInfo.annotations.push({ + type: 'busy-main-thread compositor', + description: compositor.summary, + }); + expect(compositor.verdict.failures, compositor.summary).toEqual([]); + expect(compositor.monotonic).toBe(true); + // Resolvable on the cast's grid: two position steps or more per frame. + expect(compositor.notes, compositor.summary).toEqual([]); + expect(compositor.pxPerFrame).toBeGreaterThanOrEqual(2 * compositor.stepPx); + + const raf = await run('raf'); + testInfo.annotations.push({ + type: 'busy-main-thread rAF control', + description: raf.summary, + }); + // Frozen for the whole block: no presented frame moved (the compositor + // sends none at all when nothing on screen changes), and the verdict that + // passes the compositor animation fails it on every criterion. + expect(raf.changed).toBe(0); + expect(raf.longestStallMs).toBeGreaterThan(600); + expect(raf.verdict.pass).toBe(false); + expect(raf.verdict.failures.join('\n')).toMatch(/longest stall/); + expect(raf.verdict.failures.join('\n')).toMatch(/expected frames moved/); + + // The verdict judges the frames the screencast delivered, not its rate: + // at one frame in six (a loaded machine's ~100 ms), the compositor + // animation still passes and the rAF one still fails. + const slow = await run('compositor', 6); + expect(slow.cadenceMs, slow.summary).toBeGreaterThan(60); + expect(slow.verdict.failures, slow.summary).toEqual([]); + const slowRaf = await run('raf', 6); + expect(slowRaf.verdict.pass, slowRaf.summary).toBe(false); + expect(slowRaf.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + test('frames the screencast skips while the compositor presents them are not a stall; a frozen animation still fails with the compositor record', async ({ + page, + browserName, + }, testInfo) => { + test.skip( + browserName !== 'chromium', + 'compositor traces are Chromium-only (README: engine limits)', + ); + await busyFixture(page); + const box = page.locator('#box'); + await markElement(box, {mode: 'outline'}); + const run = async (driver: 'compositor' | 'raf') => { + await box.evaluate((el, how) => { + el.getAnimations().forEach(a => a.cancel()); + el.style.transform = 'none'; + if (how === 'compositor') { + el.animate( + [{transform: 'translateY(0px)'}, {transform: 'translateY(560px)'}], + {duration: 1600, easing: 'linear'}, + ); + } else { + const start = performance.now(); + const step = (now: number) => { + const p = Math.min(1, (now - start) / 1600); + el.style.transform = `translateY(${560 * p}px)`; + if (p < 1) { + requestAnimationFrame(step); + } + }; + requestAnimationFrame(step); + } + }, driver); + const cast = await startScreencast(page); + const compositor = await startCompositorTrace(page); + await page.waitForTimeout(200); + const window = await blockMainThread(page, 700); + await page.waitForTimeout(200); + const presented = await compositor.stop(); + const tracked = await trackMarker(page, await cast.stop()); + return {window, tracked, presented}; + }; + + const moving = await run('compositor'); + expect(moving.presented.length).toBeGreaterThan(0); + // The screencast as a loaded machine delivers it: four frames in a row + // skipped mid-block, which the compositor still presented. + const mid = moving.tracked.findIndex(f => f.t > moving.window.from + 350); + const skipped = moving.tracked.filter((_, i) => i < mid || i >= mid + 4); + const alone = busyWindowProof(skipped, moving.window, {axis: 'y'}); + expect(alone.verdict.failures.join('\n'), alone.summary).toMatch( + /longest stall/, + ); + const proof = busyWindowProof(skipped, moving.window, { + axis: 'y', + presented: moving.presented, + }); + testInfo.annotations.push({ + type: 'busy-main-thread compositor record', + description: proof.summary, + }); + expect(proof.verdict.failures, proof.summary).toEqual([]); + expect(proof.recorderSkipped).toBeGreaterThanOrEqual(4); + + // A rAF animation presents no change for the whole block: the record + // excuses nothing, whatever the compositor drew meanwhile. + const frozen = await run('raf'); + const still = busyWindowProof(frozen.tracked, frozen.window, { + axis: 'y', + presented: frozen.presented, + }); + testInfo.annotations.push({ + type: 'busy-main-thread rAF control, compositor record', + description: `${still.summary}; compositor frames inside the block: ${frozen.presented.filter(t => t > frozen.window.from && t < frozen.window.to).length}`, + }); + expect(still.verdict.pass).toBe(false); + expect(still.recorderSkipped).toBe(0); + expect(still.verdict.failures.join('\n')).toMatch(/longest stall/); + }); + + test('a block that starts during a just-started transition still lets the compositor advance it', async ({ + page, + }, testInfo) => { + // `during` blocks in the frame the transition has run 16 ms. In WebKit + // the transition reaches the compositor in that frame's rendering update, + // so a loop inside the rAF callback froze it (2 of 29 frames moved). + // Linear and longer than the block, so every frame of the block moves two + // position steps or more and the transition is still running when it + // ends. The cast shows the box at rest first, so a transition that reaches + // the screen after the block began is judged from there (onScreenFromMs). + await busyFixture(page); + const box = page.locator('#box'); + await markElement(box, {mode: 'outline'}); + const cast = await startScreencast(page); + await expect.poll(() => cast.frameCount()).toBeGreaterThan(0); + await box.evaluate(el => { + el.style.transition = 'transform 1600ms linear'; + el.getBoundingClientRect(); + el.style.transform = 'translateY(560px)'; + }); + const window = await blockMainThread(page, 700, { + during: box, + minProgressMs: 16, + }); + await waitForRest(box); + const tracked = await trackMarker(page, await cast.stop()); + const proof = busyWindowProof(tracked, window, {axis: 'y'}); + testInfo.annotations.push({ + type: 'busy-main-thread transition', + description: proof.summary, + }); + expect(proof.verdict.failures, proof.summary).toEqual([]); + expect(proof.monotonic).toBe(true); + }); + + test('a block never starts on an animation that is not on the compositor yet', async ({ + page, + }, testInfo) => { + // An animation created in the frame the helper looks is still pending (not + // committed to the compositor). A block that started on it then froze it + // in Chromium: no presented frame moved. + await busyFixture(page); + const box = page.locator('#box'); + await markElement(box, {mode: 'outline'}); + await box.evaluate(el => { + el.style.willChange = 'transform'; + }); + const cast = await startScreencast(page); + // A rAF loop registered before the helper's tick runs ahead of it in every + // frame; on its 12th frame it creates the animation, and the helper's tick + // looks in that same frame. + await box.evaluate(el => { + let n = 0; + const loop = () => { + n += 1; + if (n === 12) { + el.animate( + [{transform: 'translateY(0px)'}, {transform: 'translateY(560px)'}], + {duration: 1600, easing: 'linear'}, + ); + return; + } + requestAnimationFrame(loop); + }; + requestAnimationFrame(loop); + }); + const window = await blockMainThread(page, 700, { + during: box, + minProgressMs: 0, + }); + await waitForRest(box); + const tracked = await trackMarker(page, await cast.stop()); + const proof = busyWindowProof(tracked, window, {axis: 'y'}); + testInfo.annotations.push({ + type: 'busy-main-thread pending animation', + description: proof.summary, + }); + expect(proof.verdict.failures, proof.summary).toEqual([]); + expect(proof.monotonic).toBe(true); + }); + + test('in the WebKit container, compiled shaders outlive the run', async ({ + browser, + }, testInfo) => { + // The official Playwright image keeps its browsers here. + test.skip( + testInfo.project.name !== 'webkit' || + process.env.PLAYWRIGHT_BROWSERS_PATH !== '/ms-playwright', + 'runs inside webkit-container.mjs', + ); + // A cache inside the container dies with it: every run then compiled each + // shader again, 450–700 ms in the first frame of a blurred layer. + const dir = process.env.MESA_SHADER_CACHE_DIR; + expect(dir, 'MESA_SHADER_CACHE_DIR names the host-kept cache').toBeTruthy(); + // Written on the host by the script before the container starts. + expect( + fs.readFileSync(path.join(dir ?? '', 'ASTRYX-SHADER-CACHE'), 'utf8'), + ).toContain('playwright'); + // Mesa writes what it compiles there once a page draws a blurred layer. + // Earlier runs have filled the cache already, so this run's browser gets + // an empty directory beside them, in the same host-kept mount, and the + // test watches its own writes arrive. + const fresh = fs.mkdtempSync(path.join(dir ?? '', 'self-test-')); + try { + const own = await browser.browserType().launch({ + env: {...process.env, MESA_SHADER_CACHE_DIR: fresh}, + }); + try { + const page = await own.newPage(); + await page.setContent( + '
', + ); + await page.evaluate( + () => + document + .getElementById('glass') + ?.animate([{scale: '1'}, {scale: '0.9'}], {duration: 200}) + .finished, + ); + } finally { + await own.close(); + } + expect(fs.readdirSync(fresh, {recursive: true})).not.toEqual([]); + } finally { + fs.rmSync(fresh, {recursive: true, force: true}); + } + }); + + test('rect sampling reads one rect per animation frame while the main thread is free', async ({ + page, + browserName, + }) => { + await fixture(page); + const box = page.locator('#box'); + await box.evaluate(el => { + el.animate( + [{transform: 'translateX(0px)'}, {transform: 'translateX(200px)'}], + {duration: 600, easing: 'linear'}, + ); + }); + const samples = await sampleRects(box, 400); + const xs = samples.map(s => s.box?.x ?? NaN); + const gaps = samples + .slice(1) + .map((s, i) => s.t - samples[i].t) + .sort((a, b) => a - b); + const cadence = gaps[Math.floor(gaps.length / 2)]; + expect(cadence).toBeLessThan(34); + expect(samples.length).toBeGreaterThanOrEqual(10); + if (browserName === 'chromium') { + // One sample per presented frame at 60 Hz. (Headless WebKit's animation + // frames are irregular, so only the cadence is checked there.) + expect(samples.length).toBeGreaterThanOrEqual(20); + } + expect(xs.every((x, i) => i === 0 || x >= xs[i - 1])).toBe(true); + expect(xs.at(-1) ?? 0).toBeGreaterThan(xs[0] + 80); + }); + + test('the trace counts no Layout for a transform animation and one per frame for `top`', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await fixture(page); + const box = page.locator('#box'); + // Count the animation's steady middle: starting and ending it may lay out once each. + const animate = async (property: 'transform' | 'top') => { + let started = 0; + const trace = await traceRendering(page, async () => { + started = await box.evaluate((el, prop) => { + const keyframes = + prop === 'transform' + ? [ + {transform: 'translateY(0px)'}, + {transform: 'translateY(200px)'}, + ] + : [{top: '360px'}, {top: '560px'}]; + el.animate(keyframes, {duration: 600}); + return performance.timeOrigin + performance.now(); + }, property); + await page.waitForTimeout(700); + }); + return countBetween(trace, started + 100, started + 500); + }; + const transform = await animate('transform'); + const top = await animate('top'); + expect(transform.Layout ?? 0).toBe(0); + expect(transform.Paint ?? 0).toBe(0); + // ~24 frames in 400 ms: one layout per frame. + expect(top.Layout ?? 0).toBeGreaterThan(18); + }); + + test('with invalidations, a trace tells a compositor animation from one the compositor cannot run', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await fixture(page); + const box = page.locator('#box'); + const animate = async (property: 'transform' | 'top') => { + let started = 0; + const trace = await traceRendering( + page, + async () => { + started = await box.evaluate((el, prop) => { + el.animate( + prop === 'transform' + ? [ + {transform: 'translateY(0px)'}, + {transform: 'translateY(200px)'}, + ] + : [{top: '360px'}, {top: '560px'}], + {duration: 600}, + ); + return performance.timeOrigin + performance.now(); + }, property); + await page.waitForTimeout(700); + }, + {invalidations: true}, + ); + return {trace, started}; + }; + const transform = await animate('transform'); + expect(transform.trace.animations).toEqual([ + expect.objectContaining({composited: true}), + ]); + expect( + transform.trace.styleInvalidations?.some( + inv => inv.reason === 'Animation', + ), + ).toBe(true); + const top = await animate('top'); + expect(top.trace.animations).toEqual([ + expect.objectContaining({composited: false}), + ]); + // Its per-frame layout is the page's: none of it is left out. + expect( + countBetween(top.trace, top.started + 100, top.started + 500, { + skipCompositorAnimationUpdates: true, + }).Layout ?? 0, + ).toBeGreaterThan(18); + }); + + test("the trace counts no Layout from the harness's own animation recorder, which stands down while it runs", async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + const pop = page.locator('#pop'); + // The recorder runs, as in any spec that waited for an animation first. + await waitForRest(pop); + const watch = await watchAnimations(pop); + const middle = async (askEveryFrame: boolean) => { + let started = 0; + const trace = await traceRendering(page, async () => { + started = await pop.evaluate((el, every) => { + const w = window as unknown as {stop?: boolean}; + w.stop = false; + if (every) { + const ask = () => { + if (!w.stop) { + requestAnimationFrame(ask); + } + }; + requestAnimationFrame(ask); + } + el.animate( + [ + {transform: 'translateY(0px)', opacity: 1}, + {transform: 'translateY(100px)', opacity: 0.5}, + ], + {duration: 600}, + ); + return performance.timeOrigin + performance.now(); + }, askEveryFrame); + await page.waitForTimeout(700); + await page.evaluate(() => { + (window as unknown as {stop?: boolean}).stop = true; + }); + }); + // The steady middle: starting and ending it may lay out once each. + return countBetween(trace, started + 100, started + 500); + }; + expect((await middle(false)).Layout ?? 0).toBe(0); + // Control: a page that asks for a frame every frame lays it out in each. + expect((await middle(true)).Layout ?? 0).toBeGreaterThan(18); + // Nothing the traces ran went unrecorded. + const started = await watch.started(); + expect(started.map(a => a.durationMs)).toEqual([600, 600]); + }); + + test('a waitForRest awaited inside a traced body stands down too, so the trace counts no Layout from it', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + const pop = page.locator('#pop'); + await waitForRest(pop); + let started = 0; + const trace = await traceRendering(page, async () => { + started = await pop.evaluate(el => { + el.animate( + [ + {transform: 'translateY(0px)', opacity: 1}, + {transform: 'translateY(100px)', opacity: 0.5}, + ], + {duration: 600}, + ); + return performance.timeOrigin + performance.now(); + }); + // A per-frame wait here would make every frame a main-thread frame. + await waitForRest(pop); + }); + expect(countBetween(trace, started + 100, started + 500).Layout ?? 0).toBe( + 0, + ); + // It still waited for the curve to end. + expect(trace.window.to - started).toBeGreaterThanOrEqual(590); + }); + + test('a waitForAnimation or watch.started() awaited inside a traced body stands down too, so the trace counts no Layout from it', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + const pop = page.locator('#pop'); + await waitForRest(pop); + const watch = await watchAnimations(pop); + let started = 0; + let waited: {durationMs: number}[] = []; + let watched: {durationMs: number}[] = []; + const trace = await traceRendering(page, async () => { + started = await pop.evaluate(el => { + el.animate( + [ + {transform: 'translateY(0px)', opacity: 1}, + {transform: 'translateY(100px)', opacity: 0.5}, + ], + {duration: 600}, + ); + return performance.timeOrigin + performance.now(); + }); + // Both poll until 450 ms of the curve has played, across the steady + // middle; a read of the page's animations each time would lay it out. + waited = await waitForAnimation(pop, {minProgressMs: 450}); + watched = await watch.started({minProgressMs: 450}); + await page.waitForTimeout(200); + }); + expect(countBetween(trace, started + 100, started + 500).Layout ?? 0).toBe( + 0, + ); + // Each still answered with the animation once 450 ms of it had played. + expect(waited.map(a => a.durationMs)).toEqual([600]); + expect(watched.map(a => a.durationMs)).toEqual([600]); + expect(trace.window.to - started).toBeGreaterThanOrEqual(590); + }); + + test('a waitForRest awaited inside a traced body waits for an animation the action starts two frames later', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + const pop = page.locator('#pop'); + await waitForRest(pop); + const trace = await traceRendering(page, async () => { + // The action starts the animation two frames later, as a component's + // effect often does. + await pop.evaluate(el => { + requestAnimationFrame(() => + requestAnimationFrame(() => { + (window as unknown as {__started: number}).__started = + performance.timeOrigin + performance.now(); + el.animate( + [ + {transform: 'translateY(0px)'}, + {transform: 'translateY(100px)'}, + ], + {duration: 600}, + ); + }), + ); + }); + await waitForRest(pop); + }); + const started = await page.evaluate( + () => (window as unknown as {__started?: number}).__started ?? null, + ); + // The traced window holds the whole animation. + expect(started).not.toBeNull(); + expect(trace.window.to - (started as number)).toBeGreaterThanOrEqual(590); + }); + + test('a waitForRest awaited inside a traced body waits for a run going backward to its end, and no longer', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + const pop = page.locator('#pop'); + await waitForRest(pop); + // How long a traced waitForRest holds after a 600 ms move starts. + const traced = async (reverse: boolean, endDelay = 0) => { + let started = 0; + const trace = await traceRendering(page, async () => { + started = await pop.evaluate( + (el, {reverse, endDelay}) => { + const run = el.animate( + [ + {transform: 'translateY(0px)'}, + {transform: 'translateY(100px)'}, + ], + {duration: 600, endDelay}, + ); + if (reverse) { + // Its current time falls from its end time to 0. + run.reverse(); + } + return performance.timeOrigin + performance.now(); + }, + {reverse, endDelay}, + ); + await waitForRest(pop); + }); + await waitForRest(pop); + return trace.window.to - started; + }; + // Reversed with a 200 ms end delay: the move plays from 200 to 800 ms. + expect(await traced(true, 200)).toBeGreaterThanOrEqual(790); + // A reversed run is waited for as long as the same run forward, not + // twice as long. + const forward = await traced(false); + const backward = await traced(true); + expect(backward).toBeGreaterThanOrEqual(590); + expect(backward).toBeLessThan(forward * 1.5); + }); + + test('a waitForRest awaited inside a traced body runs on the real timers, so a frozen timer gate cannot hold it', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + const pop = page.locator('#pop'); + await waitForRest(pop); + await installTimerGate(page); + await freezeTimers(page); + let outcome = ''; + await traceRendering(page, async () => { + await pop.evaluate(el => { + el.animate( + [{transform: 'translateY(0px)'}, {transform: 'translateY(100px)'}], + {duration: 300}, + ); + }); + // Held by the gate, the wait would neither resolve nor reach its + // deadline: the race reads that as "held". + outcome = await Promise.race([ + waitForRest(pop, {timeout: 2000}).then( + () => 'rested', + () => 'rejected', + ), + new Promise(resolve => setTimeout(() => resolve('held'), 4000)), + ]); + }); + await thawTimers(page); + expect(outcome).toBe('rested'); + }); + + test('inside a trace, waitForRest rests beside a scroll-timeline animation', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await fixture(page); + const scroller = page.locator('#scroller'); + await waitForRest(scroller); + let outcome = ''; + await traceRendering(page, async () => { + // A row driven by its scroller's timeline: it moves only on scroll. + await scroller.evaluate(el => { + const row = el.firstElementChild as HTMLElement; + row.animate([{opacity: 0.5}, {opacity: 1}], { + timeline: new ScrollTimeline({source: el}), + }); + }); + outcome = await waitForRest(scroller, {timeout: 2000}).then( + () => 'rested', + (error: Error) => error.message, + ); + }); + expect(outcome).toBe('rested'); + }); + + test('a CSS transition and animation that start and end inside a trace are reported, and lay out nothing in between', async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + await page.route('http://anchored.test/', route => + route.fulfill({contentType: 'text/html', body: ANCHORED}), + ); + await page.goto('http://anchored.test/'); + await page.addStyleTag({ + content: + '@keyframes harness-fade { from { opacity: 1 } to { opacity: 0.6 } }', + }); + const pop = page.locator('#pop'); + // The recorder runs, and a watch is taken before the trace. + await waitForRest(pop); + const watch = await watchAnimations(pop); + let started = 0; + const trace = await traceRendering(page, async () => { + started = await pop.evaluate(el => { + const pop = el as HTMLElement; + pop.style.transition = 'transform 400ms linear'; + void pop.offsetWidth; + pop.style.transform = 'translateY(100px)'; + pop.style.animation = 'harness-fade 400ms linear'; + return performance.timeOrigin + performance.now(); + }); + await page.waitForTimeout(600); + }); + // Its reads at the two starts fall before the steady middle. + expect(countBetween(trace, started + 100, started + 300).Layout ?? 0).toBe( + 0, + ); + const ended = await watch.started({timeout: 1_000}); + expect(ended.map(a => a.kind).sort()).toEqual([ + 'CSSAnimation', + 'CSSTransition', + ]); + expect(ended.every(a => a.finishedAt != null)).toBe(true); + }); + + test('the long-task log fails closed when it never ran on the document', async ({ + page, + }) => { + // No installLongTaskLog before navigating: an empty answer would read as + // "no long task", so it throws instead. + await fixture(page); + await expect(readLongTasks(page)).rejects.toThrow( + /not running on this document/, + ); + }); + + test("the long-task log records the page's own long task but not a DevTools evaluate, which the trace reports apart", async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'the Long Tasks API and rendering traces are Chromium-only', + ); + await installLongTaskLog(page); + await fixture(page); + // The page's own task: a timer that spins 120 ms. + const own = await page.evaluate( + () => + new Promise<{from: number; to: number}>(resolve => { + setTimeout(() => { + const from = performance.timeOrigin + performance.now(); + const end = performance.now() + 120; + while (performance.now() < end) { + // spin + } + resolve({from, to: performance.timeOrigin + performance.now()}); + }, 0); + }), + ); + await frames(page, 2); + const recorded = await readLongTasks(page, own); + expect(recorded).toHaveLength(1); + expect(recorded[0].durationMs).toBeGreaterThanOrEqual(110); + // A DevTools evaluate that spins 300 ms: the trace reports it apart from + // the page's long tasks, and the log never sees it. + let block = {from: 0, to: 0}; + const trace = await traceRendering(page, async () => { + block = await blockMainThread(page, 300); + }); + await frames(page, 2); + const inBlock = (t: {start: number}) => + t.start < block.to && t.start >= block.from - 20; + expect( + trace.devtoolsTasks.some(t => t.durationMs >= 290 && inBlock(t)), + ).toBe(true); + expect(trace.longTasks.filter(inBlock)).toEqual([]); + expect(await readLongTasks(page, block)).toEqual([]); + }); + + test("a harness read inside a trace is not the page's long task, while a test's own evaluate is, whether it calls the page directly or sets it off", async ({ + page, + browserName, + }) => { + test.skip( + browserName !== 'chromium', + 'rendering traces are Chromium-only (README: engine limits)', + ); + // Enough animated rows that describing their keyframes takes a DevTools + // task over 50 ms. + const rows = Array.from( + {length: 1200}, + (_, i) => `
row ${i}
`, + ).join(''); + await page.setContent( + `
${rows}
`, + ); + const slow = page.locator('#slow'); + await slow.evaluate(el => + el.addEventListener('click', () => { + const end = performance.now() + 60; + while (performance.now() < end) { + // spin + } + }), + ); + // Page code a test can call directly, as through a story's own API. + await page.evaluate(() => { + (window as unknown as {pageWork: (ms: number) => void}).pageWork = ( + ms: number, + ) => { + const end = performance.now() + ms; + while (performance.now() < end) { + // spin + } + }; + }); + await frames(page, 3); + const now = () => + page.evaluate(() => performance.timeOrigin + performance.now()); + const read = {from: 0, to: 0}; + const click = {from: 0, to: 0}; + const direct = {from: 0, to: 0}; + let timer = {from: 0, to: 0}; + const trace = await traceRendering(page, async () => { + read.from = await now(); + await waitForAnimation(page.locator('#list')); + read.to = await now(); + // On a slow machine each frame of 1,200 running rows is a long task of + // the page's own; the windows below hold only their own work. + await page.evaluate(() => document.getElementById('list')?.remove()); + await frames(page, 2); + // The page's own task: a timer that spins 60 ms. + timer = await page.evaluate( + () => + new Promise<{from: number; to: number}>(resolve => { + setTimeout(() => { + const from = performance.timeOrigin + performance.now(); + const end = performance.now() + 60; + while (performance.now() < end) { + // spin + } + resolve({from, to: performance.timeOrigin + performance.now()}); + }, 0); + }), + ); + // Page script run inside a DevTools evaluate: a 60 ms click handler. + click.from = await now(); + await slow.evaluate(el => (el as HTMLElement).click()); + click.to = await now(); + // Page code a test's evaluate calls directly: 60 ms of the page's work. + direct.from = await now(); + await page.evaluate(() => + (window as unknown as {pageWork: (ms: number) => void}).pageWork(60), + ); + direct.to = await now(); + }); + const within = (w: {from: number; to: number}) => (t: {start: number}) => + t.start >= w.from - 20 && t.start < w.to; + // The read itself is set apart. The rows' frames around it may be long + // tasks too, the page's own: they stay in longTasks. + expect(trace.devtoolsTasks.some(within(read))).toBe(true); + expect( + trace.longTasks.some(t => within(timer)(t) && t.durationMs >= 55), + ).toBe(true); + expect( + trace.longTasks.some(t => within(click)(t) && t.durationMs >= 55), + ).toBe(true); + expect( + trace.longTasks.some(t => within(direct)(t) && t.durationMs >= 55), + ).toBe(true); + expect(trace.devtoolsTasks.filter(within(direct))).toEqual([]); + }); +}); + test.describe('curve sampling', () => { test('a CSS transition samples onto its cubic-bezier to 0.05 px', async ({ page, @@ -961,6 +1904,91 @@ test.describe('animation state', () => { expect(started.map(a => a.durationMs)).toEqual([300]); }); + test('while a rendering trace runs the recorder reads only at CSS starts, and catches up after it', async ({ + page, + }) => { + await fixture(page); + const box = page.locator('#box'); + const watch = await watchAnimations(box); + // Counts the recorder's reads of the page's animations (each one flushes + // style): the whole document's, and one element's. Then flags a trace, as + // traceRendering does. + await page.evaluate(() => { + const w = window as unknown as { + __reads: number; + __elementReads: number; + __harnessRenderingTrace?: boolean; + }; + w.__reads = 0; + w.__elementReads = 0; + const read = document.getAnimations.bind(document); + document.getAnimations = () => { + w.__reads += 1; + return read(); + }; + const readElement = Element.prototype.getAnimations; + Element.prototype.getAnimations = function ( + this: Element, + ...args: Parameters + ) { + w.__elementReads += 1; + return readElement.apply(this, args); + }; + w.__harnessRenderingTrace = true; + }); + // During the trace: a CSS transition and a CSS animation that both end + // inside it, and a script animation still running after it. + await page.addStyleTag({ + content: + '@keyframes harness-fade { from { opacity: 1 } to { opacity: 0.6 } }', + }); + await box.evaluate(el => { + const box = el as HTMLElement; + box.style.transition = 'transform 120ms linear'; + void box.offsetWidth; + box.style.transform = 'translateX(100px)'; + box.style.animation = 'harness-fade 120ms linear'; + box.animate([{scale: '1'}, {scale: '0.9'}], {duration: 600}); + }); + await page.waitForTimeout(300); + const reads = () => + page.evaluate(() => (window as unknown as {__reads: number}).__reads); + // No frame loop: no document-wide read. One element read per CSS start + // event (transitionrun, transitionstart, animationstart), not per frame. + expect(await reads()).toBe(0); + expect( + await page.evaluate( + () => (window as unknown as {__elementReads: number}).__elementReads, + ), + ).toBeLessThanOrEqual(3); + // The trace ends: traceRendering clears the flag and resumes the recorder, + // which reads again, every frame. + await page.evaluate(() => { + const w = window as unknown as { + __harnessRenderingTrace?: boolean; + __harnessAnimations: {resume: () => void}; + }; + w.__harnessRenderingTrace = false; + w.__harnessAnimations.resume(); + }); + await frames(page, 3); + expect(await reads()).toBeGreaterThan(2); + // All three are reported, the two CSS ones that ended inside the trace + // with the time they finished. + await waitForRest(box); + const started = await watch.started(); + expect(started.map(a => a.kind).sort()).toEqual([ + 'Animation', + 'CSSAnimation', + 'CSSTransition', + ]); + expect( + started + .filter(a => a.kind !== 'Animation') + .map(a => a.finishedAt != null), + ).toEqual([true, true]); + }); + test('a wait answers with the animation the action started, not one that finished before it', async ({ page, }) => { @@ -1025,6 +2053,28 @@ test.describe('animation state', () => { await box.evaluate(el => el.getAnimations().forEach(a => a.finish())); }); + test('inside a rendering trace too, a watch taken right after a style change does not report that change', async ({ + page, + browserName, + }) => { + test.skip(browserName !== 'chromium', 'rendering traces are Chromium-only'); + await fixture(page); + const box = page.locator('#box'); + await waitForRest(box); + await traceRendering(page, async () => { + // The step: a transition the next style read creates. + await box.evaluate(el => { + el.style.transition = 'opacity 300ms linear'; + el.style.opacity = '0.5'; + }); + const watch = await watchAnimations(box); + await expect(watch.started({timeout: 200})).rejects.toThrow( + /waitForAnimation/, + ); + }); + await box.evaluate(el => el.getAnimations().forEach(a => a.finish())); + }); + test('an exit whose element the page removes at its end is still reported', async ({ page, }) => { @@ -1429,6 +2479,34 @@ test.describe('storyboards', {tag: '@storyboard'}, () => { } }); + test("the harness's own waits run on the real timers: a frozen timer gate holds neither blockMainThread's block nor sampleRects", async ({ + page, + }) => { + await fixture(page); + await installTimerGate(page); + const box = page.locator('#box'); + await box.evaluate(el => { + el.animate( + [{transform: 'translateX(0px)'}, {transform: 'translateX(200px)'}], + {duration: 1_500, easing: 'linear'}, + ); + }); + await freezeTimers(page); + // Settled, or still held after 5 s. + const within = (work: Promise) => + Promise.race([ + work.then(() => 'settled'), + new Promise(resolve => + setTimeout(() => resolve('held'), 5_000), + ), + ]); + expect( + await within(blockMainThread(page, 100, {during: box, timeout: 2_000})), + ).toBe('settled'); + expect(await within(sampleRects(box, 200))).toBe('settled'); + await thawTimers(page); + }); + test('the timer gate holds a component timer until the filmstrip is done', async ({ page, }, testInfo) => { @@ -1614,4 +2692,58 @@ test.describe('storyboards', {tag: '@storyboard'}, () => { expect(state).toMatchObject({timer: false, frame: false}); expect(state.heldFor).toBeGreaterThanOrEqual(140); }); + + test('a cast filmstrip keeps exactly the presented frames of its window, labelled from its zero', async ({ + page, + }, testInfo) => { + await fixture(page); + const box = page.locator('#box'); + // JPEG frames (WebKit's are always JPEG) take the conversion path. + const cast = await startScreencast(page, {format: 'jpeg'}); + await box.evaluate(el => + el.animate( + [{transform: 'translateX(0px)'}, {transform: 'translateX(200px)'}], + {duration: 600}, + ), + ); + await page.waitForTimeout(500); + const presented = await cast.stop(); + expect(presented.length).toBeGreaterThan(8); + // A window of the middle frames, zeroed on one of them. + const zero = presented[2].t; + const from = presented[3].t; + const to = presented[presented.length - 3].t; + const inside = presented.filter(f => f.t >= from && f.t <= to); + const seen: number[] = []; + const film = await castStoryboard(page, presented, { + name: 'harness-self-test-cast', + zero, + from, + to, + data: t => { + seen.push(t); + return {t}; + }, + }); + expect(film.frames.map(f => f.t)).toEqual(inside.map(f => f.t - zero)); + expect(film.frames.map(f => f.label)).toEqual( + inside.map(f => `t=${(f.t - zero).toFixed(1)} ms`), + ); + expect(seen).toEqual(inside.map(f => f.t)); + // Every cell is a PNG, whatever the screencast delivered. + for (const frame of film.frames) { + expect([...frame.png.subarray(0, 4)]).toEqual([0x89, 0x50, 0x4e, 0x47]); + } + const files = await film.write(testInfo); + expect(files['sheet.png']).toMatch(/sheet\.png$/); + // A window with no presented frame in it films nothing. + const empty = await castStoryboard(page, presented, { + name: 'harness-self-test-cast-empty', + zero, + from: to + 1, + to: to + 2, + }); + expect(empty.frames).toEqual([]); + await expect(empty.write(testInfo)).rejects.toThrow(/no frames/); + }); }); diff --git a/internal/interaction-harness/src/index.ts b/internal/interaction-harness/src/index.ts index 537bfc4d4beca..7a45ff45dfe41 100644 --- a/internal/interaction-harness/src/index.ts +++ b/internal/interaction-harness/src/index.ts @@ -12,10 +12,13 @@ * SYNC: When a module is added, export it here and describe it in README.md. */ +export * from './busy'; export * from './curves'; +export * from './frames'; export * from './math'; export * from './output'; export * from './scripts'; export * from './story'; export * from './storyboard'; export * from './touch'; +export * from './trace'; diff --git a/internal/interaction-harness/src/story.ts b/internal/interaction-harness/src/story.ts index 598f75d852cfe..cb57d59b50be2 100644 --- a/internal/interaction-harness/src/story.ts +++ b/internal/interaction-harness/src/story.ts @@ -6,7 +6,8 @@ * static server over a built Storybook * @output `phone` (the touch-phone browser context every interaction proof * runs in), `withStorybook` (serve the built Storybook for a spec file), and - * `openStory` (load one story and wait until it has rendered). + * `openStory` (load one story, with Storybook's highlight module off, and + * wait until it has rendered). * @position Stories are the reproduction path, as for every other browser * check in this repository: a scenario used for verification is checked in, * not built in a one-off page. @@ -59,13 +60,47 @@ export function withStorybook(test: TestType): () => string { }; } -/** Loads a story in the page and waits for its first render, its fonts and two frames. */ +/** Pages whose Storybook highlight module `openStory` turned off. */ +const highlightOff = new WeakSet(); + +export interface OpenStoryOptions { + /** + * Keeps Storybook's highlight module on. It is off by default: when on, it + * observes `#storybook-root` and, on every insertion, reads the computed + * style of every element on the page inside the inserting task, so a proof + * would measure Storybook as well as the component. + */ + readonly storybookHighlight?: boolean; +} + +/** + * Loads a story in the page and waits for its first render, its fonts and two + * frames. Storybook's highlight module is off (see `OpenStoryOptions`), and + * that is checked: its root element must be absent once the story renders. + */ export async function openStory( page: Page, origin: string, storyId: string, args?: Readonly>, + {storybookHighlight = false}: OpenStoryOptions = {}, ): Promise { + if (storybookHighlight) { + if (highlightOff.has(page)) { + throw new Error( + "openStory: this page already turned Storybook's highlight module off; open the story in a new page to keep it on", + ); + } + } else if (!highlightOff.has(page)) { + highlightOff.add(page); + // Storybook's highlight module returns at once when this is set before + // its preview runs. + await page.addInitScript(() => { + ( + globalThis as unknown as {__STORYBOOK_HIGHLIGHT_INITIALIZED?: boolean} + ).__STORYBOOK_HIGHLIGHT_INITIALIZED = true; + }); + } const params = new URLSearchParams({id: storyId, viewMode: 'story'}); if (args != null) { params.set( @@ -86,6 +121,14 @@ export async function openStory( requestAnimationFrame(() => requestAnimationFrame(() => resolve())), ); }); + if ( + !storybookHighlight && + (await page.locator('#storybook-highlights-root').count()) > 0 + ) { + throw new Error( + "openStory: Storybook's highlight module is on (#storybook-highlights-root exists), so every insertion would also read the style of every element on the page; this Storybook may no longer read __STORYBOOK_HIGHLIGHT_INITIALIZED", + ); + } } /** Resolves after `count` animation frames have been presented in the page. */ @@ -110,8 +153,9 @@ export async function frames(page: Page, count = 2): Promise { // A held callback is queued under its timer or frame id, so the page's own // clearTimeout and cancelAnimationFrame still cancel it while frozen; a held -// frame callback gets the time it actually runs at. `frame` stays the real -// requestAnimationFrame, for the harness's own waits. +// frame callback gets the time it actually runs at. `frame` and `timeout` +// stay the real requestAnimationFrame and setTimeout, for the harness's own +// waits. const TIMER_GATE = `(() => { if (window.__harnessTimerGate) return; const realTimeout = window.setTimeout.bind(window); @@ -119,7 +163,7 @@ const TIMER_GATE = `(() => { const realInterval = window.setInterval.bind(window); const realFrame = window.requestAnimationFrame.bind(window); const realCancelFrame = window.cancelAnimationFrame.bind(window); - const gate = {frozen: false, queue: [], frame: realFrame}; + const gate = {frozen: false, queue: [], frame: realFrame, timeout: realTimeout}; window.__harnessTimerGate = gate; const drop = key => { gate.queue = gate.queue.filter(entry => entry.key !== key); }; window.setTimeout = (fn, ms, ...args) => { diff --git a/internal/interaction-harness/src/storyboard.ts b/internal/interaction-harness/src/storyboard.ts index 2dc22fdc8cf04..a49207c4f81c4 100644 --- a/internal/interaction-harness/src/storyboard.ts +++ b/internal/interaction-harness/src/storyboard.ts @@ -336,7 +336,8 @@ export interface TouchStoryboardOptions extends StoryboardOptions { * photograph per event, about 100 ms between moves instead of the script's * 16.7. Its release velocity is that much lower, so a flick that dismisses * when played can settle back when filmed: a storyboard cannot show such a - * gesture; record it in real time instead. + * gesture; record it in real time instead (`startScreencast`, + * `castStoryboard`). */ export async function touchStoryboard( page: Page, @@ -364,3 +365,65 @@ export async function touchStoryboard( }); return storyboard; } + +/** + * A filmstrip of screencast frames (real presented frames, e.g. the frames of + * a busy-main-thread window), labelled with their time relative to `zero`. + * Evidence for what the compositor presented, not a deterministic storyboard. + */ +export async function castStoryboard( + page: Page, + frames: readonly { + readonly t: number; + readonly data: string; + readonly format: 'png' | 'jpeg'; + }[], + // A cast is already the screen's frames: no clip is applied to them. + options: Omit & { + readonly zero: number; + readonly from?: number; + readonly to?: number; + readonly data?: (t: number) => Readonly>; + }, +): Promise { + const storyboard = new Storyboard(page, options); + for (const frame of frames) { + if (options.from != null && frame.t < options.from) { + continue; + } + if (options.to != null && frame.t > options.to) { + continue; + } + const png = + frame.format === 'png' + ? Buffer.from(frame.data, 'base64') + : await toPng(page, frame.data); + const t = frame.t - options.zero; + storyboard.frames.push({ + label: `t=${t.toFixed(1)} ms`, + t, + data: options.data?.(frame.t) ?? {}, + png, + }); + } + return storyboard; +} + +async function toPng(page: Page, jpegBase64: string): Promise { + const scratch = await page.context().newPage(); + try { + const url = await scratch.evaluate(async data => { + const bitmap = await createImageBitmap( + await (await fetch(`data:image/jpeg;base64,${data}`)).blob(), + ); + const canvas = document.createElement('canvas'); + canvas.width = bitmap.width; + canvas.height = bitmap.height; + canvas.getContext('2d')?.drawImage(bitmap, 0, 0); + return canvas.toDataURL('image/png'); + }, jpegBase64); + return Buffer.from(url.slice(url.indexOf(',') + 1), 'base64'); + } finally { + await scratch.close(); + } +} diff --git a/internal/interaction-harness/src/storybook.interaction.browser.spec.ts b/internal/interaction-harness/src/storybook.interaction.browser.spec.ts new file mode 100644 index 0000000000000..a711feb62cb84 --- /dev/null +++ b/internal/interaction-harness/src/storybook.interaction.browser.spec.ts @@ -0,0 +1,104 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file storybook.interaction.browser.spec.ts + * @input The built Storybook (`withStorybook`) and one of its stories + * @output `openStory` turns Storybook's highlight module off, so an insertion + * in a story carries no `getComputedStyle` scan of the page; with the module + * on (the control), every insertion carries one. Both engines; Chromium's + * trace also counts the style recalculations the scan forces + * @position Self-test for story.ts; it needs the built Storybook, as every + * component proof does + */ + +import {expect, test, type Page} from '@playwright/test'; +import {openStory, withStorybook} from './story'; +import {countBetween, traceRendering} from './trace'; + +const storybook = withStorybook(test); + +/** Counts the page's `getComputedStyle` calls, from before Storybook loads. */ +function countStyleReads(): void { + const w = window as unknown as {__styleReads: number}; + w.__styleReads = 0; + const read = window.getComputedStyle.bind(window); + window.getComputedStyle = ((element: Element, pseudo?: string | null) => { + w.__styleReads += 1; + return read(element, pseudo); + }) as typeof window.getComputedStyle; +} + +/** + * Inserts an exit copy of the story's first element into `#storybook-root`, + * as an exit animation's copy is, lets the insertion's mutation microtasks run, + * and reports what ran between its marks. + */ +async function insertCopy(page: Page) { + return page.evaluate(async () => { + const w = window as unknown as {__styleReads: number}; + const root = document.getElementById('storybook-root') as HTMLElement; + const reads = w.__styleReads; + const from = + performance.timeOrigin + performance.mark('copy:start').startTime; + const copy = (root.firstElementChild as HTMLElement).cloneNode( + true, + ) as HTMLElement; + copy.setAttribute('aria-hidden', 'true'); + root.appendChild(copy); + // A MutationObserver's callback is a microtask the insertion queued: + // these run after it. + await Promise.resolve(); + await Promise.resolve(); + const to = performance.timeOrigin + performance.mark('copy:end').startTime; + const scanned = w.__styleReads - reads; + const elements = document.body.querySelectorAll('*').length; + copy.remove(); + return {from, to, scanned, elements}; + }); +} + +test("openStory turns Storybook's highlight module off: an insertion in a story carries no getComputedStyle scan of the page", async ({ + page, + browserName, +}) => { + // The insertion's reads in every engine, and in Chromium (whose trace the + // harness reads) the style recalculations between its marks. + const measure = async (p: Page) => { + if (browserName !== 'chromium') { + return {copy: await insertCopy(p), styleRecalc: null}; + } + let copy = {from: 0, to: 0, scanned: 0, elements: 0}; + const trace = await traceRendering(p, async () => { + copy = await insertCopy(p); + }); + return { + copy, + styleRecalc: + countBetween(trace, copy.from, copy.to).UpdateLayoutTree ?? 0, + }; + }; + // The harness default. + await page.addInitScript(countStyleReads); + await openStory(page, storybook(), 'core-button--primary'); + expect(await page.locator('#storybook-highlights-root').count()).toBe(0); + const off = await measure(page); + expect(off.copy.scanned).toBe(0); + if (off.styleRecalc != null) { + expect(off.styleRecalc).toBe(0); + } + + // Control: Storybook's module kept on reads the style of every element on + // the page inside the inserting task. + const control = await page.context().newPage(); + await control.addInitScript(countStyleReads); + await openStory(control, storybook(), 'core-button--primary', undefined, { + storybookHighlight: true, + }); + expect(await control.locator('#storybook-highlights-root').count()).toBe(1); + const on = await measure(control); + expect(on.copy.scanned).toBeGreaterThanOrEqual(on.copy.elements); + if (on.styleRecalc != null) { + expect(on.styleRecalc).toBeGreaterThan(0); + } + await control.close(); +}); diff --git a/internal/interaction-harness/src/trace.popover.fixture.ts b/internal/interaction-harness/src/trace.popover.fixture.ts new file mode 100644 index 0000000000000..7023d8020a1c8 --- /dev/null +++ b/internal/interaction-harness/src/trace.popover.fixture.ts @@ -0,0 +1,333 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file trace.popover.fixture.ts + * @input A rendering trace recorded with `{invalidations: true}` while a + * Popover presented under a touch on a loaded machine (Chromium) + * @output POPOVER_PRESENT_UNDER_LOAD: its Animation events, rendering events, + * style recalculations and script starts, ms from the present's start + * @position Fixture for trace.test.ts + * + * The popover layer is trace node 6; its present runs two compositor + * animations under the ids 0x25 and 0x26, and the dismissal's exit copy + * (node 59) gets the same ids once they end. In the present's window + * [150, 482] Chrome restyles the layer on its own (`Animation`), then its + * `::backdrop` (`Conditional ::backdrop`), with one Layout and Paint and no + * script since the previous pass. + */ + +export const POPOVER_PRESENT_UNDER_LOAD = { + window: [150, 482], + animationEvents: [ + { + name: 'Animation', + ph: 'b', + ts: -86600, + id2: { + local: '0x25', + }, + args: { + data: { + name: '', + nodeId: 6, + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'e', + ts: -72600, + id2: { + local: '0x25', + }, + args: { + data: {}, + }, + }, + { + name: 'Animation', + ph: 'b', + ts: -54100, + id2: { + local: '0x25', + }, + args: { + data: { + name: '', + nodeId: 6, + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'b', + ts: -52800, + id2: { + local: '0x26', + }, + args: { + data: { + name: '', + nodeId: 6, + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: -1900, + id2: { + local: '0x25', + }, + args: { + data: { + compositeFailed: 0, + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: -1900, + id2: { + local: '0x26', + }, + args: { + data: { + compositeFailed: 0, + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: 17400, + id2: { + local: '0x25', + }, + args: { + data: { + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: 17400, + id2: { + local: '0x26', + }, + args: { + data: { + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'e', + ts: 533600, + id2: { + local: '0x25', + }, + args: { + data: {}, + }, + }, + { + name: 'Animation', + ph: 'e', + ts: 537900, + id2: { + local: '0x26', + }, + args: { + data: {}, + }, + }, + { + name: 'Animation', + ph: 'b', + ts: 649200, + id2: { + local: '0x25', + }, + args: { + data: { + name: '', + nodeId: 59, + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'b', + ts: 650200, + id2: { + local: '0x26', + }, + args: { + data: { + name: '', + nodeId: 59, + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: 660900, + id2: { + local: '0x25', + }, + args: { + data: { + compositeFailed: 0, + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: 661000, + id2: { + local: '0x26', + }, + args: { + data: { + compositeFailed: 0, + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: 668300, + id2: { + local: '0x25', + }, + args: { + data: { + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'n', + ts: 668300, + id2: { + local: '0x26', + }, + args: { + data: { + state: 'running', + }, + }, + }, + { + name: 'Animation', + ph: 'e', + ts: 1202300, + id2: { + local: '0x25', + }, + args: { + data: {}, + }, + }, + { + name: 'Animation', + ph: 'e', + ts: 1202400, + id2: { + local: '0x26', + }, + args: { + data: {}, + }, + }, + ], + events: [ + { + name: 'UpdateLayoutTree', + t: 118.6, + }, + { + name: 'Layout', + t: 119.6, + }, + { + name: 'UpdateLayoutTree', + t: 120.1, + }, + { + name: 'Layout', + t: 126, + }, + { + name: 'UpdateLayoutTree', + t: 151, + }, + { + name: 'Layout', + t: 151.6, + }, + { + name: 'UpdateLayoutTree', + t: 159.3, + }, + { + name: 'Layout', + t: 159.9, + }, + { + name: 'PrePaint', + t: 160.4, + }, + { + name: 'Paint', + t: 160.4, + }, + { + name: 'Paint', + t: 160.5, + }, + { + name: 'Layerize', + t: 160.5, + }, + ], + styleInvalidations: [ + { + t: 118.6, + reason: 'Animation', + nodeId: 6, + }, + { + t: 120.1, + reason: 'Conditional ::backdrop', + nodeId: 6, + }, + { + t: 150.9, + reason: 'Animation', + nodeId: 6, + }, + { + t: 157.4, + reason: 'Conditional ::backdrop', + nodeId: 6, + }, + ], + scripts: [ + 3.4, 3.5, 3.6, 6.7, 6.7, 13.8, 13.9, 13.9, 13.9, 14.1, 14.2, 14.3, 14.3, 72, + 72, + ], +} as const; diff --git a/internal/interaction-harness/src/trace.test.ts b/internal/interaction-harness/src/trace.test.ts new file mode 100644 index 0000000000000..4b4cc6b4c24b3 --- /dev/null +++ b/internal/interaction-harness/src/trace.test.ts @@ -0,0 +1,188 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file trace.test.ts + * @input countBetween, traceAnimations, hand-built rendering traces and one + * recorded trace (trace.popover.fixture.ts) + * @output Tests which rendering passes countBetween leaves out with + * skipCompositorAnimationUpdates: only Chrome's own update for compositor + * animations, never work the page caused + * @position Unit tests for internal/interaction-harness/src/trace.ts + */ + +import {describe, expect, it} from 'vitest'; +import {POPOVER_PRESENT_UNDER_LOAD} from './trace.popover.fixture'; +import { + countBetween, + traceAnimations, + type RenderingTrace, + type TraceAnimation, +} from './trace'; + +const PASS = ['UpdateLayoutTree', 'Layout', 'PrePaint', 'Paint', 'Paint']; + +function trace( + passes: number[], + extra: Pick, +): RenderingTrace { + const events = passes.flatMap(t => + PASS.map((name, k) => ({name, t: t + k * 0.1})), + ); + return { + counts: {}, + layout: 0, + paint: 0, + styleRecalc: 0, + prePaint: 0, + durationMs: 500, + longTasks: [], + devtoolsTasks: [], + events, + window: {from: 0, to: 500}, + ...extra, + }; +} + +const COMPOSITED = [ + {nodeId: 7, composited: true}, + {nodeId: 10, composited: true}, +]; + +describe('countBetween with skipCompositorAnimationUpdates', () => { + it('leaves out a pass Chrome made on its own for compositor animations', () => { + const t = trace([4, 154], { + animations: COMPOSITED, + styleInvalidations: [ + {t: 1, reason: 'Inline CSS style declaration was mutated', nodeId: 7}, + {t: 153.7, reason: 'Animation', nodeId: 7}, + {t: 153.8, reason: 'Animation', nodeId: 10}, + ], + scripts: [0.5], + }); + expect(countBetween(t, 150, 400)).toMatchObject({Layout: 1, Paint: 2}); + expect( + countBetween(t, 150, 400, {skipCompositorAnimationUpdates: true}), + ).toEqual({}); + // The start, which the page's style writes caused, still counts. + expect( + countBetween(t, 0, 400, {skipCompositorAnimationUpdates: true}), + ).toMatchObject({Layout: 1}); + }); + + it('counts the pass when script ran since the previous one', () => { + const t = trace([4, 154], { + animations: COMPOSITED, + styleInvalidations: [{t: 153.7, reason: 'Animation', nodeId: 7}], + scripts: [150], + }); + expect( + countBetween(t, 150, 400, {skipCompositorAnimationUpdates: true}), + ).toMatchObject({Layout: 1}); + }); + + it('counts the pass when any recalculation has another reason', () => { + const t = trace([4, 154], { + animations: COMPOSITED, + styleInvalidations: [ + {t: 153.7, reason: 'Animation', nodeId: 7}, + { + t: 153.8, + reason: 'Inline CSS style declaration was mutated', + nodeId: 10, + }, + ], + scripts: [], + }); + expect( + countBetween(t, 150, 400, {skipCompositorAnimationUpdates: true}), + ).toMatchObject({Layout: 1}); + }); + + it('counts every pass of an animation the compositor cannot run', () => { + const t = trace([4, 21, 38, 154], { + animations: [{nodeId: 7, composited: false}], + styleInvalidations: [20, 37, 153].map(at => ({ + t: at, + reason: 'Animation', + nodeId: 7, + })), + scripts: [], + }); + expect( + countBetween(t, 15, 400, {skipCompositorAnimationUpdates: true}), + ).toMatchObject({Layout: 3}); + }); + + it('needs a trace recorded with invalidations', () => { + const t = trace([4], {}); + expect(() => + countBetween(t, 0, 400, {skipCompositorAnimationUpdates: true}), + ).toThrow(/invalidations: true/); + }); +}); + +describe('a recorded trace: a popover presenting on a loaded machine', () => { + const recorded = POPOVER_PRESENT_UNDER_LOAD; + const animations = traceAnimations(recorded.animationEvents, ts => ts / 1000); + const withAnimations = (list: readonly TraceAnimation[]): RenderingTrace => ({ + ...trace([], { + animations: list, + styleInvalidations: recorded.styleInvalidations, + scripts: recorded.scripts, + }), + events: recorded.events, + }); + const [from, to] = recorded.window; + + it('keeps one entry per animation when Chrome reuses an id for a later one', () => { + // The layer's present (node 6) and, under the same two ids, the exit copy + // the dismissal plays on (node 59). + expect(animations.filter(a => a.nodeId === 6 && a.composited).length).toBe( + 2, + ); + expect(animations.filter(a => a.nodeId === 59 && a.composited).length).toBe( + 2, + ); + for (const a of animations.filter(a => a.nodeId === 6 && a.composited)) { + expect(a.from).toBeLessThan(from); + expect(a.to).toBeGreaterThan(to); + } + }); + + it("leaves out Chrome's own update of the layer and of its ::backdrop", () => { + const t = withAnimations(animations); + expect(countBetween(t, from, to)).toMatchObject({Layout: 2, Paint: 2}); + expect( + countBetween(t, from, to, {skipCompositorAnimationUpdates: true}), + ).toEqual({}); + }); + + it('counts the passes when script ran before them', () => { + const t = { + ...withAnimations(animations), + scripts: [...recorded.scripts, 140], + }; + expect( + countBetween(t, from, to, {skipCompositorAnimationUpdates: true}), + ).toMatchObject({Layout: 2}); + }); + + it('counts them when the layer has no compositor animation at the time', () => { + const ended = animations.map(a => + a.nodeId === 6 ? {...a, to: Math.min(a.to ?? Infinity, 100)} : a, + ); + expect( + countBetween(withAnimations(ended), from, to, { + skipCompositorAnimationUpdates: true, + }), + ).toMatchObject({Layout: 2}); + const mainThread = animations.map(a => + a.nodeId === 6 ? {...a, composited: false} : a, + ); + expect( + countBetween(withAnimations(mainThread), from, to, { + skipCompositorAnimationUpdates: true, + }), + ).toMatchObject({Layout: 2}); + }); +}); diff --git a/internal/interaction-harness/src/trace.ts b/internal/interaction-harness/src/trace.ts new file mode 100644 index 0000000000000..50ab29d62f6ff --- /dev/null +++ b/internal/interaction-harness/src/trace.ts @@ -0,0 +1,639 @@ +// Copyright (c) Meta Platforms, Inc. and affiliates. + +/** + * @file trace.ts + * @input Uses a Playwright `Page` (Chromium: CDP `Tracing`) and the page's + * PerformanceObserver for long tasks + * @output `traceRendering` — counts of the main thread's rendering work + * (Layout, Paint, UpdateLayoutTree, PrePaint, …) between two marks — and + * `installLongTaskLog` / `readLongTasks`. + * @position The "no Layout/Paint during a transform/opacity animation" proof. + * A compositor animation costs the main thread nothing per frame; one that + * animates a layout property, or writes styles from JavaScript each frame, + * shows a Layout (and usually a Paint) per frame. Chromium only: WebKit + * exposes no comparable trace to Playwright. + * + * Counting is scoped to the renderer main thread that ran the page's own + * `performance.mark` calls, and to the time between the start and end marks, + * so other pages, the browser process and setup work are excluded. + * + * With `{invalidations: true}` the trace also records why each style + * recalculation happened, which elements animations ran on and whether they + * ran on the compositor, and when script ran. `countBetween` can then leave + * out the one rendering pass Chrome makes on its own for a compositor + * animation (its start time arriving from the compositor, late on a loaded + * machine): a pass whose style recalculations all have the reason + * `Animation`, on elements with an animation on the compositor at the time + * (one entry per animation, as Chrome reuses an animation's trace id once it + * is gone), with no script since the previous pass. A pseudo-element's + * `Conditional ::backdrop` restyle on such an element counts with the + * element's own, in that pass or the one before. Anything the page causes (a + * style write, a layout read, an animation the compositor cannot run) is + * still counted. + * + * SYNC: Keep RENDERING_EVENTS equal to the README's list. + */ + +import type {CDPSession, Page} from '@playwright/test'; + +/** + * The mark a harness function puts on its own page-side work + * (`console.timeStamp('harness-read')` at the start of the function it + * evaluates in the page), so a trace can tell the harness's reads from page + * code a test's own evaluate runs. + */ +export const HARNESS_READ = 'harness-read'; + +/** Trace events that run page script: a listener, a timer, a frame callback. */ +const PAGE_SCRIPT_EVENTS = new Set([ + 'EventDispatch', + 'FunctionCall', + 'TimerFire', + 'FireAnimationFrame', + 'FireIdleCallback', +]); + +/** Main-thread trace events that are rendering work, by their trace names. */ +export const RENDERING_EVENTS = [ + 'UpdateLayoutTree', // style recalculation + 'Layout', + 'PrePaint', + 'Paint', + 'Layerize', + 'UpdateLayer', + 'ScrollLayer', + 'HitTest', +] as const; + +export interface RenderingTrace { + /** Count per trace event name inside the window, on the page's main thread. */ + readonly counts: Readonly>; + /** Shorthand for the four that matter most. */ + readonly layout: number; + readonly paint: number; + readonly styleRecalc: number; + readonly prePaint: number; + /** Window length, ms. */ + readonly durationMs: number; + /** + * The page's own main-thread tasks longer than 50 ms inside the window (long + * tasks), epoch ms. A task that ran a test's own DevTools command (a + * `page.evaluate`) is one, whether it calls page code directly or sets it + * off; only the harness's own marked reads are in `devtoolsTasks`. + */ + readonly longTasks: readonly { + readonly start: number; + readonly durationMs: number; + }[]; + /** + * Main-thread tasks longer than 50 ms inside the window that ran a DevTools + * command the harness marked as its own read (`HARNESS_READ`) and no page + * script, epoch ms: `waitForAnimation` describing every animation's + * keyframes, or `blockMainThread(page, ms)` without `during`. + */ + readonly devtoolsTasks: readonly { + readonly start: number; + readonly durationMs: number; + }[]; + /** Every counted rendering event with its epoch-ms time, for sub-window counts. */ + readonly events: readonly {readonly name: string; readonly t: number}[]; + /** The window, epoch ms on the page's clock. */ + readonly window: {readonly from: number; readonly to: number}; + /** + * With `invalidations`: each style recalculation Chrome scheduled, with its + * reason (`Animation`, `Inline CSS style declaration was mutated`, …) and + * the element's trace node id, epoch ms. + */ + readonly styleInvalidations?: readonly { + readonly t: number; + readonly reason: string; + readonly nodeId?: number; + }[]; + /** + * With `invalidations`: one entry per animation that ran, with the element + * it ran on, whether it ran on the compositor (Chrome reported no reason it + * could not) and when it ran, epoch ms (`to` absent while it still runs). + */ + readonly animations?: readonly TraceAnimation[]; + /** + * With `invalidations`: when script started on the main thread (function + * calls, animation frame callbacks, timers, event dispatch), epoch ms. + */ + readonly scripts?: readonly number[]; +} + +/** An animation as a trace shows it (see `traceAnimations`). */ +export interface TraceAnimation { + readonly nodeId: number; + readonly composited: boolean; + readonly from?: number; + readonly to?: number; +} + +export interface TraceRenderingOptions { + /** + * Also record style recalculation reasons, the animations and whether they + * ran on the compositor, and script, for + * `countBetween(…, {skipCompositorAnimationUpdates: true})`. + */ + invalidations?: boolean; +} + +export interface CountBetweenOptions { + /** + * Leave out a rendering pass Chrome makes on its own for compositor + * animations: every style recalculation since the previous pass has the + * reason `Animation` (or is a pseudo-element's `Conditional ::…` restyle + * following that element's) and is on an element with an animation on the + * compositor at the time, and no script ran in between. Needs a trace + * recorded with `{invalidations: true}`. + */ + skipCompositorAnimationUpdates?: boolean; +} + +// Rendering events closer than this belong to one pass (one frame's style, +// layout and paint); passes are a frame apart. +const PASS_GAP_MS = 4; + +/** + * The times of the rendering events that belong to passes Chrome made on its + * own for compositor animations (see `CountBetweenOptions`). + */ +function compositorAnimationUpdates(trace: RenderingTrace): Set { + const {styleInvalidations, animations, scripts} = trace; + if (styleInvalidations == null || animations == null || scripts == null) { + throw new Error( + 'countBetween: skipCompositorAnimationUpdates needs traceRendering(…, {invalidations: true})', + ); + } + // An element counts as composited at a time when an animation on it runs + // on the compositor then and none on the main thread does. + const alive = (a: TraceAnimation, t: number) => + (a.from == null || a.from <= t) && (a.to == null || t <= a.to); + const compositedAt = (nodeId: number | undefined, t: number) => + nodeId != null && + animations.some(a => a.nodeId === nodeId && a.composited && alive(a, t)) && + !animations.some(a => a.nodeId === nodeId && !a.composited && alive(a, t)); + const events = [...trace.events].sort((a, b) => a.t - b.t); + const skipped = new Set(); + let previousEnd = -Infinity; + // The elements Chrome restyled on its own in the previous pass. + let ownBefore = new Set(); + let i = 0; + while (i < events.length) { + let j = i; + while ( + j + 1 < events.length && + events[j + 1].t - events[j].t <= PASS_GAP_MS + ) { + j += 1; + } + const start = events[i].t; + const end = events[j].t; + const causes = styleInvalidations.filter( + inv => inv.t > previousEnd && inv.t <= end, + ); + // A pseudo-element (`::backdrop`) restyles after the element it belongs + // to: `Conditional ::backdrop` is Chrome's own when that element's + // restyle is, in this pass or the one before. + const own = new Set( + causes + .filter(inv => inv.reason === 'Animation' && inv.nodeId != null) + .map(inv => inv.nodeId as number), + ); + const isAnimationUpdate = + causes.length > 0 && + causes.every( + inv => + (inv.reason === 'Animation' || + (inv.reason.startsWith('Conditional ::') && + inv.nodeId != null && + (own.has(inv.nodeId) || ownBefore.has(inv.nodeId)))) && + compositedAt(inv.nodeId, start), + ) && + !scripts.some(t => t > previousEnd && t <= start); + if (isAnimationUpdate) { + for (let k = i; k <= j; k += 1) { + skipped.add(events[k].t); + } + } + ownBefore = isAnimationUpdate ? own : new Set(); + previousEnd = end; + i = j + 1; + } + return skipped; +} + +/** Counts rendering events by name inside `[from, to]` (epoch ms). */ +export function countBetween( + trace: RenderingTrace, + from: number, + to: number, + {skipCompositorAnimationUpdates = false}: CountBetweenOptions = {}, +): Record { + const skipped = skipCompositorAnimationUpdates + ? compositorAnimationUpdates(trace) + : new Set(); + const counts: Record = {}; + for (const e of trace.events) { + if (e.t >= from && e.t <= to && !skipped.has(e.t)) { + counts[e.name] = (counts[e.name] ?? 0) + 1; + } + } + return counts; +} + +interface TraceEvent { + name: string; + cat: string; + ph: string; + ts: number; + dur?: number; + pid: number; + tid: number; + args?: Record; +} + +/** A trace event as `traceAnimations` reads it. */ +export interface AnimationTraceEvent { + readonly name: string; + readonly ph: string; + readonly ts: number; + readonly id?: string; + readonly id2?: {readonly local?: string}; + readonly args?: Record; +} + +/** + * The animations a trace shows, one entry each, from Chrome's `Animation` + * events: the element (`nodeId`), whether it ran on the compositor and when. + * Chrome names an animation's events by an id it reuses once that animation + * is gone (a popover's exit copy gets its present's ids), so a begin event + * opens a new entry under its id and later events for the id add to it. + * `toMs` turns a trace timestamp into the times the trace reports. + */ +export function traceAnimations( + events: readonly AnimationTraceEvent[], + toMs: (ts: number) => number, +): TraceAnimation[] { + const open = new Map< + string, + {nodeId?: number; composited?: boolean; from: number; to?: number} + >(); + const all: { + nodeId?: number; + composited?: boolean; + from: number; + to?: number; + }[] = []; + for (const e of [...events].sort((a, b) => a.ts - b.ts)) { + if (e.name !== 'Animation') { + continue; + } + const id = e.id2?.local ?? e.id ?? ''; + const d = ((e.args as {data?: Record} | undefined)?.data ?? + {}) as Record; + let entry = open.get(id); + if (e.ph === 'b' || entry == null) { + entry = {from: toMs(e.ts)}; + open.set(id, entry); + all.push(entry); + } + if (typeof d.nodeId === 'number') { + entry.nodeId = d.nodeId; + } + if (typeof d.compositeFailed === 'number') { + entry.composited = (entry.composited ?? true) && d.compositeFailed === 0; + } + if (e.ph === 'e') { + entry.to = toMs(e.ts); + open.delete(id); + } + } + return all.flatMap(({nodeId, composited, from, to}) => + nodeId == null + ? [] + : [ + { + nodeId, + composited: composited ?? false, + from, + ...(to == null ? {} : {to}), + }, + ], + ); +} + +/** + * Traces the page while `body` runs and counts the rendering work its main + * thread did between a start mark (placed just before `body`) and an end mark + * (just after). The harness's animation recorder, `waitForRest`, + * `waitForAnimation` and a watch's `started()` stand down meanwhile, so a body + * may wait with any of them and add no frame of its own, with one gap: on a + * CSS `@keyframes` animation (and, for an unwatched `waitForAnimation`, a + * cancelled CSS transition) the wait reads its timing, which flushes that + * animation's style, so wait on such an animation with `waitForRest`, or + * after the trace. + */ +export async function traceRendering( + page: Page, + body: () => Promise, + {invalidations = false}: TraceRenderingOptions = {}, +): Promise { + const cdp: CDPSession = await page.context().newCDPSession(page); + const events: TraceEvent[] = []; + cdp.on('Tracing.dataCollected', ({value}) => { + events.push(...(value as unknown as TraceEvent[])); + }); + const complete = new Promise(resolve => + cdp.once('Tracing.tracingComplete', () => resolve()), + ); + await cdp.send('Tracing.start', { + transferMode: 'ReportEvents', + traceConfig: { + includedCategories: [ + 'devtools.timeline', + 'disabled-by-default-devtools.timeline', + 'blink.user_timing', + 'toplevel', + ...(invalidations + ? ['disabled-by-default-devtools.timeline.invalidationTracking'] + : []), + ], + excludedCategories: ['*'], + }, + }); + const tag = `harness-${Math.random().toString(36).slice(2, 8)}`; + const mark = (name: string) => + page.evaluate( + n => performance.timeOrigin + performance.mark(n).startTime, + name, + ); + // The harness's animation recorder (curves.ts) runs a callback every frame, + // which makes each frame a main-thread one where Blink restyles every running + // animation's target (and lays out an anchored one), and it reads the page's + // animations, which flushes style: exactly what this counts. It stands down + // while this flag is set, a recorder the body itself starts included, and + // resumes once the trace ends. + const standDown = (on: boolean) => + page.evaluate(value => { + const w = window as unknown as { + __harnessRenderingTrace?: boolean; + __harnessAnimations?: {resume?: () => void}; + }; + w.__harnessRenderingTrace = value; + if (!value) { + w.__harnessAnimations?.resume?.(); + } + }, on); + await standDown(true); + let fromEpoch: number; + let toEpoch: number; + try { + fromEpoch = await mark(`${tag}:start`); + await body(); + toEpoch = await mark(`${tag}:end`); + } finally { + // Its catch-up read lands after the end mark, outside the counted window. + // A failure here would hide the body's own error, which is the one to see. + await standDown(false).catch(() => {}); + } + await cdp.send('Tracing.end'); + await complete; + await cdp.detach().catch(() => {}); + + const start = events.find(e => e.name === `${tag}:start`); + const end = events.find(e => e.name === `${tag}:end`); + if (start == null || end == null) { + throw new Error('traceRendering: the window marks were not traced'); + } + const onMain = (e: TraceEvent) => + e.pid === start.pid && + e.tid === start.tid && + e.ts >= start.ts && + e.ts <= end.ts; + // Trace time (µs, monotonic) -> epoch ms, anchored on the start mark. + const toEpochMs = (ts: number) => fromEpoch + (ts - start.ts) / 1000; + const counts: Record = {}; + const counted: {name: string; t: number}[] = []; + for (const e of events) { + if (!onMain(e) || e.ph === 'E') { + continue; + } + if ((RENDERING_EVENTS as readonly string[]).includes(e.name)) { + counts[e.name] = (counts[e.name] ?? 0) + 1; + counted.push({name: e.name, t: toEpochMs(e.ts)}); + } + } + const extra: { + -readonly [ + K in 'styleInvalidations' | 'animations' | 'scripts' + ]?: RenderingTrace[K]; + } = {}; + if (invalidations) { + const data = (e: TraceEvent) => + ((e.args as {data?: Record} | undefined)?.data ?? + {}) as Record; + extra.animations = traceAnimations( + events.filter(e => e.pid === start.pid), + toEpochMs, + ); + extra.styleInvalidations = events + .filter(e => onMain(e) && e.name === 'StyleRecalcInvalidationTracking') + .map(e => { + const d = data(e); + return { + t: toEpochMs(e.ts), + reason: String(d.reason ?? ''), + nodeId: typeof d.nodeId === 'number' ? d.nodeId : undefined, + }; + }); + extra.scripts = events + .filter( + e => + onMain(e) && + [ + 'FunctionCall', + 'FireAnimationFrame', + 'TimerFire', + 'EventDispatch', + ].includes(e.name), + ) + .map(e => toEpochMs(e.ts)); + } + // A task that ran a DevTools command received it over the DevTools + // session's pipe; page script it set off shows as its listener, timer or + // frame callback. + const main = events.filter(e => onMain(e) && e.ph !== 'E'); + const longTasks: {start: number; durationMs: number}[] = []; + const devtoolsTasks: {start: number; durationMs: number}[] = []; + for (const task of main) { + if (task.name !== 'RunTask' || (task.dur ?? 0) <= 50_000) { + continue; + } + const end = task.ts + (task.dur ?? 0); + const inside = main.filter( + e => e !== task && e.ts >= task.ts && e.ts <= end, + ); + const devtools = inside.some( + e => + e.name === 'Receive mojo message' && + ( + e.args?.chrome_mojo_event_info as + {mojo_interface_tag?: unknown} | undefined + )?.mojo_interface_tag === 'blink.mojom.DevToolsSession', + ); + // Only the harness's own reads are set apart: a test's evaluate may call + // page code directly, which leaves no listener or timer in the trace. + const harnessRead = inside.some( + e => + e.name === 'TimeStamp' && + (e.args?.data as {message?: unknown} | undefined)?.message === + HARNESS_READ, + ); + const pageScript = inside.some(e => PAGE_SCRIPT_EVENTS.has(e.name)); + (devtools && harnessRead && !pageScript ? devtoolsTasks : longTasks).push({ + start: toEpochMs(task.ts), + durationMs: (task.dur ?? 0) / 1000, + }); + } + return { + counts, + layout: counts.Layout ?? 0, + paint: counts.Paint ?? 0, + styleRecalc: counts.UpdateLayoutTree ?? 0, + prePaint: counts.PrePaint ?? 0, + durationMs: (end.ts - start.ts) / 1000, + longTasks, + devtoolsTasks, + events: counted, + window: {from: fromEpoch, to: toEpoch}, + ...extra, + }; +} + +/** + * Records when the compositor presents each frame, for `busyWindowProof`'s + * `presented`: a Chromium trace of `Display::FrameDisplayed`, on the page + * clock. Start it with the screencast, before the block, and stop it after. + * Engines without a CDP trace (WebKit) resolve `stop()` to [], and the + * verdict then judges the screencast alone. It runs its own trace, so not + * inside `traceRendering`. + */ +export async function startCompositorTrace( + page: Page, +): Promise<{stop(): Promise}> { + let cdp: CDPSession; + try { + cdp = await page.context().newCDPSession(page); + } catch { + return {stop: async () => []}; + } + const events: TraceEvent[] = []; + cdp.on('Tracing.dataCollected', ({value}) => { + events.push(...(value as unknown as TraceEvent[])); + }); + const complete = new Promise(resolve => + cdp.once('Tracing.tracingComplete', () => resolve()), + ); + await cdp.send('Tracing.start', { + transferMode: 'ReportEvents', + traceConfig: { + includedCategories: [ + 'disabled-by-default-display.framedisplayed', + 'blink.user_timing', + ], + excludedCategories: ['*'], + }, + }); + const tag = `harness-compositor-${Math.random().toString(36).slice(2, 8)}`; + const epoch = await page.evaluate( + n => performance.timeOrigin + performance.mark(n).startTime, + tag, + ); + return { + async stop() { + await cdp.send('Tracing.end'); + await complete; + await cdp.detach().catch(() => {}); + const mark = events.find(e => e.name === tag); + if (mark == null) { + throw new Error('startCompositorTrace: the clock mark was not traced'); + } + // Trace time (µs, monotonic) -> epoch ms, anchored on the mark. + return events + .filter(e => e.name === 'Display::FrameDisplayed') + .map(e => epoch + (e.ts - mark.ts) / 1000) + .sort((a, b) => a - b); + }, + }; +} + +const LONG_TASK_SCRIPT = `(() => { + if (window.__harnessLongTasks) return; + const tasks = []; + const log = {tasks, supported: false}; + window.__harnessLongTasks = log; + if (typeof PerformanceObserver === 'undefined' || !(PerformanceObserver.supportedEntryTypes || []).includes('longtask')) return; + try { + new PerformanceObserver(list => { + for (const entry of list.getEntries()) tasks.push({start: performance.timeOrigin + entry.startTime, durationMs: entry.duration, name: entry.name}); + }).observe({type: 'longtask', buffered: true}); + log.supported = true; + } catch {} +})()`; + +/** + * Records every long task (> 50 ms) the page runs (install before navigation; + * Chromium), through the Long Tasks API. That sees the tasks of the page's own + * event loop: a timer, an event handler, `blockMainThread(page, ms, {during})`. + * A DevTools `page.evaluate`, such as `blockMainThread(page, ms)` without + * `during`, is not one of them and is never recorded here; `traceRendering` + * reports it in `devtoolsTasks`, apart from the page's `longTasks`. + */ +export async function installLongTaskLog(page: Page): Promise { + await page.addInitScript(LONG_TASK_SCRIPT); +} + +export interface LongTask { + /** Epoch ms. */ + readonly start: number; + readonly durationMs: number; + readonly name: string; +} + +/** + * Long tasks recorded since navigation, optionally only those overlapping a + * window. Fails closed: it throws when the log never ran on this document + * (installed after the page navigated) or the engine has no Long Tasks API + * (WebKit), so an empty answer is evidence of no long task, never of no log. + */ +export async function readLongTasks( + page: Page, + range?: {from: number; to: number}, +): Promise { + const log = await page.evaluate( + () => + ( + window as unknown as { + __harnessLongTasks?: {tasks: LongTask[]; supported: boolean}; + } + ).__harnessLongTasks ?? null, + ); + if (log == null) { + throw new Error( + 'readLongTasks: the long-task log is not running on this document; call installLongTaskLog(page) before navigating', + ); + } + if (!log.supported) { + throw new Error( + 'readLongTasks: this engine has no Long Tasks API, so the log records nothing', + ); + } + const tasks = log.tasks; + return range == null + ? tasks + : tasks.filter( + t => t.start < range.to && t.start + t.durationMs > range.from, + ); +}