fix: clear pre-live capture ring backlog at StartLive (2.2s A/V sync lag)

AudioMixer.Start() begins mic/loopback capture at app startup to feed the
level meters, so both 2s ring buffers fill with pre-live audio. StartLive()
drained from the oldest tail sample, putting every recorded event ~2.2s late
in the audio track (confirmed by clap analysis + cross-correlation on two
takes: +2.11 to +2.22s).

Fix: AudioMixer.StartLive() now runs _micBuffer.Clear() + _loopbackBuffer.Clear()
immediately after the pipe starts, before the drain task runs. Recording now
begins at go-live; the <=10ms in-flight chunk evicted by Clear() is imperceptible.

Regression test: StartLive_DiscardsPreLiveBacklog_SoFirstAudioIsCurrent
saturates the loopback ring with stale 0.8 pre-live audio, then asserts the
wire carries fresh post-live 0.2 (max < 0.3).

Reference (external, per derivative-work rule): OBS 'Audio mixer' keeps its
buffers fed continuously and syncs the stream start timestamp at record time
rather than replaying pre-live capture; a go-live flush of the capture buffer
is the accepted pattern for live tools restarting a stream.

Docs: HANDOFF.md (fix shipped), MyMistakes.md (A/V sync measurement recipe).
This commit is contained in:
2026-09-14 11:24:12 -07:00
parent 5ba4d709ae
commit 11a7af2dc0
4 changed files with 230 additions and 148 deletions
+111 -129
View File
@@ -1,152 +1,126 @@
# HANDOFF — 2026-09-12 (webcam FIXED; audio-silence FIXED; TRUNCATION ROOT-CAUSED + FIXED for static scenes)
# HANDOFF — 2026-09-14 (AUDIO−VIDEO SYNC FIX SHIPPED: StartLive now clears the pre-live ring backlog)
## Branch / Commit State
`main` HEAD = `a62a283`. Ahead of origin by 25 commits. **NOT pushing** — user
ruling: no push until web-overlay transparency AND audio-silence are addressed.
`main` HEAD = `5ba4d70`. Ahead of origin by **27 commits**. Working tree **dirty**:
the sync fix is implemented + tests green below, HANDOFF/MyMistakes updated — NOT yet
committed. **NOT pushing** — the prior no-push ruling (transparency + audio-silence) is
clear on the first gate; the second was the sync issue, whose fix is now in the tree
but the user has not greenlit a push. On-board next: verify a take, then decide.
Uncommitted (all belong to the current work, none committed yet):
Heads-up for any reader: the previous HANDOFF (a62a283 era) described webcam/audio/
truncation fixes as **uncommitted** — that file was stale on arrival. They were
actually already committed:
```
M .gitignore
M HANDOFF.md (this file)
M MyMistakes.md (webcam collateral recipe added)
M Services/Audio/AudioSyncDelay.cs (audio-silence fix)
M Services/Compositor/SceneCompositor.cs (webcam cbW/cbH fix)
M Services/MediaCaptureFrameSource.cs (diagnostics REMOVED — clean)
M ytLive.Tests/AudioSyncDelayTests.cs (silence regression test, proven both ways)
M ytLive.Tests/SceneCompositorTests.cs (webcam regression test, proven both ways)
M Services/Encoder/FramePump.cs (slow-render probe, see TRUNCATION below)
```
- `724af14` fix: audio silence (idempotent `AudioSyncDelay.Configure`), webcam gray
block (cbW/cbH default), truncated videos (SceneGraph split/static bake docs + FramePump probe)
- `5ba4d70` docs: audio-sync offset measured ~367ms w/ 300 offset → "set SyncOffsetMs=0"
Build is green (0 warnings); 295 tests pass (audio + compositor + pump suites).
Build was green (0 warnings) and 295 tests passing at the prior session end; no code
changed this session (analysis only).
Audio.SyncOffsetMs changed DB-side to 0 (see AUDIO section) — HANDOFF-only change,
nothing new to compile.
## ✅ SHIPPED — pre-live capture ring backlog fix (2026-09-14)
## ✅ TRANSPARENCY — CLOSED (pushed gate #1)
**Root cause:** `AudioMixer.Start()` begins mic and loopback capture at **app startup**
for the level meters. The 2-second ring buffers (`_micBuffer` = 96k floats = 2.0s mono;
`_loopbackBuffer` = 192k floats = 2.0s stereo) fill continuously with pre-live audio.
`StartLive` → `LiveLoopAsync` drained from the ring's tail — the **oldest** sample —
so every recorded event landed ~2.0s late in the audio track (fixed lag, scaled with
time-since-app-launch, capped at ring depth).
User confirmed transparency is fixed (`efe88b8` era). Push gate #1 clears.
**Fix:** `AudioMixer.StartLive()` now runs `_micBuffer.Clear(); _loopbackBuffer.Clear();`
immediately after the pipe starts, before the drain task runs — the in-flight ≤10ms
chunk loss is imperceptible and correct ("recording begins at go-live").
## ✅ WEBCAM GRAY BLOCK — CLOSED
**Regression test (the ONE integration test for this change):**
`StartLive_DiscardsPreLiveBacklog_SoFirstAudioIsCurrent` in
`ytLive.Tests/AudioPipelineTests.cs` — saturates the loopback ring with stale 0.8
(simulated pre-live meters), StartLive, then emits fresh 0.2; asserts the wire carries
~0.2 (max < 0.3), failing loudly if the stale 0.8 backlog survived the clear.
Root cause: `SceneCompositor.BlitContentRaw` defaulted `cbW=cbH=0` when
`src.CropBounds` is null — regression from `ed9d7c1`. Every webcam frame (no crop
bounds) blitted to an empty 0×0 source rect → nothing drawn where the webcam
should be. Fix: default `cbW=src.Width`, `cbH=src.Height`. Regression test
`BlitContentRaw_NoCropBounds_SamplesAcrossFullSource_NotJustOrigin` proven BOTH
ways (fails on old code, passes on new). User confirmed correct webcam render in
the latest recording. All temp diagnostics stripped from
`MediaCaptureFrameSource.cs` and `SceneCompositor.cs`.
**Test collateral:** the 3 existing pipe-emit tests pre-filled the rings BEFORE
StartLive (relying on the bug as a reservoir). Their emits now land right after
StartLive (post-clear, pre-connect — the pipe drops pre-connect writes, so this keeps
the ring primed for the client) with the 2026-09-14 comments updated. All passed.
## 🟡 AUDIO SILENCE — ROOT-CAUSED AND FIXED, pending final user take
Verified: `AudioPipelineTests` 26/26 green. Room-native build 0 warnings. Full gate
pending (verify.sh clean build + full suite + scope check).
**Symptom:** mic/desktop levels showed real values in preview and in the
per-5s `Audio live:` telemetry, but `peakMix` stayed exactly `0.000` and saved
recordings were digital silence (-91 dB, verified with `ffprobe -af
volumedetect`).
### Read/Write semantics confirmed (AudioRingBuffer.cs)
**Root cause:** `AudioMixer.FillAndMix` calls `_syncDelay.Configure(...)` on
EVERY ~10ms tick (it re-reads the live UI setting each mix). The old
`AudioSyncDelay.Configure` unconditionally reallocated and zeroed the delay
buffer AND reset `_writePos=0` on every call — discarding the just-written
audio before the delay offset could ever read it back. With offset 0 the early
passthrough masked it; any non-zero saved offset = total silence. The DB has
`Audio.SyncOffsetMs = 500` (left over from TASK 22 testing) → that's what
triggered it.
Thread-safe via `_sync`: Write evicts oldest when full; Read returns from
`tail = (_head - _count + C) % C` — when full `tail == _head`, so every drained sample
is one lap behind the last write. `Clear()` is locked; it is the right seam.
**Fix:** `Configure` now early-returns when the delay samples haven't actually
changed (still reallocates/flushes on a *change*, so the live slider still
clicks rather than smearing). Regression test
`RepeatedConfigureWithSameDelay_EveryTick_StillDelivers_TheMarker` mirrors the
mixer's exact calling pattern and was proven BOTH ways (marker lost = silence
on old code; marker survives → expected 960-sample shift on new).
**Root cause (confirmed two independent takes):** `AudioMixer.Start()` begins mic and
loopback capture at **app startup** for the level meters. The 2-second ring buffers
(`_micBuffer` = 96k floats = 2.0s mono; `_loopbackBuffer` = 192k floats = 2.0s stereo)
fill continuously with pre-live audio. `StartLive` → `LiveLoopAsync` drains from the
ring's tail — the **oldest** sample, which is the moment-of-go-live sample minus the
full ring depth — so every recorded event appears ~2.0s late in the audio track. The
lag is **fixed** for the entire recording and scales linearly with "how long the app was
open before you hit record", capped at the 2.0s ring depth (plus the configured sync
offset plus ~0.1s encoder pipeline).
**Telemtery proof the fix works:** latest take (ty-20260912-1135-0000-2.mp4,
recorded WITH the fix, sync offset still 500): `peakMix` = 0.434–0.523 across
all five 5s windows (was 0.000 before). **Audio is NOT silence anymore.**
**Read/Write semantics confirmed** in `AudioRingBuffer.cs` (thread-safe via `_sync`):
Write evicts oldest samples when full (`_count == _buffer.Length`); Read returns from
`tail = (_head - _count + C) % C` — when full, `tail == _head`, meaning every drained
sample is exactly one lap behind what was last written. `Clear()` exists and is locked;
it is the right seam.
**Follow-up:** sync offset `Audio.SyncOffsetMs` measured and SET TO **0** (2026-09-12, take ty-...-1358):
**Only one Clear call exists** in the capture path: `RestartMic()` (AudioMixer.cs:132)
clears `_micBuffer` on device swap. **Neither buffer is cleared at `StartLive`** — this
is the bug.
Measurement method tri-wins instead of clap deltas: `silencedetect` on the audio
gave the count-word starts (one≈0, two@4.12, three@6.48 — audio PTS, both streams
start at 0, no mux offset), and per-frame video motion (`tblend=difference` +
`signalstats YAVG`) cross-correlated against the audio envelope peaks at shift
**+22 frames → audio LAGS video by ~367ms with the 300ms offset active** → the
pipeline's own lag is only ~70ms. The saved 300ms (TASK 22 leftover) is what made
it read as "one word late" (370ms ≈ a third of the ~2.3s pause ≈ perceptually a
full beat behind). Fix = offset 0. Expected residual ≤~70ms (imperceptible).
**Taking:** the lag also explains the earlier 13:58 take that measured only ~367ms
with 300ms offset active: the app had just been restarted for that take, so the rings
were only partially pre-filled (lag = min(2.0s, time-since-app-launch)). Two takes
hours later (rings fully saturated) reproduce the full ~2.0s backlog consistently.
## ✅ TRUNCATED VIDEO — ROOT-CAUSED AND FIXED (for baked/static scenes)
---
**Symptom:** recordings ran ~1s short at first, then HALF-length: 22.8s wall →
10.48s file. Not a mux/`-shortest` cut — the pump simply produces frames slower
than the declared 60fps.
**Take 1** (ty-20260912-1923-0000-2.mp4, talking + 3 claps):
- Audio 17.25s, video 17.05s (1023 frames), no frame drops — NOT truncated.
- Per-clap offsets: +2.16 / +2.18 / +2.15s (audio later). Cross-correlation peak:
**+133 frames (+2.217s)**, sharp and unique. Fixed offset, no drift.
- DB: `Audio.SyncOffsetMs = 300` (not 0 as the 5ba4d70 commit message claimed —
the write never actually landed).
**Mechanism (proven):** ffmpeg rawvideo timestamps frames by ARRIVAL at declared
`-r 60`. Pump deadline pacing (OBS libobs pattern) yields each frame when its
~17ms slot lands; if the render stage for that tick takes longer than the slot,
the pump can only do ~1 frame per 35ms → ~27–28fps of *submitted* frames → file
length ≈ submittedFrames/60. So a take that *should* be 22.8s muxes to ~10.5s,
and logs show `avg render 35–38ms` with 136/300 per 5s. FramePump had NO way to
tell which compositor pass ate a slow frame.
**Take 2** (ty-20260914-1104-0000-2.mp4, clean clap test):
- Audio 22.31s, video 22.10s (1326 frames), no frame drops.
- Audio clap peak at **14.04s**; video motion peak at **11.93s** (yavg 2.75 vs
background ~0.1–0.5). Offset: **+2.11s** — confirms the same mechanism.
- Tiny pre-clap blips at 0.2/1.5/4.5/13.5s are faint artifacts (< 100 RMS);
the 11617-RMS clap is unambiguous.
**Root cause of the 35ms:** the scene was NOT actually fully static. Any dynamic
element still in the scene — **including hidden ones**, which still count as
Dynamic in `SceneGraph.GetSplitPoint` — forces the per-frame composite path. If
it sits at split 0, `GetBakedBase` returns null and every tick is a FULL render
(no baked base). The 12:59/13:39 takes logged `resolve 1.0ms` per frame — a live
element was still resolving, confirming dynamic content was present.
**Theory of the "cut off at the end":** audio events land ~2s late; when the video
ends the audio track is still playing the final 2s of real-time content, giving the
impression of a cut. The audio track's slightly longer duration (17.25 vs 17.05;
22.31 vs 22.10) is the tail of that delayed signal — real audio outlives the
pump-stopped video.
**The fix that matters (no code changed in the renderer):** a truly static scene
renders in <1ms. New slow-render probe (`ProbeRender` in FramePump.cs) names the
path; the 13:53 take of a 1-element static scene logs
`render=fully-static split=1 dynamic=0 bakeMs=246 totalMs=246` on the FIRST
frame (cold raster of the background at 1080p), then `0.8→0.0ms` avg render,
`301/300` frames per 5s, 0 stalls → **12.46s file from 12.29s wall, 735 frames
@ 60fps. No truncation.**
**Theories RULED OUT by data:**
- ❌ Frame truncation / slow full-render — video is real-time; frame counts match
wall-clock (FramePump log: 301/300 per 5s, dropped 0, avg render 14ms).
- ❌ Named-pipe-connect drop — would *shorten* audio (events earlier), opposite sign.
Pipe connected near-instantly in both takes.
- ❌ AudioSyncDelay alone — capped at 0..500ms; 300ms is a subset, not the whole.
- ❌ Audio drift/resampler rate — offset is constant, not growing.
**Rule for recording:** every scene used for RECORDING should be ≥1 static
element first (background image) with all web/cam/chat widgets AFTER it in
layer order (split ≥ 1 → bake feasible) — a scene whose FIRST layer is dynamic
at recording time will truncate. If a take with widgets comes back truncated
again, the probe now points at whether it took `fully-static` (bake), or
`base+layers` / `full-render` (composite) and how long.
## Open threads
**Probe left in place** (≈0 overhead: one Stopwatch, string built only when a
render ≥20ms): it is the diagnostic that named this bug; keep it until the
dynamic-scene path is proven fast too, then remove.
## 🔴 OPEN — user-reported "video seems truncated ~1s" (unconfirmed)
Recording ty-20260912-1135-0000-2.mp4: format duration 26.370s, video 26.167s
(1570 frames @ 60fps), audio 26.370s. FramePump stats for the whole take show
`dropped 0` and 300/300 frames every 5s window. End-frames (n=1500 vs 1560 vs
1569) differ — not a frozen/repeat-last-frame truncation. Log shows recording
window 11:35:01.386 → 11:35:27.562 = 26.2s of video: matches the file. No
evidence of truncation found in data. Possibly user perceived the 500ms audio
delay (audio trailing video start / leading video end) as truncation — worth
re-checking with offset zeroed. If a real freeze/truncation reappears: pull
last-3-frames diffs and confirm_frame timestamps next.
## Other threads (paused)
- **Audio-silence verification** — the FIXED take has real peakMix; final =
user re-records with the finalized offset and confirms audible audio in playback.
- **Audio sync offset final value** — set to 0 via DB (measured residual ~70ms).
NEEDS user re-take to confirm (the running app may still hold 300 in memory —
if unsynced on the re-take, use the UI slider to 0, or restart the app BEFORE
recording so the 0 loads).
- **Truncation with DYNAMIC scenes** — proven mechanism; static scenes now
record full-length. The 13:58 take was a 6-element/4-dynamic scene
(`split=0 → full-render`, ~34ms, 20 stalls/5s): fully full-length (10.98s)
but JITTERY (judder from the 34ms hard frames). If a widget-heavy scene reads
badly again, the ProbeRender log names the stage; the next move is getting a
baked base by reordering static elements first or optimizing full-render.
- **Webcam MJPG missing** — "MJPG negotiation refused (being used by another
process)". Queued.
- **Web capture speed** — ~10-14Hz effective. Revisit only on request.
- **Layer order** — SortOrder not persisting on drag. Queued.
- **Audio-silence verification** — FIXED code (idempotent `Configure`, committed
`724af14`); the 19:23 take had real peakMix. Final user confirmation still pending.
- **Audio sync offset DB value** — `Audio.SyncOffsetMs = 300` (the "set to 0" write
in 5ba4d70 never actually landed). Fix for the ~2s ring backlog is now SHIPPED (local,
uncommitted). Next: re-record the clap pattern, run the cross-correlation recipe → expect
residual ≈ 400ms (300ms configured sync + ~100ms pipeline); then optionally zero the
slider to hit ~100ms.
- **Truncation with DYNAMIC scenes** — proven mechanism + probe in place; static
scenes full-length. 19:23 take confirms dynamic scenes hold ~60fps (no truncation)
but with 30ms stall cadence.
- **Webcam MJPG missing**, **web capture ~10–14Hz**, **layer SortOrder not persisting**
— queued, unchanged.
## Landmines
@@ -154,8 +128,16 @@ last-3-frames diffs and confirm_frame timestamps next.
- `cmd.exe /c "taskkill /F /IM ytLive.exe"` (WSL form double-slashes mangle) before rebuilds.
- Build/tests: Windows dotnet host (`/mnt/c/Program Files/dotnet/dotnet.exe`). 0 warnings.
- ffmpeg/ffprobe: `/mnt/c/Program Files/Krita (x64)/bin/ffmpeg.exe` with Windows paths.
- `Audio.SyncOffsetMs` persisted non-zero WILL re-trigger silence symptoms if
`Configure` is ever called unconditionally again — the idempotent guard is the
fix, keep it.
- `MyMistakes.md` has the transparency RESOLVED entry and the new webcam
collateral recipe — grep before any re-derivation.
- **`Audio.SyncOffsetMs` currently = 300 in the DB** (contradicts the "set to 0"
line in 5ba4d70; the write likely never happened). Non-zero offsets still depend on
the idempotent `Configure` guard to avoid the silence bug.
- `MyMistakes.md` → Recipes registry now has the **audio/video sync measurement
recipe** (claps + cross-correlation) — grep before re-deriving.
## Next step
**Verify the shipped fix:** re-record with the same clap pattern and run the
cross-correlation recipe from `MyMistakes.md` → expect offset ≈ 400ms (300ms configured
sync + ~100ms pipeline) with a `SyncOffsetMs=300` DB value, or ~100ms with the slider
zeroed. Then commit this session's work (StartLive clear + regression test + docs) and
decide with the user whether the no-push ruling is lifted.