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..d0dd49536 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 @@ -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', []); 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..ad507a14c 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. * @@ -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, 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; }; 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 e88dc2a9b..07ac518b0 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 @@ -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'], { 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..748dfd908 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,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({ 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 d4067df5c..8fed02dab 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 @@ -87,6 +87,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 66fc6c15d..a27a9de3a 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,47 @@ 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. + +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 +332,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