From 7a1003be557d76deadba12691cdd9425c57e73d8 Mon Sep 17 00:00:00 2001 From: 4gray Date: Tue, 29 Sep 2026 21:15:41 +0200 Subject: [PATCH] test(perf): attribute late layout shifts and record the first measurement evidence.settle.lateShifts lists the counted shifts after the first-card cutoff with the nodes the browser attributes them to. On master the settled score is 0.236: the recent-sources rail moves up 316 px about 12 ms after the first card and back down shortly after, a flicker #1738 did not cover. Co-Authored-By: Claude Opus 5.5 --- .../journey-renderer-probe.spec.ts | 42 +++++++++++- .../src/performance/journey-renderer-probe.ts | 66 +++++++++++++++++-- .../performance/launch-journey-record.spec.ts | 26 ++++++++ .../src/performance/launch-journey-record.ts | 7 ++ .../open-source-journey-record.spec.ts | 1 + docs/architecture/performance-journeys.md | 56 +++++++++++++--- 6 files changed, 183 insertions(+), 15 deletions(-) diff --git a/apps/electron-backend-e2e/src/performance/journey-renderer-probe.spec.ts b/apps/electron-backend-e2e/src/performance/journey-renderer-probe.spec.ts index 168308468..862d35ce1 100644 --- a/apps/electron-backend-e2e/src/performance/journey-renderer-probe.spec.ts +++ b/apps/electron-backend-e2e/src/performance/journey-renderer-probe.spec.ts @@ -25,6 +25,11 @@ interface FakeEntry { duration?: number; entryType: string; hadRecentInput?: boolean; + sources?: { + currentRect: { height: number; y: number }; + node: unknown; + previousRect: { height: number; y: number }; + }[]; startTime: number; value?: number; } @@ -419,7 +424,22 @@ test('keeps summing shifts without recent input after the first-card cutoff unti // A skeleton rail that resolved empty collapses about 15 ms after the // first card and pulls the rails below upwards (#1738). - observer.emit([layoutShift(now(), 0.5), layoutShift(now(), 0.3, true)]); + const rail = fixture.window.document.createElement('lib-dashboard-rail'); + const railSection = fixture.window.document.createElement('section'); + railSection.className = 'rail'; + railSection.setAttribute('data-test-id', 'dashboard-favorites-rail'); + rail.append(railSection); + const collapse = { + ...layoutShift(now(), 0.5), + sources: [ + { + currentRect: { height: 220, y: 300 }, + node: rail, + previousRect: { height: 220, y: 540 }, + }, + ], + }; + observer.emit([collapse, layoutShift(now(), 0.3, true)]); for (let step = 0; step < 3; step += 1) { await new Promise((resolve) => setTimeout(resolve, 20)); content.append(fixture.window.document.createElement('div')); @@ -441,6 +461,26 @@ test('keeps summing shifts without recent input after the first-card cutoff unti 'the quiet period restarts at the last mutation' ); assert.equal(state.counters.layoutShiftScoreSettled, 0.875); + // Only shifts after the cutoff are attributed; input-flagged ones are not. + assert.deepEqual( + state.settle.lateShifts.map((shift) => [shift.value, shift.sources]), + [ + [ + 0.5, + [ + { + deltaHeight: 0, + deltaY: -240, + node: 'lib-dashboard-rail[data-test-id="dashboard-favorites-rail"]', + }, + ], + ], + [0.125, []], + ] + ); + assert.ok( + state.settle.lateShifts.every((shift) => shift.afterFirstCardMs > 0) + ); // The first-card counters were frozen at the cutoff. assert.equal(state.counters.layoutShiftScore, 0.25); assert.equal(state.counters.recentInputLayoutShiftScore, 0); diff --git a/apps/electron-backend-e2e/src/performance/journey-renderer-probe.ts b/apps/electron-backend-e2e/src/performance/journey-renderer-probe.ts index b1190e3bb..94ddf8767 100644 --- a/apps/electron-backend-e2e/src/performance/journey-renderer-probe.ts +++ b/apps/electron-backend-e2e/src/performance/journey-renderer-probe.ts @@ -105,6 +105,18 @@ export interface JourneyRendererProbeCounters { recentInputLayoutShiftScore: number; } +export interface JourneyRendererProbeLateShift { + /** Entry start minus the first-card terminal epoch. */ + readonly afterFirstCardMs: number; + /** `tag.class[data-test-id]` and the vertical move of each source. */ + readonly sources: readonly { + readonly deltaHeight: number; + readonly deltaY: number; + readonly node: string; + }[]; + readonly value: number; +} + export interface JourneyRendererProbeState { readonly capabilities: { changeDetectionTicks: string; @@ -145,6 +157,11 @@ export interface JourneyRendererProbeState { domMutations: number; epochMs: number | null; lastMutationEpochMs: number | null; + /** + * Counted shifts after the first-card cutoff, at most 20, with the + * nodes that moved, so a late shift can be traced to its component. + */ + lateShifts: JourneyRendererProbeLateShift[]; observedTarget: 'documentElement' | 'root' | null; status: 'cap' | 'disabled' | 'pending' | 'quiet'; }; @@ -219,6 +236,7 @@ export function journeyRendererProbeScript( domMutations: 0, epochMs: null, lastMutationEpochMs: null, + lateShifts: [], observedTarget: null, status: settleOptions === null ? 'disabled' : 'pending', }, @@ -348,20 +366,60 @@ export function journeyRendererProbeScript( for (const entry of settleLayoutShifts) { const shift = entry as PerformanceEntry & { hadRecentInput?: boolean; + sources?: readonly LateShiftSource[]; value?: number; }; if ( - typeof shift.value === 'number' && - shift.hadRecentInput !== true && - inWindow(entry, untilEpochMs) + typeof shift.value !== 'number' || + shift.hadRecentInput === true || + !inWindow(entry, untilEpochMs) ) { - score += shift.value; + continue; + } + score += shift.value; + const entryEpochMs = performance.timeOrigin + entry.startTime; + if ( + entryEpochMs > (state.firstCardPaintEpochMs ?? untilEpochMs) && + state.settle.lateShifts.length < 20 + ) { + state.settle.lateShifts.push({ + afterFirstCardMs: + entryEpochMs - (state.terminal?.epochMs ?? 0), + sources: (shift.sources ?? []).map(describeSource), + value: shift.value, + }); } } state.counters.layoutShiftScoreSettled = score; state.settle.epochMs = untilEpochMs; state.settle.status = status; }; + type LateShiftSource = { + currentRect?: { height: number; y: number }; + node?: Node | null; + previousRect?: { height: number; y: number }; + }; + const describeSource = (source: LateShiftSource) => { + const node = source.node; + let label = node ? node.nodeName.toLowerCase() : 'unknown'; + if (node instanceof Element) { + const className = node.classList.item(0); + // Component hosts such as `lib-dashboard-rail` carry the test + // id on their first child. + const testId = + node.getAttribute('data-test-id') ?? + node.firstElementChild?.getAttribute('data-test-id'); + label += className ? `.${className}` : ''; + label += testId ? `[data-test-id="${testId}"]` : ''; + } + const before = source.previousRect; + const after = source.currentRect; + return { + deltaHeight: before && after ? after.height - before.height : 0, + deltaY: before && after ? after.y - before.y : 0, + node: label, + }; + }; // Starts at the first-card cutoff. Every mutation record under the root // restarts the quiet timer; the cap timer never moves. const startSettle = (settle: JourneyRendererProbeSettleOptions) => { diff --git a/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts index 94f3befbd..e88dc2a9b 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts @@ -49,6 +49,19 @@ function measurement( domMutations: 37, epochMs: 3_180.06, lastMutationEpochMs: 2_680, + lateShifts: [ + { + afterFirstCardMs: 14.96, + sources: [ + { + deltaHeight: 0, + deltaY: -240, + node: 'section.dashboard-rail', + }, + ], + value: 0.23049, + }, + ], observedTarget: 'root', status: 'quiet', }, @@ -156,6 +169,19 @@ test('maps the probe, IPC capture and main counters to exact counters and spawn- assert.deepEqual(record.evidence['settle'], { domMutations: 37, firstCardToSettledMs: 580, + lateShifts: [ + { + afterFirstCardMs: 15, + sources: [ + { + deltaHeight: 0, + deltaY: -240, + node: 'section.dashboard-rail', + }, + ], + value: 0.2305, + }, + ], observedTarget: 'root', reason: 'quiet', }); diff --git a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts index 7539473e4..139f045e3 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts @@ -162,6 +162,13 @@ export function toLaunchIterationRecord( firstCardToSettledMs: roundTenth( settle.epochMs - renderer.terminal.epochMs ), + lateShifts: settle.lateShifts.map((shift) => + Object.freeze({ + afterFirstCardMs: roundTenth(shift.afterFirstCardMs), + sources: shift.sources, + value: Math.round(shift.value * 10_000) / 10_000, + }) + ), observedTarget: settle.observedTarget, reason: settle.status, }), diff --git a/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts index 52f86b1e9..d4067df5c 100644 --- a/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts @@ -54,6 +54,7 @@ function measurement( domMutations: 0, epochMs: null, lastMutationEpochMs: null, + lateShifts: [], observedTarget: null, status: 'disabled', }, diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index a09ca47d0..75a4704df 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -139,16 +139,17 @@ observer. Why this point: and header stay outside the watched subtree, so their own updates neither keep the window open nor hide a shift in the content, which still counts wherever it happens. -- 500 ms is longer than any frame and any local round trip to the mock in - the J1 profile, so data that is already on its way lands inside the window. - The window does not wait for idle timers and polling, which a user would - not see as part of the launch either. +- 500 ms is many frames and well above the round trips to the local mock, + so startup data that is already on its way lands inside the window. On the + J1 profile the content pane goes quiet within about 110 ms of the first + card, so the window closes about 520-610 ms after it. - The 3 s cap bounds each iteration when something keeps mutating (an animation, a ticking label). A capped window can end in the middle of that activity, so `evidence.settle.reason` (`quiet` or `cap`) is recorded for every iteration, together with `firstCardToSettledMs` and the mutation - records seen (`domMutations`). If iterations close for different reasons, - the counter is not deterministic and will show `stable: false`. + records seen (`domMutations`). Iterations that close for different reasons + point at a settle point that is not deterministic; compare them before + trusting `stable`. Entries with `hadRecentInput === true` are excluded, as for the first-card counter; J1 has no input. The probe keeps its layout-shift observer open @@ -158,6 +159,24 @@ test waits for both. The record refuses an iteration whose window never closed or closed before the cutoff. J2's probe has no settle window (`settle.status` is `disabled`) and its counters are unchanged. +`evidence.settle.lateShifts` lists the counted shifts after the cutoff (at +most 20): the time after the first card, the value and, for each source the +browser attributes the shift to, the node (`tag.class[data-test-id]`; a +component host such as `lib-dashboard-rail` takes its first child's test id) +and its vertical move. A late shift can therefore be traced to its component +from the summary alone. + +First local measurement (macOS, 2026-09-29, `master` with #1738): all +windows closed on `quiet`, `renderer.layoutShiftScore` stayed 0, and +`renderer.layoutShiftScoreSettled` was 0.236 in 14 of 15 measured +iterations over three runs (`stable: false` in the first run with one 0, +stable in the other two). Every iteration shows the same two shifts of 0.118: +about 12 ms after the first card the `dashboard-recent-sources-rail`, which +holds the first card, moves up by 316 px, and 12-65 ms later it moves back +down. Something 316 px tall above it is removed and inserted again during +startup, a flicker #1738 did not cover. The counter is working as intended; +the flicker is a separate fix. + #### Main-process counters With `IPTVNATOR_PERF_CAPTURE=1`, which the journey sets, @@ -280,7 +299,7 @@ serial-depth counter is a better guardrail candidate than a raw call count. "launch": { "counters": { "renderer.ipcCallsToFirstCard": 12, - "renderer.layoutShiftScoreSettled": 0 + "renderer.layoutShiftScoreSettled": 0.236 }, "counterStability": { "renderer.ipcCallsToFirstCard": { @@ -289,7 +308,7 @@ serial-depth counter is a better guardrail candidate than a raw call count. }, "renderer.layoutShiftScoreSettled": { "stable": true, - "values": [0, 0, 0, 0, 0] + "values": [0.236, 0.236, 0.236, 0.236, 0.236] } }, "wallClock": { @@ -306,8 +325,21 @@ serial-depth counter is a better guardrail candidate than a raw call count. "wallClock": {}, "evidence": { "settle": { - "domMutations": 42, - "firstCardToSettledMs": 612.4, + "domMutations": 458, + "firstCardToSettledMs": 536.6, + "lateShifts": [ + { + "afterFirstCardMs": 12.4, + "sources": [ + { + "deltaHeight": 0, + "deltaY": -316, + "node": "lib-dashboard-rail[data-test-id=\"dashboard-recent-sources-rail\"]" + } + ], + "value": 0.118 + } + ], "observedTarget": "root", "reason": "quiet" } @@ -616,6 +648,10 @@ in all eighteen runner iterations; the `spawnToFirstCardMs` P50 ranged from 1,401 to 1,674 ms. All four stay evidence for now. Runner counters also differ from a Mac (12 and 571 there, the fast path without the Linux-only `getWindowState` call), so take J1 baseline values from the runner only. +`renderer.layoutShiftScoreSettled` has no baseline either: it has only been +measured on a Mac so far (see [Settle window](#settle-window)), and a +baseline needs the runner's number once the dashboard flicker it reports +is fixed. ## Charset parse benchmark