Per-element composite timing + scene dump (measurement only)

The cadence work ended with a question the log could not answer: the compositor
manages 6.8 composites/s at ~141ms while the 10:03 take did 29-34ms on the "same
scene shape" (full-render split=0 elements=6 dynamic=5). Nothing in the stats line
said WHICH of the six elements cost what, and nothing recorded the scene itself, so
the two takes could only be compared by eye. This closes that gap and nothing else:
no fix is attempted until a real take names the culprit.

- Services/Compositor/CompositeTimings.cs (new): per-window collector.
  Add(stage, ticks) accumulates; Describe(renders, minMs = 0.1) prints the averaged
  breakdown slowest-first, dropping sub-0.1ms noise.
- SceneCompositor.Render / CompositeLayers / BakeStaticBase / BlitBakedElement /
  BlitCachedLayer + SceneGraph.GetBakedBase: trailing optional CompositeTimings?
  Every stage is timed (backdrop, base, flash, social, ticker, zoom, scale, overlay,
  bake backdrop, bake overlays) and EVERY element gets its own entry keyed by
  z-index + name ("#2 Webcam"), with the nested "raster" sub-stage recording the
  paste-cache rasterize miss - the split between "re-samples every tick" and "slow
  paste" without a second session. Bake-pass elements are prefixed "bake #..." so a
  one-off rebake cannot masquerade as a per-composite cost. Callers that pass
  nothing (thumbnails, existing tests) are unaffected and pay nothing.
- FramePump: owns the collector, threads it through RenderScene/RenderFull/
  GetBakedBase/CompositeLayers, and logs "FramePump parts (N renders/5s): ..." once
  per 5s window beside the stats line (averaged per render, so it compares directly
  with "avg render"), then resets it. Also dumps the scene - "FramePump scene dump:"
  header plus one line per element (z-index, name, kind, source type, visibility,
  rect, opacity, clip) - at pump start and on every scene change.
- One Good Dog integration test (ytLive.Tests/CompositeTimingTests.cs): a real
  composite of a full-canvas element plus a 64x64 one through the real collector
  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 point.

Derivative work (AGENTS.md): OBS's answer to "which source is slow" is the Source
Profiler - average execution time of each source's tick and render functions
(https://docs.obsproject.com/reference-libobs-util-source-profiler, util/profiler.h).
Same shape here: one timer per element per composite, reported as an average, plus
the stage split this case needs.

Docs in the same commit: ai.md (new subsection "Per-element composite timing + scene
dump", the closed gap corrected in "Frame cadence"), Services/index.md (new file row
+ FramePump/SceneCompositor rows), TASKS.md (unit marked shipped, next = creator
take), HANDOFF.md (rewritten: unpushed commit, next step, verify.sh whitelist hole).

Also recorded this session (from the creator): the launch command is
`dotnet run -c Release` - Release is the DEFAULT, Debug only when explicitly named,
and perf takes must read Release. ai.md -> Run updated.

Full suite 428 tests, 0 warnings; the only failures are the known audio env flakes
(both pass in isolation). Scope check passed.
This commit is contained in:
2026-10-16 18:23:20 -07:00
parent 3cb29ea45c
commit a3a4681aac
9 changed files with 408 additions and 60 deletions
+55 -4
View File
@@ -128,9 +128,15 @@ exact instruction if the folder is missing. `FFMPEG_ZIP=<path>` 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 "<file1>" "<file2>" ...` (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 `#<z-index> <name>`** — 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.
- **`#<i> <name> 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: '<name>' 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 `#<i> <name> 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