diff --git a/HANDOFF.md b/HANDOFF.md index 4e82cb2..c9d5a9a 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -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` + (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-.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-.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) \ No newline at end of file +- `tools/ticker`: constant ~+982ms offset on the FIRST line is cosmetic (t0 a beat late) \ No newline at end of file diff --git a/MyMistakes.md b/MyMistakes.md index 9579e98..68a32e6 100644 --- a/MyMistakes.md +++ b/MyMistakes.md @@ -177,6 +177,26 @@ Both halves were solved by OBS/libyuv long ago; do not re-derive: shipping a perf fix: name the stage with a measurement, not a story; after shipping one, the NEXT number must move — a fix that doesn't change the stat wasn't the bottleneck. +8. **An encoder refed from a real-time loop must ENQUEUE, never pipe-write in the loop + (2026-09-10, take 15/16 — the "1...23...4...56..." smeared ticker).** After slice 9 the + recording played at the right DURATION but the content still hiccuped — and the aggregates + (301/300, uniform file PTS, 15.6s wall vs 15.74s file) could NOT see it. The cause finally + measured in `FfmpegEncoder.SubmitFrameAsync`: the `WriteAsync(8.3MB)+FlushAsync` to ffmpeg's + stdin BLOCKS whenever the encoder lags the pipe, and the slice-9 burst `while (now>=nextTick)` + then re-wrote that SAME stale composite for every slot that ticked past — frozen content runs. + OBS's answering machinery is the encoder queue (`libobs/obs-encoder.c`): the encoder thread + NEVER couples back into the video thread; overflow = dropped data, NEVER a frozen producer. + Fixed as: bounded `Channel` (cap 120) + a dedicated drain task owning stdin, + `SubmitFrameAsync` = copy-to-pool-array + `TryWrite` (drop-newest + count when full), pump + emits ONE fresh composite per iteration (no burst re-write), stop flushes the queue then EOF. + **Rule: verify with a clock-independent judge.** The WSL ticker that "proved" slice 9 has its + own Host-timer jitter under Windows load — so this slice burns a dot-matrix `_outputIndex` + into the bottom-right of every composite; decoding the recording reads the honest sequence + (+1/frame, jumps = counted drops) with no external clock involved. Take 17 must read + +1/frame from that strip. (A whole-frame duplicate scan was tried and is + UNRELIABLE here: the scene is always animating — session elapsed timer + REC pulse — so + no two frames are ever byte-identical.) + **Take-4 follow-ups (2026-09-04) — the symptom needed a second pass, so cite again:** render was still 58.9ms after slice 1. Slice 2 (buffer pool + opaque-row memcpy + diff --git a/Services/Encoder/FfmpegEncoder.cs b/Services/Encoder/FfmpegEncoder.cs index 7352df8..896d5a9 100644 --- a/Services/Encoder/FfmpegEncoder.cs +++ b/Services/Encoder/FfmpegEncoder.cs @@ -1,4 +1,6 @@ +using System.Buffers; using System.Diagnostics; +using System.Threading.Channels; using ytLive.Helpers; using ytLive.Models; @@ -30,6 +32,21 @@ public sealed class FfmpegEncoder : IFfmpegEncoder private Task? _stderrLoop; private bool _stopRequested; + // Pipe decoupling (slice 10, 2026-09-10): a bounded pending-frame queue drained + // by its own task (the OBS video-thread → encoder-queue model — the encoder's + // thread never couples back into the video thread; libobs obs-encoder.c). The + // pump's SubmitFrameAsync now ENQUEUES (copying into a pooled buffer) instead of + // blocking on WriteAsync when ffmpeg lags the pipe; overflow DROPS the newest + // frame (skip-newest) and counts it. BoundedChannelFullMode.Wait + TryWrite gives + // exactly that: when full, TryWrite returns false and the caller drops the item. + private const int QueueCapacity = 120; // ~2s at the tier's 60fps + private readonly Channel _frames = Channel.CreateBounded( + new BoundedChannelOptions(QueueCapacity) { SingleReader = true }); + private Task? _drainTask; + private int _droppedBackpressure; + + private readonly record struct PendingWrite(byte[] Buffer, int Length); + public FfmpegEncoder( IFfmpegLocator locator, Func? processFactory = null) @@ -40,6 +57,13 @@ public sealed class FfmpegEncoder : IFfmpegEncoder public bool IsRunning { get; private set; } + /// Frames dropped by the bounded queue because the drain task couldn't + /// keep the pipe fed (the encoder lagging the real-time capture rate). The pump + /// reports this in its stats; the burned-in frame counter in the recording + /// shows the identical jumps. Distinct from + /// (ffmpeg's own progress-derived estimate). + public int DroppedFrames => Volatile.Read(ref _droppedBackpressure); + public async Task StartAsync(EncoderOptions options, CancellationToken cancellationToken = default) { if (options == null) throw new ArgumentNullException(nameof(options)); @@ -93,26 +117,40 @@ public sealed class FfmpegEncoder : IFfmpegEncoder _stopRequested = false; _stderrLoop = RunStderrLoopAsync(process); + StartDrainLoop(process); } /// - /// Write one raw BGRA frame to ffmpeg's stdin. Serialized internally; callers - /// (the compositor pump) may race freely. Frames are written as-is — the caller - /// paces to capture rate (the compositor's job, ship step 5). + /// Enqueue one raw BGRA frame for ffmpeg's stdin (slice 10). The caller races + /// freely (the compositor pump); this never blocks on the pipe. The pixels are + /// copied into a pooled buffer first because — unlike the old direct write — the + /// write happens later on the drain thread, so the caller may (and does) recycle + /// its scratch buffer the moment this returns. When the bounded queue is full the + /// NEWEST frame is dropped and counted (freshness over coverage; the encoder is + /// already behind, so the stale-content failure mode never encodes). /// - public async Task SubmitFrameAsync(VideoFrame frame, CancellationToken cancellationToken = default) + public Task SubmitFrameAsync(VideoFrame frame, CancellationToken cancellationToken = default) { if (frame == null) throw new ArgumentNullException(nameof(frame)); - IEncoderProcess? process; lock (_gate) { if (!IsRunning) throw new InvalidOperationException("The encoder is not running."); - process = _process; } - var bytes = frame.BgraPixels; - await process!.StandardInput.WriteAsync(bytes, cancellationToken).ConfigureAwait(false); - await process.StandardInput.FlushAsync(cancellationToken).ConfigureAwait(false); + if (cancellationToken.IsCancellationRequested) + return Task.FromCanceled(cancellationToken); + + var pooled = ArrayPool.Shared.Rent(frame.BgraPixels.Length); + Buffer.BlockCopy(frame.BgraPixels, 0, pooled, 0, frame.BgraPixels.Length); + if (_frames.Writer.TryWrite(new PendingWrite(pooled, frame.BgraPixels.Length))) + return Task.CompletedTask; + + // Queue full (encoder lagging) or the channel completed during stop — drop the + // newest and count it. The caller never blocks; the encoder catches up or the + // session ends with a (reported) short gap instead of a frozen stall. + ArrayPool.Shared.Return(pooled); + Interlocked.Increment(ref _droppedBackpressure); + return Task.CompletedTask; } public async Task StopAsync(CancellationToken cancellationToken = default) @@ -127,13 +165,17 @@ public sealed class FfmpegEncoder : IFfmpegEncoder loop = _stderrLoop; } + // Flush every queued frame, then EOF: TryComplete lets the drain task write + // the buffered frames, close stdin → ffmpeg finalizes and exits by itself + // (the "did not exit after EOF" kill below is only the backstop). try { - process!.StandardInput.Dispose(); // EOF → ffmpeg finalizes + exits + _frames.Writer.TryComplete(); + if (_drainTask != null) await _drainTask.ConfigureAwait(false); } catch (Exception ex) { - AppLog.Write(ex, "FFmpeg encoder: closing stdin failed"); + AppLog.Write(ex, "FFmpeg encoder: drain loop faulted during stop"); } try @@ -178,6 +220,7 @@ public sealed class FfmpegEncoder : IFfmpegEncoder public void Dispose() { + _frames.Writer.TryComplete(); // unblock a stuck drain loop alongside the kill lock (_gate) { if (!IsRunning) return; @@ -188,6 +231,54 @@ public sealed class FfmpegEncoder : IFfmpegEncoder } } + /// + /// The drain task (slice 10): owns every stdin write, so pipe backpressure — the + /// pump's old stall — lives HERE, on a thread the pump never touches. Frames are + /// written exactly as queued (the pooled array through its recorded length — + /// ArrayPool may return a larger buffer), returned to the pool after the write + /// copies into the pipe, and stdin is closed (EOF) once the queue drains. + /// + private void StartDrainLoop(IEncoderProcess process) + { + _drainTask = Task.Run(async () => + { + try + { + try + { + while (await _frames.Reader.WaitToReadAsync().ConfigureAwait(false)) + { + while (_frames.Reader.TryRead(out var pending)) + { + await process.StandardInput.WriteAsync(pending.Buffer, 0, pending.Length) + .ConfigureAwait(false); + await process.StandardInput.FlushAsync().ConfigureAwait(false); + ArrayPool.Shared.Return(pending.Buffer); + } + } + } + catch (ChannelClosedException) + { + // channel completed while waiting — fall through to EOF + } + catch (Exception ex) + { + AppLog.Write(ex, "FFmpeg encoder: drain loop write faulted"); + } + finally + { + // EOF on every path — a byte that sits in the pool when the pipe + // breaks is garbage anyway, and ffmpeg MUST see the close to finalize. + process.StandardInput.Dispose(); + } + } + catch (Exception ex) + { + AppLog.Write(ex, "FFmpeg encoder: drain loop faulted"); + } + }); + } + private async Task ProbeEncoderAsync(string ffmpegPath, CancellationToken cancellationToken) { try diff --git a/Services/Encoder/FramePump.cs b/Services/Encoder/FramePump.cs index 737ad93..58da7c6 100644 --- a/Services/Encoder/FramePump.cs +++ b/Services/Encoder/FramePump.cs @@ -85,6 +85,7 @@ public sealed class FramePump : IDisposable private CancellationTokenSource? _cts; private Task? _pumpTask; private bool _started; + private long _outputIndex; /// Forwards the encoder's parsed health — ship step 6 binds this to the bottom bar. public event EventHandler? HealthUpdated; @@ -294,13 +295,17 @@ public sealed class FramePump : IDisposable // black box — the stats line now reports resolver time separately so a take // names the stage (get-frame vs blit) instead of feeding another guess. var resolveSw = new System.Diagnostics.Stopwatch(); - long renderTicks = 0, submitTicks = 0, resolveTicks = 0, waitTicks = 0, worstRender = 0; + long renderTicks = 0, submitTicks = 0, resolveTicks = 0, waitTicks = 0, worstRender = 0, worstSubmit = 0; int statFrames = 0; + int stalls = 0; var statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5); void ReportStats() { if (DateTime.UtcNow < statsNext) return; var target = 5d / interval.TotalSeconds; // frames expected per window + IFfmpegEncoder? encoder; + lock (_gate) encoder = _encoder; + var dropped = encoder == null ? 0 : encoder.DroppedFrames; _log?.Invoke(statFrames == 0 ? "FramePump stats: NO frames produced in 5s (loop stalled?)" : $"FramePump stats: {statFrames}/{target:F0} frames per 5s, " + @@ -308,10 +313,14 @@ public sealed class FramePump : IDisposable $"(resolve {resolveTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}), " + $"avg submit {submitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms, " + $"avg wait {waitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms, " - + $"worst render {worstRender / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F1}ms"); + + $"worst render {worstRender / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F1}ms, " + + $"worst submit {worstSubmit / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F1}ms, " + + $"dropped {dropped}, stalls {stalls}"); worstRender = 0; + worstSubmit = 0; renderTicks = submitTicks = resolveTicks = waitTicks = 0; statFrames = 0; + stalls = 0; statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5); } @@ -336,6 +345,7 @@ public sealed class FramePump : IDisposable var scene = _sceneProvider(); if (scene != null) { + var iterStart = System.Diagnostics.Stopwatch.GetTimestamp(); var compositorOptions = _compositorOptions(); VideoFrame? socialBarFrame = null; var socialBarTop = 0; @@ -377,29 +387,45 @@ public sealed class FramePump : IDisposable lock (_gate) encoder = _encoder; 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(); - while (!ct.IsCancellationRequested - && System.Diagnostics.Stopwatch.GetTimestamp() >= nextTick) + // Burned-in frame counter (slice 10 judge): a clock-independent + // pacing witness burned literally into the composite. Decode the + // recording and read the bottom-right strip: the number must advance + // +1 per frame and jump only by counted drops (queue overflow or a + // render-overrun's skipped slots). The WSL ticker replaced as the + // judge because its own timers can smear under Windows host load — + // this can't lie. + _outputIndex++; + BurnFrameIndex(frame.BgraPixels, frame.Width, frame.Height, _outputIndex); + + // Deadline pacing (slice 10 reshape): ONE fresh composite per iteration, submitted + // only when the clock has reached the next deadline. Two changes from + // the take-9 counting loop, both derived from where the stale-content + // bug actually lived: + // 1. SubmitFrameAsync no longer blocks on the pipe — it ENQUEUES into + // the encoder's bounded queue (the OBS video-thread model), so the + // pump can never stall behind ffmpeg, and overflow DROPS the + // newest frame. The queue wasn't here in the take-9 loop — a + // lagging ffmpeg made the pump's submit block, and the burst + // while-loop (below) then re-wrote the SAME stale composite for + // every slot that ticked past, which is why the ticker smeared. + // 2. One submission max per iteration: each catch-up slot now gets a + // FRESH render instead of a repeat of the stale one. Missed slots + // vanish from the file (a count-based gap, like the queue drop) — + // never duplicated frozen frames. + if (!ct.IsCancellationRequested + && System.Diagnostics.Stopwatch.GetTimestamp() >= nextTick) { + submitSw.Restart(); await encoder.SubmitFrameAsync(frame, ct); + submitSw.Stop(); statFrames++; + submitTicks += submitSw.ElapsedTicks; + if (submitSw.ElapsedTicks > worstSubmit) worstSubmit = submitSw.ElapsedTicks; nextTick += intervalTicks; } - submitSw.Stop(); - submitTicks += submitSw.ElapsedTicks; - // SubmitFrameAsync copied the bytes on every write above — the - // tick's buffers are recyclable once each due slot consumed them. + // SubmitFrameAsync copied the bytes into the encoder's queue — the + // tick's buffers are recyclable once the enqueue snapshot them. // The free-list Contains guard keeps the Cut path (BlendFrame // returns toFrame itself, aliasing scratch) safe. ReleaseScratch(frame.BgraPixels); @@ -419,6 +445,20 @@ public sealed class FramePump : IDisposable Thread.SpinWait(400); waitSw.Stop(); waitTicks += waitSw.ElapsedTicks; + + // Stall logger (slice 10): an iteration spanning more than two full + // intervals is the old bug's fingerprint — name the stage instead of + // guessing. With the queue, submit should be ~1ms, so a stall here + // means RENDER or RESOLVE (the stage terms of the last take). + var iterWall = System.Diagnostics.Stopwatch.GetTimestamp() - iterStart; + if (iterWall > 2 * intervalTicks) + { + stalls++; + _log?.Invoke($"FramePump stall: iteration {iterWall / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F0}ms " + + $"(> 2× the {interval.TotalMilliseconds:F0}ms interval): worst render " + + $"{worstRender / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F0}ms, worst submit " + + $"{worstSubmit / (double)System.Diagnostics.Stopwatch.Frequency * 1000:F0}ms, dropped {encoder.DroppedFrames}"); + } ReportStats(); } } @@ -491,6 +531,57 @@ public sealed class FramePump : IDisposable return _compositor.Render(scene, resolver, null, options, socialBarFrame, socialBarTop, scratch: scratch); } + // Dot-matrix digits (5×7, one row per raster line, '1' = lit) burned into the + // bottom-right of every composite. Basic OCR-safe shapes, sized so the strip is + // a 36×8 white box in the corner of a 1920×1080 frame — readable with a zoomed + // player, invisible at normal size. + private static readonly string[][] DigitGlyphs = + { + new[] { "01110","10001","10001","10001","10001","10001","01110" }, // 0 + new[] { "00100","01100","00100","00100","00100","00100","01110" }, // 1 + new[] { "01110","10001","00001","00010","00100","01000","11111" }, // 2 + new[] { "11111","00001","00010","00110","00001","10001","01110" }, // 3 + new[] { "00010","00110","01010","10010","11111","00010","00010" }, // 4 + new[] { "11111","10000","11110","00001","00001","10001","01110" }, // 5 + new[] { "01110","10001","10000","11110","10001","10001","01110" }, // 6 + new[] { "11111","00001","00010","00100","01000","01000","01000" }, // 7 + new[] { "01110","10001","10001","01110","10001","10001","01110" }, // 8 + new[] { "01110","10001","10001","01111","00001","10001","01110" }, // 9 + }; + + private static void BurnFrameIndex(byte[] bgra, int width, int height, long index) + { + const int digitW = 5, digitH = 7, gap = 1, margin = 2, digitCount = 6; + var stripW = digitCount * (digitW + gap) - gap; + var left = width - margin - stripW; + var top = height - margin - digitH; + + // Solid white box under the digits — the underlying scene can be anything. + for (var y = top; y < top + digitH; y++) + for (var x = left; x < left + stripW; x++) + { + var i = (y * width + x) * 4; + bgra[i] = 255; + bgra[i + 1] = 255; + bgra[i + 2] = 255; + } + + var text = index.ToString("D6"); + for (var d = 0; d < digitCount; d++) + { + var glyph = DigitGlyphs[text[d] - '0']; + for (var row = 0; row < digitH; row++) + for (var col = 0; col < digitW; col++) + { + if (glyph[row][col] != '1') continue; + var i = ((top + row) * width + (left + d * (digitW + gap) + col)) * 4; + bgra[i] = 0; + bgra[i + 1] = 0; + bgra[i + 2] = 0; + } + } + } + private void OnProcessFailed(object? sender, string message) { _log?.Invoke($"FramePump: encoder process failed: {message}"); diff --git a/Services/Encoder/IFfmpegEncoder.cs b/Services/Encoder/IFfmpegEncoder.cs index 0b3140b..522251f 100644 --- a/Services/Encoder/IFfmpegEncoder.cs +++ b/Services/Encoder/IFfmpegEncoder.cs @@ -22,4 +22,9 @@ public interface IFfmpegEncoder : IDisposable Task StartAsync(EncoderOptions options, CancellationToken cancellationToken = default); Task SubmitFrameAsync(VideoFrame frame, CancellationToken cancellationToken = default); Task StopAsync(CancellationToken cancellationToken = default); + + /// Frames dropped by the encoder's bounded queue since start (the encoder + /// lagging the real-time capture rate). Zero in a healthy session; fed to the pump's + /// stats and mirrored by gaps in the burned-in frame counter of the recording. + int DroppedFrames { get; } } diff --git a/ai.md b/ai.md index acc44b2..5f9820c 100644 --- a/ai.md +++ b/ai.md @@ -505,8 +505,9 @@ encoder step (not yet — this PR ships the seam + impl + tests only). The encoder is a **thin orchestrator over `ffmpeg.exe`** — no H.264/AAC code in the app. It spawns the subprocess (path from `IFfmpegLocator`), feeds raw BGRA master frames into stdin, and parses `-stats` stderr lines into `StreamHealth` (bitrate/FPS/duration, dropped-from-frame-count). `FfmpegEncoder` -(`IFfmpegEncoder` seam) holds: `StartAsync` (locate → probe `-encoders` → spawn → stderr loop), -`SubmitFrameAsync` (serialized stdin writes under `SemaphoreSlim`), `StopAsync` (stdin EOF → ffmpeg +(`IFfmpegEncoder` seam) holds: `StartAsync` (locate → probe `-encoders` → spawn → stderr loop → +drain loop), `SubmitFrameAsync` (slice 10: bounded-queue ENQUEUE — never a pipe write; the drain task +owns stdin writes), `StopAsync` (flush queue → stdin EOF → ffmpeg finalizes + exits by itself; a 10s watchdog kills it), `Dispose` (force-kill + wait), and the `HealthUpdated`/`ProcessFailed` events. **Pattern:** the encoder never touches `Process` — it drives the `IEncoderProcess` seam (`FfmpegEncoderProcess` wraps the real `Process`, redirected stdin/stdout/stderr @@ -775,7 +776,9 @@ seam:** `Func`, `Func` resolver, `Func`, `Func` resolver, `Func` (cap 120 ≈ + 2s at 60fps) owned by a dedicated drain task with the stdin write + flush; the caller NEVER blocks on + the pipe. Pixels are copied into an `ArrayPool` buffer before enqueue (the write now happens later on + the drain thread, so the pump's scratch reusable the moment submit returns — same contract as before). + (2) **drop-on-overflow (creator's choice: freshness over coverage):** when the queue is full the NEWEST + frame is dropped and counted (`IFfmpegEncoder.DroppedFrames`, `Interlocked`); the session never freezes + or smears — it drops. Stop flushes the whole queue then EOF (`Channel.TryComplete` → drain writes + leftovers → closes stdin → ffmpeg finalizes+exits), so no accepted frame is ever lost at stop. + (3) **pump loops ONE submit per iteration** (replacing slice 9's burst): every due slot gets a FRESH + composite — no catch-up slot ever repeats frozen content; missed slots vanish as a count-based gap. + The deadline counter is still never reset to wall-now (slice 9 ruling). + (4) **burned-in frame counter (the new judge):** `_outputIndex` is burned into a 6-digit dot-matrix + strip (white box + black 5×7 glyphs, bottom-right corner) of EVERY composite before submit. The WSL + ticker is demoted because its own timers smear under Windows host load; decoding the recording and + reading the strip is clock-independent: the number advances +1 per frame and jumps by exactly the + counted drops (queue overflow OR skipped catch-up slots). Stats gained `worst submit Xms`, `dropped N`, + `stalls K`; a stall logger names any iteration > 2× interval with its render/submit split — with the + queue, submit is ~1ms, so a stall means render/resolve. The strip sits above the social bar (bar is + composited, then burned over) — a debug judge, tiny at 1080p. Test: + `Backpressure_QueueOverflow_DropsFrames_AndNeverBlocks` (the ONE: a 40ms-per-frame sink fake makes + every enqueue fill the queue; submit must return instantly, drops are counted, stop flushes exactly + submitted − dropped bytes). Full suite 289/290 (the pre-existing compositor pixel failure unchanged). + Audio untouched (follow-up). WSL ticker-under-load reliability check still to run (informational — the + burned counter is the judge). +- **Stop ordering matters:** `StopAsync` stops the encoder — since slice 10 it FLUSHES the pending + queue (`Channel.TryComplete` → drain writes the leftovers, closes stdin → EOF → ffmpeg finalizes+exits; + an accepted frame is never lost) — **before** awaiting the loop. The old reverse-order deadlock was + a submit stuck on pipe backpressure; the drain thread owns that wait now, and stopping the encoder + first keeps the pump's own (non-blocking) submits from racing the completed queue as a spurious drop. + `ProcessFailed` self-stops the pump. `Failed` while live flips `StreamStatus.Error` (minimal). - **Health stats (ship step 6, shipped 2026-08-13):** `HealthUpdated` is bound to the bottom bar — `MainViewModel.OnFramePumpHealthUpdated` marshals to the UI thread (the encoder's stderr loop raises on diff --git a/ytLive.Tests/FfmpegEncoderTests.cs b/ytLive.Tests/FfmpegEncoderTests.cs index 88c5fbd..cdf0e25 100644 --- a/ytLive.Tests/FfmpegEncoderTests.cs +++ b/ytLive.Tests/FfmpegEncoderTests.cs @@ -39,7 +39,7 @@ public class FfmpegEncoderTests private sealed class FakeEncoderProcess : IEncoderProcess { public ProcessStartInfo? StartInfo { get; private set; } - public MemoryStream Stdin { get; } = new(); + public Stream Stdin { get; } public Stream StandardInput => Stdin; public TextReader StandardOutput { get; } public bool HasExited { get; private set; } @@ -51,8 +51,11 @@ public class FfmpegEncoderTests new(TaskCreationOptions.RunContinuationsAsynchronously); private readonly QueuedReader _error = new(); - public FakeEncoderProcess(string probeOutput = "") - => StandardOutput = new StringReader(probeOutput); + public FakeEncoderProcess(string probeOutput = "", Stream? stdin = null) + { + StandardOutput = new StringReader(probeOutput); + Stdin = stdin ?? new MemoryStream(); + } public TextReader StandardError => _error; public void EnqueueStderr(string line) => _error.Enqueue(line); @@ -152,7 +155,12 @@ public class FfmpegEncoderTests await encoder.SubmitFrameAsync(new VideoFrame(1920, 1080, BgraFrame(1920, 1080, 255, 0, 0))); await encoder.SubmitFrameAsync(new VideoFrame(1920, 1080, BgraFrame(1920, 1080, 0, 255, 0))); - Assert.Equal(2 * 1920 * 1080 * 4, encoderProc.Stdin.Length); + // The drain task writes async — poll for both frames instead of racing it. + const long twoFrames = 2 * 1920L * 1080 * 4; + var deadline = DateTime.UtcNow.AddSeconds(5); + while (encoderProc.Stdin.Length < twoFrames && DateTime.UtcNow < deadline) + await Task.Delay(10); + Assert.Equal(twoFrames, encoderProc.Stdin.Length); encoderProc.EnqueueStderr( "frame= 120 fps= 59.9 q=28.0 size= 1024KiB time=00:00:02.00 bitrate= 4000.1kbits/s speed=1.00x"); @@ -341,4 +349,72 @@ public class FfmpegEncoderTests Assert.Equal("libopenh264", FfmpegEncoderPicker.Pick("no encoders at all")); } + + /// A stdin slow enough that the encoder can't keep up — the pump's old + /// blocking-write failure mode made demonstrable. + private sealed class SlowSink : Stream + { + public long TotalBytes; + public override bool CanRead => false; + public override bool CanSeek => false; + public override bool CanWrite => true; + public override long Length => throw new NotSupportedException(); + public override long Position { get => throw new NotSupportedException(); set => throw new NotSupportedException(); } + public override void Flush() { } + public override Task FlushAsync(CancellationToken ct) => Task.CompletedTask; + public override int Read(byte[] buffer, int offset, int count) => throw new NotSupportedException(); + public override long Seek(long offset, SeekOrigin origin) => throw new NotSupportedException(); + public override void SetLength(long value) => throw new NotSupportedException(); + public override void Write(byte[] buffer, int offset, int count) => throw new NotSupportedException(); + public override async Task WriteAsync(byte[] buffer, int offset, int count, CancellationToken ct) + { + await Task.Delay(40, ct).ConfigureAwait(false); + Interlocked.Add(ref TotalBytes, count); + } + } + + /// The ONE integration test for slice 10 (the bounded-queue reshape): a + /// lagging ffmpeg must NOT stall the frame producer. With 300 fast submits against + /// a ~25fps-max sink, every queue slot fills and the NEWEST frames are dropped and + /// counted; SubmitFrameAsync must return instantly (it never touched a pipe wait — + /// the old code blocked in WriteAsync and the pump froze); StopAsync still flushes + /// every accepted frame; and the sink ends with exactly (submitted − dropped) bytes + /// — the drop counter and the recording agree (the burned-in-frame-counter premise). + [Fact] + public async Task Backpressure_QueueOverflow_DropsFrames_AndNeverBlocks() + { + var sink = new SlowSink(); + var encoderProc = new FakeEncoderProcess(stdin: sink); + var factory = new FakeEncoderProcessFactory(); + factory.Return(new FakeEncoderProcess()); + factory.Return(encoderProc); + + using var encoder = new FfmpegEncoder(new StubLocator(), factory.Create); + await encoder.StartAsync(new EncoderOptions + { + RtmpUrl = "rtmp://x/y", + Width = 64, + Height = 48, + Fps = 60, + }); + + var frame = new VideoFrame(64, 48, BgraFrame(64, 48, 255, 0, 0)); + const int submits = 300; + + var sw = System.Diagnostics.Stopwatch.StartNew(); + for (var i = 0; i < submits; i++) + await encoder.SubmitFrameAsync(frame); + sw.Stop(); + + Assert.True(sw.Elapsed < TimeSpan.FromSeconds(2), + $"SubmitFrameAsync blocked on a saturated queue: {sw.Elapsed}"); + var dropped = encoder.DroppedFrames; + Assert.True(dropped > 0, "the bounded queue must overflow-drop when the encoder lags"); + Assert.True(dropped < submits, $"the whole lot must not vanish ({dropped}/{submits})"); + + encoderProc.SignalExit(); + await encoder.StopAsync(); + + Assert.Equal((submits - dropped) * 64 * 48 * 4L, sink.TotalBytes); + } } diff --git a/ytLive.Tests/FramePumpTests.cs b/ytLive.Tests/FramePumpTests.cs index c20e3b5..b25fd37 100644 --- a/ytLive.Tests/FramePumpTests.cs +++ b/ytLive.Tests/FramePumpTests.cs @@ -62,6 +62,8 @@ public class FramePumpTests public void RaiseProcessFailed(string message) => ProcessFailed?.Invoke(this, message); public void RaiseHealth(StreamHealth health) => HealthUpdated?.Invoke(this, health); + + public int DroppedFrames { get; set; } } private static Scene BackgroundScene()