diff --git a/.github/actions/performance-journeys/action.yml b/.github/actions/performance-journeys/action.yml index 009675585..5b9ead263 100644 --- a/.github/actions/performance-journeys/action.yml +++ b/.github/actions/performance-journeys/action.yml @@ -70,5 +70,7 @@ runs: ($j.counterStability[.key] // {}) as $s | "| `\(.key)` | \(.value) | \(($s.values // []) | map(tostring) | join(", "))\(if $s.stable == false then " (unstable)" else "" end) |"), (($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(" → "))", "")) ' "$SUMMARY" | tee -a "$GITHUB_STEP_SUMMARY" diff --git a/apps/electron-backend-e2e/src/performance/journey-ipc-serial-depth.spec.ts b/apps/electron-backend-e2e/src/performance/journey-ipc-serial-depth.spec.ts new file mode 100644 index 000000000..08ebd92ac --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/journey-ipc-serial-depth.spec.ts @@ -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/ + ); +}); diff --git a/apps/electron-backend-e2e/src/performance/journey-ipc-serial-depth.ts b/apps/electron-backend-e2e/src/performance/journey-ipc-serial-depth.ts new file mode 100644 index 000000000..dc788f548 --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/journey-ipc-serial-depth.ts @@ -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(); + 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, + }); +} diff --git a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts index 00633261b..b369a62c3 100644 --- a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts +++ b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.spec.ts @@ -6,6 +6,7 @@ import test from 'node:test'; import type { ElectronApplication } from '@playwright/test'; +import { computeJourneyIpcSerialDepth } from './journey-ipc-serial-depth'; import { assertJourneyMainIpcCapture, countJourneyMainIpcInFlight, @@ -32,6 +33,7 @@ function validCapture( overrides: Partial = {} ): JourneyMainIpcCaptureState { return { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 2, callsBeforeStart: 0, callsBeforeSentinel: 7, @@ -42,6 +44,7 @@ function validCapture( processStartEpochMs: 0, senderIds: [1], sentinel: { occurrences: 1, receivedEpochMs: 2 }, + timeline: [], unmatchedCompletions: 0, start: null, ...overrides, @@ -322,6 +325,89 @@ 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('leaves out the completion of a call started before the start marker', async () => { + await withCapture( + { startSentinelId: JOURNEY_OPEN_SOURCE_START_SENTINEL_ID }, + async (fake, read) => { + fake.send(1, 'dbGetAppState', []); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [ + JOURNEY_OPEN_SOURCE_START_SENTINEL_ID, + ]); + fake.send(1, 'dbGetAppState', [], 'success'); + fake.send(1, 'xtreamRequest', []); + fake.send(1, 'xtreamRequest', [], 'success'); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [ + JOURNEY_OPEN_SOURCE_END_SENTINEL_ID, + ]); + const state = assertJourneyMainIpcCapture(await read()); + assert.deepEqual(state.timeline, [ + { method: 'xtreamRequest', phase: 'start' }, + { method: 'xtreamRequest', phase: 'end' }, + ]); + assert.doesNotThrow(() => + computeJourneyIpcSerialDepth(state.timeline) + ); + } + ); +}); + +test('attributes an ambiguous marker-method completion outside the timeline', async () => { + await withCapture( + { startSentinelId: JOURNEY_OPEN_SOURCE_START_SENTINEL_ID }, + async (fake, read) => { + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [ + JOURNEY_OPEN_SOURCE_START_SENTINEL_ID, + ]); + // An app call of the marker method overlaps the start marker. + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, ['source-1']); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [], 'success'); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [], 'success'); + fake.send(1, JOURNEY_IPC_SENTINEL_METHOD, [ + JOURNEY_OPEN_SOURCE_END_SENTINEL_ID, + ]); + const state = assertJourneyMainIpcCapture(await read()); + assert.equal(state.ambiguousTimelineCompletions, 1); + // The first completion could be either call; only the second one + // certainly belongs to the app call. + assert.deepEqual(state.timeline, [ + { method: JOURNEY_IPC_SENTINEL_METHOD, phase: 'start' }, + { method: JOURNEY_IPC_SENTINEL_METHOD, phase: 'end' }, + ]); + } + ); +}); + test('tracks bridge calls in flight from start to success or error', async () => { await withCapture({}, async (fake, read) => { fake.send(1, 'getSettings', []); diff --git a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts index a8c13ad6d..572ff766d 100644 --- a/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts +++ b/apps/electron-backend-e2e/src/performance/journey-main-ipc-capture.ts @@ -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. * @@ -37,6 +39,12 @@ export interface JourneyMainIpcSentinelState { } export interface JourneyMainIpcCaptureState { + /** + * Completions of a method with calls in flight both inside and outside + * the timeline; attributed outside. Non-zero means `timeline` may show + * a call as in flight that already completed. + */ + readonly ambiguousTimelineCompletions: number; readonly callsAfterSentinel: number; /** Calls before the start marker; always 0 without one. */ readonly callsBeforeStart: number; @@ -59,6 +67,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( @@ -72,6 +86,7 @@ export async function installJourneyMainIpcCapture( } const startSentinelId = input.startSentinelId ?? null; const state = { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 0, callsBeforeStart: 0, callsBeforeSentinel: 0, @@ -81,6 +96,7 @@ export async function installJourneyMainIpcCapture( processStartEpochMs: Date.now() - process.uptime() * 1000, inFlightByMethod: {} as Record, senderIds: [] as number[], + timeline: [] as { method: string; phase: 'end' | 'start' }[], sentinel: { occurrences: 0, receivedEpochMs: null as number | null, @@ -102,6 +118,18 @@ export async function installJourneyMainIpcCapture( } }; target[input.stateKey] = state; + // Calls in flight per method, split by whether their start is in + // the timeline. Completions carry no call id, so only these counts + // decide whether a completion belongs to the timeline. + const timelineInFlight: Record = {}; + const outsideInFlight: Record = {}; + const bump = ( + counts: Record, + method: string, + delta: number + ): void => { + counts[method] = (counts[method] ?? 0) + delta; + }; const listener = ( event: { sender: { id: number } }, payload: unknown @@ -115,7 +143,28 @@ 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') { + const method = record['method']; + const inTimeline = timelineInFlight[method] ?? 0; + const outside = outsideInFlight[method] ?? 0; + if (inTimeline > 0 && outside > 0) { + // Either call may have completed. Attribute it outside, + // so the timeline call stays in flight (excluded from + // the depth) rather than ending too early. + bump(outsideInFlight, method, -1); + state.ambiguousTimelineCompletions += 1; + } else if (inTimeline > 0) { + bump(timelineInFlight, method, -1); + if (counting) { + state.timeline.push({ method, phase: 'end' }); + } + } else if (outside > 0) { + // Started before the start marker, or a marker itself. + bump(outsideInFlight, method, -1); + } const pending = state.inFlightByMethod[record['method']] ?? 0; if (pending === 0) { state.unmatchedCompletions += 1; @@ -138,6 +187,12 @@ export async function installJourneyMainIpcCapture( } const method = record['method']; const isMarker = method === input.sentinelMethod; + if (!counting || isMarker) { + // Markers and calls outside the counting window stay out of + // the timeline; an app call of the marker method moves in + // below. + bump(outsideInFlight, method, 1); + } if ( isMarker && state.start !== null && @@ -166,6 +221,13 @@ export async function installJourneyMainIpcCapture( return; } state.callsBeforeSentinel += 1; + if (isMarker) { + // An app call of the marker method: counted, and moved from + // outside to the timeline. + bump(outsideInFlight, method, -1); + } + bump(timelineInFlight, method, 1); + state.timeline.push({ method, phase: 'start' }); state.callsByMethod[method] = (state.callsByMethod[method] ?? 0) + 1; }; diff --git a/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts index e2b81858a..1b3ad50fd 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts @@ -77,6 +77,7 @@ function measurement( }, }; const ipc: JourneyMainIpcCaptureState = { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 3, callsBeforeStart: 0, callsBeforeSentinel: 14, @@ -88,6 +89,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 { @@ -132,6 +140,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, @@ -144,6 +153,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'], { diff --git a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts index 139f045e3..f0e02f86d 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts @@ -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,13 @@ export function toLaunchIterationRecord( rendererGateReadyToShowHeldOnBlank: measurement.gate.readyToShowHeldOnBlank, ipcCallsByMethod: ipc.callsByMethod, + ipcSerialDepth: serialDepth, + ipcTimelineAmbiguousCompletions: ipc.ambiguousTimelineCompletions, + // `+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({ diff --git a/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts index 779eb4178..93f7fdb4e 100644 --- a/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/open-source-journey-record.spec.ts @@ -77,6 +77,7 @@ function measurement( }, }; const ipc: JourneyMainIpcCaptureState = { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 2, callsBeforeStart: 0, callsBeforeSentinel: 17, @@ -88,6 +89,7 @@ function measurement( senderIds: [1], sentinel: { occurrences: 1, receivedEpochMs: 10_081 }, start: { occurrences: 1, receivedEpochMs: 10_002 }, + timeline: [], unmatchedCompletions: 0, }; return { diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index 26c7cb0ab..8f65e3b8b 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -108,6 +108,7 @@ main-process counters below, which exist only with `IPTVNATOR_PERF_CAPTURE=1`: | Counter | Source | | ---------------------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | `renderer.ipcCallsToFirstCard` | `start` trace events the preload emits for every bridge invocation (listener registrations `on*`/`remove*` excluded, as in `wrapElectronApi`). The renderer probe fires one sentinel `cancelSourceProbe('__iptvnator-journey-sentinel__')` at the terminal moment; renderer-to-main IPC is ordered, so events before the sentinel are the exact count. The preload traces the call before forwarding it, and `SOURCE_HEALTH_CANCEL` only looks the id up in an in-memory map, so the sentinel never reaches the database worker. | +| `renderer.ipcSerialDepthToFirstCard` | Length of the longest chain of bridge calls before the sentinel in which each call started after the previous one completed. Derived from the same trace channel; see [Serial IPC depth](#serial-ipc-depth). | | `renderer.domMutationsToFirstCard` | `MutationRecord`s (not callback batches) from a `MutationObserver` on the document element with `childList`, `attributes`, `characterData` and `subtree`. When the init script runs before `` exists the observer watches `document`, which the blob reports in `capabilities.observedTarget`. | | `renderer.layoutShiftScore` | Sum of `layout-shift` entries with `hadRecentInput === false`, rounded to three decimals (a shift of 0.0001 flips in and out of the cutoff between runs; the CLS "good" threshold is 0.1, so three decimals keep the counter exact without hiding anything a user could see). The cutoff is sampled in a timer queued from the first `requestAnimationFrame` after the terminal batch, that is after the frame that paints the card has been committed; entries delivered live after the terminal batch are buffered and filtered by the same cutoff. | | `renderer.layoutShiftScoreSettled` | The same filter from navigation start until the settle point after the first card (see [Settle window](#settle-window)), rounded to three decimals. It catches shifts that land after the cutoff, such as skeletons that collapse once their data resolves. | @@ -248,6 +249,55 @@ instead of being faked: terminal moment and the record refuses a build where the hook exists but was not counted. +#### Serial IPC depth + +`renderer.ipcCallsToFirstCard` counts calls, but calls issued in parallel +cost one round trip, and #1716 showed that lowering the count did not move +wall-clock. `renderer.ipcSerialDepthToFirstCard` counts the round trips the +renderer made one after another instead. + +The capture records every `start` and every completion (`success` or +`error`) the preload traces, in arrival order, from install until the +sentinel (`timeline` in the capture state). The preload traces a completion +inside the wrapper's `then`, before the caller's own continuation runs, and +renderer-to-main IPC is ordered, so a call the renderer issued because +another call resolved always arrives after that call's completion. +`computeJourneyIpcSerialDepth` (`src/performance/journey-ipc-serial-depth.ts`) +then defines: + +- the depth of a call is 1 plus the largest depth of the calls that + completed before it started (1 when none had); +- the counter is the largest depth of a call that completed before the + sentinel. A call still in flight at the first card is excluded: the card + did not wait for it. Every bridge call counts, including a synchronous one, + as `renderer.ipcCallsToFirstCard` does. + +Trace events carry no call id, so when several calls of one method are in +flight the capture cannot tell which one completed. The counter attributes +each completion to the deepest in-flight call of that method (an upper +bound); `evidence.ipcSerialDepth.depthLowerBound` attributes it to the +shallowest. The two differ only when concurrent calls of one method sit at +different depths. A completion with no matching start fails the iteration. + +With a start marker (J2) the timeline starts mid-run, so the capture keeps +calls that started outside it (before the marker, and the markers +themselves) apart: their completions are left out. When a method has calls +in flight both inside and outside the timeline, a completion is attributed +outside, which leaves the timeline call in flight (excluded from the depth) +rather than ending it too early; `evidence.ipcTimelineAmbiguousCompletions` +counts these. + +Per iteration, `evidence.ipcSerialDepth.chain` names the methods of one +longest chain, first call first (at each step the predecessor is the latest +completion at the largest depth), `inFlightAtEnd` counts the calls excluded +as in flight, and `evidence.ipcTimeline` is the whole ordered timeline +(`+method` start, `-method` completion). The CI job summary prints the chain +of the first measured iteration. The chain is ordering, not proven +causality: a call placed in it may have been triggered by a timer or signal +rather than by its predecessor. [Startup work before the first +card](#startup-work-before-the-first-card) records what the chain is on +`master`. + ### Wall-clock | Entry | Derivation | @@ -290,6 +340,33 @@ path the first card waits for. That path is a serial chain of round trips (the migration reads, the inventory read and `reconcileEpgSources`), so a serial-depth counter is a better guardrail candidate than a raw call count. +`renderer.ipcSerialDepthToFirstCard` is that counter. First measurement +(macOS, 2026-09-30, `master` at 525ca7bc4, six launches): 6 in every +iteration, upper and lower bound equal, with the same chain each time: + +``` +dbGetAppState → dbRecoverLegacyPlaylists → dbGetAppState + → dbGetAppPlaylistMetas → reconcileEpgSources → setParentalLockState +``` + +The first level is three parallel `dbGetAppState` reads (with +`announcePlaylistOpenListener` and `getAppUpdateStatus`); the four calls +started after `setParentalLockState` resolved (`downloadsGetList`, +`dbGetRecentlyViewed`, `dbGetAllGlobalFavorites`, `xtreamRequest`) are +still in flight at the first card and excluded. + +The chain is ordering, and its last link shows the limit of that: nothing +on the card's path awaits `setParentalLockState`. The parental lock +service fires it (without awaiting) once `SettingsStore.loadSettings()` +has resolved, which happens only after `reconcileEpgSources`, and it +completes before the card in every measured launch. The links the card +waits for are the first five: the route resolver +(`settingsReadyResolver`) and the startup overlay (`allPlaylistsLoaded`, +set by the `loadPlaylists$` effect) both wait for `loadSettings()`, which +waits for the playlist migrations, the inventory read and +`reconcileEpgSources`. No baseline yet: the counter is promoted only after a +PR that lowers it also lowers `spawnToFirstCardMs` (Principle 3). + ### Summary schema ```json