From 09a866e6a1bc0a30a4d39aab0c74b6afa4a3266d Mon Sep 17 00:00:00 2001 From: gramps Date: Fri, 4 Sep 2026 12:02:24 -0700 Subject: [PATCH] =?UTF-8?q?perf(pump):=20slice=206=20=E2=80=94=20break=20t?= =?UTF-8?q?he=2015.6ms=20sleep=20quantum=20(the=20REAL=20ceiling=20behind?= =?UTF-8?q?=20takes=207-9)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Take 9's numbers were decisive: paste cache moved work to ~25ms/frame but the period stayed ~37ms. The missing ~12ms per tick is Task.Delay rounding every sub-tick request up to the Windows system-clock tick (~15.6ms default — documented: learn.microsoft.com/en-us/dotnet/api/system.threading.tasks.task.delay). A frame finishing 3ms early requested 3ms and slept 15.6. Producer capped at ~27fps no matter how fast the compositor got — which is why two real render fixes read as 'zero change' in playback. Game-loop/OBS canon for this (stackoverflow.com/questions/5441464; learn.microsoft.com/en-us/windows/win32/ api/timeapi/nf-timeapi-timebeginperiod): raise the timer resolution for the session, sleep only the bulk of the remainder, and SPIN the last ~2ms across the deadline. - FramePump: timeBeginPeriod(1) on entering the pump loop, timeEndPeriod(1) in the finally; pacing = bulk _pacingDelay(ahead - 2ms) + bounded Thread.SpinWait tail; blown deadlines rebase unchanged (never burst). - Stats now report avg wait: render+submit+wait must equal the period — the accounting is closed, no stage can hide in an unmeasured gap again. - Webcam dropped its IsOpaque paste-cache bypass: it re-sampled ~156k px every tick even between identical device frames; cached paste beats the sampler on hits, costs the same on misses. 52/52 per-class green (pacing + pixel suites unchanged — output byte-stable), clean build 0 warnings. Docs same commit (ai.md slice 6, TASKS.md take-10 gate, MyMistakes #3 + renumber, HANDOFF). User's top-bar spec remains next in queue (Unit B) — re-sent many times, captured, no open questions. --- HANDOFF.md | 19 +++++--- MyMistakes.md | 16 +++++-- Services/Compositor/SceneCompositor.cs | 15 +++---- Services/Encoder/FramePump.cs | 61 +++++++++++++++++++------- TASKS.md | 2 +- ai.md | 14 ++++++ 6 files changed, 92 insertions(+), 35 deletions(-) diff --git a/HANDOFF.md b/HANDOFF.md index d7162b6..20608f4 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -52,11 +52,20 @@ RealApp boot-smoke. Scope-check passed. not cache keys. Tests: `PasteCache_...` + 85/85 across compositor/pump/chat/capture/session classes; clean build 0 warnings. (Cam bypasses the cache via IsOpaque; revisit if take 9 is borderline. Follow-ups unchanged: vertical-tier alloc, debounced chat re-render on bursts.) -3. **Take 9 (user, ~30s record-only):** confirm the wordmark superscript matches the startup.log - Build line, then stats must show `≈300/300, avg render ≤ ~8ms` and playback 1x. If yes → - **recording saga CLOSED**, Unit B starts. If render ~10-15 → cam-resample cache (drop the - IsOpaque bypass); if n/300 sags only during chat bursts → debounced off-tick raster slice. -4. **Unit B — the top bar + session logic (user spec 2026-09-04 re-sent twice + decisions settled in Q&A):** +3. **Take 9 ran + slice 6 (2026-09-04, THE FINDING):** paste cache moved render 26.5→22.4ms yet + period stayed ~37ms — the gap is Task.Delay's ~15.6ms Windows sleep quantum padding every sub-tick + wait. **This is why takes 7→9 read as "zero change" despite real wins: the sleep floor dominated.** + Fixed (media-app canon, cited in code + MyMistakes #3): timeBeginPeriod(1) for the pump's life + (paired End in finally), sleep the bulk, SPIN the last 2ms across the deadline; stats gained + `avg wait` so render+submit+wait ≈ period (accounting closed — nothing can hide). Webcam now + routes through the paste cache too (bypass re-sampled 156k px even between identical device + frames). 52/52 per-class green, clean build 0 warnings, committed this slice. +4. **Take 10 (user, ~30s record-only):** read the superscript; stats must show `≈300/300, avg render + ~22, wait ~0-3` — honest 60fps IF render+submit ≤ ~16.7. If wait is near zero and n/300 sits at + ~200, the remaining gap is pure render 22ms → next slice = per-phase compositor timing (the stats + can split blit phases the same way they split resolve; that is the honest path, not a guess). + If take 10 lands at ~300/300 → recording saga CLOSED. +5. **Unit B — the top bar + session logic (user spec 2026-09-04 re-sent twice + decisions settled in Q&A):** - Two-line top bar. Line 1: center = REC + **LIVE** pills (text renamed from ON-AIR; pills become mutually-exclusive RADIOS — record-OR-stream ruling), right = avatar + **Login/Logout** button (no account status light). Line 2: centered primary **Start** (grayed while NO pill armed — diff --git a/MyMistakes.md b/MyMistakes.md index b817564..77dedf2 100644 --- a/MyMistakes.md +++ b/MyMistakes.md @@ -68,13 +68,23 @@ Both halves were solved by OBS/libyuv long ago; do not re-derive: to the intersection rect (our social-bar overlay scanned all 2M dst px for a 64px strip). A full-cover 1:1 blit also obsoletes the opaque-black pre-fill — skip dead writes. -3. **Hermetic pacing test:** inject the delay seam to RECORD the requested TimeSpan and +3. **On Windows, `Task.Delay` is a 15.6ms QUANTUM, not a timer.** Any request under one + system-clock tick sleeps a full tick (documented — learn.microsoft.com/en-us/dotnet/api/system.threading.tasks.task.delay: + "approximately 15 milliseconds on Windows systems"). A deadline pacer built on Task.Delay caps the + producer at ~40fps-ish EVEN IF render is instant — take 9 proved the signature: work fell 26.5→22.4ms + but the period sat at ~37ms (≈ one padded wait/frame), so two real optimizations read as "zero change". + Frame-accurate loops (OBS/Chromium/game-loop canon — stackoverflow.com/questions/5441464) do: + `timeBeginPeriod(1)` for the session (paired with `timeEndPeriod`), sleep only the BULK of the + remainder, SPIN the last ~2ms across the deadline. Diagnostic before touching the compositor again: + period ≈ work + 15.6 → the SLEEP is the bug, not the work. + +4. **Hermetic pacing test:** inject the delay seam to RECORD the requested TimeSpan and genuinely await it (`Task.Delay(d, ct)`) — a fake that returns `Task.CompletedTask` synchronously makes the whole pump loop run on `StartAsync`'s sync continuation and hang the test run (hit this 2026-09-03; the existing fakes all yield for exactly this reason). Assert the REQUESTED wait (< interval with a ≥cost-ms fake render) — never wall-clock rate, which flakes on loaded machines. -4. **Expensive content: raster on change, never on read (take 5, 2026-09-04).** A source +5. **Expensive content: raster on change, never on read (take 5, 2026-09-04).** A source that updates once a minute (chat text!) must not full-rasterize (`FormattedText` + `RenderTargetBitmap` + `CopyPixels` ≈ 15-25ms) every compositor tick. OBS text sources re-render on property/message change; the per-tick pass blits the cache. Implement as: @@ -83,7 +93,7 @@ Both halves were solved by OBS/libyuv long ago; do not re-derive: (the chat log) silently arm the per-tick cost even in flows that never touch the feature (signed-out record-only takes paid chat rendering!). -5. **Prove the stage, then the fix — and re-prove after every slice (2026-09-04, takes 6-8).** +6. **Prove the stage, then the fix — and re-prove after every slice (2026-09-04, takes 6-8).** The chat raster fix was REAL but the composer blamed it for the residual slowness it did not own; two takes burned before the render/resolve split showed `resolve ≈ 0` and pointed at the compositor pasting static layers per tick (`BlitCachedLayer` finished the job OBS-style). Before diff --git a/Services/Compositor/SceneCompositor.cs b/Services/Compositor/SceneCompositor.cs index adc25ac..05ca255 100644 --- a/Services/Compositor/SceneCompositor.cs +++ b/Services/Compositor/SceneCompositor.cs @@ -253,15 +253,12 @@ public sealed class SceneCompositor var ew = (float)element.Width; var eh = (float)element.Height; var isRound = element.ClipShape == ClipShape.Round; - if (frame.IsOpaque && element.Opacity >= 1f) - { - // Opaque full-strength layer (the live backdrop): raster it straight, no alpha path. - BlitContent(buffer, cropW, cropH, ex, ey, ew, eh, frame, 1f, isRound, element.IsMirrored); - } - else - { - BlitCachedLayer(buffer, cropW, cropH, ex, ey, ew, eh, frame, element, isRound); - } + // All rect-placed elements route through the paste cache (take-9 lesson): the + // IsOpaque bypass kept re-sampling the webcam (~156k px) EVERY tick even when + // the device frame had not changed; an opaque source rasterizes to an opaque + // raster whose paste is a per-pixel copy branch, so hits beat the sampler and + // misses cost exactly what the bypass cost. + BlitCachedLayer(buffer, cropW, cropH, ex, ey, ew, eh, frame, element, isRound); if (element.HasBorder) DrawBorder(buffer, cropW, cropH, ex, ey, ew, eh, element, isRound); } diff --git a/Services/Encoder/FramePump.cs b/Services/Encoder/FramePump.cs index 08d2983..79cfd22 100644 --- a/Services/Encoder/FramePump.cs +++ b/Services/Encoder/FramePump.cs @@ -64,6 +64,22 @@ public sealed class FramePump : IDisposable _freeScratch.Add(buffer); } + // Windows sleep quantum (take-9 finding, 2026-09-04): Task.Delay rounds every + // request up to the system clock tick (~15.6ms default — learn.microsoft.com/en-us/ + // dotnet/api/system.threading.tasks.task.delay: "approximately 15 milliseconds on + // Windows systems"), so a pacer requesting 3-15ms actually sleeps 15.6ms. Takes + // 5-9 measured work ~25ms but period ~37ms: one padded wait per frame hid every + // compositor improvement. Established media-app practice (game-loop/OBS canon — + // stackoverflow.com/questions/5441464; and raise the resolution for the session — + // learn.microsoft.com/en-us/windows/win32/api/timeapi/nf-timeapi-timebeginperiod): + // timeBeginPeriod(1) while the pump runs, sleep only the BULK of the remainder, + // and spin the last ~2ms across the deadline. + [System.Runtime.InteropServices.DllImport("winmm.dll")] + private static extern uint timeBeginPeriod(uint uMilliseconds); + [System.Runtime.InteropServices.DllImport("winmm.dll")] + private static extern uint timeEndPeriod(uint uMilliseconds); + private static readonly long SpinTailTicks = System.Diagnostics.Stopwatch.Frequency * 2 / 1000; // 2ms + private readonly object _gate = new(); private IFfmpegEncoder? _encoder; private CancellationTokenSource? _cts; @@ -265,11 +281,12 @@ public sealed class FramePump : IDisposable // Log the render/submit split every 5s so the next take names the stage. var renderSw = new System.Diagnostics.Stopwatch(); var submitSw = new System.Diagnostics.Stopwatch(); + var waitSw = new System.Diagnostics.Stopwatch(); // Resolve-vs-composite split (2026-09-04, take-6 ambiguity): "render" was a // 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; + long renderTicks = 0, submitTicks = 0, resolveTicks = 0, waitTicks = 0; int statFrames = 0; var statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5); void ReportStats() @@ -281,14 +298,16 @@ public sealed class FramePump : IDisposable : $"FramePump stats: {statFrames}/{target:F0} frames per 5s, " + $"avg render {renderTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms " + $"(resolve {resolveTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}), " + - $"avg submit {submitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms"); - renderTicks = submitTicks = resolveTicks = 0; + $"avg submit {submitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms, " + + $"avg wait {waitTicks / (double)System.Diagnostics.Stopwatch.Frequency * 1000 / statFrames:F1}ms"); + renderTicks = submitTicks = resolveTicks = waitTicks = 0; statFrames = 0; statsNext = DateTime.UtcNow + TimeSpan.FromSeconds(5); } // One wrapper shared by every render of the run — resolve time accumulates // inside the render measurement, and the stats line reports the split. + timeBeginPeriod(1); // pairs with timeEndPeriod in the finally — see field note VideoFrame? TimedResolver(SceneElement element) { resolveSw.Restart(); @@ -334,12 +353,9 @@ public sealed class FramePump : IDisposable frame = transition.BlendFrame(frame); transition.Tick(lastTick.Elapsed.TotalMilliseconds); } - // Restarted EVERY frame (transition or not) so a transition's first - // Tick sees per-frame time, not the pump's whole uptime. - lastTick.Restart(); - // Restarted EVERY frame (transition or not) — the old per-frame reset - // is what stops a transition that begins after idle from inheriting - // a giant ElapsedMs and completing instantly on its first tick. + // Restarted EVERY frame (transition or not): a transition begun + // after idle must not inherit a giant ElapsedMs and complete + // instantly on its first Tick. lastTick.Restart(); renderSw.Stop(); renderTicks += renderSw.ElapsedTicks; @@ -361,18 +377,28 @@ public sealed class FramePump : IDisposable // Advance the deadline; cost already spent is not slept again. // Blew the frame budget: skip the wait AND the missed ticks — - // rebase the clock rather than bursting a catch-up pile - // (OBS rewinds its tick the same way; a burst would only - // queue stale frames into the encoder). + // rebase rather than bursting a catch-up pile (OBS rewinds its + // tick; a burst only queues stale frames). Otherwise sleep the + // BULK and SPIN the 2ms tail — never hand a sub-tick remainder + // to the sleep quantum (see the timeBeginPeriod note). nextTick += intervalTicks; - var lag = nextTick - System.Diagnostics.Stopwatch.GetTimestamp(); - if (lag <= 0) + waitSw.Restart(); + var ahead = nextTick - System.Diagnostics.Stopwatch.GetTimestamp(); + if (ahead <= 0) { nextTick = System.Diagnostics.Stopwatch.GetTimestamp() + intervalTicks; - lag = 0; } - await _pacingDelay( - TimeSpan.FromSeconds(lag / (double)System.Diagnostics.Stopwatch.Frequency), ct); + else + { + 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(); + waitTicks += waitSw.ElapsedTicks; } } } @@ -396,6 +422,7 @@ public sealed class FramePump : IDisposable } finally { + timeEndPeriod(1); lock (_gate) IsRunning = false; } } diff --git a/TASKS.md b/TASKS.md index 3ca7418..287ca40 100644 --- a/TASKS.md +++ b/TASKS.md @@ -973,7 +973,7 @@ click (volume sliders keep their manual `SetSliderValueFromClick`, harmless dupl **Goal:** record the stream output to a local file, with or without simultaneously streaming. -### Status: ✅ Shipped `a9eb360` (2026-08-29) — code done (incl. manual-rename modal), build 0 warnings, 244/246 tests; **running-app verification (takes 1–5 done)**: files land (ffmpeg re-pinned month-end), **webcam-in-output + social bar visually CONFIRMED from take 3's extracted frame**, rename modal used for real (take 3 was named via it); take 3 exposed the ~2fps producer starvation and the pump stage-timing (`97ffc42`) named it in one line — `avg render 258.1ms` — **slice 1 fixed 2026-09-03** (deadline pacing per OBS video-io.c + libyuv-style row blits in `SceneCompositor`, test `Pump_Paces_To_The_Deadline_Compensating_Render_Cost`); **take 4: pacing held but render stayed 58.9ms** (2M-iteration row walk + 8.3MB/tick LOH) — **slice 2 shipped 2026-09-04**: `VideoFrame.IsOpaque` producer-contract flag → full-cover backdrop is one `Buffer.BlockCopy`; integer fixed-point bilinear general path; pump scratch pool (release strictly post-submit, owned-by-reference so cache frames are untouchable); dead per-tick `fromScene` render + the `fromSceneProvider` seam removed (BlendFrame uses `TransitionService.FromFrame` — the old render fed nothing). Tests `Pump_Pools_ScratchBuffers_Across_Frames_Without_Stale_Pixels` (the ONE) + `Composite_OpaqueFullCover_Backdrop_CopiesEveryPixel_Into_Scratch`; 59/59 per-class green, clean build 0 warnings. **take 5 ran: render 58.9→25.5ms (`138/300` ≈ 2.2x still) — cause: the per-tick chat raster (`RenderFrame` hit `RenderTargetBitmap` every tick whenever the message buffer was non-empty — the buffer survives sessions); slice 3 shipped 2026-09-04: `ChatOverlayLayer` rasters on message/config change and blits a cached frame every tick (OBS text-source pattern; test `ChatOverlayLayerCacheTests`).** **take 6 ran WITHOUT attribution (35-41ms — build provenance unknown; slice 3 effectiveness UNCONFIRMED) → build-stamp shipped instead of guessing again: `Helpers/BuildStamp` GUID per build (csproj GenerateBuildStamp; incremental builds can no longer lie), wordmark superscript + startup.log line; stats split `render (resolve)` so the next take names the stage. **takes 7–8 (stamped f190587b): chat fix CONFIRMED (`resolve ≈0`) but render stayed 26-27ms — compositor re-rasterizing STATIC layers every tick; slice 5 shipped: `BlitCachedLayer` pastes once-rasterized element-space layers (OBS surface-cache pattern; test `PasteCache_RepeatRender_IsByteIdentical_And_ContentChangePropagates`). **take 9 pending**: read stamp → stats must show `≈300/300, avg render ≤ ~8ms` → saga closes.** Known remaining churn (follow-ups, not silently done): vertical tier's final `BilinearScale` still allocates per frame; one slow tick (~15-25ms) per arriving chat message — debounced off-tick re-render if take 6 shows burst loss. **User UX spec (2026-09-04) queued behind this**: two-line top bar (LIVE rename, radio pills, Login/Logout button + avatar right-click Change Account, no account light; line 2 centered Start↔Stop grayed-until-armed) + up-front SaveFileDialog for REC (native overwrite prompt; retires the stop-time rename modal) + Go-Live dialog KEPT as preflight confirmation prefilled from the Text drawer — decisions captured in HANDOFF +### Status: ✅ Shipped `a9eb360` (2026-08-29) — code done (incl. manual-rename modal), build 0 warnings, 244/246 tests; **running-app verification (takes 1–5 done)**: files land (ffmpeg re-pinned month-end), **webcam-in-output + social bar visually CONFIRMED from take 3's extracted frame**, rename modal used for real (take 3 was named via it); take 3 exposed the ~2fps producer starvation and the pump stage-timing (`97ffc42`) named it in one line — `avg render 258.1ms` — **slice 1 fixed 2026-09-03** (deadline pacing per OBS video-io.c + libyuv-style row blits in `SceneCompositor`, test `Pump_Paces_To_The_Deadline_Compensating_Render_Cost`); **take 4: pacing held but render stayed 58.9ms** (2M-iteration row walk + 8.3MB/tick LOH) — **slice 2 shipped 2026-09-04**: `VideoFrame.IsOpaque` producer-contract flag → full-cover backdrop is one `Buffer.BlockCopy`; integer fixed-point bilinear general path; pump scratch pool (release strictly post-submit, owned-by-reference so cache frames are untouchable); dead per-tick `fromScene` render + the `fromSceneProvider` seam removed (BlendFrame uses `TransitionService.FromFrame` — the old render fed nothing). Tests `Pump_Pools_ScratchBuffers_Across_Frames_Without_Stale_Pixels` (the ONE) + `Composite_OpaqueFullCover_Backdrop_CopiesEveryPixel_Into_Scratch`; 59/59 per-class green, clean build 0 warnings. **take 5 ran: render 58.9→25.5ms (`138/300` ≈ 2.2x still) — cause: the per-tick chat raster (`RenderFrame` hit `RenderTargetBitmap` every tick whenever the message buffer was non-empty — the buffer survives sessions); slice 3 shipped 2026-09-04: `ChatOverlayLayer` rasters on message/config change and blits a cached frame every tick (OBS text-source pattern; test `ChatOverlayLayerCacheTests`).** **take 6 ran WITHOUT attribution (35-41ms — build provenance unknown; slice 3 effectiveness UNCONFIRMED) → build-stamp shipped instead of guessing again: `Helpers/BuildStamp` GUID per build (csproj GenerateBuildStamp; incremental builds can no longer lie), wordmark superscript + startup.log line; stats split `render (resolve)` so the next take names the stage. **takes 7–8 (stamped f190587b): chat fix CONFIRMED (`resolve ≈0`) but render stayed 26-27ms — compositor re-rasterizing STATIC layers every tick; slice 5 shipped: `BlitCachedLayer` pastes once-rasterized element-space layers (OBS surface-cache pattern; test `PasteCache_RepeatRender_IsByteIdentical_And_ContentChangePropagates`). **take 9 ran (c65a3cde, paste cache): render 26.5→22.4ms yet period stayed ~37ms — the gap was Task.Delay's 15.6ms sleep quantum padding every sub-tick wait: the true ceiling, hidden until then (why takes 7→9 looked like zero change). Slice 6 shipped: timeBeginPeriod(1) for the pump life + bulk-sleep + 2ms spin tail + `avg wait` stat (accounting closes) + webcam now routes through the paste cache. **take 10: stats must show `≈300/300 frames, render+submit+wait ≈ period`** → saga closes.** Known remaining churn (follow-ups, not silently done): vertical tier's final `BilinearScale` still allocates per frame; one slow tick (~15-25ms) per arriving chat message — debounced off-tick re-render if take 6 shows burst loss. **User UX spec (2026-09-04) queued behind this**: two-line top bar (LIVE rename, radio pills, Login/Logout button + avatar right-click Change Account, no account light; line 2 centered Start↔Stop grayed-until-armed) + up-front SaveFileDialog for REC (native overwrite prompt; retires the stop-time rename modal) + Go-Live dialog KEPT as preflight confirmation prefilled from the Text drawer — decisions captured in HANDOFF 1. ✅ `EncoderOptions` extended with `StreamEnabled` / `RecordEnabled` / `RecordPath` (independent intent flags) 2. ✅ `FfmpegArgs.Build` reworked into per-output blocks (stream `-f flv`, record `-f mp4`) via `AddVideoTags` diff --git a/ai.md b/ai.md index 5dc7db8..397b564 100644 --- a/ai.md +++ b/ai.md @@ -763,6 +763,20 @@ seam:** `Func`, `Func` resolver, `Func