From 4ecc2d1096a0e9a071dc47dcd04a6276544ccee7 Mon Sep 17 00:00:00 2001 From: 4gray Date: Sun, 4 Oct 2026 11:03:26 +0200 Subject: [PATCH] test(performance): add J4 search journey Measures typing a six-character query into the header search box on /workspace/search until the global search results settle, on a profile with the M3U fixture and the mock's existing 12,000-item `large` Xtream catalog. Counters: bridge calls and SQL statements per search (with a per-keystroke breakdown), serial IPC depth, DOM mutations, change-detection ticks, layout shift and long tasks; wall-clock last keystroke to settled and first keystroke to first result. Runs in the existing journeys target and the warn-only CI job, whose summary now prints the per-keystroke table. Moves J3's picsum artwork blocker into a shared helper. Co-Authored-By: Claude Opus 5.5 --- .../actions/performance-journeys/action.yml | 8 +- .github/workflows/ci.yml | 4 +- .../src/journeys/playback-journey-app.ts | 57 +- .../src/journeys/search-journey-app.ts | 335 ++++++++++++ .../src/journeys/search.journey.ts | 79 +++ .../performance/journey-external-artwork.ts | 51 ++ .../performance/journey-launch-environment.ts | 4 +- .../performance/journey-main-counters.spec.ts | 19 +- .../performance/search-journey-probe.spec.ts | 348 ++++++++++++ .../src/performance/search-journey-probe.ts | 507 ++++++++++++++++++ .../performance/search-journey-record.spec.ts | 328 +++++++++++ .../src/performance/search-journey-record.ts | 240 +++++++++ docs/architecture/performance-journeys.md | 174 +++++- 13 files changed, 2087 insertions(+), 67 deletions(-) create mode 100644 apps/electron-backend-e2e/src/journeys/search-journey-app.ts create mode 100644 apps/electron-backend-e2e/src/journeys/search.journey.ts create mode 100644 apps/electron-backend-e2e/src/performance/journey-external-artwork.ts create mode 100644 apps/electron-backend-e2e/src/performance/search-journey-probe.spec.ts create mode 100644 apps/electron-backend-e2e/src/performance/search-journey-probe.ts create mode 100644 apps/electron-backend-e2e/src/performance/search-journey-record.spec.ts create mode 100644 apps/electron-backend-e2e/src/performance/search-journey-record.ts diff --git a/.github/actions/performance-journeys/action.yml b/.github/actions/performance-journeys/action.yml index 5b9ead263..5a5246eec 100644 --- a/.github/actions/performance-journeys/action.yml +++ b/.github/actions/performance-journeys/action.yml @@ -72,5 +72,11 @@ runs: (($j.wallClock // {}) | to_entries[] | "| `\(.key)` | \(.value) | |"), "", ([($j.iterations // [])[] | select(.warmup | not) | .evidence.ipcSerialDepth // empty][0] // empty | - "Serial IPC chain (first measured iteration): \(.chain | map("`\(.)`") | join(" → "))", "")) + "Serial IPC chain (first measured iteration): \(.chain | map("`\(.)`") | join(" → "))", ""), + ([($j.iterations // [])[] | select(.warmup | not) | .evidence.perKeystroke // empty][0] // empty | + "Per keystroke (first measured iteration):", "", + "| Key | Query calls | Bridge calls | SQL statements | DOM mutations | CD ticks |", + "| --- | ---: | ---: | ---: | ---: | ---: |", + (.[] | "| `\(.key)` | \(.queryCalls) | \(.ipcCalls) | \(.sqlStatements) | \(.domMutations) | \(.cdTicks) |"), + "")) ' "$SUMMARY" | tee -a "$GITHUB_STEP_SUMMARY" diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 967d2f03a..3fcac3405 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -296,8 +296,8 @@ jobs: if: needs.performance-journeys-scope.outputs.run == 'true' runs-on: ubuntu-latest # The electron-performance build is the bulk of the time; each journey - # (launch, open-source, playback) is six fresh Electron processes plus - # one seeding run. + # (launch, open-source, playback, search) is six fresh Electron + # processes plus one seeding run. timeout-minutes: 30 # Warn-only for the first two weeks of plan item B3: a failure is # visible on the run but does not fail the workflow. diff --git a/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts b/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts index 1068f9f83..9b80ced07 100644 --- a/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts +++ b/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts @@ -1,10 +1,14 @@ -import type { ElectronApplication, Page } from '@playwright/test'; +import type { Page } from '@playwright/test'; import { configureLiveFormat } from '../xtream-live-format.fixture'; import { JOURNEY_CLICK_QUIET_MS, waitForJourneyClickQuiet, } from '../performance/journey-click-settle'; +import { + blockJourneyExternalArtwork, + readJourneyExternalArtworkCancelled, +} from '../performance/journey-external-artwork'; import { detachJourneyMainIpcCapture, installJourneyMainIpcCapture, @@ -47,14 +51,6 @@ export const PLAYBACK_JOURNEY_MAIN_IPC_STATE_KEY = '__iptvnatorJourneyPlaybackMainIpcCapture'; export const PLAYBACK_JOURNEY_PORTAL_NAME = 'Journey live portal'; const ERROR_PREFIX = 'playback-journey'; -const EXTERNAL_ARTWORK_STATE_KEY = '__iptvnatorJourneyExternalArtwork'; -/** - * The generated live catalog's channel and category logos point at - * picsum.photos. They are cancelled in the main process, so no request of - * the journey leaves the machine and a logo never loads, or fails, at a - * different moment on a runner with a different network. - */ -const EXTERNAL_ARTWORK_URLS = ['*://picsum.photos/*', '*://*.picsum.photos/*']; /** Seeds J2's profile with the local-media portal and the HTML5 player. */ export const PLAYBACK_JOURNEY_SEED: LaunchJourneySeedOptions = { @@ -68,45 +64,6 @@ export const PLAYBACK_JOURNEY_SEED: LaunchJourneySeedOptions = { }, }; -async function blockExternalArtwork( - electronApp: ElectronApplication -): Promise { - await electronApp.evaluate( - ({ session }, input) => { - const target = globalThis as unknown as Record; - if (target[input.key] !== undefined) { - throw new Error('playback-journey-artwork-block-installed'); - } - const state = { cancelled: 0 }; - target[input.key] = state; - // The app registers no onBeforeRequest listener of its own - // (only onBeforeSendHeaders), so this replaces nothing. - session.defaultSession.webRequest.onBeforeRequest( - { urls: input.urls }, - (_details, callback) => { - state.cancelled += 1; - callback({ cancel: true }); - } - ); - }, - { key: EXTERNAL_ARTWORK_STATE_KEY, urls: EXTERNAL_ARTWORK_URLS } - ); -} - -async function readCancelledExternalArtwork( - electronApp: ElectronApplication -): Promise { - return electronApp.evaluate( - (_electron, key) => - ( - (globalThis as unknown as Record)[key] as { - cancelled: number; - } - ).cancelled, - EXTERNAL_ARTWORK_STATE_KEY - ); -} - /** Dashboard card → live section → first category, as a user would. */ async function openLiveCategory(page: Page, timeoutMs: number): Promise { await page @@ -143,7 +100,7 @@ export async function measurePlaybackJourney( if (!startClick) { throw new Error('playback-journey-probe-without-start'); } - await blockExternalArtwork(electronApp); + await blockJourneyExternalArtwork(electronApp); await openLiveCategory(mainWindow, timeoutMs); const channel = mainWindow.locator(startClick.selector).first(); await channel.waitFor({ state: 'visible', timeout: timeoutMs }); @@ -199,7 +156,7 @@ export async function measurePlaybackJourney( ); return { externalArtworkCancelled: - await readCancelledExternalArtwork(electronApp), + await readJourneyExternalArtworkCancelled(electronApp), http: { afterPlaying: sinceSpawn.filter( (entry) => diff --git a/apps/electron-backend-e2e/src/journeys/search-journey-app.ts b/apps/electron-backend-e2e/src/journeys/search-journey-app.ts new file mode 100644 index 000000000..304118fdf --- /dev/null +++ b/apps/electron-backend-e2e/src/journeys/search-journey-app.ts @@ -0,0 +1,335 @@ +import type { ElectronApplication, Page } from '@playwright/test'; + +import { + blockJourneyExternalArtwork, + readJourneyExternalArtworkCancelled, +} from '../performance/journey-external-artwork'; +import { + JOURNEY_MAIN_COUNTER, + JOURNEY_PERFORMANCE_COUNTERS_CHANNEL, +} from '../performance/journey-main-counters'; +import { + countJourneyMainIpcInFlight, + detachJourneyMainIpcCapture, + installJourneyMainIpcCapture, + JOURNEY_MAIN_IPC_STATE_KEY, + JOURNEY_RENDERER_API_TRACE_CHANNEL, + peekJourneyMainIpcCaptures, + readJourneyMainIpcCapture, +} from '../performance/journey-main-ipc-capture'; +import { waitForJourneyQuiet } from '../performance/journey-quiet-wait'; +import { + armSearchJourneyProbe, + createSearchJourneyProbeOptions, + readSearchJourneyPreStartMutations, + SEARCH_JOURNEY_INPUT_SELECTOR, + SEARCH_JOURNEY_ROUTE_PATH, + waitForSearchJourneyProbe, +} from '../performance/search-journey-probe'; +import { + SEARCH_JOURNEY_QUERY_METHOD, + type SearchJourneyActivitySample, + type SearchJourneyMeasurement, + type SearchJourneySettle, +} from '../performance/search-journey-record'; +import { JOURNEY_RENDERER_GATE_KEY } from './journey-renderer-gate-client'; +import type { + LaunchJourneySeedOptions, + LaunchJourneySession, +} from './launch-journey-app'; + +/** + * J4 "Search": runs inside a process that J1 has just launched with the + * main-process counters on (SQL statements are counted). The test opens + * global search from the rail and focuses the header search box (not + * measured), lets the app settle, then types the query one key at a time + * at a fixed interval and measures until the results have settled. + * + * Main-process activity (bridge calls, SQL statements) is sampled before + * every keystroke, so the record can show what each key caused: with the + * shell's debounce, only the last interval should run a query. Contract: + * docs/architecture/performance-journeys.md. + */ +export const SEARCH_JOURNEY_MAIN_IPC_STATE_KEY = + '__iptvnatorJourneySearchMainIpcCapture'; +export const SEARCH_JOURNEY_PORTAL_NAME = 'Journey search portal'; +/** + * Six characters; on the mock's `large` account (12,000 items) the term + * matches 170 series titles, more than the first page of 100. + */ +export const SEARCH_JOURNEY_QUERY = 'system'; +/** Well below the shell's 350 ms input debounce, like steady typing. */ +export const SEARCH_JOURNEY_KEY_DELAY_MS = 100; +const QUIET_MS = 1_000; +const QUIET_POLL_MS = 100; +const QUIET_TIMEOUT_MS = 30_000; +const AFTER_SETTLED_WINDOW_MS = 500; +const ERROR_PREFIX = 'search-journey'; + +/** J1's M3U source plus the mock's existing 12,000-item `large` catalog. */ +export const SEARCH_JOURNEY_SEED: LaunchJourneySeedOptions = { + portal: { + name: SEARCH_JOURNEY_PORTAL_NAME, + password: 'large', + username: 'large', + }, +}; + +/** + * One synchronous pass in the main process: the capture's counts and the + * registered counters handler (which reads the registry synchronously), so + * no bridge call or SQL report can land between the two reads. + */ +async function sampleActivity( + electronApp: ElectronApplication +): Promise { + return electronApp.evaluate( + async (_electron, input) => { + const target = globalThis as unknown as Record; + const capture = target[input.captureKey] as + | { + callsBeforeSentinel: number; + callsByMethod: Record; + } + | undefined; + const gate = target[input.gateKey] as + | { invokeHandler?: (channel: string) => Promise } + | undefined; + if (!capture || typeof gate?.invokeHandler !== 'function') { + throw new Error('search-journey-sample-unavailable'); + } + const ipcCalls = capture.callsBeforeSentinel; + const queryCalls = capture.callsByMethod[input.queryMethod] ?? 0; + const pending = gate.invokeHandler(input.channel); + const snapshot = (await pending) as { + counters?: Record; + } | null; + const sqlStatements = snapshot?.counters?.[input.sqlCounter]; + if (typeof sqlStatements !== 'number') { + throw new Error('search-journey-sql-counter-missing'); + } + return { ipcCalls, queryCalls, sqlStatements }; + }, + { + captureKey: SEARCH_JOURNEY_MAIN_IPC_STATE_KEY, + channel: JOURNEY_PERFORMANCE_COUNTERS_CHANNEL, + gateKey: JOURNEY_RENDERER_GATE_KEY, + queryMethod: SEARCH_JOURNEY_QUERY_METHOD, + sqlCounter: JOURNEY_MAIN_COUNTER.SQL_STATEMENTS, + } + ); +} + +/** + * Waits until DOM, bridge calls (started and in flight) and SQL statements + * have all been unchanged for `QUIET_MS`, so leftovers of the launch and of + * the navigation to global search are not attributed to the first key. + */ +async function waitForSearchQuiet( + electronApp: ElectronApplication, + page: Page, + probeStateKey: string +): Promise { + const { sample, waitedMs } = await waitForJourneyQuiet({ + inFlight: (activity) => activity.ipcInFlight, + pollMs: QUIET_POLL_MS, + quietMs: QUIET_MS, + sample: async () => { + const [launchCapture, journeyCapture] = + await peekJourneyMainIpcCaptures(electronApp, [ + JOURNEY_MAIN_IPC_STATE_KEY, + SEARCH_JOURNEY_MAIN_IPC_STATE_KEY, + ]); + if (launchCapture.unmatchedCompletions > 0) { + throw new Error(`${ERROR_PREFIX}-bridge-completions-unmatched`); + } + return { + domMutations: await readSearchJourneyPreStartMutations( + page, + probeStateKey + ), + ipcCalls: journeyCapture.callsBeforeStart, + ipcInFlight: countJourneyMainIpcInFlight(launchCapture), + sqlStatements: (await sampleActivity(electronApp)) + .sqlStatements, + }; + }, + timeoutError: (activity) => + new Error(`${ERROR_PREFIX}-not-quiet: ${JSON.stringify(activity)}`), + timeoutMs: QUIET_TIMEOUT_MS, + }); + return { + preStartDomMutations: sample.domMutations, + preStartIpcCalls: sample.ipcCalls, + quietMs: QUIET_MS, + sqlStatements: sample.sqlStatements, + waitedMs, + }; +} + +function sleepUntil(epochMs: number): Promise { + const remainingMs = epochMs - Date.now(); + return remainingMs > 0 + ? new Promise((resolve) => setTimeout(resolve, remainingMs)) + : Promise.resolve(); +} + +const QUERY_TRACE_KEY = '__iptvnatorJourneySearchQueryTrace'; + +/** + * Keeps the trace events of the query method (summarized arguments and + * result, as the preload traces them) for the message of a failed settle. + */ +async function traceQueryCalls( + electronApp: ElectronApplication +): Promise { + await electronApp.evaluate( + ({ ipcMain }, input) => { + const entries: string[] = []; + (globalThis as unknown as Record)[input.key] = + entries; + ipcMain.on(input.channel, (_event, payload: unknown) => { + const record = payload as Record | null; + if (record?.['method'] === input.method && entries.length < 6) { + entries.push(JSON.stringify(record).slice(0, 600)); + } + }); + }, + { + channel: JOURNEY_RENDERER_API_TRACE_CHANNEL, + key: QUERY_TRACE_KEY, + method: SEARCH_JOURNEY_QUERY_METHOD, + } + ); +} + +/** + * What a failed settle saw: the bridge calls of the search, renderer errors + * (a search that threw shows the same empty view as one that found + * nothing), SQL statements before each key and now, and the traced query + * calls with their summarized arguments and results. + */ +async function describeSettleFailure( + electronApp: ElectronApplication, + samples: readonly SearchJourneyActivitySample[], + consoleErrors: readonly string[] +): Promise { + const [capture] = await peekJourneyMainIpcCaptures(electronApp, [ + SEARCH_JOURNEY_MAIN_IPC_STATE_KEY, + ]); + const now = await sampleActivity(electronApp); + const queryTrace = await electronApp.evaluate( + (_electron, key) => + (globalThis as unknown as Record)[key], + QUERY_TRACE_KEY + ); + return JSON.stringify({ + bridgeCalls: capture.callsByMethod, + consoleErrors, + queryTrace, + sqlBeforeKeysAndNow: [...samples, now].map( + (entry) => entry.sqlStatements + ), + }); +} + +/** Rail link → global search, then focus the header box. Not measured. */ +async function openGlobalSearch(page: Page, timeoutMs: number): Promise { + await page + .getByRole('link', { name: 'Global search', exact: true }) + .click({ timeout: timeoutMs }); + // A router navigation, not a document load: wait on the path itself. + await page + .waitForFunction( + (path) => location.pathname.endsWith(path), + SEARCH_JOURNEY_ROUTE_PATH, + { timeout: timeoutMs } + ) + .catch((failure: unknown) => { + throw new Error( + `${ERROR_PREFIX}-route-not-reached: ${page.url()} (${String(failure)})` + ); + }); + const input = page.locator(SEARCH_JOURNEY_INPUT_SELECTOR); + await input.waitFor({ state: 'visible', timeout: timeoutMs }); + await input.focus({ timeout: timeoutMs }); +} + +export async function measureSearchJourney( + session: LaunchJourneySession, + timeoutMs: number +): Promise { + const { electronApp, mainWindow } = session; + const query = SEARCH_JOURNEY_QUERY; + const probeOptions = createSearchJourneyProbeOptions(query); + // Kept for the message of a failed settle. + const consoleErrors: string[] = []; + mainWindow.on('console', (message) => { + if (message.type() === 'error' && consoleErrors.length < 10) { + consoleErrors.push(message.text().slice(0, 300)); + } + }); + await blockJourneyExternalArtwork(electronApp); + await traceQueryCalls(electronApp); + await openGlobalSearch(mainWindow, timeoutMs); + await installJourneyMainIpcCapture(electronApp, { + channel: JOURNEY_RENDERER_API_TRACE_CHANNEL, + sentinelId: probeOptions.endSentinelId, + sentinelMethod: probeOptions.sentinelMethod, + startSentinelId: probeOptions.startSentinelId, + stateKey: SEARCH_JOURNEY_MAIN_IPC_STATE_KEY, + }); + await armSearchJourneyProbe(mainWindow, probeOptions); + const settle = await waitForSearchQuiet( + electronApp, + mainWindow, + probeOptions.stateKey + ); + await detachJourneyMainIpcCapture(electronApp, JOURNEY_MAIN_IPC_STATE_KEY); + const focused = await mainWindow + .locator(SEARCH_JOURNEY_INPUT_SELECTOR) + .evaluate((input) => input === document.activeElement); + if (!focused) { + throw new Error(`${ERROR_PREFIX}-input-not-focused`); + } + // One `keyboard.type` per character on a fixed schedule, so the + // main-process sample before each key sits between two keystrokes. + const samples: SearchJourneyActivitySample[] = []; + const firstKeyAtMs = Date.now(); + for (let position = 0; position < query.length; position += 1) { + await sleepUntil(firstKeyAtMs + position * SEARCH_JOURNEY_KEY_DELAY_MS); + samples.push(await sampleActivity(electronApp)); + await mainWindow.keyboard.type(query[position]); + } + const renderer = await waitForSearchJourneyProbe( + mainWindow, + probeOptions.stateKey, + timeoutMs + ).catch(async (failure: unknown) => { + throw new Error( + `${String(failure)} ${await describeSettleFailure(electronApp, samples, consoleErrors)}` + ); + }); + const ipc = await readJourneyMainIpcCapture( + electronApp, + SEARCH_JOURNEY_MAIN_IPC_STATE_KEY, + 10_000 + ); + samples.push(await sampleActivity(electronApp)); + await new Promise((resolve) => + setTimeout(resolve, AFTER_SETTLED_WINDOW_MS) + ); + return { + afterSettled: await sampleActivity(electronApp), + afterSettledWindowMs: AFTER_SETTLED_WINDOW_MS, + externalArtworkCancelled: + await readJourneyExternalArtworkCancelled(electronApp), + ipc, + keyDelayMs: SEARCH_JOURNEY_KEY_DELAY_MS, + pid: session.launch.pid, + query, + renderer, + samples, + settle, + }; +} diff --git a/apps/electron-backend-e2e/src/journeys/search.journey.ts b/apps/electron-backend-e2e/src/journeys/search.journey.ts new file mode 100644 index 000000000..5663b4f27 --- /dev/null +++ b/apps/electron-backend-e2e/src/journeys/search.journey.ts @@ -0,0 +1,79 @@ +import { test } from '@playwright/test'; + +import type { JourneyIterationRecord } from '../performance/journey-summary'; +import { + SEARCH_JOURNEY_ID, + SEARCH_JOURNEY_UNAVAILABLE_COUNTERS, + toSearchIterationRecord, +} from '../performance/search-journey-record'; +import { + JOURNEY_ITERATION_TIMEOUT_MS, + JOURNEY_MEASURED_ITERATIONS, + JOURNEY_WARMUP_ITERATIONS, + logJourneyIteration, + writeJourneyRunEntry, +} from './journey-run'; +import { + LAUNCH_JOURNEY_MOCK_ORIGIN, + removeLaunchJourneyProfile, + runLaunchJourney, + seedLaunchJourneyProfile, +} from './launch-journey-app'; +import { + measureSearchJourney, + SEARCH_JOURNEY_SEED, +} from './search-journey-app'; + +/** + * J4 "Search": type a six-character query into the header search box on + * /workspace/search until the global search results have settled. Every + * iteration is a fresh J1 launch on a copy of the seeded profile (one M3U + * source and the mock's 12,000-item `large` Xtream catalog), with the + * main-process counters on so SQL statements are counted. + * Contract: docs/architecture/performance-journeys.md. + */ +test.describe.configure({ mode: 'serial' }); + +test('J4 search', async () => { + const iterations: JourneyIterationRecord[] = []; + let electronVersion = 'unknown'; + const templateDirectory = await seedLaunchJourneyProfile( + LAUNCH_JOURNEY_MOCK_ORIGIN, + SEARCH_JOURNEY_SEED + ); + try { + const total = JOURNEY_WARMUP_ITERATIONS + JOURNEY_MEASURED_ITERATIONS; + for (let index = 0; index < total; index += 1) { + const warmup = index < JOURNEY_WARMUP_ITERATIONS; + const { continuation, launch } = await runLaunchJourney( + templateDirectory, + JOURNEY_ITERATION_TIMEOUT_MS, + // SQL statements are a J4 counter, so unlike J2 and J3 the + // launch runs with the main-process counters and SQL hook. + { idleWindowMs: null, mainCounters: true }, + (session) => + measureSearchJourney( + session, + JOURNEY_ITERATION_TIMEOUT_MS + ).catch((failure: unknown) => { + throw new Error( + `iteration ${index}: ${String(failure)}` + ); + }) + ); + electronVersion = launch.electronVersion; + const record = toSearchIterationRecord(index, warmup, continuation); + iterations.push(record); + logJourneyIteration(SEARCH_JOURNEY_ID, record); + } + } finally { + await removeLaunchJourneyProfile(templateDirectory); + } + + await writeJourneyRunEntry( + SEARCH_JOURNEY_ID, + iterations, + SEARCH_JOURNEY_UNAVAILABLE_COUNTERS, + electronVersion + ); +}); diff --git a/apps/electron-backend-e2e/src/performance/journey-external-artwork.ts b/apps/electron-backend-e2e/src/performance/journey-external-artwork.ts new file mode 100644 index 000000000..e9cd7ce12 --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/journey-external-artwork.ts @@ -0,0 +1,51 @@ +import type { ElectronApplication } from '@playwright/test'; + +/** + * The mock's generated catalogs point channel, category, poster and cover + * artwork at picsum.photos. Journeys that render that artwork (J3, J4) + * cancel those requests in the main process, so no request of the journey + * leaves the machine and an image never loads, or fails, at a different + * moment on a runner with a different network. Contract: + * docs/architecture/performance-journeys.md. + */ +const EXTERNAL_ARTWORK_STATE_KEY = '__iptvnatorJourneyExternalArtwork'; +const EXTERNAL_ARTWORK_URLS = ['*://picsum.photos/*', '*://*.picsum.photos/*']; + +export async function blockJourneyExternalArtwork( + electronApp: ElectronApplication +): Promise { + await electronApp.evaluate( + ({ session }, input) => { + const target = globalThis as unknown as Record; + if (target[input.key] !== undefined) { + throw new Error('journey-artwork-block-installed'); + } + const state = { cancelled: 0 }; + target[input.key] = state; + // The app registers no onBeforeRequest listener of its own + // (only onBeforeSendHeaders), so this replaces nothing. + session.defaultSession.webRequest.onBeforeRequest( + { urls: input.urls }, + (_details, callback) => { + state.cancelled += 1; + callback({ cancel: true }); + } + ); + }, + { key: EXTERNAL_ARTWORK_STATE_KEY, urls: EXTERNAL_ARTWORK_URLS } + ); +} + +export async function readJourneyExternalArtworkCancelled( + electronApp: ElectronApplication +): Promise { + return electronApp.evaluate( + (_electron, key) => + ( + (globalThis as unknown as Record)[key] as { + cancelled: number; + } + ).cancelled, + EXTERNAL_ARTWORK_STATE_KEY + ); +} diff --git a/apps/electron-backend-e2e/src/performance/journey-launch-environment.ts b/apps/electron-backend-e2e/src/performance/journey-launch-environment.ts index acd9f58af..d109a2d8f 100644 --- a/apps/electron-backend-e2e/src/performance/journey-launch-environment.ts +++ b/apps/electron-backend-e2e/src/performance/journey-launch-environment.ts @@ -2,8 +2,8 @@ * Instrumentation flags a journey launch sets on the Electron process. * * Every journey needs the renderer-API trace (`IPTVNATOR_TRACE_IPC`) for its - * IPC counters. Only J1 records the main-process counters: - * `IPTVNATOR_PERF_CAPTURE` turns on the counters and their read handler, and + * IPC counters. Only J1 and J4 (for its SQL count) record the main-process + * counters: `IPTVNATOR_PERF_CAPTURE` turns on the counters and their read handler, and * `IPTVNATOR_PERF_COUNT_SQL` wraps every main-thread and worker SQLite * statement to count it (see journey-main-counters.ts). A journey that * continues from the launch without reading them (J2) leaves both off, so diff --git a/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts b/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts index 7b02bc5f0..4d07ef2b8 100644 --- a/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts +++ b/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts @@ -127,7 +127,7 @@ test('rejects snapshots that were not frozen at the moments they claim', () => { ); }); -test('only the launch journey opts into SQL statement counting', () => { +test('only the launch and search journeys opt into SQL statement counting', () => { // The import benchmarks also run with IPTVNATOR_PERF_CAPTURE=1; the SQL // hook wraps every row of a bulk insert, so they must not enable it. const sourceRoot = resolve(__dirname, '..'); @@ -146,12 +146,25 @@ test('only the launch journey opts into SQL statement counting', () => { assert.deepEqual(containing(/IPTVNATOR_PERF_COUNT_SQL/), [ join('performance', 'journey-launch-environment.ts'), ]); - // ...and only J1's launch asks for them there. Another journey that + // ...and only J1's launch and J4, which records the count as + // renderer.sqlStatementsPerSearch, ask for them. Another journey that // passed `mainCounters: true` to runLaunchJourney would be measured // under the statement hook without recording its count. - assert.deepEqual(containing(/mainCounters:\s*true/), [ + assert.deepEqual(containing(/mainCounters:\s*true/).sort(), [ join('journeys', 'launch-journey-app.ts'), + join('journeys', 'search.journey.ts'), ]); + assert.match( + readFileSync(join(sourceRoot, 'journeys', 'search.journey.ts'), 'utf8'), + /\{ idleWindowMs: null, mainCounters: true \}/ + ); + assert.match( + readFileSync( + join(sourceRoot, 'performance', 'search-journey-record.ts'), + 'utf8' + ), + /SQL_STATEMENTS: 'renderer\.sqlStatementsPerSearch'/ + ); const launchApp = readFileSync( join(sourceRoot, 'journeys', 'launch-journey-app.ts'), 'utf8' diff --git a/apps/electron-backend-e2e/src/performance/search-journey-probe.spec.ts b/apps/electron-backend-e2e/src/performance/search-journey-probe.spec.ts new file mode 100644 index 000000000..7c7d9e66d --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/search-journey-probe.spec.ts @@ -0,0 +1,348 @@ +import assert from 'node:assert/strict'; +import test from 'node:test'; + +import { JSDOM } from 'jsdom'; + +import { + JOURNEY_CD_TICK_COUNTER_KEY, + JOURNEY_IPC_SENTINEL_METHOD, + JOURNEY_PLAYBACK_PROBE_STATE_KEY, + JOURNEY_PROBE_STATE_KEY, +} from './journey-renderer-probe'; +import { + installFakePerformance, + type FakeObserver, +} from './journey-renderer-probe.test-helpers'; +import { + assertSearchJourneyProbeState, + createSearchJourneyProbeOptions, + SEARCH_JOURNEY_END_SENTINEL_ID, + SEARCH_JOURNEY_PROBE_STATE_KEY, + SEARCH_JOURNEY_START_SENTINEL_ID, + searchJourneyProbeScript, + type SearchJourneyProbeOptions, + type SearchJourneyProbeState, +} from './search-journey-probe'; + +const QUERY = 'system'; + +interface SearchFixture { + readonly bridgeCalls: unknown[]; + readonly input: HTMLInputElement; + readonly observers: FakeObserver[]; + readonly results: HTMLElement; + readonly state: () => SearchJourneyProbeState; + readonly ticks: { count: number }; + readonly window: JSDOM['window']; +} + +function createSearchFixture( + overrides: Partial = {} +): SearchFixture { + const dom = new JSDOM( + ` + + +
 +`, + { + pretendToBeVisual: true, + runScripts: 'outside-only', + url: 'http://localhost/workspace/search', + } + ); + const { window } = dom; + const observers: FakeObserver[] = []; + const bridgeCalls: unknown[] = []; + installFakePerformance(window, observers); + // See journey-renderer-probe.test-helpers.ts: tsx keeps names. + Object.defineProperty(window, '__name', { + configurable: true, + value: (target: unknown) => target, + }); + Object.defineProperty(window, 'electron', { + configurable: true, + value: Object.freeze({ + [JOURNEY_IPC_SENTINEL_METHOD]: (id: unknown) => { + bridgeCalls.push(id); + return Promise.resolve(null); + }, + }), + }); + const ticks = { count: 40 }; + Object.defineProperty(window, JOURNEY_CD_TICK_COUNTER_KEY, { + configurable: true, + value: ticks, + }); + const options = { + ...createSearchJourneyProbeOptions(QUERY), + quietMs: 30, + ...overrides, + }; + window.eval( + `(${searchJourneyProbeScript.toString()})(${JSON.stringify(options)})` + ); + const { document } = window; + return { + bridgeCalls, + input: document.querySelector('input') as HTMLInputElement, + observers, + results: document.querySelector('.results-container') as HTMLElement, + state: () => + JSON.parse( + JSON.stringify( + (window as unknown as Record)[ + options.stateKey + ] + ) + ) as SearchJourneyProbeState, + ticks, + window, + }; +} + +function wait(ms: number): Promise { + return new Promise((resolve) => setTimeout(resolve, ms)); +} + +/** A keydown in the input plus what the shell renders for it. */ +async function typeKey(fixture: SearchFixture, key: string): Promise { + fixture.input.dispatchEvent( + new fixture.window.KeyboardEvent('keydown', { bubbles: true, key }) + ); + fixture.input.setAttribute('data-value', fixture.input.value + key); + fixture.input.value += key; + await wait(0); +} + +function setQuery(fixture: SearchFixture, query: string): void { + fixture.window.history.replaceState( + null, + '', + `/workspace/search?q=${encodeURIComponent(query)}` + ); +} + +function addCards(fixture: SearchFixture, count: number): void { + for (let index = 0; index < count; index += 1) { + fixture.results.append( + fixture.window.document.createElement('app-content-card') + ); + } +} + +async function waitForFinal(fixture: SearchFixture): Promise { + const deadline = Date.now() + 2_000; + while (!fixture.state().final && Date.now() < deadline) { + await wait(5); + } +} + +test('search options use their own state key, sentinels and the query length', () => { + const options = createSearchJourneyProbeOptions(QUERY); + assert.equal(options.keystrokes, 6); + assert.equal(options.query, QUERY); + assert.equal(options.quietMs, 200); + assert.equal(options.stateKey, SEARCH_JOURNEY_PROBE_STATE_KEY); + assert.notEqual(options.stateKey, JOURNEY_PROBE_STATE_KEY); + assert.notEqual(options.stateKey, JOURNEY_PLAYBACK_PROBE_STATE_KEY); + assert.equal(options.startSentinelId, SEARCH_JOURNEY_START_SENTINEL_ID); + assert.equal(options.endSentinelId, SEARCH_JOURNEY_END_SENTINEL_ID); + assert.equal(options.sentinelMethod, JOURNEY_IPC_SENTINEL_METHOD); + assert.equal(options.cdTickCounterKey, JOURNEY_CD_TICK_COUNTER_KEY); +}); + +test('starts at the first keydown in the search box and buckets work per key', async () => { + const fixture = createSearchFixture(); + fixture.results.setAttribute('data-before', '1'); + await wait(0); + // A key elsewhere does not start the journey. + fixture.window.document.getElementById('elsewhere')?.dispatchEvent( + new fixture.window.KeyboardEvent('keydown', { + bubbles: true, + key: 'x', + }) + ); + assert.equal(fixture.state().start, null); + assert.deepEqual(fixture.bridgeCalls, []); + + for (const key of QUERY) { + fixture.ticks.count += 1; + await typeKey(fixture, key); + } + let state = fixture.state(); + assert.equal(state.preStart.domMutations, 1); + assert.deepEqual(fixture.bridgeCalls, [SEARCH_JOURNEY_START_SENTINEL_ID]); + assert.deepEqual( + state.keystrokes.map((key) => key.key), + [...QUERY] + ); + assert.deepEqual( + state.keystrokes.map((key) => key.ticks), + [41, 42, 43, 44, 45, 46] + ); + // One attribute record per key, each in its own bucket. + assert.deepEqual(state.domMutationsByKeystroke, [1, 1, 1, 1, 1, 1]); + + // The debounced term lands: results for the final query. + setQuery(fixture, QUERY); + fixture.ticks.count += 4; + addCards(fixture, 3); + await waitForFinal(fixture); + state = assertSearchJourneyProbeState(fixture.state()); + assert.equal(state.settle.status, 'quiet'); + assert.equal(state.settle.query, QUERY); + assert.equal(state.settle.cardCount, 3); + assert.equal(state.settle.ticks, 50); + assert.equal(state.capabilities.changeDetectionTicks, 'counted'); + assert.deepEqual(state.domMutationsByKeystroke, [1, 1, 1, 1, 1, 4]); + assert.equal(state.counters.domMutations, 9); + assert.equal(state.firstResult?.query, QUERY); + assert.equal(state.firstResult?.cardCount, 3); + assert.ok( + (state.settle.confirmedEpochMs ?? 0) - (state.settle.epochMs ?? 0) >= 25 + ); + assert.deepEqual(fixture.bridgeCalls, [ + SEARCH_JOURNEY_START_SENTINEL_ID, + SEARCH_JOURNEY_END_SENTINEL_ID, + ]); +}); + +test('does not settle on results for an intermediate term or while loading', async () => { + const fixture = createSearchFixture(); + for (const key of QUERY) { + await typeKey(fixture, key); + } + // Results of an earlier term are a first result, not the settle. + setQuery(fixture, 'syst'); + addCards(fixture, 2); + await wait(80); + let state = fixture.state(); + assert.equal(state.final, false); + assert.equal(state.firstResult?.query, 'syst'); + + // The final term's spinner keeps the window closed. + setQuery(fixture, QUERY); + const spinner = fixture.window.document.createElement('div'); + spinner.className = 'loading-state'; + fixture.window.document + .querySelector('app-search-results') + ?.append(spinner); + await wait(80); + assert.equal(fixture.state().final, false); + + spinner.remove(); + await waitForFinal(fixture); + state = assertSearchJourneyProbeState(fixture.state()); + assert.equal(state.settle.query, QUERY); + assert.equal(state.settle.cardCount, 2); +}); + +test('a mutation inside the quiet window restarts it', async () => { + const fixture = createSearchFixture({ quietMs: 60 }); + for (const key of QUERY) { + await typeKey(fixture, key); + } + setQuery(fixture, QUERY); + addCards(fixture, 1); + await wait(30); + addCards(fixture, 1); + const lastMutationAt = Date.now(); + await waitForFinal(fixture); + const state = assertSearchJourneyProbeState(fixture.state()); + assert.equal(state.settle.cardCount, 2); + assert.ok(Date.now() - lastMutationAt >= 55); +}); + +test('fails the iteration when results never settle', async () => { + const fixture = createSearchFixture({ settleTimeoutMs: 40 }); + for (const key of QUERY) { + await typeKey(fixture, key); + } + await waitForFinal(fixture); + const state = fixture.state(); + assert.equal(state.settle.status, 'timeout'); + assert.throws( + () => assertSearchJourneyProbeState(state), + /search-journey-probe-invalid: settle-timeout/ + ); +}); + +test('flags a keystroke beyond the expected count', async () => { + const fixture = createSearchFixture({ keystrokes: 2 }); + await typeKey(fixture, 'a'); + await typeKey(fixture, 'b'); + await typeKey(fixture, 'c'); + assert.deepEqual(fixture.state().invalidReasons, ['unexpected-keystroke']); +}); + +test('counts shifts and long tasks from the first key until the settle only', async () => { + const fixture = createSearchFixture(); + const shifts = fixture.observers.find( + (observer) => observer.type === 'layout-shift' + ); + const tasks = fixture.observers.find( + (observer) => observer.type === 'longtask' + ); + assert.ok(shifts && tasks); + // Buffered launch entries before the first key are dropped. + shifts.emit([{ entryType: 'layout-shift', startTime: 0, value: 0.5 }]); + tasks.emit([{ duration: 60, entryType: 'longtask', startTime: 0 }]); + // jsdom's clock starts with the fixture: let that task end first. + await wait(100); + for (const key of QUERY) { + await typeKey(fixture, key); + } + const now = fixture.window.performance.now(); + shifts.emit([ + { + entryType: 'layout-shift', + hadRecentInput: true, + startTime: now, + value: 0.02, + }, + { entryType: 'layout-shift', startTime: now, value: 0.01 }, + ]); + tasks.emit([ + { duration: 30, entryType: 'longtask', startTime: now }, + { duration: 80, entryType: 'longtask', startTime: now }, + ]); + setQuery(fixture, QUERY); + addCards(fixture, 1); + await waitForFinal(fixture); + const state = assertSearchJourneyProbeState(fixture.state()); + assert.equal(state.counters.recentInputLayoutShiftScore, 0.02); + assert.equal(state.counters.layoutShiftScore, 0.01); + assert.equal(state.counters.longTasks, 1); + assert.deepEqual(state.longTaskDurationsMs, [80]); + assert.ok(shifts.disconnected && tasks.disconnected); +}); + +test('rejects a state without the tick counter or the end sentinel', () => { + assert.throws( + () => assertSearchJourneyProbeState({ schemaVersion: 1 }), + /search-journey-probe-incomplete/ + ); + const base = { + capabilities: { layoutShift: true, longTask: true }, + final: true, + invalidReasons: [], + schemaVersion: 1, + sentinel: { status: 'bridge-missing' }, + start: { sentinelStatus: 'sent' }, + }; + assert.throws( + () => assertSearchJourneyProbeState(base), + /search-journey-probe-sentinel-bridge-missing/ + ); + assert.throws( + () => + assertSearchJourneyProbeState({ + ...base, + capabilities: { layoutShift: false, longTask: true }, + sentinel: { status: 'sent' }, + }), + /search-journey-probe-observer-unavailable/ + ); +}); diff --git a/apps/electron-backend-e2e/src/performance/search-journey-probe.ts b/apps/electron-backend-e2e/src/performance/search-journey-probe.ts new file mode 100644 index 000000000..3bef31100 --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/search-journey-probe.ts @@ -0,0 +1,507 @@ +import type { Page } from '@playwright/test'; + +import { + JOURNEY_CD_TICK_COUNTER_KEY, + JOURNEY_IPC_SENTINEL_METHOD, +} from './journey-renderer-probe'; + +/** + * Renderer-side probe for J4 "Search" (docs/architecture/performance-journeys.md). + * + * Armed in the loaded `/workspace/search` document after the header search + * input has focus. A capture-phase `keydown` listener on `window`, which runs + * before every listener of the app, stamps each keystroke in the input; the + * first one starts the journey and sends the start sentinel + * (`cancelSourceProbe`, as in J2 and J3). DOM mutation records and + * change-detection ticks are bucketed by the keystroke they follow, so the + * debounce behaviour is visible per key. + * + * End: after the last expected keystroke, the results for the final term are + * shown (URL `q` equals the query, a result card is visible and no loading + * state is rendered) and then no DOM mutation arrives for `quietMs`. The + * settled moment is the last mutation before that quiet window; the counters + * run until the quiet window is confirmed, when the end sentinel is sent. A + * plain "quiet after the last keystroke" would close inside the shell's + * debounce before any query ran. Without a settle by `settleTimeoutMs` + * after the last keystroke the iteration is invalid. + * + * The script must stay self-contained: Playwright serializes it with + * `toString()`, so it may only use its argument and browser globals. + */ +export const SEARCH_JOURNEY_PROBE_STATE_KEY = '__iptvnatorJourneySearchProbe'; +export const SEARCH_JOURNEY_PROBE_SCHEMA_VERSION = 1; +export const SEARCH_JOURNEY_START_SENTINEL_ID = + '__iptvnator-journey-search-start__'; +export const SEARCH_JOURNEY_END_SENTINEL_ID = + '__iptvnator-journey-search-end__'; +/** The workspace shell header's search box. */ +export const SEARCH_JOURNEY_INPUT_SELECTOR = + 'app-workspace-shell-header .search-field input[type="search"]'; +/** A rendered global search result (grouped or flat). */ +export const SEARCH_JOURNEY_RESULT_SELECTOR = + 'app-search-results .results-container app-content-card'; +/** The search layout's spinner while a query runs. */ +export const SEARCH_JOURNEY_LOADING_SELECTOR = + 'app-search-results .loading-state'; +export const SEARCH_JOURNEY_ROUTE_PATH = '/workspace/search'; +export const SEARCH_JOURNEY_QUIET_MS = 200; +export const SEARCH_JOURNEY_SETTLE_TIMEOUT_MS = 15_000; + +export interface SearchJourneyProbeOptions { + readonly cdTickCounterKey: string; + readonly endSentinelId: string; + readonly inputSelector: string; + /** Keystrokes the test types; the settle waits for the last one. */ + readonly keystrokes: number; + readonly loadingSelector: string; + /** Term the URL `q` must carry when the results count as final. */ + readonly query: string; + readonly quietMs: number; + readonly resultSelector: string; + /** The route the results must be on; the renderer path ends with it. */ + readonly routePath: string; + readonly sentinelMethod: string; + /** Hard limit from the last keystroke to the settle. */ + readonly settleTimeoutMs: number; + readonly startSentinelId: string; + readonly stateKey: string; +} + +export interface SearchJourneyProbeKeystroke { + /** `min(event.timeStamp, listener time)` as epoch milliseconds. */ + readonly epochMs: number; + readonly key: string; + /** Running tick total at the keydown, before the app handles it. */ + readonly ticks: number | null; +} + +export type SentinelStatus = 'bridge-missing' | 'failed' | 'not-sent' | 'sent'; + +export interface SearchJourneyProbeState { + readonly capabilities: { + changeDetectionTicks: + 'counted' | 'pending' | 'unavailable-counter-missing'; + layoutShift: boolean; + longTask: boolean; + }; + readonly counters: { + domMutations: number; + layoutShiftScore: number; + longTasks: number; + /** Shifts with `hadRecentInput === true`; typing is input. */ + recentInputLayoutShiftScore: number; + }; + /** Mutation records after each keystroke, until the next or the end. */ + readonly domMutationsByKeystroke: number[]; + final: boolean; + /** First batch with a visible result card, for any term. */ + firstResult: { + readonly cardCount: number; + readonly epochMs: number; + readonly query: string | null; + } | null; + readonly invalidReasons: string[]; + readonly keystrokes: SearchJourneyProbeKeystroke[]; + readonly longTaskDurationsMs: number[]; + readonly preStart: { + domMutations: number; + lastMutationEpochMs: number | null; + }; + readonly schemaVersion: number; + sentinel: { epochMs: number | null; status: SentinelStatus }; + settle: { + cardCount: number; + /** When the quiet window was confirmed; the counters stop here. */ + confirmedEpochMs: number | null; + /** Last mutation batch before the quiet window: "settled". */ + epochMs: number | null; + query: string | null; + status: 'pending' | 'quiet' | 'timeout'; + ticks: number | null; + }; + start: { + readonly epochMs: number; + readonly pathname: string; + readonly sentinelStatus: SentinelStatus; + } | null; +} + +export function searchJourneyProbeScript( + options: SearchJourneyProbeOptions +): void { + const target = globalThis as unknown as Record; + if (target[options.stateKey] !== undefined) { + return; + } + const epoch = (): number => performance.timeOrigin + performance.now(); + const bridge = target['electron'] as Record | undefined; + const state: SearchJourneyProbeState = { + capabilities: { + changeDetectionTicks: 'pending', + layoutShift: false, + longTask: false, + }, + counters: { + domMutations: 0, + layoutShiftScore: 0, + longTasks: 0, + recentInputLayoutShiftScore: 0, + }, + domMutationsByKeystroke: [], + final: false, + firstResult: null, + invalidReasons: [], + keystrokes: [], + longTaskDurationsMs: [], + preStart: { domMutations: 0, lastMutationEpochMs: null }, + schemaVersion: 1, + sentinel: { epochMs: null, status: 'not-sent' }, + settle: { + cardCount: 0, + confirmedEpochMs: null, + epochMs: null, + query: null, + status: 'pending', + ticks: null, + }, + start: null, + }; + target[options.stateKey] = state; + const readTicks = (): number | null => { + const counter = target[options.cdTickCounterKey] as + { count?: unknown } | undefined; + return typeof counter?.count === 'number' ? counter.count : null; + }; + const callSentinel = (id: string): SentinelStatus => { + const method = bridge?.[options.sentinelMethod]; + if (typeof method !== 'function') return 'bridge-missing'; + try { + void Promise.resolve(method.call(bridge, id)).catch( + () => undefined + ); + return 'sent'; + } catch { + return 'failed'; + } + }; + const readQuery = (): string | null => + new URLSearchParams(location.search).get('q'); + const visibleCards = (): number => { + let count = 0; + for (const card of Array.from( + document.querySelectorAll(options.resultSelector) + )) { + if (card.getClientRects().length > 0) count += 1; + } + return count; + }; + + // Entries before the first keystroke belong to the launch (buffered + // entries included) and are dropped. + let fromEpochMs = Number.POSITIVE_INFINITY; + const shifts: PerformanceEntry[] = []; + const tasks: PerformanceEntry[] = []; + const observe = ( + type: string, + sink: PerformanceEntry[] + ): PerformanceObserver | null => { + try { + const observer = new PerformanceObserver((list) => { + if (!state.final) sink.push(...list.getEntries()); + }); + observer.observe({ type, buffered: true }); + return observer; + } catch { + return null; + } + }; + const shiftObserver = observe('layout-shift', shifts); + const taskObserver = observe('longtask', tasks); + state.capabilities.layoutShift = shiftObserver !== null; + state.capabilities.longTask = taskObserver !== null; + + const countEntries = (untilEpochMs: number): void => { + if (shiftObserver) shifts.push(...shiftObserver.takeRecords()); + if (taskObserver) tasks.push(...taskObserver.takeRecords()); + shiftObserver?.disconnect(); + taskObserver?.disconnect(); + for (const entry of shifts) { + const shift = entry as PerformanceEntry & { + hadRecentInput?: boolean; + value?: number; + }; + const at = performance.timeOrigin + entry.startTime; + if ( + typeof shift.value !== 'number' || + at < fromEpochMs || + at > untilEpochMs + ) { + continue; + } + if (shift.hadRecentInput === true) { + state.counters.recentInputLayoutShiftScore += shift.value; + } else { + state.counters.layoutShiftScore += shift.value; + } + } + // A task overlaps the window when it ends after the first keydown: + // the task that dispatched it still counts. + for (const entry of tasks) { + const at = performance.timeOrigin + entry.startTime; + if ( + entry.duration <= 50 || + at + entry.duration < fromEpochMs || + at > untilEpochMs + ) { + continue; + } + state.counters.longTasks += 1; + state.longTaskDurationsMs.push(entry.duration); + } + }; + + let quietTimer: ReturnType | undefined; + let timeoutTimer: ReturnType | undefined; + let lastMutationEpochMs: number | null = null; + const accept = (count: number): void => { + if (count === 0) return; + if (state.start === null) { + state.preStart.domMutations += count; + state.preStart.lastMutationEpochMs = epoch(); + return; + } + state.counters.domMutations += count; + const bucket = state.keystrokes.length - 1; + state.domMutationsByKeystroke[bucket] = + (state.domMutationsByKeystroke[bucket] ?? 0) + count; + lastMutationEpochMs = epoch(); + }; + const ready = (): boolean => + location.pathname.endsWith(options.routePath) && + readQuery() === options.query && + document.querySelector(options.loadingSelector) === null && + visibleCards() > 0; + const end = (status: 'quiet' | 'timeout'): void => { + if (state.settle.status !== 'pending') return; + clearTimeout(quietTimer); + clearTimeout(timeoutTimer); + accept(mutationObserver.takeRecords().length); + mutationObserver.disconnect(); + const confirmedEpochMs = epoch(); + const ticks = readTicks(); + state.settle = { + cardCount: visibleCards(), + confirmedEpochMs, + epochMs: lastMutationEpochMs, + query: readQuery(), + status, + ticks, + }; + if (status === 'timeout') { + // What the ready condition saw, so a timeout says which part + // never held. + const input = document.querySelector(options.inputSelector); + state.invalidReasons.push( + `settle-timeout ${JSON.stringify({ + cards: visibleCards(), + input: + input instanceof HTMLInputElement ? input.value : null, + loading: + document.querySelector(options.loadingSelector) !== + null, + path: location.pathname.slice(-40), + q: readQuery(), + view: + document.querySelector( + 'app-search-results .results-container' + )?.firstElementChild?.className ?? null, + })}` + ); + } + state.capabilities.changeDetectionTicks = + ticks === null || state.keystrokes[0]?.ticks === null + ? 'unavailable-counter-missing' + : 'counted'; + countEntries(confirmedEpochMs); + const sentinelStatus = callSentinel(options.endSentinelId); + state.sentinel = { + epochMs: sentinelStatus === 'sent' ? epoch() : null, + status: sentinelStatus, + }; + window.removeEventListener('keydown', onKeydown, true); + state.final = true; + }; + const mutationObserver = new MutationObserver((records) => { + if (state.settle.status !== 'pending') return; + accept(records.length); + if (state.start === null) return; + if (state.firstResult === null) { + const cardCount = visibleCards(); + if (cardCount > 0) { + state.firstResult = { + cardCount, + epochMs: epoch(), + query: readQuery(), + }; + } + } + // Every batch after the last keystroke restarts the quiet window, + // which only opens once the final term's results are shown. + clearTimeout(quietTimer); + if (state.keystrokes.length >= options.keystrokes && ready()) { + quietTimer = setTimeout(() => end('quiet'), options.quietMs); + } + }); + mutationObserver.observe(document.documentElement ?? document, { + attributes: true, + characterData: true, + childList: true, + subtree: true, + }); + + // Capture phase on window runs before every listener of the app, so the + // start sentinel precedes any bridge call the first key causes, and the + // records queued before a key belong to the previous bucket. + const onKeydown = (event: Event): void => { + const origin = + event.target instanceof Element + ? event.target.closest(options.inputSelector) + : null; + if (origin === null || state.settle.status !== 'pending') return; + if (state.keystrokes.length >= options.keystrokes) { + state.invalidReasons.push('unexpected-keystroke'); + return; + } + accept(mutationObserver.takeRecords().length); + const listenerEpochMs = epoch(); + const eventEpochMs = performance.timeOrigin + event.timeStamp; + const epochMs = + Number.isFinite(eventEpochMs) && eventEpochMs <= listenerEpochMs + ? eventEpochMs + : listenerEpochMs; + if (state.start === null) { + state.start = { + epochMs, + pathname: location.pathname, + sentinelStatus: callSentinel(options.startSentinelId), + }; + fromEpochMs = epochMs; + } + state.keystrokes.push({ + epochMs, + key: (event as KeyboardEvent).key ?? '', + ticks: readTicks(), + }); + state.domMutationsByKeystroke.push(0); + if (state.keystrokes.length === options.keystrokes) { + timeoutTimer = setTimeout( + () => end('timeout'), + options.settleTimeoutMs + ); + } + }; + window.addEventListener('keydown', onKeydown, true); +} + +export function createSearchJourneyProbeOptions( + query: string +): SearchJourneyProbeOptions { + return { + cdTickCounterKey: JOURNEY_CD_TICK_COUNTER_KEY, + endSentinelId: SEARCH_JOURNEY_END_SENTINEL_ID, + inputSelector: SEARCH_JOURNEY_INPUT_SELECTOR, + keystrokes: query.length, + loadingSelector: SEARCH_JOURNEY_LOADING_SELECTOR, + query, + quietMs: SEARCH_JOURNEY_QUIET_MS, + resultSelector: SEARCH_JOURNEY_RESULT_SELECTOR, + routePath: SEARCH_JOURNEY_ROUTE_PATH, + sentinelMethod: JOURNEY_IPC_SENTINEL_METHOD, + settleTimeoutMs: SEARCH_JOURNEY_SETTLE_TIMEOUT_MS, + startSentinelId: SEARCH_JOURNEY_START_SENTINEL_ID, + stateKey: SEARCH_JOURNEY_PROBE_STATE_KEY, + }; +} + +export async function armSearchJourneyProbe( + page: Page, + options: SearchJourneyProbeOptions +): Promise { + await page.evaluate(searchJourneyProbeScript, options); +} + +export async function readSearchJourneyPreStartMutations( + page: Page, + stateKey: string +): Promise { + return page.evaluate((key) => { + const state = (globalThis as unknown as Record)[ + key + ] as { preStart?: { domMutations?: number } } | undefined; + const count = state?.preStart?.domMutations; + if (typeof count !== 'number') { + throw new Error('search-journey-probe-not-armed'); + } + return count; + }, stateKey); +} + +export async function waitForSearchJourneyProbe( + page: Page, + stateKey: string, + timeoutMs: number +): Promise { + await page.waitForFunction( + (key) => + ( + (globalThis as unknown as Record)[key] as + { final?: boolean } | undefined + )?.final === true, + stateKey, + { polling: 50, timeout: timeoutMs } + ); + const state = await page.evaluate( + (key) => + JSON.parse( + JSON.stringify( + (globalThis as unknown as Record)[key] + ) + ) as unknown, + stateKey + ); + return assertSearchJourneyProbeState(state); +} + +export function assertSearchJourneyProbeState( + value: unknown +): SearchJourneyProbeState { + const state = value as SearchJourneyProbeState | null; + if ( + !state || + state.schemaVersion !== SEARCH_JOURNEY_PROBE_SCHEMA_VERSION || + state.final !== true || + state.start === null + ) { + throw new Error('search-journey-probe-incomplete'); + } + if (state.invalidReasons.length > 0) { + throw new Error( + `search-journey-probe-invalid: ${state.invalidReasons.join(', ')}` + ); + } + if (state.start.sentinelStatus !== 'sent') { + throw new Error( + `search-journey-probe-start-sentinel-${state.start.sentinelStatus}` + ); + } + if (state.sentinel.status !== 'sent') { + throw new Error( + `search-journey-probe-sentinel-${state.sentinel.status}` + ); + } + // A zero from an observer that never ran is not a measurement. + if (!state.capabilities.layoutShift || !state.capabilities.longTask) { + throw new Error('search-journey-probe-observer-unavailable'); + } + return state; +} diff --git a/apps/electron-backend-e2e/src/performance/search-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/search-journey-record.spec.ts new file mode 100644 index 000000000..0d832a5ee --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/search-journey-record.spec.ts @@ -0,0 +1,328 @@ +import assert from 'node:assert/strict'; +import test from 'node:test'; + +import type { JourneyMainIpcCaptureState } from './journey-main-ipc-capture'; +import { summarizeJourneyIterations } from './journey-summary'; +import type { SearchJourneyProbeState } from './search-journey-probe'; +import { + SEARCH_JOURNEY_COUNTER, + SEARCH_JOURNEY_UNAVAILABLE_COUNTERS, + SEARCH_JOURNEY_WALL_CLOCK, + toSearchIterationRecord, + type SearchJourneyActivitySample, + type SearchJourneyMeasurement, +} from './search-journey-record'; + +const QUERY = 'system'; + +function sample( + ipcCalls: number, + queryCalls: number, + sqlStatements: number +): SearchJourneyActivitySample { + return { ipcCalls, queryCalls, sqlStatements }; +} + +/** The shape of a debounced search: only the last key runs a query. */ +function measurement( + overrides: Partial = {}, + rendererOverrides: Partial = {} +): SearchJourneyMeasurement { + const keystrokes = [...QUERY].map((key, position) => ({ + epochMs: 10_000 + position * 100, + key, + ticks: 40 + position, + })); + const renderer: SearchJourneyProbeState = { + capabilities: { + changeDetectionTicks: 'counted', + layoutShift: true, + longTask: true, + }, + counters: { + domMutations: 402, + layoutShiftScore: 0.0004, + longTasks: 0, + recentInputLayoutShiftScore: 0.0011, + }, + domMutationsByKeystroke: [0, 0, 0, 0, 0, 402], + final: true, + firstResult: { cardCount: 100, epochMs: 11_180, query: QUERY }, + invalidReasons: [], + keystrokes, + longTaskDurationsMs: [], + preStart: { domMutations: 5, lastMutationEpochMs: 8_000 }, + schemaVersion: 1, + sentinel: { epochMs: 11_400, status: 'sent' }, + settle: { + cardCount: 100, + confirmedEpochMs: 11_399.6, + epochMs: 11_192.54, + query: QUERY, + status: 'quiet', + ticks: 54, + }, + start: { + epochMs: 10_000, + pathname: '/w/search', + sentinelStatus: 'sent', + }, + ...rendererOverrides, + }; + const ipc: JourneyMainIpcCaptureState = { + ambiguousTimelineCompletions: 0, + callsAfterSentinel: 0, + callsBeforeStart: 0, + callsBeforeSentinel: 1, + callsByMethod: { dbGlobalSearch: 1 }, + inFlightByMethod: {}, + installedEpochMs: 9_000, + malformedEvents: 0, + processStartEpochMs: 1_000, + senderIds: [1], + sentinel: { occurrences: 1, receivedEpochMs: 11_401 }, + start: { occurrences: 1, receivedEpochMs: 10_001 }, + timeline: [ + { method: 'dbGlobalSearch', phase: 'start' }, + { method: 'dbGlobalSearch', phase: 'end' }, + ], + unmatchedCompletions: 0, + }; + return { + afterSettled: sample(1, 1, 121), + afterSettledWindowMs: 500, + externalArtworkCancelled: 42, + ipc, + keyDelayMs: 100, + pid: 4242, + query: QUERY, + renderer, + samples: [ + sample(0, 0, 119), + sample(0, 0, 119), + sample(0, 0, 119), + sample(0, 0, 119), + sample(0, 0, 119), + sample(0, 0, 119), + sample(1, 1, 121), + ], + settle: { + preStartDomMutations: 5, + preStartIpcCalls: 0, + quietMs: 1_000, + sqlStatements: 119, + waitedMs: 1_226, + }, + ...overrides, + }; +} + +test('maps a settled search to exact counters and wall-clock', () => { + const record = toSearchIterationRecord(1, false, measurement()); + assert.deepEqual(record.counters, { + [SEARCH_JOURNEY_COUNTER.CD_TICKS]: 14, + [SEARCH_JOURNEY_COUNTER.DOM_MUTATIONS]: 402, + [SEARCH_JOURNEY_COUNTER.IPC_CALLS]: 1, + [SEARCH_JOURNEY_COUNTER.IPC_SERIAL_DEPTH]: 1, + [SEARCH_JOURNEY_COUNTER.LAYOUT_SHIFT_SCORE]: 0.002, + [SEARCH_JOURNEY_COUNTER.LONG_TASKS]: 0, + [SEARCH_JOURNEY_COUNTER.SQL_STATEMENTS]: 2, + }); + assert.deepEqual(record.wallClock, { + [SEARCH_JOURNEY_WALL_CLOCK.FIRST_KEYSTROKE_TO_FIRST_RESULT]: 1_180, + [SEARCH_JOURNEY_WALL_CLOCK.LAST_KEYSTROKE_TO_SETTLED]: 692.5, + }); + assert.equal(record.pid, 4242); + assert.equal(record.warmup, false); +}); + +test('breaks every counter down by keystroke', () => { + const record = toSearchIterationRecord(1, false, measurement()); + const perKeystroke = record.evidence['perKeystroke'] as { + cdTicks: number; + domMutations: number; + ipcCalls: number; + key: string; + queryCalls: number; + sqlStatements: number; + }[]; + assert.deepEqual( + perKeystroke.map((entry) => entry.key), + [...QUERY] + ); + assert.deepEqual( + perKeystroke.map((entry) => entry.cdTicks), + [1, 1, 1, 1, 1, 9] + ); + assert.deepEqual( + perKeystroke.map((entry) => entry.queryCalls), + [0, 0, 0, 0, 0, 1] + ); + assert.deepEqual( + perKeystroke.map((entry) => entry.sqlStatements), + [0, 0, 0, 0, 0, 2] + ); + assert.deepEqual( + perKeystroke.map((entry) => entry.domMutations), + [0, 0, 0, 0, 0, 402] + ); + assert.deepEqual(record.evidence['sqlStatementsAfterSettled'], { + count: 0, + windowMs: 500, + }); + assert.deepEqual(record.evidence['ipcTimeline'], [ + '+dbGlobalSearch', + '-dbGlobalSearch', + ]); +}); + +test('a query per keystroke shows up per key, not only in the total', () => { + const record = toSearchIterationRecord( + 1, + false, + measurement({ + samples: [ + sample(0, 0, 100), + sample(0, 0, 100), + sample(1, 1, 102), + sample(2, 2, 104), + sample(3, 3, 106), + sample(4, 4, 108), + sample(5, 5, 110), + ], + settle: { + preStartDomMutations: 5, + preStartIpcCalls: 0, + quietMs: 1_000, + sqlStatements: 100, + waitedMs: 1_000, + }, + ipc: { + ...measurement().ipc, + callsBeforeSentinel: 5, + callsByMethod: { dbGlobalSearch: 5 }, + }, + }) + ); + assert.equal(record.counters[SEARCH_JOURNEY_COUNTER.IPC_CALLS], 5); + assert.equal(record.counters[SEARCH_JOURNEY_COUNTER.SQL_STATEMENTS], 10); + const perKeystroke = record.evidence['perKeystroke'] as { + queryCalls: number; + }[]; + assert.deepEqual( + perKeystroke.map((entry) => entry.queryCalls), + [0, 1, 1, 1, 1, 1] + ); +}); + +test('rejects iterations that did not measure a settled search', () => { + const cases: [Partial, RegExp][] = [ + [{ start: null }, /incomplete-probe/], + [ + { + settle: { ...measurement().renderer.settle, status: 'timeout' }, + }, + /incomplete-probe/, + ], + [ + { keystrokes: measurement().renderer.keystrokes.slice(1) }, + /keystroke-count/, + ], + [ + { + keystrokes: measurement().renderer.keystrokes.map((key) => ({ + ...key, + key: 'x', + })), + }, + /typed-text/, + ], + [ + { settle: { ...measurement().renderer.settle, query: 'syste' } }, + /no-results/, + ], + [{ firstResult: null }, /no-results/], + [ + { settle: { ...measurement().renderer.settle, epochMs: 9_000 } }, + /clock-order/, + ], + [{ preStart: { domMutations: 6, lastMutationEpochMs: 9_990 } }, /dom/], + [ + { + capabilities: { + changeDetectionTicks: 'unavailable-counter-missing', + layoutShift: true, + longTask: true, + }, + }, + /cd-ticks-unavailable-counter-missing/, + ], + ]; + for (const [overrides, error] of cases) { + assert.throws( + () => toSearchIterationRecord(1, false, measurement({}, overrides)), + error + ); + } +}); + +test('rejects work that moved between the quiet snapshot and the first key', () => { + const base = measurement(); + assert.throws( + () => + toSearchIterationRecord( + 1, + false, + measurement({ ipc: { ...base.ipc, callsBeforeStart: 1 } }) + ), + /activity-before-first-key-ipc/ + ); + assert.throws( + () => + toSearchIterationRecord( + 1, + false, + measurement({ + samples: [sample(0, 0, 120), ...base.samples.slice(1)], + }) + ), + /activity-before-first-key-sql/ + ); + assert.throws( + () => + toSearchIterationRecord( + 1, + false, + measurement({ + samples: [...base.samples.slice(0, 6), sample(2, 1, 121)], + }) + ), + /ipc-sample-mismatch/ + ); +}); + +test('summarizes with the shared summary and nothing unavailable', () => { + const iterations = [0, 1, 2].map((index) => + toSearchIterationRecord( + index, + index === 0, + measurement({ pid: 4_000 + index }) + ) + ); + const entry = summarizeJourneyIterations( + iterations, + SEARCH_JOURNEY_UNAVAILABLE_COUNTERS + ); + assert.equal(entry.counters[SEARCH_JOURNEY_COUNTER.IPC_CALLS], 1); + assert.equal( + entry.counterStability[SEARCH_JOURNEY_COUNTER.SQL_STATEMENTS]?.stable, + true + ); + assert.equal( + entry.wallClock[ + `${SEARCH_JOURNEY_WALL_CLOCK.LAST_KEYSTROKE_TO_SETTLED}.p50` + ], + 692.5 + ); + assert.deepEqual(entry.unavailable, {}); +}); diff --git a/apps/electron-backend-e2e/src/performance/search-journey-record.ts b/apps/electron-backend-e2e/src/performance/search-journey-record.ts new file mode 100644 index 000000000..1c92adfd8 --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/search-journey-record.ts @@ -0,0 +1,240 @@ +import { computeJourneyIpcSerialDepth } from './journey-ipc-serial-depth'; +import type { JourneyMainIpcCaptureState } from './journey-main-ipc-capture'; +import type { JourneyIterationRecord } from './journey-summary'; +import type { SearchJourneyProbeState } from './search-journey-probe'; + +/** + * Maps one measured global search (renderer probe from the first keystroke + * until the results settled, main IPC capture between the start and end + * sentinels, main-process activity sampled before every keystroke) to the + * journey summary's iteration record for J4. + */ +export const SEARCH_JOURNEY_ID = 'search'; + +export const SEARCH_JOURNEY_COUNTER = { + CD_TICKS: 'renderer.cdTicksToResults', + DOM_MUTATIONS: 'renderer.domMutationsToResults', + IPC_CALLS: 'renderer.ipcCallsPerSearch', + IPC_SERIAL_DEPTH: 'renderer.ipcSerialDepthToResults', + LAYOUT_SHIFT_SCORE: 'renderer.layoutShiftScore', + LONG_TASKS: 'renderer.longTasks', + SQL_STATEMENTS: 'renderer.sqlStatementsPerSearch', +} as const; + +export const SEARCH_JOURNEY_WALL_CLOCK = { + FIRST_KEYSTROKE_TO_FIRST_RESULT: 'firstKeystrokeToFirstResultMs', + LAST_KEYSTROKE_TO_SETTLED: 'lastKeystrokeToSettledMs', +} as const; + +export const SEARCH_JOURNEY_UNAVAILABLE_COUNTERS: Readonly< + Record +> = Object.freeze({}); + +/** Bridge method of a global search query (`DatabaseService`). */ +export const SEARCH_JOURNEY_QUERY_METHOD = 'dbGlobalSearch'; + +/** + * Main-process activity read in one synchronous pass: the journey capture's + * call counts and the running `main.sqlStatements` total. + */ +export interface SearchJourneyActivitySample { + readonly ipcCalls: number; + readonly queryCalls: number; + readonly sqlStatements: number; +} + +/** How long the app was left alone before the first keystroke. */ +export interface SearchJourneySettle { + readonly preStartDomMutations: number; + readonly preStartIpcCalls: number; + readonly quietMs: number; + readonly sqlStatements: number; + readonly waitedMs: number; +} + +export interface SearchJourneyMeasurement { + readonly externalArtworkCancelled: number; + readonly ipc: JourneyMainIpcCaptureState; + readonly keyDelayMs: number; + readonly pid: number; + readonly query: string; + readonly renderer: SearchJourneyProbeState; + /** + * Before each keystroke (index i before key i + 1), then once after the + * probe settled and once more `afterSettledWindowMs` later. + */ + readonly samples: readonly SearchJourneyActivitySample[]; + readonly afterSettled: SearchJourneyActivitySample; + readonly afterSettledWindowMs: number; + readonly settle: SearchJourneySettle; +} + +function roundTenth(value: number): number { + return Math.round(value * 10) / 10; +} + +function roundThousandth(value: number): number { + return Math.round(value * 1_000) / 1_000; +} + +function difference( + samples: readonly SearchJourneyActivitySample[], + index: number, + key: keyof SearchJourneyActivitySample +): number { + return samples[index + 1][key] - samples[index][key]; +} + +export function toSearchIterationRecord( + index: number, + warmup: boolean, + measurement: SearchJourneyMeasurement +): JourneyIterationRecord { + const { ipc, renderer, samples, settle } = measurement; + const { keystrokes, start } = renderer; + const keys = measurement.query.length; + if (start === null || renderer.settle.status !== 'quiet') { + throw new Error('search-journey-record-incomplete-probe'); + } + if (ipc.start === null) { + throw new Error('search-journey-record-ipc-without-start'); + } + if (keystrokes.length !== keys || samples.length !== keys + 1) { + throw new Error('search-journey-record-keystroke-count'); + } + if (keystrokes.map((key) => key.key).join('') !== measurement.query) { + throw new Error('search-journey-record-typed-text'); + } + if ( + renderer.settle.query !== measurement.query || + renderer.settle.cardCount === 0 || + renderer.firstResult === null + ) { + throw new Error('search-journey-record-no-results'); + } + const settledEpochMs = renderer.settle.epochMs; + const lastKeyEpochMs = keystrokes[keys - 1].epochMs; + if ( + settledEpochMs === null || + settledEpochMs < lastKeyEpochMs || + renderer.firstResult.epochMs < start.epochMs + ) { + throw new Error('search-journey-record-clock-order'); + } + // Activity between the quiet snapshot and the first key could finish + // after it and be counted as the search's. The probe and the capture + // keep counting until the first keydown, so they must still match it. + const moved = [ + renderer.preStart.domMutations !== settle.preStartDomMutations + ? 'dom' + : null, + ipc.callsBeforeStart !== settle.preStartIpcCalls ? 'ipc' : null, + samples[0].sqlStatements !== settle.sqlStatements ? 'sql' : null, + ].filter((kind): kind is string => kind !== null); + if (moved.length > 0) { + throw new Error( + `search-journey-record-activity-before-first-key-${moved.join('-')}` + ); + } + const finalSample = samples[keys]; + if (finalSample.ipcCalls !== ipc.callsBeforeSentinel) { + throw new Error('search-journey-record-ipc-sample-mismatch'); + } + const settleTicks = renderer.settle.ticks; + const ticks = keystrokes.map((key) => key.ticks); + if ( + renderer.capabilities.changeDetectionTicks !== 'counted' || + settleTicks === null || + ticks.some((value) => value === null) + ) { + throw new Error( + `search-journey-record-cd-ticks-${renderer.capabilities.changeDetectionTicks}` + ); + } + const tickAt = (position: number): number => + position < keys ? (ticks[position] as number) : settleTicks; + const serialDepth = computeJourneyIpcSerialDepth(ipc.timeline); + const perKeystroke = keystrokes.map((key, position) => + Object.freeze({ + atMs: roundTenth(key.epochMs - start.epochMs), + cdTicks: tickAt(position + 1) - tickAt(position), + domMutations: renderer.domMutationsByKeystroke[position] ?? 0, + ipcCalls: difference(samples, position, 'ipcCalls'), + key: key.key, + queryCalls: difference(samples, position, 'queryCalls'), + sqlStatements: difference(samples, position, 'sqlStatements'), + }) + ); + return Object.freeze({ + counters: Object.freeze({ + [SEARCH_JOURNEY_COUNTER.CD_TICKS]: settleTicks - tickAt(0), + [SEARCH_JOURNEY_COUNTER.DOM_MUTATIONS]: + renderer.counters.domMutations, + [SEARCH_JOURNEY_COUNTER.IPC_CALLS]: ipc.callsBeforeSentinel, + [SEARCH_JOURNEY_COUNTER.IPC_SERIAL_DEPTH]: serialDepth.depth, + // Typing is input, so shifts flagged hadRecentInput are + // included, as in J2 and J3. + [SEARCH_JOURNEY_COUNTER.LAYOUT_SHIFT_SCORE]: roundThousandth( + renderer.counters.layoutShiftScore + + renderer.counters.recentInputLayoutShiftScore + ), + [SEARCH_JOURNEY_COUNTER.LONG_TASKS]: renderer.counters.longTasks, + [SEARCH_JOURNEY_COUNTER.SQL_STATEMENTS]: + finalSample.sqlStatements - samples[0].sqlStatements, + }), + evidence: Object.freeze({ + capabilities: renderer.capabilities, + epochs: Object.freeze({ + firstKeystroke: start.epochMs, + firstResult: renderer.firstResult.epochMs, + lastKeystroke: lastKeyEpochMs, + mainIpcSentinel: ipc.sentinel.receivedEpochMs, + mainIpcStart: ipc.start.receivedEpochMs, + settleConfirmed: renderer.settle.confirmedEpochMs, + settled: settledEpochMs, + }), + externalArtworkCancelled: measurement.externalArtworkCancelled, + firstResult: Object.freeze({ + cardCount: renderer.firstResult.cardCount, + query: renderer.firstResult.query, + }), + ipcCallsAfterSettled: ipc.callsAfterSentinel, + ipcCallsByMethod: ipc.callsByMethod, + ipcSerialDepth: serialDepth, + ipcTimeline: ipc.timeline.map( + (event) => + `${event.phase === 'start' ? '+' : '-'}${event.method}` + ), + keyDelayMs: measurement.keyDelayMs, + layoutShift: Object.freeze({ + recentInput: roundThousandth( + renderer.counters.recentInputLayoutShiftScore + ), + withoutRecentInput: roundThousandth( + renderer.counters.layoutShiftScore + ), + }), + longTaskDurationsMs: renderer.longTaskDurationsMs.map(roundTenth), + perKeystroke, + query: measurement.query, + results: Object.freeze({ cardCount: renderer.settle.cardCount }), + settle, + sqlStatementsAfterSettled: Object.freeze({ + count: + measurement.afterSettled.sqlStatements - + finalSample.sqlStatements, + windowMs: measurement.afterSettledWindowMs, + }), + }), + index, + pid: measurement.pid, + wallClock: Object.freeze({ + [SEARCH_JOURNEY_WALL_CLOCK.FIRST_KEYSTROKE_TO_FIRST_RESULT]: + roundTenth(renderer.firstResult.epochMs - start.epochMs), + [SEARCH_JOURNEY_WALL_CLOCK.LAST_KEYSTROKE_TO_SETTLED]: roundTenth( + settledEpochMs - lastKeyEpochMs + ), + }), + warmup, + }); +} diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index 776e5c3dd..b177e1992 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -19,9 +19,9 @@ live in `tools/performance/`. | J4 `search` | six-character query typed into global search | results list settled | J1 is instrumented: `renderer.initialBytes` from the built output, and the -runtime counters of the launch benchmark below. J2 and J3 are instrumented by -their own specs (below). J4 follows the plan in `.plans/` and is added in its -own thread; each thread names its journey and counter in the PR description. +runtime counters of the launch benchmark below. J2, J3 and J4 are +instrumented by their own specs (below). Each thread names its journey and +counter in the PR description. ## Running the journeys @@ -291,10 +291,12 @@ registers the `performance:read-counters` IPC handler. Without the flag nothing is counted, no listener is attached and the handler does not exist; the preload never exposes the channel. SQL statements are counted only with `IPTVNATOR_PERF_COUNT_SQL=1` as well, because the hook wraps every statement -execution: the launch journey sets both (the flags are built in -`journey-launch-environment.ts`), while J2's launches and the M3U, refresh -and Xtream benchmarks do not set the SQL flag and keep measuring unwrapped -statements. A harness test fails if any other source sets the SQL flag. After the renderer probe completes, +execution: the launch journey and J4, which reports +`renderer.sqlStatementsPerSearch`, set both (the flags are built in +`journey-launch-environment.ts`), while J2's and J3's launches and the M3U, +refresh and Xtream benchmarks do not set the SQL flag and keep measuring +unwrapped statements. A harness test fails if any other source sets the SQL +flag. After the renderer probe completes, `journey-main-counters.ts` calls the handler through `electronApp.evaluate` and the gate's tap. @@ -554,6 +556,13 @@ iterations carry `evidence.media` (the video element at `playing`) and a `media` field (`null` for J1 and J2), which the probe's `schemaVersion` 1 readers ignore. +J4 adds the `journeys.search` entry, again with the same shape. Its +iterations carry `evidence.perKeystroke` (one entry per typed key, see +[J4](#j4-search-type-a-query-until-the-results-settle)), which the CI job +summary prints as a table for the first measured iteration. J4 has its own +renderer probe (`search-journey-probe.ts`, `schemaVersion` 1); the shared +probe is unchanged. + ## J2 `open-source`: open a source to a browsable list `open-source.journey.ts` reuses the J1 profile and process pattern: the @@ -782,6 +791,151 @@ machine, so check the runner's `counterStability` before trusting the mutation and request counts. No J3 baseline exists yet; J3 counters join the ratchet once three runner runs agree. +## J4 `search`: type a query until the results settle + +`search.journey.ts` follows J3: the profile is seeded once through the "Add +playlist" dialogs (`seedLaunchJourneyProfile` with `SEARCH_JOURNEY_SEED`), +every iteration copies it, spawns a fresh process through `runLaunchJourney` +and hands the running app to `measureSearchJourney` in +`src/journeys/search-journey-app.ts`. One warm-up and five measured +iterations. Unlike J2 and J3 the launch runs with the main-process counters +(`mainCounters: true`, so `IPTVNATOR_PERF_CAPTURE` and +`IPTVNATOR_PERF_COUNT_SQL`), because SQL statements are a J4 counter; every +statement then runs through the counting hook. + +**Profile.** J1's M3U source plus an Xtream portal ("Journey search portal") +on the mock's existing `large:large` scenario: 60 categories of 200 items, +so 4,000 live channels, 4,000 movies and 4,000 series. No fixture was added +for the journey. The query is `system`, which matches 170 series titles of +that deterministic catalog: more than global search's first page of 100, so +the page is full and more results are available. Six characters take the +title FTS path of `globalSearch` +(`apps/electron-backend/src/app/database/operations/content.operations.ts`); +the M3U arm runs as well, because live content is included, but none of the +four fixture channels matches. Poster artwork points at `picsum.photos` and +is cancelled in the main process as in J3 +(`src/performance/journey-external-artwork.ts`, shared by both journeys); +the count is kept as `evidence.externalArtworkCancelled`. The mock is not +put behind the request ledger: global search reads only the local database. + +**What typing does.** The header search box +(`app-workspace-shell-header .search-field input[type="search"]`) applies +its term after `SEARCH_INPUT_DEBOUNCE_MS` (350 ms, +`WorkspaceShellSearchSyncService`) and writes it to the URL as `q`. On +`/workspace/search` (`app.routes.ts`, Electron only) `SearchResultsComponent` +adopts `q` and runs `executeSearch` after its own 300 ms debounce, which +calls the `dbGlobalSearch` bridge method once with a limit of 101. + +**Start.** After J1 has ended, the test clicks the rail's **Global search** +link and focuses the header search box (not measured), installs the IPC +capture with a start sentinel, arms the probe +(`src/performance/search-journey-probe.ts`) and waits until the app has +been quiet for 1 s: no DOM mutation, no new or pending bridge call, and an +unchanged `main.sqlStatements` total (30 s timeout, which fails the +iteration). J1's capture is detached. The test then types the query with one +`keyboard.type` call per character on a fixed schedule, 100 ms apart from +the first key (well below the 350 ms debounce, as steady typing would be), +and samples the main process just before each key. The probe's +capture-phase `keydown` listener on `window` stamps every key in the search +box before the app sees it; the first one starts the journey and sends +`cancelSourceProbe('__iptvnator-journey-search-start__')`. The record +rejects an iteration whose DOM mutations, bridge calls or SQL statements +moved between the quiet snapshot and the first key. + +**End.** "No DOM mutation for 200 ms after the last keystroke" alone would +end inside the 650 ms of debounce, before any query ran: nothing in the DOM +changes while the term waits. So after the sixth key the probe waits for +the results of the final term to be shown (the path ends with +`/workspace/search`, the URL `q` is the query, no `.loading-state` is +rendered and an `app-content-card` in the results container is visible). The +mutation batch that first meets that condition opens a 200 ms quiet window, +and every later batch restarts it. When the window elapses the journey has +settled: the settled moment is the last mutation batch, the counters stop at +the confirmation, and the probe sends +`cancelSourceProbe('__iptvnator-journey-search-end__')`. Without a settle +within 15 s of the last key the probe marks the iteration invalid +(`settle-timeout`). + +A settle that times out fails the iteration with what the probe and the +main process saw: the URL `q`, the input's value, the results view, the +bridge calls, renderer console errors, the SQL totals before each key, and +the traced `dbGlobalSearch` calls with their summarized arguments and +results. + +### Counters + +| Counter | Source | +| ---------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `renderer.ipcCallsPerSearch` | Bridge `start` trace events between the start and end sentinels, as `renderer.ipcCallsToFirstPage` in J2. `evidence.ipcCallsByMethod` names them. | +| `renderer.sqlStatementsPerSearch` | `main.sqlStatements` (main thread and database worker, see [Main-process counters](#main-process-counters)) read right before the first key and again after the probe settled. The worker reports its count before the response it belongs to, so the statements of a query are counted before its results reach the renderer. Statements in the 500 ms after that read are kept as `evidence.sqlStatementsAfterSettled`, so background work that would have leaked into the count is visible. | +| `renderer.ipcSerialDepthToResults` | `computeJourneyIpcSerialDepth` over the capture's timeline between the sentinels (see [Serial IPC depth](#serial-ipc-depth)); `evidence.ipcSerialDepth.chain` and `evidence.ipcTimeline` show the calls. | +| `renderer.domMutationsToResults` | `MutationRecord`s from the first keydown until the quiet window was confirmed (by definition none arrive inside it). | +| `renderer.cdTicksToResults` | `ApplicationRef` ticks from the first keydown (read in the capture-phase listener, before the app handles the key) until the confirmation (see [Change-detection ticks](#change-detection-ticks)). | +| `renderer.layoutShiftScore` | All `layout-shift` entries from the first keydown until the confirmation, including `hadRecentInput` ones (typing is input, as in J2 and J3), rounded to three decimals; the split is under `evidence.layoutShift`. | +| `renderer.longTasks` | `longtask` entries over 50 ms whose time range overlaps the window from the first keydown to the confirmation. Evidence until shown to be stable on the runner. | + +`evidence.perKeystroke` breaks the journey down by key: for each typed +character, what happened from that key until the next one (the last entry: +until the settle). `domMutations` and `cdTicks` are split at the renderer's +keydown stamps. `ipcCalls`, `queryCalls` (`dbGlobalSearch` calls) and +`sqlStatements` are differences of the main-process samples taken just +before each key, so their boundaries sit a few milliseconds before the +renderer's. A search with working debounce shows zeros for the first five +keys and one query after the last; a search that queried on every key from +the second character on would show a `dbGlobalSearch` call and its +statements in each of those entries, even when a later key superseded the +result. + +No counter is listed under `unavailable`. HTTP requests are not a J4 +counter: global search does not touch the network. + +### Wall-clock + +| Entry | Derivation | +| ---------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------- | +| `firstKeystrokeToFirstResultMs.p50/.p90` | First mutation batch with a visible result card (for any term) minus the first keydown. | +| `lastKeystrokeToSettledMs.p50/.p90` | Settled moment (the last mutation batch before the 200 ms quiet window) minus the last keydown. The quiet window itself is not included. | + +Both are taken in the renderer. With the current debounces both include +the 650 ms the term waits (350 ms in the shell, then 300 ms in the results +component); the first also includes the 500 ms of typing. + +### First measurement + +Local, macOS, 2026-10-04, three full `perf:journeys` runs plus repeated J4 +runs. In the runs where J4 completed (the first and third full runs), every +counter was identical in all ten measured iterations except one: +`renderer.ipcCallsPerSearch` 1 (`dbGlobalSearch`), +`renderer.sqlStatementsPerSearch` 2, `renderer.ipcSerialDepthToResults` 1, +`renderer.domMutationsToResults` 402 (100 cards on the first page), +`renderer.layoutShiftScore` 0 and `renderer.longTasks` 0. +`renderer.cdTicksToResults` read 14 in all five iterations of the third run +and 13, 18, 13, 15, 13 in the first, so check the runner's +`counterStability` before trusting it. P50/P90 +`lastKeystrokeToSettledMs` 686/692 ms and `firstKeystrokeToFirstResultMs` +1,178/1,184 ms in the third run (699/720 and 1,193/1,210 in the first). + +Per keystroke, the first five keys caused one change-detection tick each +and nothing else: no bridge call, no SQL statement and no DOM mutation. +All of the work followed the sixth key. Search therefore does not run a +query per keystroke. The debounce does dominate the wall clock: about +650 ms of the 686 ms from the last key to settled is the two stacked +debounces (350 ms in the shell, then 300 ms in the results component). The +query itself, from the bridge call to the rendered first page, takes the +remaining 30-40 ms. + +About one launch in sixty showed the empty-results view: the single +`dbGlobalSearch` call went out with the same arguments (`system`, all three +types, hidden categories included, limit 101) and the main process answered +with an empty array in about 20 ms, with no renderer error. The database +was unchanged from passing launches (the same 119 statements before the +first key, the usual 2 for the query, none afterwards), and every failure +traced was the first launch after seeding. The journey fails such an +iteration instead of measuring it, so a full run occasionally fails J4. +The cause is in the app, not the harness, and is not fixed here. No J4 +baseline exists yet; J4 counters join the ratchet once three runner runs +agree. + ## `renderer.initialBytes` The bytes a browser fetches before Angular can bootstrap, read from the built @@ -1079,8 +1233,10 @@ reports slow imports of non-Latin playlists. 2. Give the journey its own probe options (`cardSelector`, `companionSelectors`, `routeFragment`, `startClick` for a click start, `media` for a media-event end such as J3's `playing`) or extend - `journey-renderer-probe.ts` when the end condition is neither. Use a state - key and sentinel ids of its own. Keep the probe self-contained: Playwright + `journey-renderer-probe.ts` when the end condition is neither. A journey + whose start or end does not fit that probe gets a probe of its own, as + J4's typed start and quiet-window end do (`search-journey-probe.ts`). Use + a state key and sentinel ids of its own. Keep the probe self-contained: Playwright serializes it with `toString()`. A click-started journey settles with `waitForJourneyClickQuiet` from `journey-click-settle.ts`. 3. Map the measurement to a `JourneyIterationRecord` in a