Say when a recording starts and when it cannot keep up

A 4K60 game view recording on the user's machine had 517 of 827
frames. The rest were skipped without a word: when the editor's tick
came late, FrameGate let the due slots pass, and only frames lost to a
busy encoder or read back counted as dropped. The file kept its time
but stuttered, and nothing said so.

- FrameGate counts the frames it took and the slots the recording's
  time has room for. The difference is skipped, next to dropped in
  __gm.recording().
- FramePace judges the missed frames over spans of 2 s. The first
  time more than 10 % are missed, the log warns once with the frames
  a second the recording really got.
- At the end, when more than 5 % are missed, a warning gives the
  frames of the whole file and what helps (30 fps or a smaller
  resolution). It comes after the upload's notice, which would cover
  it at once in the editor.
- The first second counts for neither warning. Without that, a short
  e2e recording warned about 3 frames lost while starting.
- A recording that starts logs an info line with its size, fps, codec
  and sound. TakeHost.log takes a level for it. The editor recording
  keeps the line to the console, its notice would be in the video.
- consoleLine is the one place with an eslint exception for
  console.info, so the console panel shows the line plain.

Found along the way: headless Chrome in WSL records the editor with
real stutter in e2e 67 (1280x800@60 27 %, 2304x1440@30 12-14 %). That
is the software encoder there, and only now shown.

Tests:
- Gate on melektaus-atx: green, 309 files, 4810 tests.
- Unit recording.test.ts: 36 green, 6 new for FrameGate.skipped and
  FramePace. With skipped stuck at 0 the test turns red.
- e2e 67 on melektaus-atx: ALL PASSED, 15 checks, run twice. The new
  67b-ii slows the editor to about 20 fps: a 640x360@60 recording
  says "about 19 of 60 fps" and saves with 95 of 192 frames.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

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

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;
+  }
 }
 
 /**

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());

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),
     });

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`),
     });

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(

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,

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', () => {

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(