diff --git a/README.md b/README.md index 28c7d670..4f4c3a64 100644 --- a/README.md +++ b/README.md @@ -47,7 +47,7 @@ npm run build # writes dist/ and regenerates index.html; the folder is wh The browser suite and the three example games need a machine with a GPU: ```bash -node tools/seed-e2e.mjs && node tools/e2e.mjs # the editor, 2077 checks (GM_STEPS=20 for one step) +node tools/seed-e2e.mjs && node tools/e2e.mjs # the editor, 2080 checks (GM_STEPS=20 for one step) # every tool signs in first – see the Accounts page node tools/seed-jumprun.mjs && node tools/smoke-jumprun.mjs node tools/seed-tetris.mjs && node tools/smoke-tetris.mjs diff --git a/src/core/recording/recording.ts b/src/core/recording/recording.ts index cb4b4c89..6130e4d4 100644 --- a/src/core/recording/recording.ts +++ b/src/core/recording/recording.ts @@ -250,6 +250,9 @@ export class RecordingClock { */ export class FrameGate { private next = 0; + /** Frames taken so far, and the recording's time of the last. */ + private taken = 0; + private lastMs = 0; constructor(private readonly fps: number) {} @@ -257,8 +260,81 @@ export class FrameGate { const period = 1000 / this.fps; if (ms < this.next - period / 4) return false; this.next = Math.max(this.next + period, ms + period / 2); + this.taken++; + this.lastMs = ms; return true; } + + /** The frames the recording's time up to the last one taken has room for. */ + get slots(): number { + return this.taken === 0 ? 0 : Math.max(this.taken, Math.round((this.lastMs * this.fps) / 1000) + 1); + } + + /** + * The frames no drawn frame came for: the screen drew too late or too seldom. The video holds the + * frame before over them, so it stutters, though its time stays right. + */ + get skipped(): number { + return this.slots - this.taken; + } +} + +/** How long a recording runs before it is judged: its first moments may stall while it starts. */ +const PACE_SETTLE_MS = 1000; +/** How much of its time a recording is judged over at once. */ +const PACE_SPAN_MS = 2000; +/** The share of frames a recording may miss over a span before it is said to fall behind. */ +export const PACE_MOST_MISSED_WHILE = 0.1; +/** The share of frames a whole recording may miss, once settled, before its end says so. */ +const PACE_MOST_MISSED = 0.05; + +/** Where a recording stood: its time, and the frames it had missed by then. */ +interface PacePoint { + ms: number; + missed: number; +} + +/** + * Whether a recording keeps up with its fps: told once, the first time it misses more than + * `PACE_MOST_MISSED_WHILE` of the frames over a span, and at its end, when it missed more than + * `PACE_MOST_MISSED` of them. Both leave out its first moments. + */ +export class FramePace { + private settled: PacePoint | null = null; + private last: PacePoint | null = null; + private from: PacePoint | null = null; + private told = false; + + constructor(private readonly fps: number) {} + + /** + * At the recording's time `ms`, with `missed` frames missed so far: the frames a second it got + * over the span just ended, if that is the first time it fell behind; null otherwise. + */ + behind(ms: number, missed: number): number | null { + if (ms < PACE_SETTLE_MS) return null; + this.settled ??= { ms, missed }; + this.last = { ms, missed }; + if (this.told) return null; + if (!this.from) { + this.from = { ms, missed }; + return null; + } + const span = ms - this.from.ms; + if (span < PACE_SPAN_MS) return null; + const share = (missed - this.from.missed) / ((span * this.fps) / 1000); + this.from = { ms, missed }; + if (share <= PACE_MOST_MISSED_WHILE) return null; + this.told = true; + return Math.max(0, Math.round(this.fps * (1 - share))); + } + + /** Whether the recording, once settled, missed so many frames that it stutters. */ + get stutters(): boolean { + const { settled, last } = this; + if (!settled || !last || last.ms <= settled.ms) return false; + return (last.missed - settled.missed) / (((last.ms - settled.ms) * this.fps) / 1000) > PACE_MOST_MISSED; + } } /** diff --git a/src/editor/EditorRecorder.ts b/src/editor/EditorRecorder.ts index 8725f769..7aad90b2 100644 --- a/src/editor/EditorRecorder.ts +++ b/src/editor/EditorRecorder.ts @@ -14,7 +14,13 @@ import { type RecordingUploadOptions, } from '../core/recording/recording'; import { renderCount, requestRender, Theme, toHex, ui } from '../ui'; -import { type FrameSource, type MadeRecording, Take, type TakeInfo } from '../viewport/RecordingTake'; +import { + consoleLine, + type FrameSource, + type MadeRecording, + Take, + type TakeInfo, +} from '../viewport/RecordingTake'; /** What the editor recorder needs of the editor. */ export interface EditorRecorderHost { @@ -65,7 +71,9 @@ export class EditorRecorder { const source = new CanvasSource(app.canvas, plan.size, settings.fps, settings.pointer); const upload = { convert: settings.convert, adopt: settings.convert && settings.adopt }; const host = { - log: (line: string) => this.host.log(line), + // The notice would be in the recording: a line that warns of nothing stays in the console. + log: (line: string, level: 'info' | 'warn' = 'warn') => + level === 'info' ? consoleLine(line, level) : this.host.log(line), saved: (recording: MadeRecording) => this.host.saved(recording, upload), }; const name = recordingName(settings.name, new Date()); diff --git a/src/editor/PlaySession.ts b/src/editor/PlaySession.ts index 44b67dcd..3f184d2c 100644 --- a/src/editor/PlaySession.ts +++ b/src/editor/PlaySession.ts @@ -18,7 +18,7 @@ import type { World } from '../runtime/World'; import { onFrame, ui } from '../ui'; import { soundLibrary } from '../viewport/SoundLibrary'; import { GameRecorder } from '../viewport/GameRecorder'; -import type { MadeRecording } from '../viewport/RecordingTake'; +import { consoleLine, type MadeRecording } from '../viewport/RecordingTake'; import type { RecordingUploadOptions } from '../core/recording/recording'; import { videoLibrary } from '../viewport/VideoLibrary'; import { FrameMeter, type FrameTimes } from './frameMeter'; @@ -94,9 +94,9 @@ export class PlaySession { ) { this.recorder = new GameRecorder({ view: () => host.gameView, - log: (line) => { + log: (line, level) => { this.world?.log.push(line); - console.warn('[recording]', line); + consoleLine(line, level); }, saved: (recording, options) => host.recordingSaved(recording, options), }); diff --git a/src/player/Player.ts b/src/player/Player.ts index 2463ac55..5ba659f8 100644 --- a/src/player/Player.ts +++ b/src/player/Player.ts @@ -8,6 +8,7 @@ import { behaviorError } from '../runtime/systems/BehaviorSystem'; import { Input } from '../runtime/systems/Input'; import { downloadBlob, requestRender } from '../ui'; import { GameRecorder } from '../viewport/GameRecorder'; +import { consoleLine } from '../viewport/RecordingTake'; import { soundLibrary } from '../viewport/SoundLibrary'; import { videoLibrary } from '../viewport/VideoLibrary'; import type { GameScreen } from './GameScreen'; @@ -33,9 +34,9 @@ export class Player { screen.onStart = () => this.start(); this.recorder = new GameRecorder({ view: () => screen, - log: (line) => { + log: (line, level) => { this.run?.world.log.push(line); - console.warn('[recording]', line); + consoleLine(line, level); }, saved: (recording) => downloadBlob(recording.blob, `${recording.name}.mkv`), }); diff --git a/src/viewport/GameRecorder.ts b/src/viewport/GameRecorder.ts index fefcefe9..b7ef4ba2 100644 --- a/src/viewport/GameRecorder.ts +++ b/src/viewport/GameRecorder.ts @@ -23,7 +23,7 @@ export interface RecordingView { /** Where the recorder looks, and what it tells; `saved` gets what the node asked to become of it. */ export interface RecordingHost { view(): RecordingView | null; - log(line: string): void; + log(line: string, level?: 'info' | 'warn'): void; saved(recording: MadeRecording, options: RecordingUploadOptions): void; } @@ -64,7 +64,7 @@ export class GameRecorder implements RecordingSink { const source = new ViewSource(name, settings, this.host); const upload = { convert: settings.convert, adopt: settings.convert && settings.adopt }; const host: TakeHost = { - log: (line) => this.host.log(line), + log: (line, level) => this.host.log(line, level), saved: (recording) => this.host.saved(recording, upload), }; const take = new Take( diff --git a/src/viewport/RecordingTake.ts b/src/viewport/RecordingTake.ts index 25269f74..df3cc95b 100644 --- a/src/viewport/RecordingTake.ts +++ b/src/viewport/RecordingTake.ts @@ -11,6 +11,7 @@ import { import { avcCodec, FrameGate, + FramePace, isKeyFrame, RECORDING_MOST_BYTES, RecordingClock, @@ -42,11 +43,22 @@ export interface MadeRecording { /** What a take tells. */ export interface TakeHost { - /** A line for whoever started it: the log of the run, or the editor's notice. */ - log(line: string): void; + /** + * A line for whoever started it: the log of the run, or the editor's notice. An `info` line is + * no warning; the editor keeps it to its console, its notice would be in the recording. + */ + log(line: string, level?: 'info' | 'warn'): void; saved(recording: MadeRecording): void; } +/** A line of a recording in the browser's console, and so in the editor's console panel. */ +export function consoleLine(line: string, level: 'info' | 'warn' = 'warn'): void { + // An info line is no warning: the console panel shows it plain. + // eslint-disable-next-line no-console + if (level === 'info') console.info('[recording]', line); + else console.warn('[recording]', line); +} + /** * Where a take gets its pictures: the game view (`GameRecorder`) or the whole editor * (`EditorRecorder`). @@ -86,7 +98,10 @@ export interface TakeInfo { codec: string; sound: boolean; frames: number; + /** Frames taken that had nowhere to go: the encoder or the read back was still busy. */ dropped: number; + /** Frames no drawn frame came for, see `FrameGate.skipped`. */ + skipped: number; soundFrames: number; /** From the first frame to the end of the last, in ms. */ durationMs: number; @@ -104,6 +119,7 @@ export class Take { private size = { w: 0, h: 0 }; private readonly clock = new RecordingClock(); private readonly gate: FrameGate; + private readonly pace: FramePace; private video: VideoEncoder | null = null; private audio: AudioEncoder | null = null; private tap: { node: AudioWorkletNode; rate: number; release(): void } | null = null; @@ -142,6 +158,7 @@ export class Take { private readonly options: { sound?: boolean } = {}, ) { this.gate = new FrameGate(fps); + this.pace = new FramePace(fps); } /** @@ -164,6 +181,13 @@ export class Take { () => { if (this.state !== 'starting') return; this.state = 'recording'; + const { w, h } = this.size; + const codec = this.codec.startsWith('avc1') ? 'H.264' : 'VP9'; + const sound = this.audio ? 'with sound' : 'without sound'; + this.host.log( + `Recording "${this.name}" started: ${w}x${h} at ${this.fps} fps, ${codec}, ${sound}`, + 'info', + ); if (this.stopAsked) this.finish(''); }, (error: unknown) => this.fail(error instanceof Error ? error.message : String(error)), @@ -308,11 +332,33 @@ export class Take { if (!this.clock.started) this.clock.start(now); const ms = this.clock.at(now); if (!this.gate.take(ms)) return; - if (this.source.busy || video.encodeQueueSize >= MOST_QUEUED || !this.source.take(ms)) { - this.dropped++; - return; - } - this.lastFrameAt = now; + if (this.source.busy || video.encodeQueueSize >= MOST_QUEUED || !this.source.take(ms)) this.dropped++; + else this.lastFrameAt = now; + const got = this.pace.behind(ms, this.missed); + if (got !== null) + this.host.log( + `Recording "${this.name}" can't keep up: about ${got} of ${this.fps} fps, so the video will stutter`, + ); + } + + /** Frames the recording's time has room for that are not in it. */ + private get missed(): number { + return this.gate.skipped + this.dropped; + } + + /** + * Says at the end how many frames a recording missed, when it missed so many it stutters; the + * count is the whole file's, its first moments too. + */ + private tellMissed(): void { + if (!this.pace.stutters) return; + const slots = this.gate.slots; + const missed = Math.min(this.missed, slots); + const helps = this.fps > 30 ? '30 fps or a smaller resolution' : 'a smaller resolution'; + this.host.log( + `Recording "${this.name}" has ${slots - missed} of ${slots} frames: ${missed} missed ` + + `(${Math.round((missed / slots) * 100)} %), so it stutters – ${helps} helps`, + ); } private get taking(): boolean { @@ -433,6 +479,8 @@ export class Take { width: this.size.w, height: this.size.h, }); + // After the upload's notice, or the editor's would cover this one at once. + this.tellMissed(); } /** @@ -517,6 +565,7 @@ export class Take { sound: this.audio !== null, frames: this.frames, dropped: this.dropped, + skipped: this.gate.skipped, soundFrames: this.soundFrames, durationMs: this.frames > 0 ? Math.round(this.lastMs + 1000 / this.fps) : 0, lastFrameAt: this.lastFrameAt, diff --git a/tests/core/recording.test.ts b/tests/core/recording.test.ts index 3b90b705..6a637459 100644 --- a/tests/core/recording.test.ts +++ b/tests/core/recording.test.ts @@ -16,6 +16,7 @@ import { elapsedText, fitPicture, FrameGate, + FramePace, i420Layout, isKeyFrame, pictureTransform, @@ -165,6 +166,84 @@ describe('FrameGate', () => { it('takes about 60 a second from a 144 Hz screen', () => { expect(Math.abs(taken(60, 1000 / 144, 10) - 600)).toBeLessThanOrEqual(6); }); + + const gateAfter = (fps: number, gaps: number[], seconds: number) => { + const gate = new FrameGate(fps); + for (let i = 0, ms = 0; ms < seconds * 1000; ms += gaps[i++ % gaps.length]!) gate.take(ms); + return gate; + }; + + it('counts no frame skipped while the screen keeps up', () => { + expect(gateAfter(60, [1000 / 60], 10).skipped).toBe(0); + expect(gateAfter(30, [1000 / 60], 10).skipped).toBe(0); + expect(gateAfter(60, [1000 / 144], 10).skipped).toBeLessThanOrEqual(1); + }); + + it('counts the frames a slow screen skips, as many as the recording misses', () => { + // As in a 4K recording on the user's machine: 18 and 35 ms in turn, about 38 a second. + const slow = gateAfter(60, [18, 35], 10); + expect(slow.slots).toBeGreaterThanOrEqual(599); + expect(slow.slots).toBeLessThanOrEqual(601); + expect(slow.skipped).toBe(slow.slots - 378); + // A 50 Hz screen leaves out one in six of 60, however evenly the frames come. + const fifty = gateAfter(60, [20], 10); + expect(Math.abs(fifty.skipped - 100)).toBeLessThanOrEqual(2); + }); +}); + +describe('FramePace', () => { + /** What `behind` said, frame by frame, of a recording that misses `missedPerSecond`. */ + const said = (fps: number, missedPerSecond: (s: number) => number, seconds: number) => { + const pace = new FramePace(fps); + const told: { at: number; got: number }[] = []; + let missed = 0; + for (let ms = 0; ms <= seconds * 1000; ms += 1000 / fps) { + missed += missedPerSecond(ms / 1000) / fps; + const got = pace.behind(ms, Math.round(missed)); + if (got !== null) told.push({ at: Math.round(ms), got }); + } + return told; + }; + + it('says once that a recording falls behind, with the frames a second it gets', () => { + const told = said(60, () => 22, 20); + expect(told).toHaveLength(1); + expect(told[0]!.got).toBe(38); + // It has settled for a second and then judged two. + expect(told[0]!.at).toBeGreaterThanOrEqual(3000); + expect(told[0]!.at).toBeLessThan(3100); + }); + + it('lets a stall while it starts and a few frames missed pass', () => { + // Half a second lost at the start, then 5 % missed: never more than a tenth over a span. + expect(said(60, (s) => (s < 0.5 ? 60 : 3), 20)).toEqual([]); + }); + + it('says at the end that a recording stutters only when it missed frames after it settled', () => { + const after = (missedPerSecond: (s: number) => number, seconds: number) => { + const pace = new FramePace(60); + let missed = 0; + for (let ms = 0; ms <= seconds * 1000; ms += 1000 / 60) { + missed += missedPerSecond(ms / 1000) / 60; + pace.behind(ms, Math.round(missed)); + } + return pace.stutters; + }; + // A stall while it starts, in a short recording too: e2e 67 missed 3 of 37 frames so. + expect(after((s) => (s < 0.3 ? 60 : 0), 1.2)).toBe(false); + expect(after((s) => (s < 0.5 ? 60 : 1), 20)).toBe(false); + expect(after(() => 22, 13.8)).toBe(true); + expect(after(() => 6, 20)).toBe(true); + // Shorter than its first second: nothing to judge. + expect(after(() => 30, 0.9)).toBe(false); + }); + + it('says it when a recording falls behind only later', () => { + const told = said(30, (s) => (s < 7 ? 0 : 12), 20); + expect(told).toHaveLength(1); + expect(told[0]!.got).toBe(18); + expect(told[0]!.at).toBeGreaterThan(7000); + }); }); describe('pictureTransform', () => { diff --git a/tools/e2e/67-recording.mjs b/tools/e2e/67-recording.mjs index a9bc449f..49ce1e3c 100644 --- a/tools/e2e/67-recording.mjs +++ b/tools/e2e/67-recording.mjs @@ -120,7 +120,60 @@ export async function recording(t) { log.some((line) => line.includes('Start recording is ignored') && line.includes(during.takes[1].name)), JSON.stringify({ log, takes: during.takes.map((take) => take.name) }), ); + check( + 'a recording says in the log when it starts: its size, fps and sound', + log.some((line) => line === `Recording "${NAME}" started: 1920x1080 at 30 fps, H.264, with sound`) && + log.some( + (line) => + line.startsWith(`Recording "${during.takes[1].name}" started: `) && line.includes(' at 60 fps'), + ), + JSON.stringify(log), + ); + + // 67b-ii. Frames 45 ms apart, about 22 a second: the second take, at 60 fps, skips most of its + // frames. It says so once while it records, and again when it is saved, with the count. + await evaluate(`(() => { + window.__rc67slow = true; + const slow = () => { + if (!window.__rc67slow) return; + const until = performance.now() + 45; + while (performance.now() < until); + requestAnimationFrame(slow); + }; + requestAnimationFrame(slow); + })()`); + const behind = `(__gm.world()?.log ?? []).find((line) => line.includes("can't keep up"))`; + await waitUntil(`${behind} !== undefined`, { + timeout: 15_000, + label: 'the slow take says it falls behind', + }); + await evaluate('window.__rc67slow = false; 0'); + const behindLine = await json(behind); + const slowTake = (await recordings()).takes[1]; + const got = Number(/about (\d+) of 60 fps/.exec(behindLine ?? '')?.[1]); + check( + 'a recording that falls behind says so while it records, with the frames a second it gets', + behindLine?.startsWith(`Recording "${slowTake.name}" can't keep up`) && + got > 5 && + got < 40 && + slowTake.skipped > 0 && + slowTake.dropped + slowTake.skipped > slowTake.frames / 2, + JSON.stringify({ behindLine, slowTake }), + ); await stop(); + await waitUntil(`__gm.recording().takes[1]?.state === 'done'`, { label: 'the slow take is saved' }); + const consoleLines = (await json('__gm.console.lines()')).filter((line) => + line.text.startsWith('[recording]'), + ); + const summary = consoleLines.find((line) => line.text.includes(`"${slowTake.name}" has `)); + check( + 'and says when it is saved how many frames it missed; the start is an info line, the rest warns', + summary?.level === 'warn' && + /has \d+ of \d+ frames: \d+ missed \(\d+ %\), so it stutters/.test(summary.text) && + consoleLines.some((line) => line.level === 'info' && line.text.includes(`"${NAME}" started`)) && + consoleLines.some((line) => line.level === 'warn' && line.text.includes("can't keep up")), + JSON.stringify(consoleLines.slice(-8)), + ); // 67c. Ending the run saved the second take; both became video assets once the server had them. await waitUntil(