fix(rec): recordings played ~1.4x fast — CFR emission, drop -re

Root cause (measured, not guessed): the take-3 'rebase on overrun' reset
nextTick to wall-now, erasing every missed slot. Pump delivered 215-219/300
per 5s (~43fps) but rawvideo carries no timestamps — ffmpeg muxes by frame
count at -framerate 60, so every recording played fast with honest-looking
stats. A second pacer, ffmpeg -re, throttled the demux separately
('Resumed reading ... after a lag' 0.79s->4.82s).

Fix follows libobs video-io.c (https://github.com/obsproject/obs-studio)
- the video thread never resets its deadline; one frame per interval slot,
a late render repeats content (judder), never skips time:
1. FramePump: count-based emission, while(now>=nextTick){Submit; nextTick+=I}
2. FfmpegArgs: -re removed - the pump is the pacer

Muxed duration is now frame-count/fps == wall time by construction. Covers
game background + webcam (one shared pump). 0 warnings; suite 288/289 -
the one failure (Composite_FullScene_MasterPixels 1380,700) also fails with
this change stashed: pre-existing, untouched, recorded as follow-up.
This commit is contained in:
2026-09-10 08:35:30 -07:00
parent d212d5ae2c
commit bd396e488c
5 changed files with 117 additions and 62 deletions
+41 -29
View File
@@ -1,46 +1,58 @@
# HANDOFF — 2026-09-08 # HANDOFF — 2026-09-10
## Branch / Commit State ## Branch / Commit State
**`main` HEAD = `081e4c1`** — take-24 (PasteKey CropBounds). Working tree carries the `main` HEAD = `1a39b09`, ahead of origin by 12, working tree carries THE recording-timing
real fix (uncommitted): pre-parse transparency injection + diagnostics. 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).
## Web Overlay — the ROOT CAUSE (finally named, not guessed) ## Recording TIMING — the fix (the "plays too fast" saga)
WebView2's `CapturePreviewAsync` **always honors the page's own background** — the widget **Root cause, proven by measurement (not guessed):** the pump's take-3 "rebase on overrun"
page paints html/body opaque, so the captured PNG has **no alpha-0 margins, ever**. reset `nextTick` to wall-now every time it fell behind, silently erasing missed slots. The
`DefaultBackgroundColor=Transparent` only shows through pages without a background style. pump delivered `215-219/300 per 5s` (~43fps) but ffmpeg muxes rawvideo by frame count at
All prior takes (19-24) assumed the capture had transparent margins — it never did. `-framerate 60` — no per-frame timestamps — so every recording played ~1.4x fast with
`FindContentBounds` therefore had nothing to crop to, and every blend saw alpha=255 = stats that looked honest (a rebased frame is never "late"). `-re` on the demux was a second
black box + "transparency broken" + lost resizing. One bug, three symptoms. fighting pacer ("Resumed reading … after a lag" grew 0.79s→4.82s).
**Fix applied (verify by running):** **Fix (the OBS `video-io.c` shape — one frame per interval slot, deadline never reset):**
1. `WebView2Manager.InitializeAsync`: `AddScriptToExecuteOnDocumentCreatedAsync(TransparentBackgroundScript)` 1. `FramePump.PumpAsync`: `while (now >= nextTick) { SubmitFrame(frame); nextTick += intervalTicks; }`
— injects html/body `background:transparent` BEFORE the page parses/scripts run (the — one submit per crossed slot; a slow render re-writes the current composite (judder,
OBS user.css equivalent). NavStarting/NavCompleted keep the script as post-load re-assert. never a skip). `nextTick` NEVER rebases to wall-now.
2. Restored the take-23/24 compositor crop path (stride-correct `BlitContentRaw` + 2. `FfmpegArgs`: `-re` deleted from the rawvideo input; the pump is the pacer.
`CropBounds` in PasteKey) — my previous take-25 gutting was wrong.
3. Diagnostics: first capture per source dumps the RAW WebView2 PNG to
`%TEMP%\ytLive-web-<id>.png` and logs alpha stats + FindContentBounds result to
startup.log.
## NEXT STEP (user run required once) **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.
Run the app with the web overlay, then: ## NEXT STEP (ONE user run required)
- Read `%APPDATA%\ytLlive\startup.log` — the `alpha[min=..,max=..,mean=..,zero=..%]`
line PROVES whether the capture is transparent now (mean near 0 + high zero% + a tight Record ~30s with the WSL ticker visible in the preview (`cd tools && ./ticker` in a terminal,
contentBounds = fixed) or still opaque (mean ~255 → injection didn't beat the page). Ctrl-C to stop), then check:
- Agent can PIL-analyze `%TEMP%\ytLive-web-<id>.png` for the true alpha bbox. - 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
## Still Open ## Still Open
- Chat overlay missing from recording (separate issue — not yet touched this session) - Web overlay: the pre-parse transparency injection (committed `1a39b09`) is NOT yet proven
- Audio/sync: non-event (headset volume), closed — 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).
## Landmines ## Landmines
- testhost shares startup.log with app — filter by time when triaging - 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 - testhost/exe lock DLLs: `taskkill /F /IM testhost.exe /IM ytLive.exe` before rebuild
- Do NOT run full-suite vstest (WASAPI hang); flow = clean build + per-class + scope-check - 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` - Kill app before build: `/mnt/c/Windows/System32/taskkill.exe /F /IM ytLive.exe`
- The PNG dump is written ONCE per session per source (DebugPngWritten flag) - 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)
+13 -3
View File
@@ -105,9 +105,19 @@ Both halves were solved by OBS/libyuv long ago; do not re-derive:
frame makes the period `render + submit + interval` — the producer can hit ≤ half frame makes the period `render + submit + interval` — the producer can hit ≤ half
the declared rate even with a free render. OBS's `video_thread` the declared rate even with a free render. OBS's `video_thread`
(`libobs/media-io/video-io.c`) advances an absolute `nextTick += intervalTicks` and (`libobs/media-io/video-io.c`) advances an absolute `nextTick += intervalTicks` and
sleeps only the remainder; if the deadline blew, skip the wait AND the missed ticks sleeps only the remainder. **NEVER "rebase" the deadline to wall-now when it blows** —
(rebase, no catch-up burst — a burst queues stale frames). Critical with rawvideo: the take-3 note I originally wrote here ("skip … the missed ticks (rebase)") was the
pts is stamped by ARRIVAL, so a starved producer silently time-lapses the file. PROVEN-wrong advice: resetting `nextTick` erases the missed slots, so a 43fps reality
was authored into a 60fps container and every recording played ~1.4x fast (take 12/13,
2026-09-10). The rebase even kept the stats looking honest (render+wait == period, no
loss) because a rebased frame is never "late". OBS keeps the counter MOVING and outputs
ONE frame per interval tick — a late render shows as REPEATED footage (judder; duration
stays correct), never a skip and never a wall-now reset. Critical with rawvideo:
pts is stamped by ARRIVAL, so the muxed duration is pure frame count ÷ fps — the only
way to make duration == wall time under ANY load is exactly one frame per interval slot.
Corollary: **never add a second pacer.** `ffmpeg -re` on the rawvideo input throttles
the pipe independently and fights the pump (its "Resumed reading … after a lag" grew
0.79s→4.82s in the same take). Removed; the pump IS the pacer.
2. **A 1080p frame is ~2.07M pixels — the hot path must be row-simple.** Per-pixel 2. **A 1080p frame is ~2.07M pixels — the hot path must be row-simple.** Per-pixel
`Math.Round` + float source-over in managed code costs ~100ns/px = the whole 258ms. `Math.Round` + float source-over in managed code costs ~100ns/px = the whole 258ms.
libyuv's pattern (https://chromium.googlesource.com/libyuv/libyuv/): branch per libyuv's pattern (https://chromium.googlesource.com/libyuv/libyuv/): branch per
+3 -2
View File
@@ -2,7 +2,9 @@ namespace ytLive.Services.Encoder;
/// <summary> /// <summary>
/// Builds the FFmpeg command line for a live RTMP push (TASK 4 ship step 3): /// Builds the FFmpeg command line for a live RTMP push (TASK 4 ship step 3):
/// raw BGRA frames via stdin (paced <c>-re</c>), real audio via the named pipe /// raw BGRA frames via stdin (paced by the frame pump — the pump holds a strict
/// CFR cadence, so <c>-re</c> would only add a second, fighting pacer), real
/// audio via the named pipe
/// (TASK 9 — the mixer streams f32le at 48 kHz stereo into <c>\\.\pipe\&lt;name&gt;</c>; /// (TASK 9 — the mixer streams f32le at 48 kHz stereo into <c>\\.\pipe\&lt;name&gt;</c>;
/// WASAPI loopback + the mic ride the pipe instead of the old anullsrc silence), /// WASAPI loopback + the mic ride the pipe instead of the old anullsrc silence),
/// H.264 + AAC encoding, FLV muxing to the ingestion URL. Pure — the encoder /// H.264 + AAC encoding, FLV muxing to the ingestion URL. Pure — the encoder
@@ -16,7 +18,6 @@ public static class FfmpegArgs
{ {
"-hide_banner", "-loglevel", "info", "-hide_banner", "-loglevel", "info",
"-stats", "-stats_period", "0.5", "-stats", "-stats_period", "0.5",
"-re",
"-f", "rawvideo", "-pix_fmt", "bgra", "-f", "rawvideo", "-pix_fmt", "bgra",
"-video_size", $"{options.Width}x{options.Height}", "-video_size", $"{options.Width}x{options.Height}",
"-framerate", options.Fps.ToString(), "-framerate", options.Fps.ToString(),
+34 -26
View File
@@ -376,42 +376,50 @@ public sealed class FramePump : IDisposable
IFfmpegEncoder? encoder; IFfmpegEncoder? encoder;
lock (_gate) encoder = _encoder; lock (_gate) encoder = _encoder;
if (encoder == null) break; if (encoder == null) break;
// Count-based CFR emission (libobs video-io.c — the frame interval
// is a DEADLINE and the output stream holds its declared rate):
// one frame per interval slot, whatever the render cost. When the
// renderer falls behind, the SAME fresh composite is written again
// for every slot that ticked past, so a slow render expresses as
// duplicated footage (judder) — never as a skipped timestamp. The
// deadline counter is NEVER reset to wall-now: the old rebase
// erased every missed slot, so a 43fps reality was authored into a
// 60fps container and every recording played ~1.4x fast (rawvideo
// carries no timestamps — muxed duration is pure frame count).
submitSw.Restart(); submitSw.Restart();
await encoder.SubmitFrameAsync(frame, ct); while (!ct.IsCancellationRequested
&& System.Diagnostics.Stopwatch.GetTimestamp() >= nextTick)
{
await encoder.SubmitFrameAsync(frame, ct);
statFrames++;
nextTick += intervalTicks;
}
submitSw.Stop(); submitSw.Stop();
submitTicks += submitSw.ElapsedTicks; submitTicks += submitSw.ElapsedTicks;
// Submit copied the bytes — everything from this tick is recyclable.
// Release AFTER submit, and the free-list Contains guard makes the // SubmitFrameAsync copied the bytes on every write above — the
// Cut path (BlendFrame returns toFrame itself, aliasing scratch) safe. // tick's buffers are recyclable once each due slot consumed them.
// The free-list Contains guard keeps the Cut path (BlendFrame
// returns toFrame itself, aliasing scratch) safe.
ReleaseScratch(frame.BgraPixels); ReleaseScratch(frame.BgraPixels);
ReleaseScratch(scratch); ReleaseScratch(scratch);
statFrames++;
ReportStats();
// Advance the deadline; cost already spent is not slept again. // Sleep the BULK of the remainder, SPIN the 2ms tail — never hand
// Blew the frame budget: skip the wait AND the missed ticks — // a sub-tick remainder to the sleep quantum (the timeBeginPeriod
// rebase rather than bursting a catch-up pile (OBS rewinds its // note). If the renderer already ate the budget there is nothing
// tick; a burst only queues stale frames). Otherwise sleep the // left to sleep and the loop renders the next frame straight away.
// BULK and SPIN the 2ms tail — never hand a sub-tick remainder
// to the sleep quantum (see the timeBeginPeriod note).
nextTick += intervalTicks;
waitSw.Restart(); waitSw.Restart();
var ahead = nextTick - System.Diagnostics.Stopwatch.GetTimestamp(); var ahead = nextTick - System.Diagnostics.Stopwatch.GetTimestamp();
if (ahead <= 0) if (ahead > SpinTailTicks)
{ await _pacingDelay(TimeSpan.FromSeconds(
nextTick = System.Diagnostics.Stopwatch.GetTimestamp() + intervalTicks; (ahead - SpinTailTicks) / (double)System.Diagnostics.Stopwatch.Frequency), ct);
} while (!ct.IsCancellationRequested
else && System.Diagnostics.Stopwatch.GetTimestamp() < nextTick)
{ Thread.SpinWait(400);
if (ahead > SpinTailTicks)
await _pacingDelay(TimeSpan.FromSeconds(
(ahead - SpinTailTicks) / (double)System.Diagnostics.Stopwatch.Frequency), ct);
while (!ct.IsCancellationRequested
&& System.Diagnostics.Stopwatch.GetTimestamp() < nextTick)
Thread.SpinWait(400);
}
waitSw.Stop(); waitSw.Stop();
waitTicks += waitSw.ElapsedTicks; waitTicks += waitSw.ElapsedTicks;
ReportStats();
} }
} }
} }
+26 -2
View File
@@ -515,7 +515,9 @@ integration test fakes the whole subprocess (probe + encoder) with a Channel-bac
`Complete()` is EOF (`null`), never a `ChannelClosedException`. `Complete()` is EOF (`null`), never a `ChannelClosedException`.
**Decisions (locked):** args are pure (`FfmpegArgs.Build`, no string building in the encoder): **Decisions (locked):** args are pure (`FfmpegArgs.Build`, no string building in the encoder):
`-re -f rawvideo -pix_fmt bgra -video_size WxH -framerate FPS -i pipe:0` + a **real audio input — the `-f rawvideo -pix_fmt bgra -video_size WxH -framerate FPS -i pipe:0` (**NO `-re`** — the FramePump
is the pacer since slice 9, 2026-09-10; `-re` added a second, fighting clock on the rawvideo demux)
+ a **real audio input — the
mixer writes IEEE-float stereo to a Windows named pipe** (`-f f32le -ar 48000 -ac 2 mixer writes IEEE-float stereo to a Windows named pipe** (`-f f32le -ar 48000 -ac 2
-i \\.\pipe\ytllive_audio`, name via `EncoderOptions.AudioPipeName`; replaced the old `-f lavfi -i -i \\.\pipe\ytllive_audio`, name via `EncoderOptions.AudioPipeName`; replaced the old `-f lavfi -i
anullsrc` silence in the TASK 8 audio milestone) + explicit `-map 0:v -map 1:a` + `-c:v <enc> -b:v K anullsrc` silence in the TASK 8 audio milestone) + explicit `-map 0:v -map 1:a` + `-c:v <enc> -b:v K
@@ -700,7 +702,8 @@ seam:** `Func<Scene?>`, `Func<SceneElement, VideoFrame?>` resolver, `Func<Compos
258.1ms, avg submit 1.5ms`. Two defects, both fixed: (1) the pump slept the FULL interval after each 258.1ms, avg submit 1.5ms`. Two defects, both fixed: (1) the pump slept the FULL interval after each
render, so period = render + interval — OBS's `video_thread` (libobs/media-io/video-io.c) pattern render, so period = render + interval — OBS's `video_thread` (libobs/media-io/video-io.c) pattern
replaces it: absolute `nextTick += intervalTicks` deadline, sleep only the remainder, and on overrun replaces it: absolute `nextTick += intervalTicks` deadline, sleep only the remainder, and on overrun
skip the wait AND the missed ticks (rebase, never burst stale frames). (2) the compositor did skip the wait. (NOTE, slice 9: the original "skip the missed ticks (rebase)" half of this fix was
wrong — see the slice 9 correction below.) (2) the compositor did
per-pixel float sampling + `Math.Round` blending over all 2.07M master pixels (backdrop) and scanned per-pixel float sampling + `Math.Round` blending over all 2.07M master pixels (backdrop) and scanned
the whole destination per overlay (a 64px social-bar strip cost 2M iterations). `SceneCompositor` now the whole destination per overlay (a 64px social-bar strip cost 2M iterations). `SceneCompositor` now
follows the libyuv pattern (BSD-3, chromium.googlesource.com/libyuv/libyuv — cited per the follows the libyuv pattern (BSD-3, chromium.googlesource.com/libyuv/libyuv — cited per the
@@ -810,6 +813,27 @@ seam:** `Func<Scene?>`, `Func<SceneElement, VideoFrame?>` resolver, `Func<Compos
reuses a canvas scratch + 8-deep output ring + a reused WriteableBitmap instead of minting two reuses a canvas scratch + 8-deep output ring + a reused WriteableBitmap instead of minting two
fresh arrays + a new bitmap per 10Hz tick. Next suspect if gen2 stays hot: the WPF preview load fresh arrays + a new bitmap per 10Hz tick. Next suspect if gen2 stays hot: the WPF preview load
itself driving gen2 — recorded as follow-up, untouched this slice. itself driving gen2 — recorded as follow-up, untouched this slice.
- **Slice 9 — the "rebase" WAS the recording time-lapse (2026-09-10, the recording playback-timing
take):** slice 6's "blown deadlines still rebase" was the recording-timing bug all along. In a real
take the pump emitted `215-219/300 per 5s` (~43fps) while `render+wait == period` still looked closed —
the rebase ERASED every missed slot (deadline = wall-now again), so the missed ticks never showed in
the stats. rawvideo has no per-frame timestamps: ffmpeg muxes by frame count at `-framerate 60`, so a
43fps reality was authored into a 60fps container and **every recording played ~1.4x fast** (takes
confirmed with a WSL ticker visible in the recording: file duration 11.44s vs ~15.5s wall). Two
defects, both fixed the OBS way (`libobs/media-io/video-io.c` — the video thread NEVER resets its
deadline; every interval tick outputs ONE frame, and a late render means repeated content — judder —
never a skipped timestamp):
(1) **count-based CFR emission:** `while (GetTimestamp() >= nextTick) { SubmitFrame(frame); nextTick += intervalTicks; statFrames++; }`
submits exactly one frame per crossed slot, re-writing the current composite when the render overruns
(duplicated footage = correct duration, not a time-lapse), and `nextTick` is NEVER reset to wall-now;
(2) **`-re` removed from `FfmpegArgs`** — it was a second, fighting pacer on the rawvideo demux
(its "Resumed reading … after a lag" grew 0.79s→4.82s across the take, leaving the pump behind its own
honest-stats count). One fix covers the game background AND the webcam — both flow through this one
pump. Muxed duration is now frame-count ÷ fps == wall time by construction. Test: the pump suite stays
green unchanged — the pacing test's `<interval` wait assertion still holds because the frame emits at
the next slot boundary, not immediately. (Unrelated pre-existing failure found the same day:
`Composite_FullScene_MasterPixels` pixel (1380,700) cyan-vs-magenta — reproduces with this fix stashed,
untouched by it, recorded as a follow-up.)
- **Stop ordering matters:** `StopAsync` stops the encoder (closes stdin → EOF → ffmpeg finalizes+exits) - **Stop ordering matters:** `StopAsync` stops the encoder (closes stdin → EOF → ffmpeg finalizes+exits)
**before** awaiting the loop, because closing stdin unblocks a write stuck on pipe backpressure — the **before** awaiting the loop, because closing stdin unblocks a write stuck on pipe backpressure — the
reverse order would deadlock. `ProcessFailed` self-stops the pump. `Failed` while live flips reverse order would deadlock. `ProcessFailed` self-stops the pump. `Failed` while live flips