test(performance): J4 settles only on the final term's query

The probe could settle on cards of an earlier term that stay visible while
the final term debounces. The journey now stamps every dbGlobalSearch trace
event in the main process, and the record requires the last query between
the sentinels to be for the final term and to have completed before the
end sentinel. Iterations with a keydown gap over 250 ms (below the 350 ms
debounce) are rejected; gaps and the final query are kept as evidence.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
4grayandClaude Opus 5.5 committed 2026-10-04 21:43:36 +02:00
1 parent 4ecc2d1096
commit 7675c01756
4 files changed
+229 -14

No files matched your search

@@ -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<void> {
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<void> {
await electronApp.evaluate(
({ ipcMain }, input) => {
const entries: string[] = [];
const entries: unknown[] = [];
(globalThis as unknown as Record<string, unknown>)[input.key] =
entries;
ipcMain.on(input.channel, (_event, payload: unknown) => {
const record = payload as Record<string, unknown> | 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<SearchJourneyQueryTraceEntry[]> {
return electronApp.evaluate(
(_electron, key) =>
JSON.parse(
JSON.stringify(
(globalThis as unknown as Record<string, unknown>)[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<string, unknown>)[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,
@@ -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]
);
});
@@ -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
+16 -2
View File
@@ -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