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 d0dd49536..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, @@ -354,6 +356,58 @@ test('records starts and completions in order between the markers', async () => ); }); +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 ad507a14c..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 @@ -39,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; @@ -80,6 +86,7 @@ export async function installJourneyMainIpcCapture( } const startSentinelId = input.startSentinelId ?? null; const state = { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 0, callsBeforeStart: 0, callsBeforeSentinel: 0, @@ -111,7 +118,18 @@ export async function installJourneyMainIpcCapture( } }; target[input.stateKey] = state; - let markerCompletionsToSkip = 0; + // 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 @@ -129,17 +147,23 @@ export async function installJourneyMainIpcCapture( 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 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) { @@ -163,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 && @@ -170,7 +200,6 @@ 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) { @@ -192,6 +221,12 @@ 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 07ac518b0..375b89006 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 @@ -76,6 +76,7 @@ function measurement( }, }; const ipc: JourneyMainIpcCaptureState = { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 3, callsBeforeStart: 0, callsBeforeSentinel: 14, 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 748dfd908..f0e02f86d 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts @@ -160,6 +160,7 @@ export function toLaunchIterationRecord( 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 }) => 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 8fed02dab..03c162068 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 @@ -76,6 +76,7 @@ function measurement( }, }; const ipc: JourneyMainIpcCaptureState = { + ambiguousTimelineCompletions: 0, callsAfterSentinel: 2, callsBeforeStart: 0, callsBeforeSentinel: 17, diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index a27a9de3a..b406b349a 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -279,6 +279,14 @@ 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