diff --git a/apps/electron-backend-e2e/src/journeys/search-journey-app.ts b/apps/electron-backend-e2e/src/journeys/search-journey-app.ts index 304118fdf..d15a7019d 100644 --- a/apps/electron-backend-e2e/src/journeys/search-journey-app.ts +++ b/apps/electron-backend-e2e/src/journeys/search-journey-app.ts @@ -30,6 +30,7 @@ import { SEARCH_JOURNEY_QUERY_METHOD, type SearchJourneyActivitySample, type SearchJourneyMeasurement, + type SearchJourneyQueryTraceEntry, type SearchJourneySettle, } from '../performance/search-journey-record'; import { JOURNEY_RENDERER_GATE_KEY } from './journey-renderer-gate-client'; @@ -177,22 +178,36 @@ function sleepUntil(epochMs: number): Promise { 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. + * Records every trace event of the query method in the main process, with + * the term and result length the preload's summaries carry and the main + * process's arrival epoch (the clock the IPC capture stamps its sentinels + * with). The record uses it to prove the final term's query completed + * before the settle, so results of an earlier term cannot end the journey. + * The summaries hold the search term and counts only. */ async function traceQueryCalls( electronApp: ElectronApplication ): Promise { await electronApp.evaluate( ({ ipcMain }, input) => { - const entries: string[] = []; + const entries: unknown[] = []; (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)); - } + if (record?.['method'] !== input.method) return; + const args = record['args'] as { items?: unknown[] } | null; + const result = record['result'] as { length?: unknown } | null; + const term = args?.items?.[0]; + entries.push({ + epochMs: Date.now(), + phase: String(record['phase']), + resultLength: + typeof result?.length === 'number' + ? result.length + : null, + term: typeof term === 'string' ? term : null, + }); }); }, { @@ -203,11 +218,25 @@ async function traceQueryCalls( ); } +async function readQueryTrace( + electronApp: ElectronApplication +): Promise { + return electronApp.evaluate( + (_electron, key) => + JSON.parse( + JSON.stringify( + (globalThis as unknown as Record)[key] + ) + ) as SearchJourneyQueryTraceEntry[], + QUERY_TRACE_KEY + ); +} + /** * 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. + * calls with their terms and result lengths. */ async function describeSettleFailure( electronApp: ElectronApplication, @@ -218,11 +247,7 @@ async function describeSettleFailure( 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 - ); + const queryTrace = await readQueryTrace(electronApp); return JSON.stringify({ bridgeCalls: capture.callsByMethod, consoleErrors, @@ -328,6 +353,7 @@ export async function measureSearchJourney( keyDelayMs: SEARCH_JOURNEY_KEY_DELAY_MS, pid: session.launch.pid, query, + queryTrace: await readQueryTrace(electronApp), renderer, samples, settle, 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 index 0d832a5ee..87fc992b3 100644 --- a/apps/electron-backend-e2e/src/performance/search-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/search-journey-record.spec.ts @@ -96,6 +96,20 @@ function measurement( keyDelayMs: 100, pid: 4242, query: QUERY, + queryTrace: [ + { + epochMs: 11_150, + phase: 'start', + resultLength: null, + term: QUERY, + }, + { + epochMs: 11_170, + phase: 'success', + resultLength: 101, + term: null, + }, + ], renderer, samples: [ sample(0, 0, 119), @@ -202,6 +216,22 @@ test('a query per keystroke shows up per key, not only in the total', () => { callsBeforeSentinel: 5, callsByMethod: { dbGlobalSearch: 5 }, }, + queryTrace: ['sy', 'sys', 'syst', 'syste', QUERY].flatMap( + (term, position) => [ + { + epochMs: 10_150 + position * 100, + phase: 'start', + resultLength: null, + term, + }, + { + epochMs: 10_170 + position * 100, + phase: 'success', + resultLength: 101, + term: null, + }, + ] + ), }) ); assert.equal(record.counters[SEARCH_JOURNEY_COUNTER.IPC_CALLS], 5); @@ -326,3 +356,69 @@ test('summarizes with the shared summary and nothing unavailable', () => { ); assert.deepEqual(entry.unavailable, {}); }); + +test('rejects a settle that did not wait for the final query', () => { + const start = (epochMs: number, term: string) => ({ + epochMs, + phase: 'start', + resultLength: null, + term, + }); + const success = (epochMs: number) => ({ + epochMs, + phase: 'success', + resultLength: 101, + term: null, + }); + // Results of an earlier term were shown; the final query never ran + // before the end sentinel. + assert.throws( + () => + toSearchIterationRecord( + 1, + false, + measurement({ + queryTrace: [ + start(10_500, 'syste'), + success(10_520), + start(11_500, QUERY), + success(11_520), + ], + }) + ), + /final-query-not-run/ + ); + // The final query started but had not completed at the end sentinel. + assert.throws( + () => + toSearchIterationRecord( + 1, + false, + measurement({ queryTrace: [start(11_390, QUERY)] }) + ), + /final-query-incomplete/ + ); + const record = toSearchIterationRecord(1, false, measurement()); + assert.deepEqual(record.evidence['finalQuery'], { + durationMs: 20, + resultLength: 101, + term: QUERY, + }); +}); + +test('rejects typing slower than the accepted cadence', () => { + const base = measurement(); + const keystrokes = base.renderer.keystrokes.map((key, position) => ({ + ...key, + epochMs: key.epochMs + (position >= 3 ? 200 : 0), + })); + assert.throws( + () => + toSearchIterationRecord(1, false, measurement({}, { keystrokes })), + /typing-cadence: 100, 100, 300, 100, 100/ + ); + assert.deepEqual( + toSearchIterationRecord(1, false, base).evidence['keyIntervalsMs'], + [100, 100, 100, 100, 100] + ); +}); diff --git a/apps/electron-backend-e2e/src/performance/search-journey-record.ts b/apps/electron-backend-e2e/src/performance/search-journey-record.ts index 1c92adfd8..99563a12b 100644 --- a/apps/electron-backend-e2e/src/performance/search-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/search-journey-record.ts @@ -33,6 +33,22 @@ export const SEARCH_JOURNEY_UNAVAILABLE_COUNTERS: Readonly< /** Bridge method of a global search query (`DatabaseService`). */ export const SEARCH_JOURNEY_QUERY_METHOD = 'dbGlobalSearch'; +/** + * Longest accepted gap between two keydowns. Below the shell's 350 ms input + * debounce, so a late key on a busy machine cannot let an intermediate term + * run a query that steady typing would not. + */ +export const SEARCH_JOURNEY_MAX_KEY_INTERVAL_MS = 250; + +/** One traced query event, stamped in the main process on arrival. */ +export interface SearchJourneyQueryTraceEntry { + readonly epochMs: number; + readonly phase: string; + /** Length of the returned array, on `success`. */ + readonly resultLength: number | null; + readonly term: string | null; +} + /** * Main-process activity read in one synchronous pass: the journey capture's * call counts and the running `main.sqlStatements` total. @@ -67,6 +83,8 @@ export interface SearchJourneyMeasurement { readonly afterSettled: SearchJourneyActivitySample; readonly afterSettledWindowMs: number; readonly settle: SearchJourneySettle; + /** Every traced query event of the process, in arrival order. */ + readonly queryTrace: readonly SearchJourneyQueryTraceEntry[]; } function roundTenth(value: number): number { @@ -85,6 +103,42 @@ function difference( return samples[index + 1][key] - samples[index][key]; } +/** + * The query the settle waited for: the last one started between the start + * and end sentinels. It must be for the final term and must have completed + * before the end sentinel, otherwise the probe settled on results of an + * earlier term (still shown while the final term debounced). + */ +function finalQuery( + trace: readonly SearchJourneyQueryTraceEntry[], + fromEpochMs: number, + untilEpochMs: number, + query: string +) { + const inWindow = trace.filter( + (entry) => entry.epochMs >= fromEpochMs && entry.epochMs <= untilEpochMs + ); + const starts = inWindow.filter((entry) => entry.phase === 'start'); + const completions = inWindow.filter( + (entry) => entry.phase === 'success' || entry.phase === 'error' + ); + const last = starts.at(-1); + if (last === undefined || last.term !== query) { + throw new Error('search-journey-record-final-query-not-run'); + } + const completion = completions.find( + (entry) => entry.epochMs >= last.epochMs && entry.phase === 'success' + ); + if (completion === undefined || completions.length < starts.length) { + throw new Error('search-journey-record-final-query-incomplete'); + } + return Object.freeze({ + durationMs: completion.epochMs - last.epochMs, + resultLength: completion.resultLength, + term: last.term, + }); +} + export function toSearchIterationRecord( index: number, warmup: boolean, @@ -136,6 +190,29 @@ export function toSearchIterationRecord( `search-journey-record-activity-before-first-key-${moved.join('-')}` ); } + const keyIntervalsMs = keystrokes + .slice(1) + .map((key, position) => + roundTenth(key.epochMs - keystrokes[position].epochMs) + ); + if ( + keyIntervalsMs.some( + (interval) => interval > SEARCH_JOURNEY_MAX_KEY_INTERVAL_MS + ) + ) { + throw new Error( + `search-journey-record-typing-cadence: ${keyIntervalsMs.join(', ')}` + ); + } + if (ipc.sentinel.receivedEpochMs === null) { + throw new Error('search-journey-record-ipc-without-end'); + } + const lastQuery = finalQuery( + measurement.queryTrace, + ipc.start.receivedEpochMs ?? Number.POSITIVE_INFINITY, + ipc.sentinel.receivedEpochMs, + measurement.query + ); const finalSample = samples[keys]; if (finalSample.ipcCalls !== ipc.callsBeforeSentinel) { throw new Error('search-journey-record-ipc-sample-mismatch'); @@ -205,7 +282,9 @@ export function toSearchIterationRecord( (event) => `${event.phase === 'start' ? '+' : '-'}${event.method}` ), + finalQuery: lastQuery, keyDelayMs: measurement.keyDelayMs, + keyIntervalsMs, layoutShift: Object.freeze({ recentInput: roundThousandth( renderer.counters.recentInputLayoutShiftScore diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index b177e1992..e07449689 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -856,11 +856,25 @@ the confirmation, and the probe sends within 15 s of the last key the probe marks the iteration invalid (`settle-timeout`). +The DOM alone cannot tell the final term's results from an earlier term's +that are still shown while the final term debounces, so the main process +also checks. A listener on the renderer-API trace channel stamps every +`dbGlobalSearch` event on arrival, with the term and result length that the +preload's summaries carry. The record requires that the last query started +between the start and end sentinels is for the final term and completed +before the end sentinel (`final-query-not-run`, `final-query-incomplete`). +The final query's start shows the loading state, which keeps the quiet +window closed until its results replace the old ones. +`evidence.finalQuery` keeps its term, result length and duration. The +record also rejects an iteration in which two keydowns were more than +250 ms apart (`typing-cadence`; the gaps are `evidence.keyIntervalsMs`). +At that point a late key on a busy machine could let the 350 ms debounce +apply an intermediate term, which steady typing does not. + 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. +the traced `dbGlobalSearch` calls with their terms and result lengths. ### Counters