perf(pump): slice 6 — break the 15.6ms sleep quantum (the REAL ceiling behind takes 7-9)

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.
This commit is contained in:
2026-09-04 12:02:24 -07:00
parent 6af2026906
commit 09a866e6a1
6 changed files with 92 additions and 35 deletions
+14 -5
View File
@@ -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 —
+13 -3
View File
@@ -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
+6 -9
View File
@@ -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);
}
+44 -17
View File
@@ -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;
}
}
+1 -1
View File
@@ -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`
+14
View File
@@ -763,6 +763,20 @@ seam:** `Func<Scene?>`, `Func<SceneElement, VideoFrame?>` resolver, `Func<Compos
existing pixel suite guards sampler semantics. Take 9 must show `≈300/300, avg render ≤ ~8ms`;
if it lands there, the recording saga closes. Follow-ups unchanged: vertical-tier scale alloc,
debounced chat re-render under message bursts.
- **Slice 6 — the sleep quantum WAS the ceiling (take 9, 2026-09-04):** period measured ~37ms while
work (render+submit) was ~25 — the missing ~12ms is `Task.Delay` rounding EVERY request up to the
Windows clock tick (documented ~15.6ms default; learn.microsoft.com/en-us/dotnet/api/system.threading.tasks.task.delay).
A frame finishing 3ms early requests a 3ms wait and sleeps a full 15.6 — capping the producer at
~27fps NO MATTER how fast the compositor ran. This is why takes 7→9 showed zero playback change
despite real render wins: the sleep floor dominated everything above it. Established fix (game-loop
canon — stackoverflow.com/questions/5441464; timeBeginPeriod — learn.microsoft.com/en-us/windows/win32/api/timeapi/nf-timeapi-timebeginperiod):
`timeBeginPeriod(1)` for the pump's lifetime (paired `timeEndPeriod` in the finally), sleep only the
BULK of the remainder (request minus 2ms), `Thread.SpinWait` the last ~2ms across the deadline;
blown deadlines still rebase. Stats gained `avg wait Xms` so render+submit+wait must ≈ period —
the accounting is closed, no stage can hide again. Same slice: the webcam's `IsOpaque` paste-cache
bypass was removed (it re-sampled ~156k px every tick even between identical device frames; the
cached paste beats the sampler on hits and costs the same on misses). Take 10 verdict: `≈300/300`
honest fps — if short, the wait/render split names the remaining term with no ambiguity left.
- **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
reverse order would deadlock. `ProcessFailed` self-stops the pump. `Failed` while live flips