From 27e989f20495d8520f35698666f0f77aa553485a Mon Sep 17 00:00:00 2001 From: 4gray Date: Mon, 28 Sep 2026 09:15:39 +0200 Subject: [PATCH] test(perf): settle J2 on pending bridge calls and start HTTP at the click - The journey IPC capture pairs every traced start with its success or error and exposes the calls still in flight. J2 settles only when J1's capture, installed before the document loaded, has none pending, so a slow startup call cannot resolve after the click and count as J2. - The mock HTTP window starts at the renderer's click stamp instead of the test-side mark taken before Playwright's actionability checks. Co-Authored-By: Claude Opus 5.5 --- .../src/journeys/open-source-journey-app.ts | 68 +++++++++++++------ .../journey-main-ipc-capture.spec.ts | 37 ++++++++++ .../performance/journey-main-ipc-capture.ts | 38 ++++++++++- .../performance/launch-journey-record.spec.ts | 2 + .../open-source-journey-record.spec.ts | 2 + docs/architecture/performance-journeys.md | 24 ++++--- 6 files changed, 140 insertions(+), 31 deletions(-) diff --git a/apps/electron-backend-e2e/src/journeys/open-source-journey-app.ts b/apps/electron-backend-e2e/src/journeys/open-source-journey-app.ts index 489e9e260..79e1c8058 100644 --- a/apps/electron-backend-e2e/src/journeys/open-source-journey-app.ts +++ b/apps/electron-backend-e2e/src/journeys/open-source-journey-app.ts @@ -2,7 +2,9 @@ import type { ElectronApplication, Page } from '@playwright/test'; import { defaultXtreamPortalName } from '../electron-test-fixtures'; import { + countJourneyMainIpcInFlight, installJourneyMainIpcCapture, + JOURNEY_MAIN_IPC_STATE_KEY, JOURNEY_RENDERER_API_TRACE_CHANNEL, peekJourneyMainIpcCapture, readJourneyMainIpcCapture, @@ -40,6 +42,7 @@ interface ActivitySample { readonly httpInFlight: number; readonly httpRequests: number; readonly ipcCalls: number; + readonly ipcInFlight: number; } async function readPreStartMutations( @@ -60,9 +63,12 @@ async function readPreStartMutations( /** * Waits until DOM, bridge and mock traffic have all been unchanged for - * `QUIET_MS` with no mock request in flight (a slow response can still - * trigger follow-up work). An app that never settles fails the iteration - * instead of producing a count that includes its background work. + * `QUIET_MS` with no mock request and no bridge call in flight: a slow + * response or a pending bridge call can still change the DOM or trigger + * follow-up work after the click. Pending bridge calls come from J1's + * capture, which was installed before the document loaded and so has seen + * every call start. An app that never settles fails the iteration instead + * of producing a count that includes its background work. */ async function waitForQuiet( electronApp: ElectronApplication, @@ -72,17 +78,27 @@ async function waitForQuiet( ): Promise { const startedMs = Date.now(); const armMark = ledger.mark(); - const sample = async (): Promise => ({ - domMutations: await readPreStartMutations(page, probeStateKey), - httpInFlight: ledger.inFlight(), - httpRequests: ledger.mark(), - ipcCalls: ( - await peekJourneyMainIpcCapture( - electronApp, - OPEN_SOURCE_JOURNEY_MAIN_IPC_STATE_KEY - ) - ).callsBeforeStart, - }); + const sample = async (): Promise => { + const launchCapture = await peekJourneyMainIpcCapture( + electronApp, + JOURNEY_MAIN_IPC_STATE_KEY + ); + if (launchCapture.unmatchedCompletions > 0) { + throw new Error('open-source-journey-bridge-completions-unmatched'); + } + return { + domMutations: await readPreStartMutations(page, probeStateKey), + httpInFlight: ledger.inFlight(), + httpRequests: ledger.mark(), + ipcCalls: ( + await peekJourneyMainIpcCapture( + electronApp, + OPEN_SOURCE_JOURNEY_MAIN_IPC_STATE_KEY + ) + ).callsBeforeStart, + ipcInFlight: countJourneyMainIpcInFlight(launchCapture), + }; + }; let last = await sample(); let quietSinceMs = Date.now(); for (;;) { @@ -93,7 +109,8 @@ async function waitForQuiet( next.domMutations !== last.domMutations || next.httpInFlight > 0 || next.httpRequests !== last.httpRequests || - next.ipcCalls !== last.ipcCalls + next.ipcCalls !== last.ipcCalls || + next.ipcInFlight > 0 ) { last = next; quietSinceMs = now; @@ -177,7 +194,6 @@ export async function measureOpenSourceJourney( ledger, probeOptions.stateKey ); - const ledgerMark = ledger.mark(); await card.click({ timeout: timeoutMs }); const renderer: JourneyRendererProbeState = await waitForJourneyRendererProbe( @@ -191,12 +207,24 @@ export async function measureOpenSourceJourney( 10_000 ); await waitForMockQuiet(ledger); + // The journey starts at the renderer's click stamp, not when Playwright + // began its actionability checks, so a request that arrives in between + // stays before the click like it does for every other J2 counter. The + // ledger's clock is this process's wall clock and the stamp is the + // renderer's; both read the same host clock. + const clickEpochMs = renderer.start?.epochMs; + if (clickEpochMs === undefined) { + throw new Error('open-source-journey-click-not-started'); + } + const sinceSpawn = ledger.since(spawnLedgerMark); return { http: { - beforeClick: ledger - .since(spawnLedgerMark) - .slice(0, ledgerMark - spawnLedgerMark), - requests: ledger.since(ledgerMark), + beforeClick: sinceSpawn.filter( + (entry) => entry.epochMs < clickEpochMs + ), + requests: sinceSpawn.filter( + (entry) => entry.epochMs >= clickEpochMs + ), }, ipc, pid: session.launch.pid, diff --git a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts index 49f0b18cb..d6a7f8aa3 100644 --- a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts +++ b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts @@ -8,6 +8,7 @@ import type { ElectronApplication } from '@playwright/test'; import { assertJourneyMainIpcCapture, + countJourneyMainIpcInFlight, installJourneyMainIpcCapture, JOURNEY_RENDERER_API_TRACE_CHANNEL, peekJourneyMainIpcCapture, @@ -33,11 +34,13 @@ function validCapture( callsBeforeStart: 0, callsBeforeSentinel: 7, callsByMethod: { dbGetAppPlaylists: 1, getSettings: 6 }, + inFlightByMethod: {}, installedEpochMs: 1, malformedEvents: 0, processStartEpochMs: 0, senderIds: [1], sentinel: { occurrences: 1, receivedEpochMs: 2 }, + unmatchedCompletions: 0, start: null, ...overrides, }; @@ -307,3 +310,37 @@ test('rejects a start marker that is missing, repeated or after the sentinel', a 7 ); }); + +test('tracks bridge calls in flight from start to success or error', async () => { + await withCapture({}, async (fake, read) => { + fake.send(1, 'getSettings', []); + fake.send(1, 'getSettings', []); + fake.send(1, 'xtreamRequest', [{ action: 'get_account_info' }]); + let state = await read(); + assert.deepEqual(state.inFlightByMethod, { + getSettings: 2, + xtreamRequest: 1, + }); + assert.equal(countJourneyMainIpcInFlight(state), 3); + fake.send(1, 'getSettings', [], 'success'); + fake.send(1, 'xtreamRequest', [], 'error'); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [ + JOURNEY_OPEN_SOURCE_END_SENTINEL_ID, + ]); + state = await read(); + assert.deepEqual(state.inFlightByMethod, { + [JOURNEY_IPC_SENTINEL_METHOD]: 1, + getSettings: 1, + }); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [], 'success'); + fake.send(1, 'getSettings', [], 'success'); + state = await read(); + assert.equal(countJourneyMainIpcInFlight(state), 0); + assert.equal(state.unmatchedCompletions, 0); + // A completion whose start this capture never saw. + fake.send(1, 'dbGetAppState', [], 'success'); + state = await read(); + assert.equal(state.unmatchedCompletions, 1); + assert.equal(countJourneyMainIpcInFlight(state), 0); + }); +}); diff --git a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts index d62ba8cc9..4e7dbbd08 100644 --- a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts +++ b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts @@ -43,11 +43,20 @@ export interface JourneyMainIpcCaptureState { /** Calls from the start marker (or install) up to the sentinel. */ readonly callsBeforeSentinel: number; readonly callsByMethod: Record; + /** + * Bridge calls started but not yet completed, per method. The preload + * follows every `start` with exactly one `success` or `error` (sync and + * async results alike), so a capture installed before the document + * loads sees every pair. + */ + readonly inFlightByMethod: Record; readonly installedEpochMs: number; readonly malformedEvents: number; readonly processStartEpochMs: number; readonly senderIds: number[]; readonly sentinel: JourneyMainIpcSentinelState; + /** Completions without a start seen by this capture (installed late). */ + readonly unmatchedCompletions: number; /** Null when the capture has no start marker. */ readonly start: JourneyMainIpcSentinelState | null; } @@ -70,11 +79,13 @@ export async function installJourneyMainIpcCapture( installedEpochMs: Date.now(), malformedEvents: 0, processStartEpochMs: Date.now() - process.uptime() * 1000, + inFlightByMethod: {} as Record, senderIds: [] as number[], sentinel: { occurrences: 0, receivedEpochMs: null as number | null, }, + unmatchedCompletions: 0, start: startSentinelId === null ? null @@ -100,9 +111,24 @@ export async function installJourneyMainIpcCapture( state.malformedEvents += 1; return; } - if (record['phase'] !== 'start') { + const phase = record['phase']; + if (phase === 'success' || phase === 'error') { + const pending = state.inFlightByMethod[record['method']] ?? 0; + if (pending === 0) { + state.unmatchedCompletions += 1; + } else if (pending === 1) { + delete state.inFlightByMethod[record['method']]; + } else { + state.inFlightByMethod[record['method']] = pending - 1; + } return; } + if (phase !== 'start') { + return; + } + // Sentinels included: their completions arrive like any other. + state.inFlightByMethod[record['method']] = + (state.inFlightByMethod[record['method']] ?? 0) + 1; const senderId = event.sender.id; if (!state.senderIds.includes(senderId)) { state.senderIds.push(senderId); @@ -143,6 +169,16 @@ export async function installJourneyMainIpcCapture( }, options); } +/** Total of `inFlightByMethod`. */ +export function countJourneyMainIpcInFlight( + state: JourneyMainIpcCaptureState +): number { + return Object.values(state.inFlightByMethod).reduce( + (total, count) => total + count, + 0 + ); +} + /** Raw state without waiting for the sentinel, for settling checks. */ export async function peekJourneyMainIpcCapture( electronApp: ElectronApplication, 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 da44e41af..e1df24260 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 @@ -59,12 +59,14 @@ function measurement( callsBeforeStart: 0, callsBeforeSentinel: 14, callsByMethod: { dbGetAppPlaylists: 1, getSettings: 13 }, + inFlightByMethod: {}, installedEpochMs: 1_100, malformedEvents: 0, processStartEpochMs: 900, senderIds: [1], sentinel: { occurrences: 1, receivedEpochMs: 2_602 }, start: null, + unmatchedCompletions: 0, }; return { electronVersion: '43.3.0', 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 0016811c8..0eb4260bc 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 @@ -71,12 +71,14 @@ function measurement( callsBeforeStart: 0, callsBeforeSentinel: 17, callsByMethod: { dbGetAppState: 6, dbGetContent: 2, xtreamRequest: 1 }, + inFlightByMethod: {}, installedEpochMs: 9_500, malformedEvents: 0, processStartEpochMs: 1_000, senderIds: [1], sentinel: { occurrences: 1, receivedEpochMs: 10_081 }, start: { occurrences: 1, receivedEpochMs: 10_002 }, + unmatchedCompletions: 0, }; return { http: { diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index 3cee8ae0f..6b394a7f0 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -253,9 +253,13 @@ of these launches are not reported again. (`dashboard-recent-sources-rail-card` with the portal's name; the probe also accepts an `app-playlist-item` row on `/workspace/sources`). Before the click the test hovers the card and waits until the app has been quiet for -1 s: no DOM mutation, no bridge call, no new request to the mock and none -in flight (30 s -timeout, which fails the iteration). The settle wait and what happened during +1 s: no DOM mutation, no new bridge call, no new request to the mock, and +neither a bridge call nor a mock request still in flight (30 s timeout, which +fails the iteration). Bridge calls in flight come from J1's IPC capture: it +was installed before the document loaded, and the preload follows every +traced `start` with exactly one `success` or `error`, so a call that is still +pending cannot resolve after the click and have its DOM changes or follow-up +calls counted as J2. The settle wait and what happened during it are kept under `evidence.settle`. The renderer probe is armed in the loaded document with `page.evaluate` (the same self-contained script as J1, with `startClick` set). It registers a capture-phase `click` listener on @@ -297,13 +301,13 @@ strings and stream paths carry credentials and are never stored. ### Counters -| Counter | Source | -| ---------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `renderer.ipcCallsToFirstPage` | Bridge `start` trace events between the start and end sentinels, counted by a second `journey-main-ipc-capture.ts` instance installed with `startSentinelId`. Calls before the start marker are tallied separately (`callsBeforeStart`); a start marker that is missing, repeated or received after the end sentinel fails the iteration. | -| `renderer.domMutationsToFirstPage` | `MutationRecord`s from the click until the terminal batch. Records produced before the click (hover, settling) are taken from the observer at the start and counted under `evidence.settle` instead. | -| `renderer.layoutShiftScore` | Sum of all `layout-shift` entries from the click until the post-paint cutoff, rounded to three decimals. Unlike J1 it includes entries with `hadRecentInput === true`: the journey is a response to the click and runs inside the 500 ms input window, so the CLS filter would always read 0. The split is under `evidence.layoutShift`. | -| `renderer.longTasks` | `longtask` entries over 50 ms that started at or after the click (buffered entries from J1 are dropped) and before the cutoff. Evidence until it is shown to be stable on the CI runner, as for J1. | -| `main.mockHttpRequestsToSettled` | Requests the proxy received from the click until, after the terminal batch, no new request had arrived for 1 s and none was in flight (a response slower than that, and what it triggers, stays inside the window). Bounding by the terminal would compare the test process's clock with the renderer's, so the count up to the terminal epoch is evidence only (`evidence.httpRequestsToFirstPage`); `evidence.httpRequestsByRoute` names the requests. | +| Counter | Source | +| ---------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `renderer.ipcCallsToFirstPage` | Bridge `start` trace events between the start and end sentinels, counted by a second `journey-main-ipc-capture.ts` instance installed with `startSentinelId`. Calls before the start marker are tallied separately (`callsBeforeStart`); a start marker that is missing, repeated or received after the end sentinel fails the iteration. | +| `renderer.domMutationsToFirstPage` | `MutationRecord`s from the click until the terminal batch. Records produced before the click (hover, settling) are taken from the observer at the start and counted under `evidence.settle` instead. | +| `renderer.layoutShiftScore` | Sum of all `layout-shift` entries from the click until the post-paint cutoff, rounded to three decimals. Unlike J1 it includes entries with `hadRecentInput === true`: the journey is a response to the click and runs inside the 500 ms input window, so the CLS filter would always read 0. The split is under `evidence.layoutShift`. | +| `renderer.longTasks` | `longtask` entries over 50 ms that started at or after the click (buffered entries from J1 are dropped) and before the cutoff. Evidence until it is shown to be stable on the CI runner, as for J1. | +| `main.mockHttpRequestsToSettled` | Requests the proxy received from the click until, after the terminal batch, no new request had arrived for 1 s and none was in flight (a response slower than that, and what it triggers, stays inside the window). The window starts at the renderer's click stamp, the same boundary as every other J2 counter, not when Playwright began its actionability checks; the proxy stamps requests with the test process's wall clock, and both processes read the same host clock. Bounding by the terminal would compare the test process's clock with the renderer's, so the count up to the terminal epoch is evidence only (`evidence.httpRequestsToFirstPage`); `evidence.httpRequestsByRoute` names the requests. | `renderer.cdTicksToFirstPage` and `main.sqlStatementsToFirstPage` are listed under `unavailable` for the same reasons as their J1 counterparts.