Read the first instrumented take: the judder did not reproduce, no element is slow

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 <hash> 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.
This commit is contained in:
2026-10-16 19:05:01 -07:00
parent 84cbec2d19
commit cdf82f688d
5 changed files with 325 additions and 57 deletions
+70 -54
View File
@@ -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 (`#<i> <name>`, 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<string>` enumerated by the test while the pump logged from its own
thread. Fixed with `ConcurrentBag<string>`. **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 <hash>` 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 "<file1>" "<file2>" ...` (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-<date>-<time>-<ms>-<seq>.mp4`; a
duplicate name gets a `-2` suffix — the log's path and the file on disk can differ that way).
- LAN credentials: `CREDENTIALS.md` (gitignored). Google Cloud OAuth project number `198374416003`,
owned by `llamachile.shop@gmail.com` — verify at
`https://console.cloud.google.com/apis/credentials?project=198374416003`.