test(perf): measure the serial IPC depth before the J1 first card

Adds renderer.ipcSerialDepthToFirstCard to the launch journey: the length
of the longest chain of bridge calls in which each call started after the
previous one completed, among calls that completed before the first card.
The main IPC capture now records the ordered start/completion timeline;
the depth, its lower bound, the chain and the timeline are per-iteration
evidence, and the CI job summary prints the chain.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
4grayandClaude Opus 5.5 committed 2026-09-30 22:29:44 +02:00
1 parent 525ca7bc44
commit eda0fe615a
9 files changed
+422 -1

No files matched your search

@@ -0,0 +1,150 @@
import assert from 'node:assert/strict';
import test from 'node:test';
import {
computeJourneyIpcSerialDepth,
type JourneyIpcTimelineEvent,
} from './journey-ipc-serial-depth';
/** `+name` starts a call of `name`, `-name` completes one. */
function timeline(...events: string[]): JourneyIpcTimelineEvent[] {
return events.map((event) => ({
method: event.slice(1),
phase: event.startsWith('+') ? 'start' : 'end',
}));
}
test('an empty timeline has depth 0', () => {
assert.deepEqual(computeJourneyIpcSerialDepth([]), {
chain: [],
depth: 0,
depthLowerBound: 0,
inFlightAtEnd: 0,
});
});
test('parallel calls count as one level', () => {
const result = computeJourneyIpcSerialDepth(
timeline('+a', '+b', '+c', '-b', '-a', '-c')
);
assert.equal(result.depth, 1);
assert.equal(result.depthLowerBound, 1);
assert.deepEqual(result.chain, ['c']);
});
test('each call that starts after a completion adds a level', () => {
const result = computeJourneyIpcSerialDepth(
timeline('+a', '-a', '+b', '-b', '+c', '-c')
);
assert.equal(result.depth, 3);
assert.deepEqual(result.chain, ['a', 'b', 'c']);
});
test('a call started before an earlier call completed does not chain on it', () => {
// b starts while a is in flight, so b is level 1 even though it ends later.
const result = computeJourneyIpcSerialDepth(
timeline('+a', '+b', '-a', '+c', '-b', '-c')
);
assert.equal(result.depth, 2);
assert.deepEqual(result.chain, ['a', 'c']);
});
test('the longest chain wins over a later but shallower one', () => {
const result = computeJourneyIpcSerialDepth(
timeline(
'+a',
'+x',
'-a',
'+b',
'-b',
'+c',
'-c',
// x resolves last but only ever was level 1.
'-x'
)
);
assert.equal(result.depth, 3);
assert.deepEqual(result.chain, ['a', 'b', 'c']);
});
test('calls still in flight at the end are excluded', () => {
const result = computeJourneyIpcSerialDepth(
timeline('+a', '-a', '+b', '-b', '+c', '+d')
);
assert.equal(result.depth, 2);
assert.equal(result.inFlightAtEnd, 2);
assert.deepEqual(result.chain, ['a', 'b']);
});
test('the chain names the latest completion at the deepest level', () => {
const result = computeJourneyIpcSerialDepth(
timeline('+a', '+b', '-a', '-b', '+c', '-c')
);
assert.deepEqual(result.chain, ['b', 'c']);
});
test('the J1 startup shape measures the recovery chain', () => {
// Shape of the 2026-09-30 macOS trace on master.
const result = computeJourneyIpcSerialDepth(
timeline(
'+announcePlaylistOpenListener',
'+dbGetAppState',
'+dbGetAppState',
'+dbGetAppState',
'+getAppUpdateStatus',
'-announcePlaylistOpenListener',
'-getAppUpdateStatus',
'-dbGetAppState',
'-dbGetAppState',
'-dbGetAppState',
'+dbRecoverLegacyPlaylists',
'-dbRecoverLegacyPlaylists',
'+dbGetAppState',
'-dbGetAppState',
'+dbGetAppPlaylistMetas',
'-dbGetAppPlaylistMetas',
'+reconcileEpgSources',
'-reconcileEpgSources',
'+setParentalLockState',
'-setParentalLockState',
'+downloadsGetList',
'+dbGetRecentlyViewed'
)
);
assert.equal(result.depth, 6);
assert.equal(result.depthLowerBound, 6);
assert.equal(result.inFlightAtEnd, 2);
assert.deepEqual(result.chain, [
'dbGetAppState',
'dbRecoverLegacyPlaylists',
'dbGetAppState',
'dbGetAppPlaylistMetas',
'reconcileEpgSources',
'setParentalLockState',
]);
});
test('concurrent calls of one method at different depths give bounds', () => {
// Two `a` calls are in flight at depths 1 and 2; which one completes
// first is unknown, and only the deeper one would put `c` at depth 3.
const events = timeline('+a', '+b', '-b', '+a', '-a', '+c', '-c', '-a');
const result = computeJourneyIpcSerialDepth(events);
assert.equal(result.depth, 3);
assert.equal(result.depthLowerBound, 2);
assert.deepEqual(result.chain, ['b', 'a', 'c']);
});
test('synchronous calls chain like any other bridge call', () => {
// The preload emits a sync call's completion right after its start.
const result = computeJourneyIpcSerialDepth(
timeline('+a', '-a', '+sync', '-sync', '+b', '-b')
);
assert.equal(result.depth, 3);
});
test('a completion without a start fails the measurement', () => {
assert.throws(
() => computeJourneyIpcSerialDepth(timeline('+a', '-b')),
/journey-ipc-serial-depth-unmatched-end:b/
);
});
@@ -0,0 +1,109 @@
/**
* Serial depth of the bridge calls on the way to a journey's end
* (`renderer.ipcSerialDepthToFirstCard`, see performance-journeys.md).
*
* Input is the capture's timeline: one `start` per bridge invocation and one
* `end` per completion, in the order the renderer sent them. The preload
* sends a call's completion before the caller's continuation runs, and
* renderer-to-main IPC is ordered, so a call that the renderer issued
* because another one resolved always appears after that call's `end`.
*
* The depth of a call is 1 + the largest depth of the calls that ended
* before it started. The serial depth is the largest depth among calls that
* ended within the timeline: the length of the longest chain in which each
* call started after the previous one completed. Calls still in flight at the
* end of the timeline are excluded; the journey's end did not wait for them.
*
* Trace events carry no call id. When several calls of one method are in
* flight, a completion is attributed to the deepest of them (`depth`) and,
* in a second pass, to the shallowest (`depthLowerBound`). The two agree
* unless concurrent calls of one method sit at different depths.
*
* `chain` follows one longest chain back from its last call; at each step
* the predecessor is the latest completion at the largest depth before the
* call started. It shows which methods form the chain, not causality: the
* timeline cannot tell which completion a start actually waited for.
*/
export interface JourneyIpcTimelineEvent {
readonly method: string;
readonly phase: 'end' | 'start';
}
export interface JourneyIpcSerialDepth {
/** Methods of one longest chain, first call first. */
readonly chain: readonly string[];
readonly depth: number;
readonly depthLowerBound: number;
/** Calls started within the timeline that had not completed at its end. */
readonly inFlightAtEnd: number;
}
interface TimelineCall {
readonly depth: number;
readonly method: string;
readonly parent: TimelineCall | null;
}
type Attribution = 'deepest' | 'shallowest';
function walk(
timeline: readonly JourneyIpcTimelineEvent[],
attribution: Attribution
): { deepest: TimelineCall | null; inFlight: number } {
const inFlight = new Map<string, TimelineCall[]>();
let deepest: TimelineCall | null = null;
let inFlightCount = 0;
for (const event of timeline) {
const pending = inFlight.get(event.method) ?? [];
if (event.phase === 'start') {
pending.push({
depth: (deepest?.depth ?? 0) + 1,
method: event.method,
parent: deepest,
});
inFlight.set(event.method, pending);
inFlightCount += 1;
continue;
}
if (pending.length === 0) {
throw new Error(
`journey-ipc-serial-depth-unmatched-end:${event.method}`
);
}
let chosen = 0;
for (let index = 1; index < pending.length; index += 1) {
const better =
attribution === 'deepest'
? pending[index].depth > pending[chosen].depth
: pending[index].depth < pending[chosen].depth;
if (better) {
chosen = index;
}
}
const [call] = pending.splice(chosen, 1);
inFlightCount -= 1;
// Ties go to the latest completion: the call a later start most
// plausibly waited on, which is what `chain` reports.
if (deepest === null || call.depth >= deepest.depth) {
deepest = call;
}
}
return { deepest, inFlight: inFlightCount };
}
export function computeJourneyIpcSerialDepth(
timeline: readonly JourneyIpcTimelineEvent[]
): JourneyIpcSerialDepth {
const upper = walk(timeline, 'deepest');
const lower = walk(timeline, 'shallowest');
const chain: string[] = [];
for (let call = upper.deepest; call !== null; call = call.parent) {
chain.unshift(call.method);
}
return Object.freeze({
chain: Object.freeze(chain),
depth: upper.deepest?.depth ?? 0,
depthLowerBound: lower.deepest?.depth ?? 0,
inFlightAtEnd: upper.inFlight,
});
}
@@ -42,6 +42,7 @@ function validCapture(
processStartEpochMs: 0,
senderIds: [1],
sentinel: { occurrences: 1, receivedEpochMs: 2 },
timeline: [],
unmatchedCompletions: 0,
start: null,
...overrides,
@@ -322,6 +323,37 @@ test('rejects a start marker that is missing, repeated or after the sentinel', a
);
});
test('records starts and completions in order between the markers', async () => {
await withCapture(
{ startSentinelId: JOURNEY_OPEN_SOURCE_START_SENTINEL_ID },
async (fake, read) => {
fake.send(1, 'getSettings', []);
fake.send(1, 'getSettings', [], 'success');
fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [
JOURNEY_OPEN_SOURCE_START_SENTINEL_ID,
]);
fake.send(1, 'dbGetAppPlaylist', ['playlist-1']);
// The start marker's own completion is not part of the journey.
fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [], 'success');
fake.send(1, 'dbGetAppPlaylist', [], 'success');
fake.send(1, 'xtreamRequest', [{ action: 'get_account_info' }]);
fake.send(1, 'xtreamRequest', [], 'error');
fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [
JOURNEY_OPEN_SOURCE_END_SENTINEL_ID,
]);
fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [], 'success');
fake.send(1, 'getSettings', []);
const state = assertJourneyMainIpcCapture(await read());
assert.deepEqual(state.timeline, [
{ method: 'dbGetAppPlaylist', phase: 'start' },
{ method: 'dbGetAppPlaylist', phase: 'end' },
{ method: 'xtreamRequest', phase: 'start' },
{ method: 'xtreamRequest', phase: 'end' },
]);
}
);
});
test('tracks bridge calls in flight from start to success or error', async () => {
await withCapture({}, async (fake, read) => {
fake.send(1, 'getSettings', []);
@@ -1,5 +1,7 @@
import type { ElectronApplication } from '@playwright/test';
import type { JourneyIpcTimelineEvent } from './journey-ipc-serial-depth';
/**
* Main-process side of the journey IPC counter.
*
@@ -59,6 +61,12 @@ export interface JourneyMainIpcCaptureState {
readonly unmatchedCompletions: number;
/** Null when the capture has no start marker. */
readonly start: JourneyMainIpcSentinelState | null;
/**
* Bridge starts and completions in arrival order, from the start marker
* (or install) until the sentinel, sentinels excluded. Input of
* `computeJourneyIpcSerialDepth`.
*/
readonly timeline: JourneyIpcTimelineEvent[];
}
export async function installJourneyMainIpcCapture(
@@ -81,6 +89,7 @@ export async function installJourneyMainIpcCapture(
processStartEpochMs: Date.now() - process.uptime() * 1000,
inFlightByMethod: {} as Record<string, number>,
senderIds: [] as number[],
timeline: [] as { method: string; phase: 'end' | 'start' }[],
sentinel: {
occurrences: 0,
receivedEpochMs: null as number | null,
@@ -102,6 +111,7 @@ export async function installJourneyMainIpcCapture(
}
};
target[input.stateKey] = state;
let markerCompletionsToSkip = 0;
const listener = (
event: { sender: { id: number } },
payload: unknown
@@ -115,7 +125,22 @@ export async function installJourneyMainIpcCapture(
return;
}
const phase = record['phase'];
const counting =
state.sentinel.receivedEpochMs === null &&
(state.start === null || state.start.receivedEpochMs !== null);
if (phase === 'success' || phase === 'error') {
if (
record['method'] === input.sentinelMethod &&
markerCompletionsToSkip > 0
) {
// The start marker's own completion.
markerCompletionsToSkip -= 1;
} else if (counting) {
state.timeline.push({
method: record['method'],
phase: 'end',
});
}
const pending = state.inFlightByMethod[record['method']] ?? 0;
if (pending === 0) {
state.unmatchedCompletions += 1;
@@ -145,6 +170,7 @@ export async function installJourneyMainIpcCapture(
carries(record['args'], startSentinelId)
) {
state.start.occurrences += 1;
markerCompletionsToSkip += 1;
// A start marker after the sentinel stays unstamped, which
// the assertion rejects.
if (state.sentinel.receivedEpochMs === null) {
@@ -166,6 +192,7 @@ export async function installJourneyMainIpcCapture(
return;
}
state.callsBeforeSentinel += 1;
state.timeline.push({ method, phase: 'start' });
state.callsByMethod[method] =
(state.callsByMethod[method] ?? 0) + 1;
};
@@ -87,6 +87,13 @@ function measurement(
senderIds: [1],
sentinel: { occurrences: 1, receivedEpochMs: 2_602 },
start: null,
timeline: [
{ method: 'getSettings', phase: 'start' },
{ method: 'getSettings', phase: 'end' },
{ method: 'dbGetAppPlaylists', phase: 'start' },
{ method: 'getSettings', phase: 'start' },
{ method: 'dbGetAppPlaylists', phase: 'end' },
],
unmatchedCompletions: 0,
};
return {
@@ -131,6 +138,7 @@ test('maps the probe, IPC capture and main counters to exact counters and spawn-
'main.sqlStatementsBeforeReadyToShow': 9,
'renderer.domMutationsToFirstCard': 480,
'renderer.ipcCallsToFirstCard': 14,
'renderer.ipcSerialDepthToFirstCard': 2,
'renderer.layoutShiftScore': 0.123,
'renderer.layoutShiftScoreSettled': 0.23,
'renderer.longTasks': 2,
@@ -143,6 +151,19 @@ test('maps the probe, IPC capture and main counters to exact counters and spawn-
dbGetAppPlaylists: 1,
getSettings: 13,
});
assert.deepEqual(record.evidence['ipcSerialDepth'], {
chain: ['getSettings', 'dbGetAppPlaylists'],
depth: 2,
depthLowerBound: 2,
inFlightAtEnd: 1,
});
assert.deepEqual(record.evidence['ipcTimeline'], [
'+getSettings',
'-getSettings',
'+dbGetAppPlaylists',
'+getSettings',
'-dbGetAppPlaylists',
]);
assert.deepEqual(record.evidence['longTaskDurationsMs'], [71.3, 120]);
assert.equal(record.evidence['ipcCallsAfterFirstCard'], 3);
assert.deepEqual(record.evidence['mainCountersAtRead'], {
@@ -3,6 +3,7 @@ import {
JOURNEY_MAIN_COUNTER,
type JourneyMainCountersState,
} from './journey-main-counters';
import { computeJourneyIpcSerialDepth } from './journey-ipc-serial-depth';
import type { JourneyMainIpcCaptureState } from './journey-main-ipc-capture';
import type { JourneyRendererProbeState } from './journey-renderer-probe';
import type { JourneyIterationRecord } from './journey-summary';
@@ -21,6 +22,7 @@ export const LAUNCH_JOURNEY_COUNTER = {
JOURNEY_MAIN_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW,
DOM_MUTATIONS: 'renderer.domMutationsToFirstCard',
IPC_CALLS: 'renderer.ipcCallsToFirstCard',
IPC_SERIAL_DEPTH: 'renderer.ipcSerialDepthToFirstCard',
LAYOUT_SHIFT_SCORE: 'renderer.layoutShiftScore',
LAYOUT_SHIFT_SCORE_SETTLED: 'renderer.layoutShiftScoreSettled',
LONG_TASKS: 'renderer.longTasks',
@@ -83,6 +85,7 @@ export function toLaunchIterationRecord(
) {
throw new Error('launch-journey-record-clock-order');
}
const serialDepth = computeJourneyIpcSerialDepth(ipc.timeline);
const { settle } = renderer;
if (
(settle.status !== 'quiet' && settle.status !== 'cap') ||
@@ -113,6 +116,7 @@ export function toLaunchIterationRecord(
[LAUNCH_JOURNEY_COUNTER.DOM_MUTATIONS]:
renderer.counters.domMutations,
[LAUNCH_JOURNEY_COUNTER.IPC_CALLS]: ipc.callsBeforeSentinel,
[LAUNCH_JOURNEY_COUNTER.IPC_SERIAL_DEPTH]: serialDepth.depth,
[LAUNCH_JOURNEY_COUNTER.LAYOUT_SHIFT_SCORE]: roundThousandth(
renderer.counters.layoutShiftScore
),
@@ -155,6 +159,12 @@ export function toLaunchIterationRecord(
rendererGateReadyToShowHeldOnBlank:
measurement.gate.readyToShowHeldOnBlank,
ipcCallsByMethod: ipc.callsByMethod,
ipcSerialDepth: serialDepth,
// `+method` for a start, `-method` for a completion.
ipcTimeline: ipc.timeline.map(
({ method, phase }) =>
`${phase === 'start' ? '+' : '-'}${method}`
),
longTaskDurationsMs: renderer.longTaskDurationsMs.map(roundTenth),
observedTarget: renderer.capabilities.observedTarget,
settle: Object.freeze({
@@ -87,6 +87,7 @@ function measurement(
senderIds: [1],
sentinel: { occurrences: 1, receivedEpochMs: 10_081 },
start: { occurrences: 1, receivedEpochMs: 10_002 },
timeline: [],
unmatchedCompletions: 0,
};
return {