diff --git a/quest/m1/README.md b/quest/m1/README.md index 7a3b2b9a1b..fbae123049 100644 --- a/quest/m1/README.md +++ b/quest/m1/README.md @@ -61,7 +61,6 @@ blocks. The quests that gated m0 lines moved under them. - [A watch and publish release ships assets()](/quest/m1/assets-release.md) - the release that lets the sites host the worklets - [Dogfood hosted worklets](/quest/m1/dogfood-assets.md) - moq.dev and the moq.pro dashboard host the worklets and call `assets()` after the release - [More tests under load](/quest/m1/test-flakes-2/README.md) - the second round of load-only failures, one quest per flake, fixed at the cause -- [CI runner stalls](/quest/m1/ci-runner-stalls.md) - the 0.4 to 0.8 s freezes of both interop tracks on CI are attributed from a week of nightlies and fixed or told apart from playback bugs - [Subscriber max-delay](/quest/m1/subscriber-max-delay.md) - subscriber staleness becomes `max_delay`; publisher retention stays `max_age` - [Wire compatibility](/quest/m1/wire-compat.md) - a nightly run tests this checkout against the last published release for tokens, session wire, and catalog/container - [Same-epoch importers](/quest/m1/hop-aligned-import.md) - importers sharing one `--epoch` and fed one stream publish identical groups and timestamps, so failover between a redundant pair survives diff --git a/quest/m1/ci-runner-stalls.md b/quest/m1/ci-runner-stalls.md deleted file mode 100644 index 6d3aea5d20..0000000000 --- a/quest/m1/ci-runner-stalls.md +++ /dev/null @@ -1,24 +0,0 @@ -# [S] Interop freezes on CI runners are attributed - -## Goal - -The 0.4 to 0.8 s freezes where both interop tracks stop at once on CI are -attributed to the runner, the relay, or the player, with evidence from the -nightly traces. A cause in our code is fixed at its source; a runner stall is -documented, and the interop checks tell it apart from a playback bug instead -of failing on it as one. - -## Plan - -Found in [#4529](https://github.com/moq-dev/moq/pull/4529) while chasing the -cold-start tone check: some CI traces show both tracks freezing together, -which that fix shortens but cannot remove. #4529 added the player's `delay` to -the interop trace, so a week of nightlies after it lands shows the freezes -without the delay-flush noise that hid them. - -Collect the failing and passing nightly interop traces for that week, line up -each freeze against relay and player timestamps, and look for what the -runner was doing (CPU steal, GC, disk). Decided with the maintainer: diagnose -first from real nightlies rather than assume a runner stall. - -Public API: none. Wire: none. diff --git a/test/interop/README.md b/test/interop/README.md index 0d87ea48d5..7c18acdae6 100644 --- a/test/interop/README.md +++ b/test/interop/README.md @@ -146,6 +146,14 @@ median, and audio/video skew must stay within one 200ms tone step for 90% of samples. One step is the floor set by the analyser window straddling a step boundary and the canvas holding a frame up to one frame old. +A freeze of both tracks is not one failure. When the player's sample clock +jumps by 400ms or more and both the presented frame and the received audio sit +still across that jump, or the publisher's own frame clock sits still with +them, the window names a runner stall and leaves it out of the playback rate +and tone. The picture and the tone staying still while the publisher clock +keeps moving still fails as playback: that is the relay or the player, and the +trace's `pub=` column is what separates them. + The run ends with negative controls. Each injects a defect in the fixture and names the assertion that has to catch it, and passes only by failing there: diff --git a/test/interop/clients/js/media.ts b/test/interop/clients/js/media.ts index d73259a50e..dd815ff56f 100644 --- a/test/interop/clients/js/media.ts +++ b/test/interop/clients/js/media.ts @@ -46,9 +46,13 @@ import { } from "./harness"; import { type CaptureState, + countedElapsed, FAULTS, + gradedSamples, + jointStalls, lateJoinStartsLive, leakedPlayerStarted, + rateElapsed, SAMPLE_MS, SAMPLE_RATE, } from "./src/contract"; @@ -121,14 +125,29 @@ const percentile = (values: number[], p: number) => { return sorted[Math.min(sorted.length - 1, Math.floor(sorted.length * p))]; }; -/** Collect distinct samples from the player for `ms`, so a window can be measured after the fact. */ -async function collect(page: Page, errors: BrowserErrors, ms: number): Promise { - const samples: PlayerState[] = []; +/** A player sample, plus the publisher frame read beside it when the fixture page was sampled. */ +type Reading = PlayerState & { publisherFrame?: number }; + +/** + * Collect distinct samples from the player for `ms`, so a window can be measured after the fact. + * + * `publisher`, when passed, is read on each new player sample. That frame clock is what separates + * a runner stall from playback that froze while the source kept painting. + */ +async function collect(page: Page, errors: BrowserErrors, ms: number, publisher?: Page): Promise { + const samples: Reading[] = []; const deadline = Date.now() + ms; while (Date.now() < deadline) { throwPageErrors(errors); const sample = await readPlayerState(page).catch(() => undefined); - if (sample && sample.seq !== samples[samples.length - 1]?.seq) samples.push(sample); + if (sample && sample.seq !== samples[samples.length - 1]?.seq) { + const publisherFrame = publisher + ? await readFixtureState(publisher) + .then((state) => state.frameId) + .catch(() => undefined) + : undefined; + samples.push(publisherFrame === undefined ? sample : { ...sample, publisherFrame }); + } await sleep(SAMPLE_MS / 2); } throwPageErrors(errors); @@ -169,13 +188,14 @@ async function waitFrozen(page: Page, errors: BrowserErrors, assertion: string, // One sample as a line: elapsed time, the frame on the canvas, the tone step heard against the one // that frame belongs to, how far the tone stood above the noise floor, and whether audio was // arriving at all, which separates a silent player from a publisher that stopped sending. -function traceLine(sample: PlayerState, start: number): string { +function traceLine(sample: Reading, start: number): string { const step = sample.frameId === undefined ? "?" : Pattern.expectedStep(sample.frameId); const margin = sample.toneDb !== undefined && sample.noiseDb !== undefined ? sample.toneDb - sample.noiseDb : 0; + const pub = sample.publisherFrame === undefined ? "" : ` pub=${sample.publisherFrame}`; return ( ` +${((sample.at - start) / 1000).toFixed(2)}s frame=${sample.frameId ?? "-"} ` + `step=${sample.toneStep ?? "-"}/${step} tone=${margin.toFixed(0)}dB ${sample.toneHz?.toFixed(0) ?? "-"}Hz ` + - `paused=${sample.paused} delay=${sample.delay}ms audio=${sample.audioBytes}B${sample.audioStalled ? " stalled" : ""}` + `paused=${sample.paused} delay=${sample.delay}ms audio=${sample.audioBytes}B${sample.audioStalled ? " stalled" : ""}${pub}` ); } @@ -186,7 +206,7 @@ function traceLine(sample: PlayerState, start: number): string { * the tone off the graph root that feeds the speakers. A failure prints every reading in the window, * so the summary can be traced back to the readings behind it. */ -function assertMedia(samples: PlayerState[], label: string): void { +function assertMedia(samples: Reading[], label: string): void { try { measure(samples, label); } catch (err) { @@ -197,7 +217,7 @@ function assertMedia(samples: PlayerState[], label: string): void { } } -function measure(samples: PlayerState[], label: string): void { +function measure(samples: Reading[], label: string): void { check(samples.length >= 10, "sampling", () => `${label}: only ${samples.length} samples in the window`); const readable = samples.filter((s) => s.frameId !== undefined); @@ -207,9 +227,29 @@ function measure(samples: PlayerState[], label: string): void { () => `${label}: ${readable.length}/${samples.length} presented frames carried a readable fixture pattern`, ); + const stalls = jointStalls(samples); + const runnerMs = stalls + .filter((stall) => stall.kind === "runner") + .reduce((sum, stall) => sum + (stall.to - stall.from), 0); + const pathMs = stalls + .filter((stall) => stall.kind === "path") + .reduce((sum, stall) => sum + (stall.to - stall.from), 0); + // The summary line is what a passing nightly keeps. The trace itself is only printed on failure. + const runnerNote = runnerMs > 0 ? `, runner stall ${(runnerMs / 1000).toFixed(2)}s` : ""; + const excused = runnerMs > 0 ? `; runner stall ${(runnerMs / 1000).toFixed(2)}s` : ""; + + check( + pathMs === 0, + "video progress", + () => + `${label}: both tracks sat still for ${(pathMs / 1000).toFixed(2)}s while the publisher clock moved${excused}`, + ); + const first = readable[0]; const last = readable[readable.length - 1]; - const elapsed = (last.at - first.at) / 1000; + // A runner stall is the machine, not the picture. A window that is mostly stalled keeps the raw clock and fails. + const elapsedMs = rateElapsed(last.at - first.at, countedElapsed(first.at, last.at, stalls)); + const elapsed = elapsedMs / 1000; const advance = (last.frameId ?? 0) - (first.frameId ?? 0); const rate = advance / elapsed; const want = Pattern.FPS * MIN_RATE; @@ -217,7 +257,7 @@ function measure(samples: PlayerState[], label: string): void { rate >= want, "video progress", () => - `${label}: presented ${advance} frames in ${elapsed.toFixed(1)}s, ${rate.toFixed(1)}fps against a ${want.toFixed(1)}fps floor`, + `${label}: presented ${advance} frames in ${elapsed.toFixed(1)}s, ${rate.toFixed(1)}fps against a ${want.toFixed(1)}fps floor${excused}`, ); const back = readable.findIndex((s, i) => i > 0 && (s.frameId ?? 0) < (readable[i - 1].frameId ?? 0)); @@ -228,14 +268,16 @@ function measure(samples: PlayerState[], label: string): void { `${label}: presented frame went backwards, ${readable[back - 1]?.frameId} then ${readable[back]?.frameId}`, ); - const toned = samples.filter((s) => s.toneStep !== undefined); + const graded = gradedSamples(samples, stalls); + const toned = graded.filter((s) => s.toneStep !== undefined); check( - toned.length >= samples.length * AGREEMENT, + toned.length >= graded.length * AGREEMENT, "audio tone", - () => `${label}: ${toned.length}/${samples.length} samples carried the fixture tone above the noise floor`, + () => + `${label}: ${toned.length}/${graded.length} samples carried the fixture tone above the noise floor${excused}`, ); - const skews = samples + const skews = graded .filter((s) => s.frameId !== undefined && s.toneStep !== undefined) .map((s) => Pattern.stepSkew(s.toneStep as number, Pattern.expectedStep(s.frameId as number))); check(skews.length > 0, "audio/video sync", () => `${label}: no sample carried both a frame and a tone`); @@ -259,7 +301,7 @@ function measure(samples: PlayerState[], label: string): void { ); console.error( ` ${label}: ${rate.toFixed(1)}fps presented over ${advance} frames, tone ${margin.toFixed(0)}dB above the floor, ` + - `skew median ${median.toFixed(0)}ms p95 ${p95.toFixed(0)}ms (browser output, not a speaker)`, + `skew median ${median.toFixed(0)}ms p95 ${p95.toFixed(0)}ms${runnerNote} (browser output, not a speaker)`, ); } @@ -519,7 +561,7 @@ try { predicate: (state) => state.audioContext === "running", }); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "cold start"); + assertMedia(await collect(player, playerErrors, WINDOW_MS, publisher), "cold start"); // ── pause and resume ───────────────────────────────────────────────────── if (wants("pause")) { @@ -562,7 +604,7 @@ try { predicate: (state) => !state.paused && (state.frameId ?? 0) > paused, }); console.error(` resumed ${(resumed.frameId ?? 0) - paused} frames past the pause`); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after resume"); + assertMedia(await collect(player, playerErrors, WINDOW_MS, publisher), "after resume"); } // ── unsubscribe and rejoin ─────────────────────────────────────────────── @@ -583,7 +625,7 @@ try { description: `the presented frame to move past the ${left} it stopped on`, predicate: (state) => (state.frameId ?? 0) > left, }); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after rejoin"); + assertMedia(await collect(player, playerErrors, WINDOW_MS, publisher), "after rejoin"); } // ── detach and reattach ────────────────────────────────────────────────── @@ -624,7 +666,7 @@ try { description: `the presented frame to move past the ${busy.frameId} showing before the detach`, predicate: (state) => (state.frameId ?? 0) > (busy.frameId ?? 0), }); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after reattach"); + assertMedia(await collect(player, playerErrors, WINDOW_MS, publisher), "after reattach"); } // ── publisher stop and same-path republish ─────────────────────────────── @@ -649,7 +691,7 @@ try { predicate: (state) => state.frameId !== undefined && state.frameId < (before.frameId ?? 0), }); console.error(` recovered at frame ${recovered.frameId}, restarted from ${before.frameId}`); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "after republish"); + assertMedia(await collect(player, playerErrors, WINDOW_MS, publisher), "after republish"); } // ── late join ──────────────────────────────────────────────────────────── @@ -676,8 +718,10 @@ try { () => `joined at frame ${joined.frameId}, timestamp ${joined.videoTimestamp}ms before the current GOP's ${live.timestamp}ms keyframe`, ); - console.error(` joined at frame ${joined.frameId}, timestamp ${joined.videoTimestamp}ms, current GOP began at ${live.timestamp}ms`); - assertMedia(await collect(player, playerErrors, WINDOW_MS), "late join"); + console.error( + ` joined at frame ${joined.frameId}, timestamp ${joined.videoTimestamp}ms, current GOP began at ${live.timestamp}ms`, + ); + assertMedia(await collect(player, playerErrors, WINDOW_MS, publisher), "late join"); } if (wants("capture-denial")) await captureDenial(`${broadcast}-capture.hang`); diff --git a/test/interop/clients/js/src/contract.test.ts b/test/interop/clients/js/src/contract.test.ts index 4afa6e19a6..a5e51e664b 100644 --- a/test/interop/clients/js/src/contract.test.ts +++ b/test/interop/clients/js/src/contract.test.ts @@ -1,6 +1,23 @@ import { expect, test } from "bun:test"; import * as Moq from "@moq/net"; -import { lateJoinStartsLive, leakedPlayerStarted, readLiveGop, type Resources } from "./contract"; +import { + countedElapsed, + gradedSamples, + type JointSample, + jointStalls, + lateJoinStartsLive, + leakedPlayerStarted, + type Resources, + rateElapsed, + readLiveGop, +} from "./contract"; + +const flat = (at: number, frameId: number | undefined, audioBytes: number, publisherFrame?: number): JointSample => ({ + at, + frameId, + audioBytes, + publisherFrame, +}); const playing: Resources = { transports: 1, sockets: 0, audioContexts: 1, workers: 0 }; @@ -19,7 +36,6 @@ test("unchanged counts are not a leak start", () => { expect(leakedPlayerStarted(playing, playing)).toBe(false); }); - test("late join uses the published GOP when painting is ahead of capture", async () => { const broadcast = new Moq.Broadcast.Producer(); const track = broadcast.createTrack("video"); @@ -52,3 +68,75 @@ test("late join uses the published GOP when painting is ahead of capture", async broadcast.close(); } }); + +test("a joint freeze is a runner stall when the publisher clock sits still", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, 10, 1000, 40)); + expect(jointStalls(samples)).toEqual([{ kind: "runner", from: 0, to: 600 }]); +}); + +test("a joint freeze is the path when the publisher clock keeps moving", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, 10, 1000, 40 + i * 2)); + expect(jointStalls(samples)).toEqual([{ kind: "path", from: 0, to: 600 }]); +}); + +test("one frame of publisher motion is the read gap, not a moving clock", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, 10, 1000, i === 0 ? 40 : 41)); + expect(jointStalls(samples)).toEqual([{ kind: "runner", from: 0, to: 600 }]); +}); + +test("a sample-clock hole with both tracks still is a runner stall without a publisher reading", () => { + expect(jointStalls([flat(0, 10, 1000), flat(600, 10, 1000)])).toEqual([{ kind: "runner", from: 0, to: 600 }]); +}); + +test("a sample-clock hole names the runner even when the publisher frame jumped across it", () => { + expect(jointStalls([flat(0, 10, 1000, 10), flat(700, 10, 1000, 40)])).toEqual([ + { kind: "runner", from: 0, to: 700 }, + ]); +}); + +test("an unread publisher clock does not excuse a steady joint freeze", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, 10, 1000)); + expect(jointStalls(samples)).toEqual([{ kind: "path", from: 0, to: 600 }]); +}); + +test("a publisher frame that restarts is the path, not a stopped clock", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, 10, 1000, i === 0 ? 100 : 0)); + expect(jointStalls(samples)).toEqual([{ kind: "path", from: 0, to: 600 }]); +}); + +test("frozen video is not a joint stall while audio is still arriving", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, 0, 1000 + i * 100, 0)); + expect(jointStalls(samples)).toEqual([]); +}); + +test("advancing frames are not a joint stall while audio sits still", () => { + const samples = Array.from({ length: 13 }, (_, i) => flat(i * 50, i, 1000, i)); + expect(jointStalls(samples)).toEqual([]); +}); + +test("a sampling gap during playback is not a joint stall when the frame and the audio both moved", () => { + expect(jointStalls([flat(0, 10, 100, 10), flat(800, 34, 5000, 34)])).toEqual([]); +}); + +test("a flat stretch under 400ms is not a stall", () => { + expect(jointStalls([flat(0, 1, 1, 1), flat(100, 1, 1, 1)])).toEqual([]); + expect(jointStalls([flat(0, 1, 1, 1), flat(350, 1, 1, 1)])).toEqual([]); +}); + +test("runner stalls come out of the elapsed time and the tone pool", () => { + const samples = [flat(0, 1, 1, 1), flat(800, 1, 1, 1), flat(850, 2, 200, 20), flat(4000, 90, 9000, 120)]; + const stalls = jointStalls(samples); + expect(stalls).toEqual([{ kind: "runner", from: 0, to: 800 }]); + expect(countedElapsed(0, 4000, stalls)).toBe(3200); + expect(rateElapsed(4000, 3200)).toBe(3200); + expect(rateElapsed(4000, 500)).toBe(4000); + + const tone = Array.from({ length: 20 }, (_, i) => ({ at: i * 50 })); + const interior = gradedSamples(tone, [{ kind: "runner", from: 100, to: 400 }]); + expect(interior.map((sample) => sample.at)).toEqual([ + 0, 50, 100, 400, 450, 500, 550, 600, 650, 700, 750, 800, 850, 900, 950, + ]); + + const eaten = Array.from({ length: 12 }, (_, i) => ({ at: i * 50 })); + expect(gradedSamples(eaten, [{ kind: "runner", from: 0, to: 550 }])).toBe(eaten); +}); diff --git a/test/interop/clients/js/src/contract.ts b/test/interop/clients/js/src/contract.ts index 43b0a1ee4f..c6ef162dfd 100644 --- a/test/interop/clients/js/src/contract.ts +++ b/test/interop/clients/js/src/contract.ts @@ -183,6 +183,129 @@ export type Sample = { resources: Resources; }; +/** + * Both tracks sitting still this long is a freeze. + * + * Shorter than the one-second pause check, and long enough that a slow sample + * is not one. A 0.4s hole is the freeze the nightly traces were being read for. + */ +export const JOINT_STALL_MS = 400; + +/** One player reading, plus the publisher's own frame clock when it was sampled. */ +export type JointSample = { + /** `performance.now()` when the player sample was taken, in milliseconds. */ + at: number; + /** Presented fixture frame. Absent when the canvas is not the fixture. */ + frameId?: number; + /** Encoded audio bytes the player has received. */ + audioBytes: number; + /** Frame the publisher had painted. Absent when that page was not read. */ + publisherFrame?: number; +}; + +/** A stretch where the presented frame and the received audio both sat still. */ +export type JointStall = { + /** `runner` when the page or the publisher clock stopped. `path` when only playback did. */ + kind: "runner" | "path"; + /** `at` of the first sample in the stretch, in milliseconds. */ + from: number; + /** `at` of the last sample in the stretch, in milliseconds. */ + to: number; +}; + +/** + * Stretches where one presented frame and one audio byte count both sit still. + * + * `runner` when the sample clock jumped, because the page was not scheduled, or + * when the publisher's own frame clock sat still with the tracks. `path` when + * that clock kept moving: the relay or the player. An unread publisher clock is + * `path` too. The freeze is not excused without evidence the source stopped. + */ +export function jointStalls(samples: readonly JointSample[], minMs = JOINT_STALL_MS): JointStall[] { + const stalls: JointStall[] = []; + let i = 0; + while (i < samples.length) { + const start = samples[i]; + if (start.frameId === undefined) { + i++; + continue; + } + let j = i; + while ( + j + 1 < samples.length && + samples[j + 1].frameId === start.frameId && + samples[j + 1].audioBytes === start.audioBytes + ) { + j++; + } + const end = samples[j]; + if (j > i && end.at - start.at >= minMs) { + // A hole this long means the page was not scheduled. That names the runner + // even when the publisher frame moved across the hole. + let samplerGap = false; + for (let k = i; k < j; k++) { + if (samples[k + 1].at - samples[k].at >= minMs) samplerGap = true; + } + const pubStart = start.publisherFrame; + const pubEnd = end.publisherFrame; + // One frame of publisher motion is the gap between the two reads, not a clock that kept running. + const publisherStopped = + pubStart !== undefined && pubEnd !== undefined && pubEnd >= pubStart && pubEnd - pubStart <= 1; + stalls.push({ + kind: samplerGap || publisherStopped ? "runner" : "path", + from: start.at, + to: end.at, + }); + } + i = j + 1; + } + return stalls; +} + +/** + * Wall time minus runner stalls, in milliseconds. + * + * A path stall stays in the elapsed time. The picture sitting still while the + * source moved is a playback failure. + */ +export function countedElapsed(firstAt: number, lastAt: number, stalls: readonly JointStall[]): number { + let elapsed = lastAt - firstAt; + for (const stall of stalls) { + if (stall.kind !== "runner") continue; + const from = Math.max(stall.from, firstAt); + const to = Math.min(stall.to, lastAt); + if (to > from) elapsed -= to - from; + } + return elapsed; +} + +/** + * Elapsed time the frame rate uses. + * + * Runner stalls come out once a second of the window is left. Below that the + * stall ate the measurement, and the raw clock has to fail it. + */ +export function rateElapsed(rawMs: number, countedMs: number, minMs = 1000): number { + return countedMs >= minMs ? countedMs : rawMs; +} + +/** + * Samples a tone or sync agreement counts. + * + * A runner stall's interior is the machine, not the player. Too little left is + * a window that never played, so the whole set is graded and the silence still fails. + */ +export function gradedSamples( + samples: readonly T[], + stalls: readonly JointStall[], + min = 10, +): readonly T[] { + const kept = samples.filter( + (sample) => !stalls.some((stall) => stall.kind === "runner" && sample.at > stall.from && sample.at < stall.to), + ); + return kept.length >= min ? kept : samples; +} + // ── the refused session ───────────────────────────────────────────────────── /** How a refused session ended, as `WebTransport.closed` reported it to the page. */