diff --git a/HANDOFF.md b/HANDOFF.md index 20d4b28..b873e2c 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -1,42 +1,66 @@ -# HANDOFF — 2026-10-14 (clean tree; all units committed AND pushed) +# HANDOFF — 2026-10-16 (work committed locally; NOT pushed — push at the next milestone) ## At a glance -- **Branch** main, tracking `origin/main`. **HEAD = `origin/main` = `931ab46`** — 0 ahead, 0 behind. - Everything below is pushed; nothing is local-only. -- Working tree is **clean** (the stray `Assets/llamacasty-text-nobg-2.png~` backup was deleted 2026-10-14). +- **Branch** main, tracking `origin/main`. **origin/main = `931ab46`; HEAD = the tip commit "Per-element + composite timing + scene dump (measurement only)"** — **2 ahead, 0 behind** (nothing pushed this + session; per the commit/push policy, push only at sub-milestones/milestones, when the creator says + so). This file cannot record its own commit's hash — amending a commit changes that hash — so the tip + is named by subject. + - The two local-only commits are `3cb29ea` (**the previous session's HANDOFF refresh — the old + handoff claimed it was pushed; it never was**) and the tip. So "0 ahead" in the 2026-10-14 handoff + was wrong — check `git log origin/main..HEAD`, never the handoff's own claim. +- Working tree **clean** after the commit. +- No app run, recording, or test session happened 2026-10-11 → 10-16 (verified against + `%APPDATA%\ytLlive\startup.log`: last activity 2026-10-10 13:26). The creator was away for a family + emergency and has only just returned — **there is still no take of the instrumented build.** -## Recent units (all committed + pushed) -- `931ab46` — pinned chat: `ChatMessage.IsPinned`, `MainViewModel.PinnedChatMessage` + - Pin/Clear commands (`Helpers/RelayCommandGeneric.cs`), LeftPanel pinned banner via `NotNullToVis`. - Plus brand wordmark assets. (This was previously mislabeled in the old handoff as "not mine — do NOT commit"; it is committed.) -- `8e1d6f4` — strip tile artwork + on-air indicator (per-scene `Scene.ThumbnailAssetId`, shared - `OnAirImageAssetId`, PreviewPane green rect removed, tile labels FontSize 20, Asset-pruner keep-set - fix). 427 pass, 0 warnings. -- `06f88f4` — scene strip renders in canonical F1–F5 order (`ReorderScenesToCanonical`). -- `63bf844` — desktop lock: `ShowActivated = !FullscreenGameRunningNow` + `FullScreenDetectorOverride`. +## This session's unit (committed, unpushed — the tip commit) +- **Per-element composite timing + scene dump — MEASUREMENT ONLY (2026-10-16).** Closes the gap the + cadence work left: the 141ms take and the 30ms take could not be compared because the log named no + element and recorded no scene. + - `Services/Compositor/CompositeTimings.cs` (new): collector; `Describe(renders, minMs = 0.1)` + prints the averaged breakdown slowest-first. + - `SceneCompositor.Render` / `CompositeLayers` / `BakeStaticBase` / `BlitBakedElement` / + `BlitCachedLayer` + `SceneGraph.GetBakedBase`: trailing optional `CompositeTimings?` — every stage + and every element timed (`# `, nested `raster` = paste-cache miss). Existing callers + unaffected. + - `FramePump`: `FramePump parts (N renders/5s): …` per stats window; `FramePump scene dump:` block + (header + one line per element) at pump start and on scene change. + - Gate test: `ytLive.Tests/CompositeTimingTests.cs` (one `[Fact]`, real composite through the real + collector + dump formatter). Full suite 428 tests; 0 warnings; scope check passed. + - Derivative citation: OBS Source Profiler (per-source tick/render average) — see `ai.md` + "Per-element composite timing + scene dump". ## Next step -- **Webcam cadence work** (creator-queued 2026-10-05; see TASKS.md → "Webcam cadence → resolution"). - **ACTUAL NEXT UNIT: per-element composite timing + a scene dump at pump start.** Measurement only — - no fix until it names which of the 6 elements eats ~140ms. Needs a creator recording/session to read. - The compositor manages **6.8 composites/s at ~141ms** and the file is **88.7% duplicate frames** — that - is the judder; the camera itself delivers 30.0/s clean. +- **Creator take on the instrumented build, Release** (`"/mnt/c/Program Files/dotnet/dotnet.exe" run + -c Release`). Read the two new lines in `%APPDATA%\ytLlive\startup.log`: + `FramePump parts (N renders/5s): …` (which element / which stage eats the budget) and the + `FramePump scene dump:` block (the shape the take was made from). **No fix is to be attempted until + the parts line names the element** — the 10:03 → 12:01 regression (29–34ms → 143–155ms) is still + unexplained, and the competing explanations in the map (21:9 source rect vs. same-shape regression) + are unresolved on purpose until a reading decides it. ## Also still open (operational) +- **verify.sh's known-failure whitelist is too loose (found 2026-10-16):** it counts matching names and + passes if `KNOWN > 0`, so a NEW third failure rides along unnoticed. This session's full run showed + `AudioPipelineTests.MasterLimiter_CapsTheLiveMix_OnThePipe` failing beside the two known ones — it + passes in isolation (29/29), so it is an audio-device env flake like + `Mix_HonorsProviderGains…` (system audio playing). **Follow-up: tighten the script** (require EVERY + failure line to be in the whitelist) and add `MasterLimiter_CapsTheLiveMix_OnThePipe` to the list. + Not fixed in this unit — out of scope (`scripts/verify.sh` was not in the declared file list). - **Vertical-format regression (STALE, not fixed):** 1080p60-vertical selection no longer shrinks the capture border in the preview. Mechanism mapped in `Controls/PreviewPane.xaml:319-322` (crop Rectangle bound to `OutputRectX/Y/W/H` + `IsOutputCropped`, driven by `MainViewModel.Streaming.cs` `ApplyStreamQuality`; `DimRects` in `MainViewModel.cs:91-94`). Root cause unknown — paused. - ⛔ Sudo password rotation pending (user; then update both password lines in `CREDENTIALS.md`). - TASK 56 secret scan before `gramps/LlamaCasty` goes public. -- TASK 55 disk hygiene queued (`startup.log` uncapped). +- TASK 55 disk hygiene queued (`startup.log` uncapped — now 22MB and growing with the new lines). ## Tests -- Full suite **427 passed / 0 failed / 0 skipped / 0 warnings** (as of `8e1d6f4`). Known env flakes: - `Mix_HonorsProviderGains…` (fails while system audio plays), `RealMouseDrag…` (needs an idle desktop), - `Round_Clip_Corner…` (grab/geometry under active mouse). The verify gate whitelists only the latter two — - `RealMouseDrag…` failing mid-session needs one re-run when the desktop idles. +- Full suite **426 passed / 2 failed / 0 skipped / 0 warnings** (2026-10-16, 428 total incl. the new + test). Both failures are the audio env flake (see above) and pass in isolation. - Pre-commit gate: `./scripts/verify.sh "" "" ...` (clean build + full suite + scope check). + **Read its output — it can pass with an unlisted failure present (see the landmine above).** ## Secrets / paths (do not re-hunt) - Layout DB: `%APPDATA%\ytLlive\ytLlive.db` (SQLite, full-rewrite per save). Auth: `%APPDATA%\ytLlive\ytLlive.auth` diff --git a/Services/Compositor/CompositeTimings.cs b/Services/Compositor/CompositeTimings.cs new file mode 100644 index 0000000..8e32e92 --- /dev/null +++ b/Services/Compositor/CompositeTimings.cs @@ -0,0 +1,76 @@ +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; + +namespace ytLive.Services.Compositor; + +/// +/// Per-stage composite timing (webcam-cadence unit, 2026-10-16): wall time per render +/// pass, split into named stages — the backdrop, every element (keyed by z-index + +/// name), the global overlays, and the final output scale. The pump owns one instance +/// for the whole session, passes it into / +/// CompositeLayers / BakeStaticBase, and logs an averaged breakdown every +/// stats window — the "which of the 6 elements eats ~140ms" reading the old stats line +/// could not give (it reported render/acquire/resolve, never the culprit layer). +/// Stage names are stable and greppable: backdrop, base, +/// flash, social, ticker, zoom, scale, +/// bake backdrop, bake overlays, and #<index> <name> per +/// element (bake-pass elements are prefixed bake so a one-off rebake cannot +/// masquerade as a per-composite cost). A #<i> <name> raster sub-stage NESTS inside its parent's total +/// (it is the paste-cache rasterize miss — the prime suspect when one element costs a +/// full resample every tick). Stage time INCLUDES that stage's frame resolve; resolve +/// is separately totalled in the stats line. +/// Single writer in production (the pump's render thread — every blit joins its +/// workers before returning); the lock only makes a test able +/// to share one across threads. +/// +public sealed class CompositeTimings +{ + private readonly object _gate = new(); + private readonly Dictionary _stages = new(StringComparer.Ordinal); + + /// Accumulate one stage sample. Non-positive ticks are dropped — a + /// skipped layer must not create a zero-cost entry that dilutes the reading. + public void Add(string stage, long ticks) + { + if (ticks <= 0 || stage.Length == 0) return; + lock (_gate) + { + _stages.TryGetValue(stage, out var cur); + _stages[stage] = cur + ticks; + } + } + + /// Clear every stage — called once per stats window after the parts line + /// is logged, so each window reports its own breakdown. + public void Reset() + { + lock (_gate) _stages.Clear(); + } + + /// Average milliseconds per render for every stage at or above + /// , sorted slowest-first: + /// "#2 Webcam 88.1ms, backdrop 61.2ms, #2 Webcam raster 84.0ms". + /// is the divisor (the window's render count, so the + /// numbers compare directly with the stats line's avg render). The floor + /// keeps a healthy pipeline from burying the contender in zeroes; the empty string + /// means nothing was composited (the fully-static shortcut and C4 cache hits do no + /// per-element work — an empty parts line there is the correct reading). + public string Describe(int renders, double minMs = 0.1) + { + List> snap; + lock (_gate) + { + if (_stages.Count == 0) return string.Empty; + snap = _stages.ToList(); + } + + var freq = (double)Stopwatch.Frequency; + var parts = snap + .Select(kv => (Stage: kv.Key, Ms: kv.Value / freq * 1000.0 / System.Math.Max(1, renders))) + .Where(p => p.Ms >= minMs) + .OrderByDescending(p => p.Ms) + .Select(p => $"{p.Stage} {p.Ms:F1}ms"); + return string.Join(", ", parts); + } +} diff --git a/Services/Compositor/SceneCompositor.cs b/Services/Compositor/SceneCompositor.cs index a57360c..62bd178 100644 --- a/Services/Compositor/SceneCompositor.cs +++ b/Services/Compositor/SceneCompositor.cs @@ -54,7 +54,8 @@ public sealed class SceneCompositor VideoFrame? staticBase = null, int split = -1, byte[]? scratch = null, - VideoFrame? tickerFrame = null) + VideoFrame? tickerFrame = null, + CompositeTimings? timings = null) { if (scene == null) throw new ArgumentNullException(nameof(scene)); if (frameFor == null) throw new ArgumentNullException(nameof(frameFor)); @@ -76,12 +77,15 @@ public sealed class SceneCompositor { if (staticBase.Width != cropW || staticBase.Height != cropH) throw new ArgumentException("The static base must match the source rect.", nameof(staticBase)); + var tBase = System.Diagnostics.Stopwatch.GetTimestamp(); Buffer.BlockCopy(staticBase.BgraPixels, 0, buffer, 0, buffer.Length); + timings?.Add("base", System.Diagnostics.Stopwatch.GetTimestamp() - tBase); } else { if (split < 0) split = scene.Elements.Count; + var tBackdrop = System.Diagnostics.Stopwatch.GetTimestamp(); var elements = scene.Elements; var liveCapture = elements.OfType().FirstOrDefault(s => s.IsBackground); var liveCaptureFrame = liveCapture != null && liveCapture.IsVisible ? frameFor(liveCapture) : null; @@ -149,8 +153,11 @@ public sealed class SceneCompositor if (backgroundFrame != null) BlitContent(buffer, cropW, cropH, 0, 0, cropW, cropH, backgroundFrame, 1f, false, false); - foreach (var element in elements) + timings?.Add("backdrop", System.Diagnostics.Stopwatch.GetTimestamp() - tBackdrop); + + for (var ei = 0; ei < elements.Count; ei++) { + var element = elements[ei]; if (!element.IsVisible) continue; switch (element) { @@ -162,7 +169,7 @@ public sealed class SceneCompositor } var fullFrame = frameFor(element); if (fullFrame == null) continue; - BlitBakedElement(buffer, cropW, cropH, options, element, fullFrame); + BlitBakedElement(buffer, cropW, cropH, options, element, fullFrame, timings, $"#{ei} {element.Name}"); } } @@ -181,17 +188,29 @@ public sealed class SceneCompositor } var frame = frameFor(element); if (frame == null) continue; - BlitBakedElement(buffer, cropW, cropH, options, element, frame); + BlitBakedElement(buffer, cropW, cropH, options, element, frame, timings, $"#{i} {element.Name}"); } if (flashFrame != null) + { + var tFlash = System.Diagnostics.Stopwatch.GetTimestamp(); BlitOverlay(buffer, cropW, cropH, options, flashFrame, 0, 0); + timings?.Add("flash", System.Diagnostics.Stopwatch.GetTimestamp() - tFlash); + } if (socialBarFrame != null && socialBarFrame.Width > 0 && socialBarFrame.Height > 0) + { + var tSocial = System.Diagnostics.Stopwatch.GetTimestamp(); BlitOverlay(buffer, cropW, cropH, options, socialBarFrame, 0, socialBarTop); + timings?.Add("social", System.Diagnostics.Stopwatch.GetTimestamp() - tSocial); + } if (tickerFrame != null && tickerFrame.Width > 0 && tickerFrame.Height > 0) + { + var tTicker = System.Diagnostics.Stopwatch.GetTimestamp(); BlitOverlay(buffer, cropW, cropH, options, tickerFrame, tickerFrame.OriginX, tickerFrame.OriginY); + timings?.Add("ticker", System.Diagnostics.Stopwatch.GetTimestamp() - tTicker); + } // The zoom box is layer n+1: a live 2x view of a FIXED capture window sampled // from the frame just composited (all layers). Drawn LAST — above everything. @@ -199,10 +218,17 @@ public sealed class SceneCompositor // the box; the content it shows never changes (creator ruling 2026-10-08). var zoom = scene.Elements.OfType().FirstOrDefault(z => z.IsZoomActive); if (zoom != null) + { + var tZoom = System.Diagnostics.Stopwatch.GetTimestamp(); BlitZoom(buffer, cropW, cropH, options, zoom); + timings?.Add("zoom", System.Diagnostics.Stopwatch.GetTimestamp() - tZoom); + } - return StretchMath.BilinearScale( + var tScale = System.Diagnostics.Stopwatch.GetTimestamp(); + var scaled = StretchMath.BilinearScale( new VideoFrame(cropW, cropH, buffer), options.OutputWidth, options.OutputHeight); + timings?.Add("scale", System.Diagnostics.Stopwatch.GetTimestamp() - tScale); + return scaled; } /// @@ -220,12 +246,14 @@ public sealed class SceneCompositor Func options, VideoFrame? socialBarFrame = null, int socialBarTop = 0, - VideoFrame? flashFrame = null) + VideoFrame? flashFrame = null, + CompositeTimings? timings = null) { if (split <= 0) return null; var opts = options(); if (opts.SourceRectWidth <= 0 || opts.SourceRectHeight <= 0) return null; + var tBake = System.Diagnostics.Stopwatch.GetTimestamp(); var cropW = opts.SourceRectWidth; var cropH = opts.SourceRectHeight; var buffer = new byte[cropW * cropH * 4]; @@ -250,6 +278,8 @@ public sealed class SceneCompositor BlitContent(buffer, cropW, cropH, 0, 0, cropW, cropH, backgroundFrame, 1f, false, false); } + timings?.Add("bake backdrop", System.Diagnostics.Stopwatch.GetTimestamp() - tBake); + for (var i = 0; i < split; i++) { var element = scene.Elements[i]; @@ -264,14 +294,19 @@ public sealed class SceneCompositor } var frame = frameFor(element); if (frame == null) continue; - BlitBakedElement(buffer, cropW, cropH, opts, element, frame); + BlitBakedElement(buffer, cropW, cropH, opts, element, frame, timings, $"bake #{i} {element.Name}"); } var baked = new VideoFrame(cropW, cropH, buffer); - if (flashFrame != null) - baked = Overlay(baked, opts, flashFrame, 0, 0); - if (socialBarFrame != null && socialBarFrame.Width > 0 && socialBarFrame.Height > 0) - baked = Overlay(baked, opts, socialBarFrame, 0, socialBarTop); + if (flashFrame != null || (socialBarFrame != null && socialBarFrame.Width > 0 && socialBarFrame.Height > 0)) + { + var tOverlays = System.Diagnostics.Stopwatch.GetTimestamp(); + if (flashFrame != null) + baked = Overlay(baked, opts, flashFrame, 0, 0); + if (socialBarFrame != null && socialBarFrame.Width > 0 && socialBarFrame.Height > 0) + baked = Overlay(baked, opts, socialBarFrame, 0, socialBarTop); + timings?.Add("bake overlays", System.Diagnostics.Stopwatch.GetTimestamp() - tOverlays); + } return baked; } @@ -291,7 +326,8 @@ public sealed class SceneCompositor int socialBarTop = 0, VideoFrame? flashFrame = null, byte[]? scratch = null, - VideoFrame? tickerFrame = null) + VideoFrame? tickerFrame = null, + CompositeTimings? timings = null) { var cropW = options.SourceRectWidth; var cropH = options.SourceRectHeight; @@ -299,7 +335,9 @@ public sealed class SceneCompositor var buffer = scratch != null && scratch.Length == baseFrame.BgraPixels.Length ? scratch : new byte[baseFrame.BgraPixels.Length]; + var tBase = System.Diagnostics.Stopwatch.GetTimestamp(); Buffer.BlockCopy(baseFrame.BgraPixels, 0, buffer, 0, baseFrame.BgraPixels.Length); + timings?.Add("base", System.Diagnostics.Stopwatch.GetTimestamp() - tBase); for (var i = split; i < scene.Elements.Count; i++) { @@ -315,22 +353,35 @@ public sealed class SceneCompositor } var frame = frameFor(element); if (frame == null) continue; - BlitBakedElement(buffer, cropW, cropH, options, element, frame); + BlitBakedElement(buffer, cropW, cropH, options, element, frame, timings, $"#{i} {element.Name}"); } if (tickerFrame != null && tickerFrame.Width > 0 && tickerFrame.Height > 0) + { + var tTicker = System.Diagnostics.Stopwatch.GetTimestamp(); BlitOverlay(buffer, cropW, cropH, options, tickerFrame, tickerFrame.OriginX, tickerFrame.OriginY); + timings?.Add("ticker", System.Diagnostics.Stopwatch.GetTimestamp() - tTicker); + } var zoom = scene.Elements.OfType().FirstOrDefault(z => z.IsZoomActive); if (zoom != null) + { + var tZoom = System.Diagnostics.Stopwatch.GetTimestamp(); BlitZoom(buffer, cropW, cropH, options, zoom); + timings?.Add("zoom", System.Diagnostics.Stopwatch.GetTimestamp() - tZoom); + } - return StretchMath.BilinearScale(new VideoFrame(cropW, cropH, buffer), options.OutputWidth, options.OutputHeight); + var tScale = System.Diagnostics.Stopwatch.GetTimestamp(); + var scaled = StretchMath.BilinearScale(new VideoFrame(cropW, cropH, buffer), options.OutputWidth, options.OutputHeight); + timings?.Add("scale", System.Diagnostics.Stopwatch.GetTimestamp() - tScale); + return scaled; } private static void BlitBakedElement( - byte[] buffer, int cropW, int cropH, CompositorOptions options, SceneElement element, VideoFrame frame) + byte[] buffer, int cropW, int cropH, CompositorOptions options, SceneElement element, VideoFrame frame, + CompositeTimings? timings, string stage) { + var tElement = System.Diagnostics.Stopwatch.GetTimestamp(); var ex = (float)(element.X - options.SourceRectX); var ey = (float)(element.Y - options.SourceRectY); var ew = (float)element.Width; @@ -342,9 +393,10 @@ public sealed class SceneCompositor // 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); + BlitCachedLayer(buffer, cropW, cropH, ex, ey, ew, eh, frame, element, isRound, timings, stage); if (element.HasBorder) DrawBorder(buffer, cropW, cropH, ex, ey, ew, eh, element, isRound); + timings?.Add(stage, System.Diagnostics.Stopwatch.GetTimestamp() - tElement); } /// Non-opaque layer blit through the paste cache: the element-space raster @@ -356,7 +408,8 @@ public sealed class SceneCompositor private static void BlitCachedLayer( byte[] buffer, int cropW, int cropH, float ex, float ey, float ew, float eh, - VideoFrame frame, SceneElement element, bool isRound) + VideoFrame frame, SceneElement element, bool isRound, + CompositeTimings? timings, string stage) { if (ew <= 0 || eh <= 0) return; var dw = (int)System.Math.Ceiling(ew); @@ -374,6 +427,7 @@ public sealed class SceneCompositor if (raster == null) { + var tRaster = System.Diagnostics.Stopwatch.GetTimestamp(); // Rasterize in ELEMENT space on a TRANSPARENT base: the sampler writes 255 // alpha only where it actually draws, so untouched margins (outside the // round clip, past the UniformToFill edges) stay alpha 0 and the paste @@ -398,6 +452,7 @@ public sealed class SceneCompositor _pasteCache[key!] = raster; _elementRasters[element] = raster; } + timings?.Add(stage + " raster", System.Diagnostics.Stopwatch.GetTimestamp() - tRaster); } // Paste at integer position; opacity blends. The raster is never flagged diff --git a/Services/Encoder/FramePump.cs b/Services/Encoder/FramePump.cs index 0ae353b..36772ad 100644 --- a/Services/Encoder/FramePump.cs +++ b/Services/Encoder/FramePump.cs @@ -35,6 +35,12 @@ public sealed class FramePump : IDisposable private readonly SceneGraph? _sceneGraph; private readonly SceneCompositor _compositor = new(); + /// Per-stage composite timing for the CURRENT stats window (webcam-cadence + /// unit, 2026-10-16): the compositor records each stage into this collector and + /// logs the averaged breakdown, then clears it — the + /// "which of the 6 elements eats ~140ms" reading (see the parts line). + private readonly CompositeTimings _timings = new(); + // Master-buffer scratch pool (take-4 starvation fix, slice 2 of 2): a fresh // 8.3MB byte[] every tick is ~500MB/s of LOH churn — GC stalls masquerading // as render cost. The pump pools ONLY buffers it handed out (reference-equality @@ -402,6 +408,19 @@ public sealed class FramePump : IDisposable + $"worst submit {worstSubmit / freq * 1000:F1}ms, " + $"dropped {dropped}, stalls {stalls}{cacheDetail}, {webcamCadence.Summarize().Describe("webcam")}" + (detail.Length > 0 ? " | " + detail : "")); + + // Per-stage breakdown (webcam-cadence unit, 2026-10-16): the stats line above + // says WHAT a composite cost; this says WHERE it went — one entry per stage, + // slowest first, averaged per render so the numbers compare with `avg render`. + // No entries (fully-static shortcut, or every render a C4 cache hit) means no + // per-element work happened — that IS the reading. The sub-stage + // `#i raster` is the paste-cache rasterize miss and nests in its + // element's total. + var parts = _timings.Describe(statRenders); + if (parts.Length > 0) + _log?.Invoke($"FramePump parts ({statRenders} renders/5s): {parts}"); + _timings.Reset(); + worstRender = 0; worstSubmit = 0; renderTicks = submitTicks = resolveTicks = waitTicks = 0; @@ -430,6 +449,8 @@ public sealed class FramePump : IDisposable return frame; } + Scene? lastDumpedScene = null; + try { while (!ct.IsCancellationRequested) @@ -437,6 +458,18 @@ public sealed class FramePump : IDisposable var scene = _sceneProvider(); if (scene != null) { + // Scene dump (webcam-cadence unit, 2026-10-16): the 141ms regression + // could not be compared take-to-take because the log recorded no scene + // shape at all. Dump it when the pump starts on a scene and whenever + // the active scene changes — one header line plus one line per element + // (z-index, name, kind, source type, visibility, rect, opacity, clip). + if (!ReferenceEquals(scene, lastDumpedScene)) + { + lastDumpedScene = scene; + foreach (var line in FormatSceneDump(scene, _sceneGraph?.GetSplitPoint(scene) ?? -1)) + _log?.Invoke(line); + } + var iterStart = System.Diagnostics.Stopwatch.GetTimestamp(); var compositorOptions = _compositorOptions(); VideoFrame? socialBarFrame = null; @@ -470,7 +503,7 @@ public sealed class FramePump : IDisposable sw.Restart(); var scratch = AcquireScratch(scratchSize); acquireTicks += sw.ElapsedTicks; - frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, TimedResolver); + frame = RenderScene(scene, compositorOptions, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, TimedResolver, _timings); if (_transition is { Active: true } transition) { frame = transition.BlendFrame(frame); @@ -614,13 +647,14 @@ public sealed class FramePump : IDisposable VideoFrame? tickerFrame, VideoFrame? flashFrame, byte[]? scratch = null, - Func? resolver = null) + Func? resolver = null, + CompositeTimings? timings = null) { resolver ??= _frameResolver; if (_sceneGraph == null) { var sw = System.Diagnostics.Stopwatch.StartNew(); - var frame = RenderFull(scene, options, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, resolver); + var frame = RenderFull(scene, options, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, resolver, timings); ProbeRender("full-no-graph", scene, -1, sw.ElapsedMilliseconds, 0); return frame; } @@ -630,7 +664,7 @@ public sealed class FramePump : IDisposable { // Fully static scene: bake once, reuse. var sw = System.Diagnostics.Stopwatch.StartNew(); - var baked = _sceneGraph.GetBakedBase(scene, _frameResolver, _compositorOptions); + var baked = _sceneGraph.GetBakedBase(scene, _frameResolver, _compositorOptions, timings: timings); if (baked != null) { // BUG (pre-existing, found while wiring the branding credit 2026-09-26): @@ -639,31 +673,35 @@ public sealed class FramePump : IDisposable // cached bake is not mutated and the flash still cannot get sticky in it. if (socialBarFrame != null || tickerFrame != null || flashFrame != null) { + var tOverlay = System.Diagnostics.Stopwatch.GetTimestamp(); var withOverlays = baked; if (flashFrame != null) withOverlays = SceneCompositor.Overlay(withOverlays, options, flashFrame, 0, 0); if (tickerFrame != null) withOverlays = SceneCompositor.Overlay(withOverlays, options, tickerFrame, tickerFrame.OriginX, tickerFrame.OriginY); if (socialBarFrame != null) withOverlays = SceneCompositor.Overlay(withOverlays, options, socialBarFrame, socialBarTop, 0); baked = withOverlays; + timings?.Add("overlay", System.Diagnostics.Stopwatch.GetTimestamp() - tOverlay); } + var tScale = System.Diagnostics.Stopwatch.GetTimestamp(); var stretched = StretchMath.BilinearScale(baked, options.OutputWidth, options.OutputHeight); + timings?.Add("scale", System.Diagnostics.Stopwatch.GetTimestamp() - tScale); ProbeRender("fully-static", scene, split, sw.ElapsedMilliseconds, (int)sw.ElapsedMilliseconds); return stretched; } } var swBase = System.Diagnostics.Stopwatch.StartNew(); - var baseFrame = _sceneGraph.GetBakedBase(scene, _frameResolver, _compositorOptions); + var baseFrame = _sceneGraph.GetBakedBase(scene, _frameResolver, _compositorOptions, timings: timings); if (baseFrame != null) { var frame = SceneCompositor.CompositeLayers( - baseFrame, scene, split, resolver, options, socialBarFrame, socialBarTop, flashFrame: flashFrame, tickerFrame: tickerFrame, scratch: scratch); + baseFrame, scene, split, resolver, options, socialBarFrame, socialBarTop, flashFrame: flashFrame, tickerFrame: tickerFrame, scratch: scratch, timings: timings); ProbeRender("base+layers", scene, split, swBase.ElapsedMilliseconds, 0); return frame; } // No static base (first layer is dynamic or empty scene) — full render. var swFull = System.Diagnostics.Stopwatch.StartNew(); - var frame2 = RenderFull(scene, options, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, resolver); + var frame2 = RenderFull(scene, options, socialBarFrame, socialBarTop, tickerFrame, flashFrame, scratch, resolver, timings); ProbeRender("full-render", scene, split, swFull.ElapsedMilliseconds, 0); return frame2; } @@ -676,7 +714,8 @@ public sealed class FramePump : IDisposable private VideoFrame RenderFull( Scene scene, CompositorOptions options, VideoFrame? socialBarFrame, int socialBarTop, VideoFrame? tickerFrame, VideoFrame? flashFrame, - byte[]? scratch, Func resolver) + byte[]? scratch, Func resolver, + CompositeTimings? timings = null) { // 1:1 guard: the cache stores the OUTPUT bytes and scratch is source-sized — // at 1:1 they are the same buffer size. Off-size tiers (a vertical 1080×1920 @@ -697,7 +736,7 @@ public sealed class FramePump : IDisposable return new VideoFrame(options.SourceRectWidth, options.SourceRectHeight, scratch); } - var rendered = _compositor.Render(scene, resolver, flashFrame, options, socialBarFrame, socialBarTop, scratch: scratch, tickerFrame: tickerFrame); + var rendered = _compositor.Render(scene, resolver, flashFrame, options, socialBarFrame, socialBarTop, scratch: scratch, tickerFrame: tickerFrame, timings: timings); CacheRenders++; if (useCache) { @@ -718,6 +757,33 @@ public sealed class FramePump : IDisposable return rendered; } + /// The pump's scene dump (webcam-cadence unit, 2026-10-16): one header line + /// plus one line per element, in z-order, carrying the shape two takes must be + /// compared by — index, name, kind, source type, visibility, rect in master pixels, + /// opacity, clip. is the SceneGraph split point (-1 when no + /// graph is wired: the full-render path). The 10:03 vs 12:01 regression + /// (29–34ms → 143–155ms at "the same scene shape") could not be compared because the + /// log recorded no scene at all; this is that record. + internal static string[] FormatSceneDump(Scene scene, int split) + { + var lines = new List + { + $"FramePump scene dump: '{scene.Name}' elements={scene.Elements.Count}" + + (split >= 0 ? $" split={split}" : "") + }; + for (var i = 0; i < scene.Elements.Count; i++) + { + var e = scene.Elements[i]; + var source = e is Source s + ? $" type={s.Type}{(s.IsBackground ? " background" : "")}" + : ""; + lines.Add($" [{i}] {e.Name} kind={e.Kind}{source}" + + $" vis={(e.IsVisible ? 1 : 0)} rect={e.X:F0},{e.Y:F0} {e.Width:F0}x{e.Height:F0}" + + $" op={e.Opacity:F2} clip={e.ClipShape}"); + } + return lines.ToArray(); + } + /// Hash the complete set of inputs the compositor's FULL render consumes: /// the crop/output dimensions, the social bar, and — in element order, mirroring /// SceneCompositor.Render's iteration — every element's layout/visual fields diff --git a/Services/SceneGraph.cs b/Services/SceneGraph.cs index 7a2f7be..db936a3 100644 --- a/Services/SceneGraph.cs +++ b/Services/SceneGraph.cs @@ -111,7 +111,8 @@ public sealed class SceneGraph Func options, VideoFrame? socialBarFrame = null, int socialBarTop = 0, - VideoFrame? flashFrame = null) + VideoFrame? flashFrame = null, + CompositeTimings? timings = null) { var split = GetSplitPoint(scene); if (split == 0) return null; @@ -124,7 +125,7 @@ public sealed class SceneGraph } var baked = SceneCompositor.BakeStaticBase( - scene, split, frameFor, options, socialBarFrame, socialBarTop, flashFrame); + scene, split, frameFor, options, socialBarFrame, socialBarTop, flashFrame, timings); if (baked == null) return null; lock (_gate) diff --git a/Services/index.md b/Services/index.md index cc74c2f..2cf56f3 100644 --- a/Services/index.md +++ b/Services/index.md @@ -41,7 +41,8 @@ External-facing logic: YouTube API, persistence. See | `ScreenCaptureSourceFactory.cs` | `Resolve(key)` parses `monitor:` / `window:` / `picker:` into a source; `PickAsync()` shows the OS `GraphicsCapturePicker` and returns the `picker:` key (transient — a reload falls back to auto-detection) | | `WebView2Manager.cs` | **Web-source ownership (TASK 17, composition-capture since 2026-09-14):** per registered `Source { Type: WebSource }` it owns a `CoreWebView2CompositionController` + its visual tree (`RootVisualTarget` child under a 1920×1080 root `ContainerVisual` on one `Windows.UI.Composition.Compositor` created on the UI thread via the CoreMessaging `CreateDispatcherQueueController` P/Invoke), a wrapped `WebCaptureFrameSource`, and the shared crop-sized `WriteableBitmap` preview (dispatcher-coalesced copy at Render priority, `PreviewBitmapChanged` raised only on recreation). Nav + `TransparentBackgroundScript` injection unchanged. Public ctor `(Dispatcher)`; internal seam ctor `(Dispatcher, Func?)` for hermetic tests (no WinRT). Caller: `MainViewModel.InitWebView2()` (now invoked from `MainWindow_Loaded` — the parent HWND must exist). See `../ai.md` "Slice 14" | | `WebCaptureFrameSource.cs` | The `IScreenCaptureSource` for a web session: owns the `GraphicsCaptureItem` (`CreateFromVisual`) + a free-threaded `Direct3D11CaptureFramePool` (2 buffers) + session; readback via `SoftwareBitmap.CreateCopyFromSurfaceAsync` (BGRA, **`BitmapAlphaMode.Straight`** — the compositor blends straight alpha); per-frame `FindContentBounds` alpha-bbox (internal static, unit-tested) stamps `VideoFrame.CropBounds`; ring up to 2 fresh frames + Epoch reuse; `IsOpaque=false`. Mirror of `ScreenCaptureFrameSource` | -| `Compositor/SceneCompositor.cs` | **The output compositor (TASK 4 ship step 1)**: renders a scene into the encoder's master `VideoFrame` (tightly-packed BGRA8), mirroring the XAML preview minus editing chrome — backdrop → background → elements (`UniformToFill` cover-crop, round clip, mirror, opacity, border) → branding flash → social bar (optional `socialBarFrame` + `socialBarTop` in master space, blitted last so the bar sits above the flash; the old `BlitFlash` generalized to `BlitOverlay` with source offsets). **TASK 47:** `Render` + `CompositeLayers` take a trailing `tickerFrame` blitted at (0,0) after the bar — the alert ticker is a message-scrolling dynamic overlay, never baked. Pure and WPF-free: frames injected via a `Func` resolver (webcam → DeviceId, image → AssetId, backdrop → CaptureKey); output sized by `CompositorOptions` (16:9 = full master 1:1; vertical 9:16 = 607×1080 crop → 1080×1920 bilinear). Preview stays XAML (editing view); this is the output view — see `ai.md` "Scene compositor" | +| `Compositor/SceneCompositor.cs` | **The output compositor (TASK 4 ship step 1)**: renders a scene into the encoder's master `VideoFrame` (tightly-packed BGRA8), mirroring the XAML preview minus editing chrome — backdrop → background → elements (`UniformToFill` cover-crop, round clip, mirror, opacity, border) → branding flash → social bar (optional `socialBarFrame` + `socialBarTop` in master space, blitted last so the bar sits above the flash; the old `BlitFlash` generalized to `BlitOverlay` with source offsets). **TASK 47:** `Render` + `CompositeLayers` take a trailing `tickerFrame` blitted at (0,0) after the bar — the alert ticker is a message-scrolling dynamic overlay, never baked. Pure and WPF-free: frames injected via a `Func` resolver (webcam → DeviceId, image → AssetId, backdrop → CaptureKey); output sized by `CompositorOptions` (16:9 = full master 1:1; vertical 9:16 = 607×1080 crop → 1080×1920 bilinear). Preview stays XAML (editing view); this is the output view — see `ai.md` "Scene compositor". **2026-10-16 (measurement only):** `Render`/`CompositeLayers`/`BakeStaticBase` take a trailing optional `CompositeTimings?` — every stage and every element timed (`# `, nested `raster`) and reported by the pump's parts line; zero cost for callers that pass nothing | +| `Compositor/CompositeTimings.cs` | **Per-element composite timing (2026-10-16, measurement only)**: the collector the pump owns for a stats window — `Add(stage, ticks)` accumulates, `Describe(renders, minMs = 0.1)` prints the averaged breakdown slowest-first. Stage names: `backdrop`/`base`/`flash`/`social`/`ticker`/`zoom`/`scale`/`overlay`, `bake backdrop`/`bake overlays`/`bake #i name`, and **one entry per element `# `** with the nested `raster` sub-stage (paste-cache rasterize miss) — the line that names WHICH of the six elements eats the render budget. See `ai.md` "Per-element composite timing + scene dump" | | `Compositor/CompositorOptions.cs` | The active tier's output rect (source space over the 1920×1080 master, integer-aligned — `MainViewModel.OutputRectX` can be 656.5) + target W×H | | `Compositor/StretchMath.cs` | Pure pixel math: the WPF `UniformToFill` cover-crop, clamped bilinear sample/scale (unit-tested half of the compositor) | | `Compositor/StaticPixelCache.cs` | Asset bytes → cached BGRA8 `VideoFrame`, decoded once per content hash — the output path's raw-pixel source (the preview uses ImageCache's `BitmapImage`) | @@ -57,7 +58,7 @@ External-facing logic: YouTube API, persistence. See | `Encoder/FfmpegArgs.cs` | Pure FFmpeg command-line builder: rawvideo `pipe:0` input, `anullsrc` silent audio (WASAPI replaces it), H.264+AAC, closed GOP (`-g fps×4 -keyint_min -sc_threshold 0 -bf 0`, `yuv420p`), FLV → RTMP | | `Encoder/FfmpegProgressParser.cs` | Pure parser for `frame=/fps=/size=/time=/bitrate=` stats lines → `FfmpegProgress` | | `Encoder/FfmpegEncoderPicker.cs` | Pure H.264 encoder picker from `-encoders` output: NVENC → QSV → AMF → OpenH264; **never returns libx264** (GPL) | -| `Encoder/FramePump.cs` | **TASK 4 ship step 5**: the live frame producer — while live it snapshots the active scene each tick, resolves every element to its latest frame (`Func` resolver), composites it into the tier's output frame, and paces frames into the encoder at the tier's FPS. All collaborators constructor-injected seams; free of WPF and the capture managers. `StartAsync` never throws (failures log + `Failed`); no RTMP URL = encoder skipped; `StopAsync` stops the encoder before awaiting the loop (backpressure deadlock); `ProcessFailed` self-stops. Since the bar bug-fix branch it takes an optional `socialBar: Func<(VideoFrame? Frame, SocialBarPosition Position)>?` seam — a pre-rendered bar strip composited last (above the flash) at the top edge or `SourceRectHeight − bar height`. **TASK 47:** adds an `alertTicker: Func?` ctor seam (parallel to `socialBar`), read per tick and threaded through `RenderScene`/`RenderFull` + **mixed into `BuildFullRenderSignature`** so the ticker scroll changes the cache key. See `ai.md` "Live frame pipeline" | +| `Encoder/FramePump.cs` | **TASK 4 ship step 5**: the live frame producer — while live it snapshots the active scene each tick, resolves every element to its latest frame (`Func` resolver), composites it into the tier's output frame, and paces frames into the encoder at the tier's FPS. All collaborators constructor-injected seams; free of WPF and the capture managers. `StartAsync` never throws (failures log + `Failed`); no RTMP URL = encoder skipped; `StopAsync` stops the encoder before awaiting the loop (backpressure deadlock); `ProcessFailed` self-stops. Since the bar bug-fix branch it takes an optional `socialBar: Func<(VideoFrame? Frame, SocialBarPosition Position)>?` seam — a pre-rendered bar strip composited last (above the flash) at the top edge or `SourceRectHeight − bar height`. **TASK 47:** adds an `alertTicker: Func?` ctor seam (parallel to `socialBar`), read per tick and threaded through `RenderScene`/`RenderFull` + **mixed into `BuildFullRenderSignature`** so the ticker scroll changes the cache key. See `ai.md` "Live frame pipeline". **2026-10-16:** owns a `CompositeTimings` collector, passes it through `RenderScene`/`RenderFull`/`GetBakedBase`/`CompositeLayers`, logs `FramePump parts (N renders/5s): …` (per-stage breakdown, slowest first) beside the stats line each 5s window, and dumps the scene shape — `FramePump scene dump:` header + one line per element (z-index, name, kind, type, visibility, rect, opacity, clip) — at pump start and on every scene change | | `Encoder/FfmpegLocator.cs` | The default locator: PATH probe wins, then the cache, then pull+extract (`ffmpeg.exe` **+ the `libav*.dll` family** via a staging dir, failures via `AppLog`). Pinned to BtbN `autobuild-2026-08-09-13-03` **lgpl-shared** (dynamic linking = LGPL compliance without static-relink §6 material; no GPL libx264; NVENC/QSV/AMF + libopenh264 + native AAC — see `ai.md` → Licensing). Search dirs / tools dir / downloader constructor-injected for hermetic tests. Wired into the encoder since ship step 5 | | `INotificationService.cs` | **Toast seam (TASK 24)**: `Show(title, message, AppNotificationSeverity)` + `AppNotificationSeverity { Info, Success, Warning, Error }` + `Info/Success/Warning/Error` extension methods — non-blocking user-facing messages; VMs/services raise through this so failures surface without MessageBox blocking the UI thread | | `NotificationService.cs` | The default seam impl (Notification.Wpf 11.0.0, MIT): wraps a library `NotificationManager`; routes to the in-window `NotificationArea` named `ToastArea` (MainWindow bottom-right above the footer); lifetimes via the pure `BuildRequest` mapping + `Cards` tint table — Info/Success ~4s, Warning ~8s auto-dismiss, Error sticky (`NeverExpires()` = `TimeSpan.MaxValue`, never null); dark card tints matching the health-banner language; all Show calls marshal to the captured Dispatcher. See [`../ai.md`](../ai.md) "Toast notifications" | diff --git a/TASKS.md b/TASKS.md index 6129040..4cb4f5c 100644 --- a/TASKS.md +++ b/TASKS.md @@ -171,9 +171,13 @@ second encoder path needing a "redirect". Record+simulcast is one ffmpeg with tw so the file is **88.7% duplicate frames** and that is the judder. 720p triples the bytes stretched per render on an already-over-budget path. Keep `ExclusiveControl` + 720p as a **sharpness** win and schedule it AFTER the compositor work. - - **⏭ ACTUAL NEXT: per-element composite timing + a scene dump at pump start.** One run names which - of the 6 elements eats 140ms and explains the 10:03→12:01 regression (29–34ms → 143–155ms, same - scene shape). Measurement only — no fix until it names the element. + - **✅ SHIPPED 2026-10-16 (measurement only): per-element composite timing + a scene dump.** + `CompositeTimings` + the pump's `FramePump parts (N renders/5s): …` line and + `FramePump scene dump:` block (see `ai.md` → "Per-element composite timing + scene dump"). + One integration test: `ytLive.Tests/CompositeTimingTests.cs`. **NOW WAITING ON A CREATOR TAKE + (Release):** the parts line must name which of the 6 elements eats the ~140ms and the dump must + show the shape of the slow take vs the fast one (10:03 → 12:01, 29–34ms → 143–155ms, same shape). + **No fix until a real reading names the element** — the next unit is the fix that reading dictates. - **Unit 2 (later, unchanged):** blinking amber **"SD" badge**, preview only, never in the recording/stream, when a better format was available and not obtained. Top-right corner, or the 1:30 rim point when the clip is round. diff --git a/ai.md b/ai.md index 9a702de..87dbaba 100644 --- a/ai.md +++ b/ai.md @@ -128,9 +128,15 @@ exact instruction if the folder is missing. `FFMPEG_ZIP=` reuses a pre-dow ```bash # From WSL, ALWAYS use the Windows dotnet host — never Linux `dotnet` for this project: "/mnt/c/Program Files/dotnet/dotnet.exe" build "C:\Users\gramp\Documents\Code\projects\ytLive\ytLive.csproj" -"/mnt/c/Program Files/dotnet/dotnet.exe" run +"/mnt/c/Program Files/dotnet/dotnet.exe" run -c Release # the launch command (creator, 2026-10-16): Release, not Debug — perf takes must read Release numbers ``` +**Run-mode convention (creator directive 2026-10-16):** the creator launches with `-c Release` +by DEFAULT. Debug runs happen ONLY when the AI explicitly names the Debug command for a +specific reason — never implicitly, and never for reading performance numbers (Debug pixel +paths are several × slower; every take in the 141ms saga read Debug numbers where Release is +the real reading). + **Pre-commit gate (write it down — I forgot once):** ALWAYS run `./scripts/verify.sh "" "" ...` (declared scope) before committing. It forces a **clean** build (0 warnings), the full test suite (passes only the 2 known pre-existing `[FAIL]`s), and @@ -749,9 +755,10 @@ pure pixel work in the composite, not frame lookup. Two consequences, both load- the judder measurably worse. - **The 10:01 take hit 25.6 images/s and the 12:01 take 6.8, same scene shape (`full-render split=0 elements=6 dynamic=5`), same 640×480 camera.** Composites went 29–34ms → - 143–155ms between sessions with nothing logged explaining it. **There is no per-element composite - breakdown and no scene dump at pump start**, so the log cannot name the culprit — that gap is the - next thing to close, and guessing at it is explicitly out of bounds. + 143–155ms between sessions with nothing logged explaining it. That comparison was made by EYE on + two takes because the log carried no per-element breakdown and no scene dump — both now exist + (see "Per-element composite timing + scene dump" below); naming the culprit is a reading, not a + guess, and guessing is explicitly out of bounds. **Counter subtlety, so it is not re-derived:** the pump's `webcam` line read 13/s while the file held 6.8/s. Not a bug — the counter stamps a frame when the resolver FIRST sees it, and one composite takes @@ -763,6 +770,50 @@ design. `SetMediaStreamPropertiesAsync` attempts are refused under `SharedReadOnly`, so 720p MJPG is available — but see above, it is a quality win only. +### Per-element composite timing + scene dump (UNIT 0 follow-up, 2026-10-16 — MEASUREMENT ONLY) + +The gap the cadence work left open is now closed by instrumentation, and closed by nothing else: the +141ms take was never compared to the 30ms take because **no line in the log said which element cost +what, and no line said what the scene WAS.** Both now exist. No fix has been attempted, and none is +allowed until a real reading names the culprit. + +- **`Services/Compositor/CompositeTimings.cs`** — a collector owned by the pump, threaded through + `SceneCompositor.Render` / `CompositeLayers` / `BakeStaticBase` / `BlitBakedElement` / + `BlitCachedLayer` (and `SceneGraph.GetBakedBase` → bake path) as an optional last parameter, so + every other caller (thumbnails, tests, transition preview) is untouched and costs nothing. + `Add(stage, ticks)` accumulates; `Describe(renders, minMs = 0.1)` renders the averaged breakdown + slowest-first, dropping sub-0.1ms noise. +- **Stage names** (stable, greppable): `backdrop` (prefill + live capture + background art + their + resolves), `base` (the cached-bake `BlockCopy`), `flash`, `social`, `ticker`, `zoom`, `scale`, + `overlay` (the fully-static path's per-frame overlay copies), `bake backdrop`, `bake overlays`, and + **one entry per element as `# `** — the index IS the z-order, so the log names the + layer by both position and name. Bake-pass elements are prefixed `bake #…` so a one-off rebake + cannot masquerade as a per-composite cost. +- **`# raster` nests inside its element's total** and is the paste-cache rasterize miss + (`BlitCachedLayer`'s `raster == null` branch) — the direct answer to "is one element re-sampling + every tick, or is the paste itself slow". A stage's time includes that stage's frame resolve; + `resolve` is separately totalled in the existing stats line. +- **`FramePump parts (N renders/5s): …`** — logged once per 5s window (same window as + `FramePump stats`), averaged per render so the numbers compare directly with `avg render`, then the + collector is reset. **No parts line, or a short one, is a reading too:** the fully-static shortcut + and C4 cache hits composite no elements (`cache 92R/130H` beside a missing parts line is expected). +- **`FramePump scene dump: '' elements=N split=S`** followed by one line per element + (`[i] name kind=… type=… vis=… rect=x,y WxH op=… clip=…`), logged when the pump first runs and + whenever the active scene changes. This is the record the 10:01/12:01 comparison never had. +- Gate test: `ytLive.Tests/CompositeTimingTests.cs` (one `[Fact]`) — a REAL composite of a full-canvas + element plus a 64×64 one must rank the full-canvas element first, carry the `raster` sub-stage and + the fixed stages, and the dump must name both elements with z-index/type/rect and echo the split. + +**Read takes in Release.** The creator launches `dotnet run -c Release`; Debug pixel paths are +several× slower, so a Debug number is not a reading of this pipeline (see Run). + +**Derivative check (AGENTS.md):** this is not invented — OBS's own answer to "which source is slow" is +the **Source Profiler**, which reports the *average execution time of each source's tick and render +functions* ([docs.obsproject.com → Source Profiler](https://docs.obsproject.com/reference-libobs-util-source-profiler), +per-source timers via `util/profiler.h`). Same shape here: one timer per element per composite, reported +as an average, plus the stage split. The `# raster` sub-stage is the extra this case needs — +it separates "re-sampled every tick" from "slow paste" without another session. + ### Render budget — getting a composite inside 16.67ms (UNITs 4-5, 2026-10-05) The pump emits one encoder frame per 16.67ms slot and **pads with a duplicate when a composite diff --git a/ytLive.Tests/CompositeTimingTests.cs b/ytLive.Tests/CompositeTimingTests.cs new file mode 100644 index 0000000..c8447bd --- /dev/null +++ b/ytLive.Tests/CompositeTimingTests.cs @@ -0,0 +1,70 @@ +using Xunit; +using ytLive.Models; +using ytLive.Services; +using ytLive.Services.Compositor; +using ytLive.Services.Encoder; + +namespace ytLive.Tests; + +/// +/// Per-element composite timing + the pump's scene dump (webcam-cadence unit, +/// 2026-10-16). The judder diagnosis ended with a question the log could not answer: +/// the compositor was doing 6.8 composites/s at ~141ms each, and nothing in the stats +/// line said WHICH of the scene's six elements ate the budget — only that the render +/// cost 141ms. This pins the two readings that close that gap: a real composite +/// attributes wall time per element (slowest first) with the paste-cache rasterize +/// split, and the scene dump records the shape a take was made from. +/// +public class CompositeTimingTests +{ + /// The ONE integration test for this change: a REAL SceneCompositor.Render + /// over a full-canvas element plus a small one, through the real timing collector — + /// the parts line must name both elements, sort the full-canvas one first, and carry + /// the raster sub-stage; the dump must name every element with its z-index, source + /// type and rect, and echo the split point. No 5s stats window is waited on: the + /// window logic only formats what the collector already accumulated. + [Fact] + public void Composite_Timings_Rank_The_Slowest_Element_And_The_Dump_Names_The_Scene_Shape() + { + const int w = 640, h = 480; + var scene = new Scene { Name = "Live" }; + var big = new Source { Type = SourceType.Image, Name = "FullCanvas", X = 0, Y = 0, Width = w, Height = h }; + var small = new Source { Type = SourceType.Image, Name = "TinyBadge", X = 16, Y = 16, Width = 64, Height = 64 }; + scene.Elements.Add(big); + scene.Elements.Add(small); + + var bigFrame = SceneCompositorTests.Solid(w, h, 200, 40, 40); + var smallFrame = SceneCompositorTests.Solid(64, 64, 40, 200, 40); + VideoFrame? FrameFor(SceneElement e) => ReferenceEquals(e, big) ? bigFrame : smallFrame; + + var options = new CompositorOptions + { + SourceRectX = 0, SourceRectY = 0, SourceRectWidth = w, SourceRectHeight = h, + OutputWidth = w, OutputHeight = h, + }; + + var timings = new CompositeTimings(); + new SceneCompositor().Render(scene, FrameFor, null, options, timings: timings); + + // minMs 0: a 640×480 test scene is sub-millisecond per stage, so the production + // 0.1ms floor would hide exactly the entries being asserted. + var parts = timings.Describe(1, minMs: 0); + Assert.Contains("#0 FullCanvas", parts); + Assert.Contains("#1 TinyBadge", parts); + Assert.Contains("#0 FullCanvas raster", parts); // the paste-cache rasterize miss + Assert.Contains("scale", parts); + Assert.Contains("backdrop", parts); + Assert.True( + parts.IndexOf("#0 FullCanvas", StringComparison.Ordinal) < parts.IndexOf("#1 TinyBadge", StringComparison.Ordinal), + $"the full-canvas element must rank above the 64×64 one: {parts}"); + + var dump = FramePump.FormatSceneDump(scene, split: 1); + Assert.Contains("FramePump scene dump: 'Live' elements=2 split=1", dump[0]); + Assert.Contains(dump, l => l.Contains("[0] FullCanvas") && l.Contains("type=Image") + && l.Contains("vis=1") && l.Contains("rect=0,0 640x480")); + Assert.Contains(dump, l => l.Contains("[1] TinyBadge") && l.Contains("rect=16,16 64x64")); + + // No SceneGraph wired (-1) — the dump says nothing about a split point. + Assert.DoesNotContain("split=", FramePump.FormatSceneDump(scene, split: -1)[0]); + } +}