diff --git a/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts b/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts index 9a8589f21..1068f9f83 100644 --- a/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts +++ b/apps/electron-backend-e2e/src/journeys/playback-journey-app.ts @@ -1,7 +1,10 @@ import type { ElectronApplication, Page } from '@playwright/test'; import { configureLiveFormat } from '../xtream-live-format.fixture'; -import { waitForJourneyClickQuiet } from '../performance/journey-click-settle'; +import { + JOURNEY_CLICK_QUIET_MS, + waitForJourneyClickQuiet, +} from '../performance/journey-click-settle'; import { detachJourneyMainIpcCapture, installJourneyMainIpcCapture, @@ -16,7 +19,10 @@ import { JOURNEY_OPEN_SOURCE_START_SELECTOR, waitForJourneyRendererProbe, } from '../performance/journey-renderer-probe'; -import type { PlaybackJourneyMeasurement } from '../performance/playback-journey-record'; +import { + PLAYBACK_JOURNEY_AFTER_PLAYING_WINDOW_MS, + type PlaybackJourneyMeasurement, +} from '../performance/playback-journey-record'; import type { LaunchJourneySeedOptions, LaunchJourneySession, @@ -174,8 +180,19 @@ export async function measurePlaybackJourney( if (clickEpochMs === undefined || playingEpochMs === undefined) { throw new Error('playback-journey-probe-incomplete'); } + // A live stream never leaves the mock quiet, so instead of J2's quiet + // wait the ledger is watched for a fixed window after `playing`. + const afterPlayingUntilEpochMs = + playingEpochMs + PLAYBACK_JOURNEY_AFTER_PLAYING_WINDOW_MS; + const remainingMs = + afterPlayingUntilEpochMs - (performance.timeOrigin + performance.now()); + if (remainingMs > 0) { + await new Promise((resolve) => setTimeout(resolve, remainingMs)); + } // The ledger stamps arrivals with this process's clock, the probe with - // the renderer's; both read the same host clock (as in J2). + // the renderer's; both read the same host clock (as in J2). The record + // keeps the distance of the nearest request to each boundary, so a + // count that a small clock difference could flip is visible. const sinceSpawn = ledger.since(spawnLedgerMark); const beforeClick = sinceSpawn.filter( (entry) => entry.epochMs < clickEpochMs @@ -185,7 +202,9 @@ export async function measurePlaybackJourney( await readCancelledExternalArtwork(electronApp), http: { afterPlaying: sinceSpawn.filter( - (entry) => entry.epochMs >= playingEpochMs + (entry) => + entry.epochMs >= playingEpochMs && + entry.epochMs < afterPlayingUntilEpochMs ), afterSettleBeforeClick: beforeClick.filter( (entry) => entry.sequence >= settledLedgerMark diff --git a/apps/electron-backend-e2e/src/performance/playback-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/playback-journey-record.spec.ts index 12c249360..21bd8df3c 100644 --- a/apps/electron-backend-e2e/src/performance/playback-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/playback-journey-record.spec.ts @@ -193,6 +193,12 @@ test('maps the media-terminated probe, IPC window and mock ledger to exact count mainIpcStart: 10_001, playing: 10_349.84, }); + // Click 10,000: last request before at 8,000, first after at 10,020. + // Playing 10,349.84: last before at 10,030, first after at 10,400. + assert.deepEqual(record.evidence['httpBoundaryMarginsMs'], { + click: 20, + playing: 50.2, + }); assert.equal(record.evidence['externalArtworkCancelled'], 8); assert.equal(record.evidence['ipcCallsAfterPlaying'], 3); }); diff --git a/apps/electron-backend-e2e/src/performance/playback-journey-record.ts b/apps/electron-backend-e2e/src/performance/playback-journey-record.ts index 9639322f7..ce0f59a44 100644 --- a/apps/electron-backend-e2e/src/performance/playback-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/playback-journey-record.ts @@ -33,6 +33,9 @@ export const PLAYBACK_JOURNEY_WALL_CLOCK = { CLICK_TO_PLAYING: 'clickToPlayingMs', } as const; +/** How long requests after `playing` are observed, for evidence only. */ +export const PLAYBACK_JOURNEY_AFTER_PLAYING_WINDOW_MS = 1_000; + export const PLAYBACK_JOURNEY_UNAVAILABLE_COUNTERS: Readonly< Record > = Object.freeze({ @@ -46,7 +49,7 @@ export interface PlaybackJourneyMeasurement { /** Logo requests to picsum.photos cancelled in the main process. */ readonly externalArtworkCancelled: number; readonly http: { - /** Requests at or after `playing` seen when the ledger was read. */ + /** Requests in the first second after `playing`. */ readonly afterPlaying: readonly JourneyMockRequest[]; /** Mock requests after the app settled but before the click stamp. */ readonly afterSettleBeforeClick: number; @@ -64,6 +67,24 @@ export interface PlaybackJourneyMeasurement { const ROUTE_FRAGMENT = '/workspace/xtreams/'; const LIVE_STREAM_ROUTE = /^\/live\/:username\/:password\/[^/]+\.ts$/; +/** + * Distance of the nearest ledger request to a boundary on either side + * (null when there is none). The ledger and the renderer stamp with + * different processes' clocks; a small margin flags a count that a clock + * difference could move across the boundary. + */ +function boundaryMarginMs( + before: readonly JourneyMockRequest[], + after: readonly JourneyMockRequest[], + boundaryEpochMs: number +): number | null { + const distances = [ + ...before.map((entry) => boundaryEpochMs - entry.epochMs), + ...after.map((entry) => entry.epochMs - boundaryEpochMs), + ]; + return distances.length === 0 ? null : roundTenth(Math.min(...distances)); +} + function roundTenth(value: number): number { return Math.round(value * 10) / 10; } @@ -160,6 +181,18 @@ export function toPlaybackIterationRecord( http.beforeClick ), httpRequestsByRoute: countJourneyMockRoutes(http.toPlaying), + httpBoundaryMarginsMs: Object.freeze({ + click: boundaryMarginMs( + http.beforeClick, + http.toPlaying, + start.epochMs + ), + playing: boundaryMarginMs( + http.toPlaying, + http.afterPlaying, + terminal.epochMs + ), + }), ipcCallsAfterPlaying: ipc.callsAfterSentinel, ipcCallsByMethod: ipc.callsByMethod, layoutShift: Object.freeze({ diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index 008802ef4..26c7cb0ab 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -552,6 +552,20 @@ ignored. | `renderer.layoutShiftScore` | All `layout-shift` entries from the click until the `playing` event, including `hadRecentInput` ones (as J2), rounded to three decimals. Entries delivered up to the post-paint cutoff are read, but only those that started by the event count. | | `renderer.longTasks` | `longtask` entries over 50 ms whose time range overlaps the window from the click to the `playing` event, so the task that dispatched the event counts. Evidence until shown to be stable on the runner. | +`renderer.httpRequestsToPlaying` compares the ledger's arrival stamps +(test process) with the renderer's click and `playing` stamps. Both are +`performance.timeOrigin + performance.now()` on the same host clock, but the +two processes' time origins can differ by a fraction of a millisecond, so +every iteration records `evidence.httpBoundaryMarginsMs`: the distance of +the nearest request on either side of the click and of `playing`. A margin +of a few milliseconds means a clock difference could move that request +across the boundary. Locally the first request after the click arrives 3-6 +ms after its stamp (the click causes it, so it cannot precede the click) and +the nearest request to `playing` is more than 170 ms away; both are well +above a sub-millisecond origin difference. `evidence.httpRequestsAfterPlayingByRoute` covers a fixed +window of 1 s after `playing` (the test waits that long before reading the +ledger), not a quiet mock as in J2: a live stream has no quiet end. + Two counters are listed under `unavailable`. `renderer.cdTicksToPlaying` is missing for the same reason as in J1 and J2. `renderer.ipcSerialDepthToPlaying` is missing because the serial-depth