From cdf82f688dbb56290390d0923b418753bbdd998e Mon Sep 17 00:00:00 2001 From: gramps Date: Fri, 16 Oct 2026 19:04:38 -0700 Subject: [PATCH] Read the first instrumented take: the judder did not reproduce, no element is slow MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The measurement unit existed to name which of the six scene elements eats ~140ms per composite. The creator's Release recording (ty-20261016-1841-559-0002.mp4, 174.5s, 1920x1080@60) names none of them — the whole composite costs ~1ms: composites 301 per 5s = 60/s, every slot, 0 dropped, 0 stalls after warm-up avg render 1.0-1.1ms (worst 2.5ms) = ~7% of the 16.67ms budget parts "#5 HD Pro Webcam C920 0.4ms, #5 ... raster 0.2ms, backdrop 0.2ms" - the other four elements never reach the 0.1ms print floor C4 cache 151R/150H: half the ticks were a whole-frame BlockCopy webcam 30.0/s at the resolver, longest gap 50.0ms (one 60Hz frame of sampling phase, not a drop) the FILE 29.6 distinct webcam images/s, 82% of images held exactly 2 frames, longest hold 267ms (the healthy 30fps-in-60fps signature) The two stalls are not composite cost: 124ms on the very first render (warm-up) and 53ms entering the "Chat" scene (a rebake). So the historic slow numbers are not a slow scene but different configurations: - Oct 9 19:48 (only bad take still on disk) was the VERTICAL tier: "FramePump started (1080x1920 @ 60 fps) scene='Live' comp=608x1080" - the 607x1080 centre crop upscaled to 2M px, 92 renders/5s, avg render 45.0ms, worst 278ms. - Oct 5 12:01 (141ms) logged no scene=/comp= at all - the suffix did not exist yet, so the map's "21:9 -> 1920x803" explanation stays a hypothesis, not a reading. - Every slow window shows "cache xR/0H" (the whole-frame cache never reusing) while this take shows 151R/150H, and one Oct 5 take latches mid-take (1.5ms -> 3.0ms -> 45.2ms in 15s, then stays). That latch is the lead for the next take; it is a hypothesis and the parts line is what will decide it. Corrections to the map (same commit, stale facts replaced not appended): - "It was never Debug-vs-Release" is WITHDRAWN: same 1920x1080 tier, Oct 9 = 10.4ms vs this Release take's 1.0ms, and Build carries no configuration - every pre-2026-10-16 render number is config-unknown. - The "same scene shape" 10:01/12:01 comparison is superseded: it was an eye comparison of takes whose geometry was never logged. New: scripts/webcam-cadence.py - the ground-truth probe for what the FILE holds, beside what the pump says it did. It took three wrong readings to get right (H.264 re-encoding defeats exact-pixel comparison; a round-clip crop's corners leak 60fps background; a fixed crop across a scene switch reads background), all recorded in MyMistakes.md as a recipe, including an ffmpeg-native cross-check (tblend=difference + signalstats.YAVG - the same metric, the technique already in this repo's A/V-sync recipe) which agreed: 52.2% duplicates / 28.6 distinct/s vs 50.7% / 29.6/s on different windows of the same take. Next: no fix is allowed yet - the creator makes a Release take in the failing geometry (vertical 1080p60 tier first), and that take's parts line names the stage. Docs in the same commit: ai.md (new "What the first instrumented take said" section, the two corrections, the parts-line denominators, the tool in the inventory), TASKS.md (reading outcome), HANDOFF.md (rewritten), MyMistakes.md (recipe). Gates: clean build 0 warnings, full suite 428/428, scope check passed. --- HANDOFF.md | 124 ++++++++++++++++++++---------------- MyMistakes.md | 46 +++++++++++++ TASKS.md | 12 ++++ ai.md | 69 +++++++++++++++++++- scripts/webcam-cadence.py | 131 ++++++++++++++++++++++++++++++++++++++ 5 files changed, 325 insertions(+), 57 deletions(-) create mode 100644 scripts/webcam-cadence.py diff --git a/HANDOFF.md b/HANDOFF.md index b873e2c..d22b1da 100644 --- a/HANDOFF.md +++ b/HANDOFF.md @@ -1,70 +1,86 @@ # HANDOFF — 2026-10-16 (work committed locally; NOT pushed — push at the next milestone) ## At a glance -- **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.** +- **Branch** main, tracking `origin/main`. **origin/main = `931ab46`; HEAD = the tip commit + "Read the first instrumented take: the judder did not reproduce, no element is slow"** — + **4 ahead, 0 behind** (nothing pushed this session; per the commit/push policy, push only 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 four local-only commits: `3cb29ea` (**previous session's HANDOFF refresh — the old handoff + claimed it was pushed; it never was**), `a3a4681` (per-element composite timing + scene dump), + `84cbec2` (FramePumpTests thread-safe log sink), the tip. Always check + `git log origin/main..HEAD` — never a handoff's own "0 ahead" claim. +- Working tree clean after the tip commit. +- **The creator's first take of the instrumented build happened today** (18:40–18:44, Release + recording). **The judder did NOT reproduce and no element is slow** — full reading in `ai.md` → + "✅ What the first instrumented take said". Nothing is queued to fix from it. -## 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". +## This session (2 commits — both unpushed) +1. **`84cbec2` — FramePumpTests race fix (own commit, creator-approved).** A full-suite failure + (`Stats_ReportRealRendersAndDistinctWebcamFrames…`, "Collection was modified") was a **test-side + data race**: a plain `List` enumerated by the test while the pump logged from its own + thread. Fixed with `ConcurrentBag`. **Proof: full suite 428/428 passed, 0 warnings.** + Lesson recorded in `MyMistakes.md` → "known failure label" (2nd instance). +2. **The reading (this is the tip commit).** Take `ty-20261016-1841-559-0002.mp4` (174.5s, Release + `e95154d9`, 1920×1080 1:1, recording): **60 composites/s, avg render 1.0–1.1ms, biggest element = + webcam 0.4ms**, backdrop 0.2ms, other four under the 0.1ms floor, `cache 151R/150H`, webcam 30.0/s + at the resolver (longest gap 50ms), and the FILE holds **29.6 distinct webcam images/s with 82% of + images held exactly 2 frames**. No culprit element exists in this take. + - **The historic slow numbers are different configurations:** Oct 9 19:48 (still on disk) was the + **vertical** tier (`comp=608x1080`, 45ms, 92 renders/5s); Oct 5 12:01's geometry was never logged + (the `scene=/comp=` suffix didn't exist) so the map's 21:9 story stays a hypothesis. Every slow + window shows `cache xR/0H`; one Oct 5 take latches fast→slow (1.5ms → 45ms) within 15s. + - **Corrected in the map (not appended):** "it was never Debug-vs-Release" is withdrawn (same + 1920×1080 tier: Oct 9 = 10.4ms vs today's Release 1.0ms, and `Build ` records no + configuration), and the "same scene shape" 10:01/12:01 comparison is superseded. + - **Same commit ships the probe + its recipe.** `scripts/webcam-cadence.py` (new tool): the + ground-truth check for what the FILE holds. Its three traps (H.264 re-encoding defeats + exact-pixel comparison; a round-clip crop's corners leak 60fps background; a fixed crop across a + scene switch reads background) cost three wrong readings — all in `MyMistakes.md`, with an + ffmpeg-native cross-check (`tblend=difference` + `signalstats.YAVG`) that agreed (52.2% + duplicates / 28.6 distinct/s). ## Next step -- **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. +- **Creator take in the FAILING geometry — the vertical 1080p60 tier first** (creator's pick from the + two options offered). Then, if the creator is willing, the 21:9 display config. +- Read three lines in `%APPDATA%\ytLlive\startup.log`: `FramePump parts (N renders/5s): …` (which + stage/element eats the budget), the `FramePump scene dump:` block (the shape), and `cache NR/NH` + (0 hits = the slow state's signature). **No fix until that take names the stage** — the latch + hypothesis (a composite pushed past the camera period can never reuse the whole-frame cache again) + is unproven and the `parts` line is what 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). +## Open (operational) +- **verify.sh's known-failure whitelist is too loose (confirmed twice on 2026-10-16):** it passes when + ANY known failure appears, so a new failure rides along unnoticed — and when the ONLY failure is a + known flake (`LayerReorderPersistenceTests.RealMouseDrag_OnTheLayerList_PersistsTheReorder`, which + passes in isolation) it reports "NOT the known pre-existing pair". **Follow-up: require EVERY + failure line to be whitelisted**, and add `MasterLimiter_CapsTheLiveMix_OnThePipe` + + `RealMouseDrag_OnTheLayerList_PersistsTheReorder` to the list. Not fixed here — `scripts/verify.sh` + was never in a declared file list. +- **A pre-existing stash from older work is still sitting there:** `stash@{0}` = "WIP on main: + 0464593 Compositor: fast-path opaque 1:1 when source fills canvas" (NOT this session's; do not drop + it blindly). - **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`). + capture border in the preview (`Controls/PreviewPane.xaml:319-322` + `MainViewModel.Streaming.cs` + `ApplyStreamQuality`). Root cause unknown — paused. Note the vertical tier is ALSO the only slow + take still on disk, so if the next take reproduces the 45ms there, this area gets touched twice. +- ⛔ Sudo password rotation pending (user; then update both `CREDENTIALS.md` password lines). - TASK 56 secret scan before `gramps/LlamaCasty` goes public. -- TASK 55 disk hygiene queued (`startup.log` uncapped — now 22MB and growing with the new lines). +- TASK 55 disk hygiene (`startup.log` uncapped — 23MB and the new lines add to it every 5s). ## Tests -- 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).** +- Full suite **428/428 passed, 0 warnings** (2026-10-16, the gate run for `84cbec2`) — a completely + clean run, including the audio tests that usually flake. +- Known flaky-by-environment (all pass in isolation): `AudioPipelineTests.Mix_HonorsProviderGains…`, + `MasterLimiter_CapsTheLiveMix_OnThePipe`, `LayerReorderPersistenceTests.RealMouseDrag…`, + `Round_Clip_Corner…`. **Read verify.sh's output — it can pass with an unlisted failure present, or + fail on a known flake (see above).** ## Secrets / paths (do not re-hunt) -- Layout DB: `%APPDATA%\ytLlive\ytLlive.db` (SQLite, full-rewrite per save). Auth: `%APPDATA%\ytLlive\ytLlive.auth` - (DPAPI). Startup log: `%APPDATA%\ytLlive\startup.log`. +- Layout DB: `%APPDATA%\ytLlive\ytLlive.db` (SQLite, full-rewrite per save). Auth: + `%APPDATA%\ytLlive\ytLlive.auth` (DPAPI). Startup log: `%APPDATA%\ytLlive\startup.log` (23MB). +- Recordings land in `C:\Users\gramp\Downloads\recordings\` (`ty--