fix(rec): bounded encoder queue + drop policy + burned frame counter — the "1...23...4...56..." smeared-ticker take

slice 9 made the DURATION right but content still hiccuped; aggregates (301/300, uniform
file PTS) could not see it. Measured root cause: FfmpegEncoder.SubmitFrameAsync BLOCKED
on WriteAsync(8.3MB)+FlushAsync when ffmpeg lagged the pipe, and the burst while-loop
re-wrote that same stale composite per crossed slot — frozen runs.

OBS shape (derivative, wrapped pre-1.0): the encoder queue in libobs/obs-encoder.c —
encoder thread never couples back into the video thread; overflow = dropped data, never
a frozen producer. https://github.com/obsproject/obs-studio/blob/master/libobs/obs-encoder.c

- FfmpegEncoder: SubmitFrameAsync is now an enqueue (ArrayPool copy) into a bounded
  Channel (cap 120) drained by its own task; drop-newest + count when full;
  StopAsync flushes the queue then EOF (TryComplete). IFfmpegEncoder.DroppedFrames.
- FramePump: ONE fresh composite per iteration (burst loop deleted); worst-submit stat,
  stall logger (>2x interval names the stage), dropped/stalls in stats.
- Burned-in 6-digit dot-matrix frame counter (white box, bottom-right) on every composite
  — the clock-independent judge replacing the WSL ticker: +1/frame, jumps = counted drops.
- ONE new test Backpressure_QueueOverflow_DropsFrames_AndNeverBlocks (slow-sink fake:
  submit never blocks, drops counted, stop flushes exactly submitted-minus-dropped).
- Full suite 290 tests, 289 pass — sole failure the pre-existing compositor pixel test.
- Docs same-commit: ai.md slice 10 (+ encoder/stop-note corrections), MyMistakes point 8,
  HANDOFF.

Audio untouched (queued follow-up); web overlay still frozen pending timing closure.
This commit is contained in:
2026-09-10 09:32:55 -07:00
parent bd396e488c
commit c45cbc93b7
8 changed files with 414 additions and 79 deletions
+50 -39
View File
@@ -2,57 +2,68 @@
## Branch / Commit State
`main` HEAD = `1a39b09`, ahead of origin by 12, working tree carries THE recording-timing
fix (uncommitted): count-based CFR emission in `FramePump.cs` + `-re` removal in
`FfmpegArgs.cs`, plus this handoff / `ai.md` slice 9 / `MyMistakes.md` recipe correction.
`tools/` holds `ticker.c` + the built `ticker` (WSL, unused by git yet).
`main` HEAD = `bd396e4` (committed this session: `d212d5a` tools ticker, `bd396e4` the
slice-9 CFR + `-re` removal). Now carries the **slice-10 reshape, UNCOMMITTED**:
bounded encoder queue + drop policy + burned-in frame counter in `FfmpegEncoder.cs` /
`IFfmpegEncoder.cs` / `FramePump.cs`, the one new backpressure test in
`ytLive.Tests/FfmpegEncoderTests.cs`, + `ai.md` slice-10 / `MyMistakes.md` point 8 /
this handoff. Working tree clean vs. the last commit **except** the slice-10 set.
## Recording TIMING — the fix (the "plays too fast" saga)
## The timing saga — where it stands
**Root cause, proven by measurement (not guessed):** the pump's take-3 "rebase on overrun"
reset `nextTick` to wall-now every time it fell behind, silently erasing missed slots. The
pump delivered `215-219/300 per 5s` (~43fps) but ffmpeg muxes rawvideo by frame count at
`-framerate 60` — no per-frame timestamps — so every recording played ~1.4x fast with
stats that looked honest (a rebased frame is never "late"). `-re` on the demux was a second
fighting pacer ("Resumed reading … after a lag" grew 0.79s→4.82s).
- **slice 9 (committed `bd396e4`)** fixed the DURATION (count-based CFR, deadline never
rebased, `-re` removed): file length == wall time by frame-count construction.
- **But the CONTENT still hiccuped** — the creator read "1...23...4...56..." in the
recording, and the aggregates (301/300, uniform PTS, 15.6s wall vs 15.74s file) could
NOT see it. Root cause finally measured in `FfmpegEncoder.SubmitFrameAsync`: it BLOCKED
on `WriteAsync(8.3MB)+FlushAsync` when ffmpeg lagged the pipe, and slice 9's burst
`while` loop then re-wrote that SAME composite for every crossed slot — frozen runs.
- **slice 10 (current, uncommitted)** — the OBS `obs-encoder.c` shape:
1. `FfmpegEncoder.SubmitFrameAsync` is an ENQUEUE into a bounded `Channel<byte[]>`
(cap 120) drained by its own task; the pump NEVER blocks on the pipe.
2. Queue full → drop the NEWEST frame + count (`IFfmpegEncoder.DroppedFrames`).
Stop flushes the whole queue, then EOF.
3. Pump: ONE fresh composite per iteration (burst loop deleted) — no stale re-write.
4. **Burned-in frame counter** (the new judge, replaces the WSL ticker): 6-digit
dot-matrix strip, white box, bottom-right of every composite. Decoding the file
reads +1/frame; jumps = counted drops. Clock-independent.
5. Stats: `worst submit`, `dropped N`, `stalls K`; stall log names iterations > 2× interval.
**Fix (the OBS `video-io.c` shape — one frame per interval slot, deadline never reset):**
1. `FramePump.PumpAsync`: `while (now >= nextTick) { SubmitFrame(frame); nextTick += intervalTicks; }`
— one submit per crossed slot; a slow render re-writes the current composite (judder,
never a skip). `nextTick` NEVER rebases to wall-now.
2. `FfmpegArgs`: `-re` deleted from the rawvideo input; the pump is the pacer.
## NEXT STEP (ONE user run required — the take that closes timing)
**Verified:** build 0 warnings; full suite 288/289 — the sole failure
(`Composite_FullScene_MasterPixels` line 109, pixel (1380,700) cyan vs magenta) ALSO fails
with this fix stashed, i.e. pre-existing and untouched by it. DO NOT fix it here; it is a
separate compositor investigation.
Record ~20s (WSL ticker visible in the preview is optional now — the burned counter is
the judge), then check:
- **decode the recording and read the bottom-right frame counter** (probe a few frames
widely spaced + the same region across a densely-sampled range): the number advances
**exactly +1 per frame**, jumping only where drops are countable
- `%APPDATA%\ytLlive\startup.log`: `FramePump stats:` ≈ n/n per 5s (n=300 @60fps),
`dropped 0`, `stalls 0`, `worst submit ≈ 1-3ms`
- NO "FramePump stall:" lines, NO frozen-content runs in the playback
- Extract a few frames around any suspicious moment and correlation-check the strip.
## NEXT STEP (ONE user run required)
## Committed so far this session (before slice 10)
Record ~30s with the WSL ticker visible in the preview (`cd tools && ./ticker` in a terminal,
Ctrl-C to stop), then check:
- recording duration ≈ wall time (should be, by frame-count construction)
- `%APPDATA%\ytLlive\startup.log` "FramePump stats:" shows ≈ n/n per 5s, n = 300 @60fps
- NO "Resumed reading … after a lag" lines remain
- ticker advances ~1s per second of footage
- `d212d5a` — tools: WSL ticker (`tools/ticker.c` + binary)
- `bd396e4` — fix(rec): CFR emission + `-re` removal + docs (ai.md slice 9, MyMistakes,
HANDOFF). Cites libobs video-io.c.
- Do NOT push until the user says (multi-commit local only).
## Still Open
- Web overlay: the pre-parse transparency injection (committed `1a39b09`) is NOT yet proven
— both recorded diagnostic PNGs (`%TEMP%\ytLive-web-<id>.png`) were 100% alpha=0 AND
RGB=0 (an EMPTY capture, not an opaque one). Diagnosis "capture is empty" needs a fresh
run; the first-capture dump may be the pre-load about:blank frame. Frozen pending the
timing verification.
- Audio silence: `no audio.mp4` measured -91dB (digital silence), 3KiB muxed audio stream —
the named-pipe audio delivered ~nothing. Separate from timing; not yet touched.
- Pre-existing: `Composite_FullScene_MasterPixels` (see above).
- Web overlay: pre-parse transparency injection NOT yet proven — recorded diagnostic PNGs
(`%TEMP%\ytLive-web-<id>.png`) were 100% alpha=0 AND RGB=0 (an EMPTY capture). Frozen
pending the timing verification.
- Audio silence: silent audio (full-length, -91dB) in the take-15 file — the named-pipe
audio delivers ~nothing. Separate from timing; queued follow-up, NOT this change.
- WSL-ticker-under-heavy-load reliability check: informational (burned counter is judge).
- Pre-existing: `Composite_FullScene_MasterPixels` line 109 pixel (1380,700) — verbose
cyan-vs-magenta; fails with slice-9 stashed; untouched by both slices. Separate
compositor investigation. DO NOT fix in the timing work.
## Landmines
- testhost shares startup.log with app — filter by time when triaging
- testhost/exe lock DLLs: `taskkill /F /IM testhost.exe /IM ytLive.exe` before rebuild
- Build via the Windows dotnet host: `/mnt/c/Program Files/dotnet/dotnet.exe build …`
- Kill app before build: `/mnt/c/Windows/System32/taskkill.exe /F /IM ytLive.exe`
- Build via the Windows dotnet host: `/mnt/c/Program Files/dotnet/dotnet.exe build "C:\Users\gramp\Documents\Code\projects\ytLive\ytLive.csproj"`
- No Linux ffmpeg / no sudo on this box — probing uses `/mnt/c/Program Files/Krita (x64)/bin/ffmpeg.exe`
via WSL interop; frames landed in `/mnt/c/Users/gramp/AppData/Local/Temp/ylf/`
- `tools/ticker`: constant ~+982ms offset on the FIRST line is cosmetic (t0 captured a beat late)
- `tools/ticker`: constant ~+982ms offset on the FIRST line is cosmetic (t0 a beat late)