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 f8e90a123..9dfa35301 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 @@ -13,6 +13,9 @@ import { JOURNEY_OPEN_SOURCE_PROBE_STATE_KEY, JOURNEY_OPEN_SOURCE_START_SENTINEL_ID, JOURNEY_PROBE_STATE_KEY, + JOURNEY_SETTLE_CAP_MS, + JOURNEY_SETTLE_QUIET_MS, + JOURNEY_SETTLE_ROOT_SELECTOR, journeyRendererProbeScript, type JourneyRendererProbeOptions, type JourneyRendererProbeState, @@ -22,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; } @@ -45,7 +53,14 @@ interface Fixture { const PAGE = `
IPTVnator
-`; +
`; + +/** Short settle timers so the launch fixtures do not wait 500 ms each. */ +const FAST_SETTLE = { + capMs: 1_000, + quietMs: 30, + rootSelector: JOURNEY_SETTLE_ROOT_SELECTOR, +} as const; function installFakePerformance( window: JSDOM['window'], @@ -114,7 +129,11 @@ function createFixture( }); return createFixtureFromDom( dom, - { ...createLaunchJourneyProbeOptions(), ...optionOverrides }, + { + ...createLaunchJourneyProbeOptions(), + settle: FAST_SETTLE, + ...optionOverrides, + }, bridge ); } @@ -171,16 +190,20 @@ const liveStates: (() => JourneyRendererProbeState)[] = []; /** * Waits `ms`, then until every probe that reached its terminal batch has also - * passed the post-paint cutoff (a rAF plus a timer). A fixed delay alone - * flakes when the harness runs all spec files in parallel. + * passed the post-paint cutoff (a rAF plus a timer) and closed its settle + * window. A fixed delay alone flakes when the harness runs all spec files in + * parallel. */ async function settle(ms = 40): Promise { await new Promise((resolve) => setTimeout(resolve, ms)); - const deadline = Date.now() + 2_000; + const deadline = Date.now() + 3_000; while ( liveStates.some((read) => { const state = read(); - return state.terminal !== null && !state.final; + return ( + state.terminal !== null && + (!state.final || state.settle.status === 'pending') + ); }) && Date.now() < deadline ) { @@ -193,7 +216,7 @@ function renderFirstCard(fixture: Fixture): void { document.getElementById('initial-splash')?.remove(); const rail = document.createElement('section'); rail.setAttribute('data-test-id', 'dashboard-recent-sources-rail'); - document.querySelector('app-root')?.append(rail); + document.querySelector('main.workspace-content')?.append(rail); const card = document.createElement('div'); card.setAttribute('data-test-id', 'dashboard-recent-sources-rail-card'); rail.append(card); @@ -361,6 +384,206 @@ test('sums layout shifts without recent input and counts long tasks over 50 ms u assert.equal(fixture.state().counters.longTasks, 3); }); +function layoutShift( + startTime: number, + value: number, + hadRecentInput = false +): FakeEntry { + return { entryType: 'layout-shift', hadRecentInput, startTime, value }; +} + +async function waitFor( + predicate: () => boolean, + timeoutMs = 3_000 +): Promise { + const deadline = Date.now() + timeoutMs; + while (!predicate()) { + if (Date.now() > deadline) throw new Error('waitFor timed out'); + await new Promise((resolve) => setTimeout(resolve, 5)); + } +} + +test('keeps summing shifts without recent input after the first-card cutoff until the workspace content is quiet', async () => { + const fixture = createFixture({ + settle: { ...FAST_SETTLE, capMs: 5_000, quietMs: 80 }, + }); + const [observer] = fixture.observers as [FakeObserver]; + const now = () => fixture.window.performance.now(); + const content = fixture.window.document.querySelector( + 'main.workspace-content' + ) as HTMLElement; + observer.emit([layoutShift(now(), 0.25)]); + renderFirstCard(fixture); + await waitFor(() => fixture.rawState().final); + const cutoff = fixture.state(); + assert.equal(cutoff.counters.layoutShiftScore, 0.25); + assert.equal(cutoff.settle.status, 'pending'); + assert.equal(cutoff.settle.observedTarget, 'root'); + assert.equal(cutoff.counters.layoutShiftScoreSettled, 0); + assert.equal(observer.disconnected, false); + + // A skeleton rail that resolved empty collapses about 15 ms after the + // first card and pulls the rails below upwards (#1738). + 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')); + } + // Queued, not yet delivered, when the settle point is sampled. + observer.queue.push( + layoutShift(now(), 0.125), + layoutShift(now() + 60_000, 9) + ); + // Outside the settle root: does not keep the window open. + fixture.window.document.body.setAttribute('data-late', '1'); + await settle(); + const state = fixture.state(); + assert.equal(state.settle.status, 'quiet'); + assert.equal(state.settle.domMutations, 3); + assert.ok(state.settle.epochMs !== null && state.settle.epochMs > 0); + assert.ok( + state.settle.epochMs - (state.settle.lastMutationEpochMs ?? 0) >= 75, + '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); + assert.equal(observer.disconnected, true); + assert.doesNotThrow(() => assertJourneyRendererProbeState(state)); + + observer.emit([layoutShift(now(), 1)]); + content.append(fixture.window.document.createElement('div')); + await settle(); + assert.equal(fixture.state().counters.layoutShiftScoreSettled, 0.875); + assert.equal(fixture.state().settle.domMutations, 3); +}); + +test('the cap ends the settle window while the workspace content keeps mutating', async () => { + const fixture = createFixture({ + settle: { ...FAST_SETTLE, capMs: 250, quietMs: 150 }, + }); + const [observer] = fixture.observers as [FakeObserver]; + const now = () => fixture.window.performance.now(); + const { document } = fixture.window; + renderFirstCard(fixture); + await waitFor(() => fixture.rawState().final); + const content = document.querySelector('main.workspace-content'); + const ticker = setInterval(() => { + content?.setAttribute('data-tick', String(now())); + }, 10); + try { + observer.emit([layoutShift(now(), 0.0625)]); + await waitFor(() => fixture.rawState().settle.status !== 'pending'); + observer.emit([layoutShift(now(), 0.5)]); + await new Promise((resolve) => setTimeout(resolve, 50)); + } finally { + clearInterval(ticker); + } + const state = fixture.state(); + assert.equal(state.settle.status, 'cap'); + assert.ok(state.settle.domMutations > 0); + assert.ok( + (state.settle.epochMs ?? 0) - (state.firstCardPaintEpochMs ?? 0) >= 245, + 'the cap is measured from the first-card cutoff' + ); + assert.equal(state.counters.layoutShiftScoreSettled, 0.0625); + assert.doesNotThrow(() => assertJourneyRendererProbeState(state)); +}); + +test('a late cap timer ends the window at its scheduled deadline', async () => { + const fixture = createFixture({ + settle: { ...FAST_SETTLE, capMs: 100, quietMs: 60_000 }, + }); + const [observer] = fixture.observers as [FakeObserver]; + const now = () => fixture.window.performance.now(); + renderFirstCard(fixture); + await waitFor(() => fixture.rawState().final); + const cutoffMs = + (fixture.rawState().firstCardPaintEpochMs ?? 0) - + fixture.window.performance.timeOrigin; + observer.emit([layoutShift(now(), 0.25)]); + // Hold the main thread past the cap so its timer runs late, and shift + // the layout after the deadline while it is held. + while (now() < cutoffMs + 250) { + // busy + } + observer.emit([layoutShift(now(), 0.5)]); + observer.queue.push(layoutShift(now(), 1)); + await waitFor(() => fixture.rawState().settle.status !== 'pending'); + const state = fixture.state(); + assert.equal(state.settle.status, 'cap'); + const settledAfterCutoff = + (state.settle.epochMs ?? 0) - (state.firstCardPaintEpochMs ?? 0); + assert.ok( + settledAfterCutoff >= 100 && settledAfterCutoff < 150, + `settle point at the deadline, not when the timer ran (${settledAfterCutoff} ms)` + ); + assert.equal(state.counters.layoutShiftScoreSettled, 0.25); +}); + +test('watches the document element when the settle root is missing', async () => { + const fixture = createFixture({ + settle: { ...FAST_SETTLE, rootSelector: 'app-missing-root' }, + }); + renderFirstCard(fixture); + await settle(); + const state = fixture.state(); + assert.equal(state.settle.observedTarget, 'documentElement'); + assert.equal(state.settle.status, 'quiet'); +}); + +test('refuses a probe whose settle window is still open', async () => { + const fixture = createFixture({ + settle: { ...FAST_SETTLE, capMs: 60_000, quietMs: 60_000 }, + }); + renderFirstCard(fixture); + await waitFor(() => fixture.rawState().final); + assert.throws( + () => assertJourneyRendererProbeState(fixture.state()), + /settle-pending/ + ); + // Mark the window closed so later tests' `settle()` does not wait on it, + // and stop its timers so they do not keep the runner alive. + fixture.rawState().settle.status = 'cap'; + fixture.window.close(); +}); + test('does not end while the splash is present, off the workspace route, or before a card is visible', async () => { const withSplash = createFixture(); const rail = withSplash.window.document.createElement('div'); @@ -437,6 +660,13 @@ test('launch options target the workspace source cards and the shared sentinel', assert.equal(options.routeFragment, '/workspace'); assert.match(options.cardSelector, /dashboard-recent-sources-rail-card/); assert.match(options.cardSelector, /app-playlist-item/); + assert.deepEqual(options.settle, { + capMs: JOURNEY_SETTLE_CAP_MS, + quietMs: JOURNEY_SETTLE_QUIET_MS, + rootSelector: 'main.workspace-content', + }); + assert.equal(JOURNEY_SETTLE_QUIET_MS, 500); + assert.equal(JOURNEY_SETTLE_CAP_MS, 3_000); }); // J2 "Open a source": the probe is armed in a loaded document and starts at @@ -643,6 +873,10 @@ test('drops performance entries from before the click and keeps recent-input shi assert.equal(state.final, true); assert.equal(state.counters.layoutShiftScore, 0.125); assert.equal(state.counters.recentInputLayoutShiftScore, 0.25); + // J2 has no settle window: the observers close at the cutoff. + assert.equal(state.settle.status, 'disabled'); + assert.equal(state.counters.layoutShiftScoreSettled, 0); + assert.ok(fixture.observers.every((observer) => observer.disconnected)); assert.equal(state.counters.longTasks, 1); assert.deepEqual(state.longTaskDurationsMs, [90]); }); 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 f54728746..0326119b0 100644 --- a/apps/electron-backend-e2e/src/performance/journey-renderer-probe.ts +++ b/apps/electron-backend-e2e/src/performance/journey-renderer-probe.ts @@ -12,7 +12,9 @@ import type { Page } from '@playwright/test'; * `window` (which runs before any listener of the app) and starts counting at * the first click inside `startClick.selector`. It counts DOM mutations, * layout shifts and long tasks until the journey's terminal condition and - * then emits one JSON blob under `options.stateKey`. + * then emits one JSON blob under `options.stateKey`. With `options.settle` + * (J1) it keeps summing layout shifts after the first card until the page + * has settled, for shifts such as collapsing skeletons that land later. * * IPC invocations are not counted here: the bridge object exposed by * `contextBridge` is frozen, so the probe cannot wrap it. Instead the probe @@ -50,6 +52,23 @@ export interface JourneyRendererProbeStartClick { readonly sentinelId: string; } +/** + * J1's settle window after the first card: it ends once nothing under + * `rootSelector` has mutated for `quietMs`, or `capMs` after the first-card + * cutoff, whichever comes first. See docs/architecture/performance-journeys.md. + */ +export interface JourneyRendererProbeSettleOptions { + readonly capMs: number; + readonly quietMs: number; + /** Falls back to the document element when nothing matches. */ + readonly rootSelector: string; +} + +export const JOURNEY_SETTLE_QUIET_MS = 500; +export const JOURNEY_SETTLE_CAP_MS = 3_000; +/** The workspace shell's content pane; the rail and header stay outside. */ +export const JOURNEY_SETTLE_ROOT_SELECTOR = 'main.workspace-content'; + export interface JourneyRendererProbeOptions { /** Selector for the element whose visibility ends the journey. */ readonly cardSelector: string; @@ -59,6 +78,8 @@ export interface JourneyRendererProbeOptions { /** Pathname fragment the terminal route must contain. */ readonly routeFragment: string; readonly sentinelId: string; + /** Absent: no settle window, the probe ends at the first-card cutoff. */ + readonly settle?: JourneyRendererProbeSettleOptions; readonly sentinelMethod: string; /** Element id of the inline splash that must be gone at the end. */ readonly splashId: string; @@ -71,6 +92,11 @@ export interface JourneyRendererProbeCounters { domMutations: number; /** Shifts with `hadRecentInput === false` (the CLS definition). */ layoutShiftScore: number; + /** + * The same filter from the journey's start until the settle point. Zero + * while `settle.status` is `pending` or `disabled`. + */ + layoutShiftScoreSettled: number; longTasks: number; /** * Shifts with `hadRecentInput === true`. Zero for J1, which has no @@ -79,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; @@ -113,6 +151,20 @@ export interface JourneyRendererProbeState { readonly epochMs: number | null; readonly status: 'bridge-missing' | 'failed' | 'not-sent' | 'sent'; }; + /** `final` freezes the first-card counters; the settle window ends later. */ + settle: { + /** Mutation records under the settle root after the cutoff. */ + 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'; + }; start: { /** `min(event.timeStamp, listener time)` as epoch milliseconds. */ readonly epochMs: number; @@ -145,6 +197,7 @@ export function journeyRendererProbeScript( } const epoch = (): number => performance.timeOrigin + performance.now(); const startClick = options.startClick ?? null; + const settleOptions = options.settle ?? null; const companionSelectors = options.companionSelectors ?? []; const bridge = target['electron'] as Record | undefined; const state: JourneyRendererProbeState = { @@ -159,6 +212,7 @@ export function journeyRendererProbeScript( counters: { domMutations: 0, layoutShiftScore: 0, + layoutShiftScoreSettled: 0, longTasks: 0, recentInputLayoutShiftScore: 0, }, @@ -178,6 +232,14 @@ export function journeyRendererProbeScript( preStart: { domMutations: 0, lastMutationEpochMs: null }, schemaVersion: 1, sentinel: { epochMs: null, status: 'not-sent' }, + settle: { + domMutations: 0, + epochMs: null, + lastMutationEpochMs: null, + lateShifts: [], + observedTarget: null, + status: settleOptions === null ? 'disabled' : 'pending', + }, start: null, terminal: null, }; @@ -249,13 +311,24 @@ export function journeyRendererProbeScript( // cutoff wait here so the cutoff applies to them as well. const pendingLayoutShifts: PerformanceEntry[] = []; const pendingLongTasks: PerformanceEntry[] = []; + // Every layout shift delivered until the settle point, kept apart from + // the first-card path so that counter stays exactly as it was; the + // settle bound is applied once it is known. + const settleLayoutShifts: PerformanceEntry[] = []; + const collectSettleShifts = (entries: readonly PerformanceEntry[]) => { + if (state.settle.status === 'pending') { + settleLayoutShifts.push(...entries); + } + }; const observe = ( type: string, accept: (entries: readonly PerformanceEntry[], until: number) => void, - pending: PerformanceEntry[] + pending: PerformanceEntry[], + collect: ((entries: readonly PerformanceEntry[]) => void) | null ): PerformanceObserver | null => { try { const observer = new PerformanceObserver((list) => { + collect?.(list.getEntries()); if (state.final) return; if (state.terminal !== null) { pending.push(...list.getEntries()); @@ -272,23 +345,133 @@ export function journeyRendererProbeScript( const layoutShiftObserver = observe( 'layout-shift', acceptLayoutShift, - pendingLayoutShifts + pendingLayoutShifts, + collectSettleShifts ); const longTaskObserver = observe( 'longtask', acceptLongTasks, - pendingLongTasks + pendingLongTasks, + null ); state.capabilities.layoutShift = layoutShiftObserver !== null; state.capabilities.longTask = longTaskObserver !== null; + const endSettle = (status: 'cap' | 'quiet', untilEpochMs: number) => { + if (layoutShiftObserver) { + collectSettleShifts(layoutShiftObserver.takeRecords()); + layoutShiftObserver.disconnect(); + } + let score = 0; + 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) + ) { + 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. A timer can run + // late on a busy main thread, so the settle point is the deadline it was + // scheduled for, never the moment it ran: a late timer must not let + // shifts after the deadline into the counter. + const startSettle = (settle: JourneyRendererProbeSettleOptions) => { + const root = document.querySelector(settle.rootSelector); + state.settle.observedTarget = + root === null ? 'documentElement' : 'root'; + let quietTimer: ReturnType | undefined; + let quietDeadlineEpochMs = Number.POSITIVE_INFINITY; + const capDeadlineEpochMs = epoch() + settle.capMs; + const capTimer = setTimeout(() => end('cap'), settle.capMs); + const settleObserver = new MutationObserver((records) => { + if (state.settle.status !== 'pending') return; + state.settle.domMutations += records.length; + state.settle.lastMutationEpochMs = epoch(); + armQuiet(); + }); + const end = (status: 'cap' | 'quiet'): void => { + if (state.settle.status !== 'pending') return; + clearTimeout(quietTimer); + clearTimeout(capTimer); + state.settle.domMutations += settleObserver.takeRecords().length; + settleObserver.disconnect(); + const deadline = + status === 'cap' ? capDeadlineEpochMs : quietDeadlineEpochMs; + endSettle(status, Math.min(epoch(), deadline)); + }; + const armQuiet = (): void => { + clearTimeout(quietTimer); + quietDeadlineEpochMs = epoch() + settle.quietMs; + quietTimer = setTimeout(() => end('quiet'), settle.quietMs); + }; + settleObserver.observe(root ?? document.documentElement ?? document, { + attributes: true, + characterData: true, + childList: true, + subtree: true, + }); + armQuiet(); + }; + const finalize = (untilEpochMs: number): void => { if (layoutShiftObserver) { + const records = layoutShiftObserver.takeRecords(); + collectSettleShifts(records); acceptLayoutShift( - [...pendingLayoutShifts, ...layoutShiftObserver.takeRecords()], + [...pendingLayoutShifts, ...records], untilEpochMs ); - layoutShiftObserver.disconnect(); + if (settleOptions === null) layoutShiftObserver.disconnect(); } if (longTaskObserver) { acceptLongTasks( @@ -299,6 +482,7 @@ export function journeyRendererProbeScript( } state.firstCardPaintEpochMs = untilEpochMs; state.final = true; + if (settleOptions !== null) startSettle(settleOptions); }; const callSentinel = (id: string): 'bridge-missing' | 'failed' | 'sent' => { const method = bridge?.[options.sentinelMethod]; @@ -441,6 +625,11 @@ export function createLaunchJourneyProbeOptions(): JourneyRendererProbeOptions { routeFragment: '/workspace', sentinelId: JOURNEY_IPC_SENTINEL_ID, sentinelMethod: JOURNEY_IPC_SENTINEL_METHOD, + settle: { + capMs: JOURNEY_SETTLE_CAP_MS, + quietMs: JOURNEY_SETTLE_QUIET_MS, + rootSelector: JOURNEY_SETTLE_ROOT_SELECTOR, + }, splashId: 'initial-splash', stateKey: JOURNEY_PROBE_STATE_KEY, }; @@ -501,10 +690,17 @@ export async function waitForJourneyRendererProbe( stateKey: string, timeoutMs: number ): Promise { + // A settle window, where enabled, ends after `final`. await page.waitForFunction( - (key) => - (globalThis as unknown as Record)[key] - ?.final === true, + (key) => { + const state = ( + globalThis as unknown as Record< + string, + { final?: boolean; settle?: { status?: string } } + > + )[key]; + return state?.final === true && state.settle?.status !== 'pending'; + }, stateKey, { polling: 50, timeout: timeoutMs } ); @@ -532,6 +728,9 @@ export function assertJourneyRendererProbeState( ) { throw new Error('journey-renderer-probe-incomplete'); } + if (state.settle.status === 'pending') { + throw new Error('journey-renderer-probe-settle-pending'); + } if (state.invalidReasons.length > 0) { throw new Error( `journey-renderer-probe-invalid: ${state.invalidReasons.join(', ')}` 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 168b59348..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 @@ -22,6 +22,7 @@ function measurement( counters: { domMutations: 480, layoutShiftScore: 0.123456789, + layoutShiftScoreSettled: 0.2304999, longTasks: 2, recentInputLayoutShiftScore: 0, }, @@ -44,6 +45,26 @@ function measurement( preStart: { domMutations: 0, lastMutationEpochMs: null }, schemaVersion: 1, sentinel: { epochMs: 2_601, status: 'sent' }, + settle: { + 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', + }, start: null, terminal: { cardCount: 2, @@ -111,6 +132,7 @@ test('maps the probe, IPC capture and main counters to exact counters and spawn- 'renderer.domMutationsToFirstCard': 480, 'renderer.ipcCallsToFirstCard': 14, 'renderer.layoutShiftScore': 0.123, + 'renderer.layoutShiftScoreSettled': 0.23, 'renderer.longTasks': 2, }); assert.deepEqual(record.wallClock, { @@ -141,8 +163,28 @@ test('maps the probe, IPC capture and main counters to exact counters and spawn- rendererGateBlankLoaded: 1_050, rendererGateReleased: 1_150, rendererProbeInstalled: 1_200, + settled: 3_180.06, spawn: 1_000, }); + 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', + }); }); test('rejects measurements whose clocks or probes are inconsistent', () => { @@ -183,6 +225,50 @@ test('rejects measurements whose clocks or probes are inconsistent', () => { ); }); +test('refuses a launch whose settle window did not end after the first-card cutoff', () => { + const base = measurement(); + const withSettle = ( + settle: Partial + ): LaunchJourneyMeasurement => ({ + ...base, + renderer: { + ...base.renderer, + settle: { ...base.renderer.settle, ...settle }, + }, + }); + assert.throws( + () => + toLaunchIterationRecord( + 0, + false, + withSettle({ epochMs: null, status: 'pending' }) + ), + /settle-pending/ + ); + assert.throws( + () => + toLaunchIterationRecord( + 0, + false, + withSettle({ epochMs: null, status: 'disabled' }) + ), + /settle-disabled/ + ); + assert.throws( + () => toLaunchIterationRecord(0, false, withSettle({ epochMs: 2_640 })), + /settle-quiet/ + ); + const capped = toLaunchIterationRecord( + 0, + false, + withSettle({ epochMs: 5_650, status: 'cap' }) + ); + assert.equal( + (capped.evidence['settle'] as { reason: string }).reason, + 'cap' + ); +}); + test('names the counters the harness cannot measure yet', () => { assert.deepEqual(Object.keys(LAUNCH_JOURNEY_UNAVAILABLE_COUNTERS), [ 'renderer.cdTicksToFirstCard', 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 2ebae4c26..139f045e3 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts @@ -22,6 +22,7 @@ export const LAUNCH_JOURNEY_COUNTER = { DOM_MUTATIONS: 'renderer.domMutationsToFirstCard', IPC_CALLS: 'renderer.ipcCallsToFirstCard', LAYOUT_SHIFT_SCORE: 'renderer.layoutShiftScore', + LAYOUT_SHIFT_SCORE_SETTLED: 'renderer.layoutShiftScoreSettled', LONG_TASKS: 'renderer.longTasks', } as const; @@ -56,6 +57,11 @@ function roundTenth(value: number): number { return Math.round(value * 10) / 10; } +/** Layout-shift scores keep three decimals; see performance-journeys.md. */ +function roundThousandth(value: number): number { + return Math.round(value * 1_000) / 1_000; +} + export function toLaunchIterationRecord( index: number, warmup: boolean, @@ -77,6 +83,15 @@ export function toLaunchIterationRecord( ) { throw new Error('launch-journey-record-clock-order'); } + const { settle } = renderer; + if ( + (settle.status !== 'quiet' && settle.status !== 'cap') || + settle.epochMs === null || + renderer.firstCardPaintEpochMs === null || + settle.epochMs < renderer.firstCardPaintEpochMs + ) { + throw new Error(`launch-journey-record-settle-${settle.status}`); + } if ( renderer.capabilities.changeDetectionTicks !== 'unavailable-ng-global-not-published' @@ -98,8 +113,11 @@ export function toLaunchIterationRecord( [LAUNCH_JOURNEY_COUNTER.DOM_MUTATIONS]: renderer.counters.domMutations, [LAUNCH_JOURNEY_COUNTER.IPC_CALLS]: ipc.callsBeforeSentinel, - [LAUNCH_JOURNEY_COUNTER.LAYOUT_SHIFT_SCORE]: - Math.round(renderer.counters.layoutShiftScore * 1_000) / 1_000, + [LAUNCH_JOURNEY_COUNTER.LAYOUT_SHIFT_SCORE]: roundThousandth( + renderer.counters.layoutShiftScore + ), + [LAUNCH_JOURNEY_COUNTER.LAYOUT_SHIFT_SCORE_SETTLED]: + roundThousandth(renderer.counters.layoutShiftScoreSettled), [LAUNCH_JOURNEY_COUNTER.LONG_TASKS]: renderer.counters.longTasks, }), evidence: Object.freeze({ @@ -123,6 +141,7 @@ export function toLaunchIterationRecord( rendererGateBlankLoaded: measurement.gate.blankLoadedEpochMs, rendererGateReleased: measurement.gate.releasedEpochMs, rendererProbeInstalled: renderer.installed.epochMs, + settled: settle.epochMs, spawn: spawnEpochMs, }), firstCard: Object.freeze({ @@ -138,6 +157,21 @@ export function toLaunchIterationRecord( ipcCallsByMethod: ipc.callsByMethod, longTaskDurationsMs: renderer.longTaskDurationsMs.map(roundTenth), observedTarget: renderer.capabilities.observedTarget, + settle: Object.freeze({ + domMutations: settle.domMutations, + 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, + }), }), index, pid: measurement.pid, 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 656b60fac..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 @@ -30,6 +30,7 @@ function measurement( counters: { domMutations: 1_596, layoutShiftScore: 0.0004, + layoutShiftScoreSettled: 0, longTasks: 1, recentInputLayoutShiftScore: 0.22061, }, @@ -49,6 +50,14 @@ function measurement( preStart: { domMutations: 4, lastMutationEpochMs: 9_100 }, schemaVersion: 1, sentinel: { epochMs: 10_080.5, status: 'sent' }, + settle: { + domMutations: 0, + epochMs: null, + lastMutationEpochMs: null, + lateShifts: [], + observedTarget: null, + status: 'disabled', + }, start: { epochMs: 10_000.2, listenerEpochMs: 10_001, diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index ac83bba1b..cf3a0d660 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -95,7 +95,8 @@ main-process counters below, which exist only with `IPTVNATOR_PERF_CAPTURE=1`: - `journey-renderer-probe.ts` is registered with `addInitScript` on that `about:blank` page, so it runs at the start of the real document. It records that it ran while the document was still `loading` with zero - scripts and emits one JSON blob under `window.__iptvnatorJourneyProbe`. + scripts and emits one JSON blob under `window.__iptvnatorJourneyProbe`, + complete once the [settle window](#settle-window) has closed. - `journey-main-ipc-capture.ts` subscribes to the preload's renderer-API trace channel (`IPTVNATOR_DEBUG_TRACE_EVENT`, enabled with `IPTVNATOR_TRACE_IPC=1`) through `electronApp.evaluate`, also before the @@ -109,8 +110,81 @@ main-process counters below, which exist only with `IPTVNATOR_PERF_CAPTURE=1`: | `renderer.ipcCallsToFirstCard` | `start` trace events the preload emits for every bridge invocation (listener registrations `on*`/`remove*` excluded, as in `wrapElectronApi`). The renderer probe fires one sentinel `cancelSourceProbe('__iptvnator-journey-sentinel__')` at the terminal moment; renderer-to-main IPC is ordered, so events before the sentinel are the exact count. The preload traces the call before forwarding it, and `SOURCE_HEALTH_CANCEL` only looks the id up in an in-memory map, so the sentinel never reaches the database worker. | | `renderer.domMutationsToFirstCard` | `MutationRecord`s (not callback batches) from a `MutationObserver` on the document element with `childList`, `attributes`, `characterData` and `subtree`. When the init script runs before `` exists the observer watches `document`, which the blob reports in `capabilities.observedTarget`. | | `renderer.layoutShiftScore` | Sum of `layout-shift` entries with `hadRecentInput === false`, rounded to three decimals (a shift of 0.0001 flips in and out of the cutoff between runs; the CLS "good" threshold is 0.1, so three decimals keep the counter exact without hiding anything a user could see). The cutoff is sampled in a timer queued from the first `requestAnimationFrame` after the terminal batch, that is after the frame that paints the card has been committed; entries delivered live after the terminal batch are buffered and filtered by the same cutoff. | +| `renderer.layoutShiftScoreSettled` | The same filter from navigation start until the settle point after the first card (see [Settle window](#settle-window)), rounded to three decimals. It catches shifts that land after the cutoff, such as skeletons that collapse once their data resolves. | | `renderer.longTasks` | `longtask` entries over 50 ms up to that same cutoff, which includes the task that rendered the card. The count depends on machine speed, so it is evidence until a run shows it is stable on the CI runner. | +#### Settle window + +`renderer.layoutShiftScore` stops at the first-card cutoff, one frame after +the terminal batch. A shift that lands later is invisible to it: in #1738, +rail skeletons of rails that resolved empty collapsed about 15 ms after the +first card and pulled the rails below upwards, a shift of about 0.23 on every +relaunch with sources that the counter read as 0. +`renderer.layoutShiftScoreSettled` sums the same entries until the page has +settled. The first-card counter is unchanged, so its baselines and history +stay comparable. + +The settle window opens at the first-card cutoff. A second +`MutationObserver` watches `main.workspace-content`, the workspace shell's +content pane (the document element if it is missing, reported in +`evidence.settle.observedTarget`). The window closes when nothing in that +subtree has mutated for 500 ms, or 3 s after the cutoff, whichever comes +first. The settle point is the deadline the firing timer was scheduled for +(the last mutation plus 500 ms, or the cutoff plus 3 s), or the moment it +ran if that is earlier, so a timer delayed by a busy main thread does not +let later shifts in. Every entry that starts at or before the settle point +counts, including entries still queued in the observer. Why this point: + +- A DOM change in the content pane is what causes the shifts this counter + is after (data resolving, skeletons swapped for content), so quiet in that + subtree is a condition the page reaches, not a guess at a delay. The rail + 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 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`). 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 +only for this window: `final` still marks the first-card counters as +frozen, `settle.status` moves from `pending` to `quiet` or `cap`, and the +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. + +On the Linux CI runner (`Performance journeys` job of #1756, run +36618062068) the same flicker is a race: the measured iterations read +`[0, 0, 0.235, 0, 0]` (`stable: false`, every window `quiet` about 540 ms +after the first card), and the one hit shows the same two 316 px moves of +the recent-sources rail. + #### Main-process counters With `IPTVNATOR_PERF_CAPTURE=1`, which the journey sets, @@ -231,11 +305,18 @@ serial-depth counter is a better guardrail candidate than a raw call count. }, "journeys": { "launch": { - "counters": { "renderer.ipcCallsToFirstCard": 12 }, + "counters": { + "renderer.ipcCallsToFirstCard": 12, + "renderer.layoutShiftScoreSettled": 0.236 + }, "counterStability": { "renderer.ipcCallsToFirstCard": { "stable": true, "values": [12, 12, 12, 12, 12] + }, + "renderer.layoutShiftScoreSettled": { + "stable": true, + "values": [0.236, 0.236, 0.236, 0.236, 0.236] } }, "wallClock": { @@ -250,7 +331,27 @@ serial-depth counter is a better guardrail candidate than a raw call count. "pid": 1, "counters": {}, "wallClock": {}, - "evidence": {} + "evidence": { + "settle": { + "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" + } + } } ] } @@ -260,7 +361,9 @@ serial-depth counter is a better guardrail candidate than a raw call count. `journeys..counters.` and `journeys..wallClock.` are plain numbers so `tools/performance/check-journey-ratchet.mjs` can compare them with -`tools/performance/journey-baselines.json`. A J1 runtime baseline is added +`tools/performance/journey-baselines.json`. The summary writer checks only +that every measured iteration reports the same counter names with finite +values, so a new counter needs no schema change. A J1 runtime baseline is added once its counter is deterministic on the CI runner; the launch counters are not yet (see [Ratchet](#ratchet)), so the summary is evidence only. @@ -272,8 +375,8 @@ iteration copies it and spawns a fresh process through `runLaunchJourney`, which measures J1 as usual (gate, probe, IPC capture) and then hands the running app to `measureOpenSourceJourney` in `src/journeys/open-source-journey-app.ts`. The click therefore happens after -J1's terminal condition and its counters are final, and the two journeys never -overlap. One warm-up and five measured iterations, as for J1; the J1 numbers +J1's terminal condition and its counters are final, and after J1's settle +window has closed, so the two journeys never overlap. One warm-up and five measured iterations, as for J1; the J1 numbers of these launches are not reported again. J2 does not read J1's main-process counters, so its launches run without `IPTVNATOR_PERF_CAPTURE` and `IPTVNATOR_PERF_COUNT_SQL` (`runLaunchJourney` with @@ -553,6 +656,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: the runner reads +it as `stable: false` because the dashboard flicker it reports is a race +there (see [Settle window](#settle-window)). Add the runner's number once +that flicker is fixed and the counter is deterministic. ## Charset parse benchmark