diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md new file mode 100644 index 000000000..08f769604 --- /dev/null +++ b/.agents/specs/ltx25-phase-instrument.md @@ -0,0 +1,360 @@ +# `LTX25-PHASE-INSTRUMENT` — the phase table measures its own cost, and says where its residue is + +Issues: [#1668](https://github.com/mudler/vllm.cpp/issues/1668) (item 4 of four), +[#1569](https://github.com/mudler/vllm.cpp/issues/1569), +[#1571](https://github.com/mudler/vllm.cpp/issues/1571). +Record this row implements from: +[`ltx25-phase-residue.md`](ltx25-phase-residue.md). +Related and deliberately NOT closed here: +[#1439](https://github.com/mudler/vllm.cpp/issues/1439), +[#1567](https://github.com/mudler/vllm.cpp/issues/1567), +[#1568](https://github.com/mudler/vllm.cpp/issues/1568), +[#1570](https://github.com/mudler/vllm.cpp/issues/1570). + +This row has **no matrix row and therefore no lifecycle state**, for the reason +`ltx25-phase-residue.md` records for itself: the phase log is an instrument +inside the LTX-2.5 driver, and no matrix in this tree keys instruments. Its state +is the issues it closes and the tests that hold it. + +## Scope + +[`ltx25-phase-residue.md`](ltx25-phase-residue.md) is a RECORD of work that was +measured, gate-run and reviewed three times, and then closed unmerged. This row +lands the part of it that is about the INSTRUMENT rather than about the LTX-2.5 +driver, and it lands the two gaps that record filed against itself. + +IN SCOPE: + +1. **`Record::instrument_seconds` and `PhaseLog::Instrument()`** — the + instrument charging its own out-of-record wall to the innermost live non-span + record, and to the table when none is live. #1668 item 4. +2. **`WriteJson` reads its clock before it serialises**, plus the gate that + holds it. #1569, and #1668 item 4's second half. +3. **The residue decomposed into the gaps between adjacent leaves**, in the + emitted file. #1571. + +OUT OF SCOPE, and each is named because each was tempting: + +- **The three driver anchors** — `load.dit_config`, `artifacts.mux`, + `denoise.update` and `Ltx2ConditioningTrace::sampler_updates`. They are #1668 + items 1 to 3, they touch `ltx2_video.cpp` and the `Carrying` table in + `test_ltx2_video.cpp`, and #1568 and #1570 both need `denoise.update` to exist + before they can be closed. They are one unit and this is not it. They land in + the follow-on row, which is why #1668 stays open here. +- **Widening either floor.** `leaves >= 0.95 * wall` and + `covered >= min_coverage * leaf_seconds` are untouched by this row, in both + their form and their constants. +- **Any bound with `instrument_seconds` in a denominator.** See `## Design` 4. + +## Our baseline + +Everything measured here is already measured, in +[`ltx25-phase-residue.md`](ltx25-phase-residue.md) `## Our baseline`, and is not +re-derived. What that record establishes and this row builds on: + +- 92% of a 19.178 ms residue on the 64x64x9 fixture is ONE gap, the load's + prologue. The sixteen gaps between adjacent named phases hold 6.8 us each. +- The residue does NOT scale with wall — about 1 ms across walls of 0.8 s to + 4.6 s, and 0.82 to 86 ms across 10 s to 120 s. A share-based bound is therefore + worst at the SMALLEST wall. +- `residue <= 2 * instrument` was measured across three fresh reviews and + WITHDRAWN. It is not re-proposed. `## Design` 4 states what replaced it. + +What is NEW here is one measurement, and it is the one #1569 asks for: what the +copy-and-sort inside `WriteJson` costs, and how far the two clock orderings are +apart once the table is large enough for that copy and that sort to exist. It is +in `## Evidence`. + +## Design + +### 1. The instrument charges its own wall + +`PhaseLog::Open` stamps `o.start` AFTER taking the process-wide mutex, so the +mutex wait precedes the record. `PhaseLog::Close` stamps `r.end` BEFORE it emits +its progress line and erases the entry, so that tail follows the record. Both +land outside every record, and until now nothing could tell them from a phase +nobody named. + +The rule is one sentence: **every interval of the instrument's own wall is +charged to the innermost live non-span record at the moment it is spent, and to +the table when none is live.** Spans are excluded because `Sum` excludes spans, +so time inside a span but outside a leaf is exactly the residue; charging it to +the enclosing `load` or `generate` span would hide it in a number nothing adds +up. + +Ported from `refs/pull/1556/head` = `b45ea3bbb`, which measured, gate-ran and +three-times-reviewed this mechanism. The port is behaviour-identical. What is +NOT ported is that branch's `load.setup` anchor, which `519303d15` already landed +on `main` as `load.open`, and its withdrawn bound, whose constant is deleted +rather than raised. + +### 2. `WriteJson` reads its clock first + +`Sum(records, Elapsed())` after `ByStart(Records())` charges the WRITER's copy +and sort to the RENDER's wall, and therefore to `unaccounted_seconds`. The clock +read moves to the first statement of the function. + +### 3. The residue is decomposed in the file + +The leaves `Sum` adds are non-overlapping — `Open` marks a leaf `nested` +whenever another leaf is live — and `ByStart` orders them. So the complement of +their union inside `[0, wall]` is exactly `wall - sum_leaf_seconds`. The emitter +writes that complement as `gaps`: one interval before each leaf, one after the +last, each carrying the two names it lies between. + +**This is the row's best gate, and the reason is that it is not a measurement.** +The gaps add to `unaccounted_seconds` by construction. A gate over that sum is +arithmetic over numbers already in the file, so no box load can move its verdict. +Every other assertion this table has ever carried was a ratio of two wall-clock +quantities, and two of them spent three months being argued about. + +### 4. What replaces the withdrawn bound, and what does not + +**Nothing in this row puts `instrument_seconds` in a denominator.** That is the +single most important sentence here, and [`ltx25-phase-residue.md`](ltx25-phase-residue.md) +`## Design` 3 is the evidence: the un-instrumented remainder of a boundary +dilates FASTER than the instrumented part under contention, so a residue measured +against the instrument's own charge has a heavy right tail — 4 red in 45 runs at +load 88 with a maximum of 4.115, and 28 in 160 at load 125 reaching 5.55. + +`instrument_seconds` is therefore emitted and REPORTED, never asserted against. +A reader subtracts it before calling a residue a phase nobody named. The two +floors keep `wall` and `leaf_seconds` in their denominators, which is the better +conditioning: those grow with contention exactly when a preemption inflates the +numerator. + +### 5. The one new bound, and how it is derived + +#1569 needs a gate, and a gate needs a comparison. The comparison is +`head < 0.5 * serialize`, where both quantities are measured in the same run: + +- `head` is `wall_seconds` as the writer recorded it, minus the elapsed clock the + test read immediately before calling the writer. Under the correct ordering it + contains one function call and one uncontended mutex — the instrument's own + resolution. Under the mutated ordering it contains one whole copy of the record + vector and one whole `stable_sort` of it. +- `serialize` is that same copy and that same sort, performed by the test through + the same public `Records()`, on the same data, on this box, in this run. + +So the constant is not a tolerance. Under the correct order the head holds ZERO +copies and ZERO sorts; under the mutated order it holds exactly one of each and +is therefore at least `1.0 * serialize` **by the definition of the two +quantities**. Any constant strictly inside `(0, 1)` separates them. 0.5 is the +midpoint, and the measured separation is five orders of magnitude, not a factor +of two. + +**The estimator is a MINIMUM over K probes, and that is what makes this not the +withdrawn bound wearing a new name.** Contention is one-sided: it can only make +a measured interval longer. The honest head is a floor near the clock's +resolution plus a preemption that sometimes lands in it; the mutated head has a +HARD floor of one serialization, present in every iteration. A minimum over K +strips the sporadic term from the honest side and cannot strip the deterministic +term from the defective side. The withdrawn bound compared two single +measurements of comparable magnitude and the tail decided it. This compares the +minima of two populations that differ by five orders of magnitude. + +`serialize > 1e-5` guards the comparison from the other side. A table too cheap +to serialise cannot separate the two orderings at all, which is precisely why +#1569's three-record case stayed green 10 of 10 under its own mutation. A +precondition that fails loudly is the difference between a gate and a mute +switch. + +## Dependencies + +None. `LTX25-DEVICE-RESIDENCY` owns `render_phase_log.{h,cpp}`'s existence and +the `load.open` anchor; this row extends the instrument and renames nothing. + +## Risks and decisions + +**D1 — the instrument's cost is CHARGED, never subtracted globally.** A single +global subtraction is a number nobody can attribute. Charging each interval to +the innermost live non-span record keeps the attribution local and makes the +conservation invariant testable, which is what the unit cases assert. + +**D2 — a new test executable rather than a block in `test_ltx2_video`.** Two of +the four cases need a table of thousands of records, which no render produces, +and `test_ltx2_video` costs a fixture build and has been measured at 30-36 GB of +anonymous resident set. Three other issues are editing that file concurrently. +The instrument's own cases go in `tests/vllm/multimodal/test_render_phase_log.cpp`. + +**D3 — reachability stays in `test_ltx2_video`.** Every case in the new file +calls `PhaseLog` directly, which proves the class works and never that a render +reaches it — the exact failure `AGENTS.md` "Nothing lands dead" names. The +assertion that `vllm_video_generate`'s own table carries `instrument_seconds` and +a reconciling `gaps` is added to `a render through the ABI emits a phase table +that SUMS to wall`, and it is the only thing this row adds to that file. + +**D4 — a negative gap is emitted rather than clamped.** It cannot arise while +the non-overlap invariant holds, so clamping would hide a broken instrument +inside a number that still adds up. The unit case asserts it is never negative. + +**D5 — `#1668` is NOT closed by this row.** It owns four items and this row +lands one. Closing it on the strength of item 4 would lose items 1 to 3, which +is the failure #1668 was filed to prevent. + +## Tests + +`tests/vllm/multimodal/test_render_phase_log.cpp`, four cases: + +| Case | What it holds | Shape | +|---|---|---| +| the instrument charges its own cost to the innermost LEAF | attribution: a child's boundary is the parent's cost, a boundary under a bare span is the table's, a span is not a leaf | "it moved", "it did not move at all", "it is positive" — no duration compared | +| the instrument's own cost is CONSERVED across the table and its records | every charge non-negative, no record charged past its own duration, the table's share no larger than the residue it is part of | inequalities between two numbers in the same file | +| the emitted table DECOMPOSES its residue into the gaps between leaves | N leaves give N+1 gaps, each names the two leaves it lies between, none is negative, and they SUM to `unaccounted_seconds` | an accounting identity, plus one lower bound on a `sleep` | +| the emitter reads its CLOCK before it serialises the table | #1569 | `## Design` 5 | + +Plus, in `tests/vllm/multimodal/test_ltx2_video.cpp`, inside the existing ABI +render case: the emitted table carries `instrument_seconds`, carries `gaps`, and +those gaps reconcile to that render's own `unaccounted_seconds`. That is D3. + +## Gates + +`ctest --test-dir build -R 'test_render_phase_log|test_ltx2_video'`, plus +`scripts/agent-preflight.sh`. + +`main` is RED on its own baseline at `019f66c1a` — `build-test-cpu`, both +`sanitize-cpu` arms and both `windows-msvc-*` — so inheritance is established by +FAILURE TEXT rather than by job name. + +## Stop conditions + +- Do not widen either floor to close a red. Name the phase, or leave the red and + file the gap. +- Do not put `instrument_seconds` in a denominator without reading + [`ltx25-phase-residue.md`](ltx25-phase-residue.md) `## Design` 3, and never + accept a 20-run distribution as evidence about a quantity of that shape. +- Do not close #1668 from this row. D5. +- Do not close #1439. It asks for a bound on a quantity the scheduler cannot + move; the gap decomposition gives a reader that quantity and asserts an + identity over it, and neither is the budget #1439 asks for. + +## Owed + +| Issue | Owed | +|---|---| +| [#1668](https://github.com/mudler/vllm.cpp/issues/1668) | items 1 to 3, the three driver anchors and `sampler_updates`. Item 4 lands here | +| [#1570](https://github.com/mudler/vllm.cpp/issues/1570) | the bound on `instrument_seconds / duration_seconds` per record. It needs `instrument_seconds`, which this row lands, and it is worth setting on the anchors rather than on this row's synthetic scopes — a bound on `unit.child` measures nothing anybody ships | +| [#1568](https://github.com/mudler/vllm.cpp/issues/1568) | the `denoise.step` / `denoise.update` seconds transfer. `denoise.update` does not exist yet | +| [#1567](https://github.com/mudler/vllm.cpp/issues/1567) | the res_2s arm's anchor. No gate in this tree renders on that arm | +| [#1439](https://github.com/mudler/vllm.cpp/issues/1439) | NOT closed. See `## Stop conditions` | + +## Evidence + +Measured on this branch, on an x86_64 box at load average 103 to 131 -- which is +5 to 6 times its core count and is the regime the withdrawn bound failed in. +Build: `cmake -S . -B build -DVLLM_CPP_BUILD_TESTS=ON`, no `CMAKE_BUILD_TYPE`, +which is what `build-test-cpu` configures. + +### The #1569 bound, over 50 consecutive runs under real load + +The one bound this row keeps. Each run executed the ONE case and the case count +was recorded for every run, because a `-tc` filter that matches nothing prints +`0 cases ran` and `Status: SUCCESS!` and is indistinguishable from a green run. +All 50 read `test cases: 1 | 1 passed | 0 failed`. + +| quantity | min | median | p90 | max | +|---|---:|---:|---:|---:| +| `head / serialize` | 0.000716 | 0.002308 | 0.003115 | **0.004228** | +| `head` seconds | 5.02e-6 | 8.22e-6 | 1.04e-5 | 1.19e-5 | +| `serialize` seconds | 2.55e-3 | 3.26e-3 | -- | 9.65e-3 | +| box load average | 102.8 | 125.7 | -- | 131.4 | + +**0 red in 50.** The bound is 0.5, so the worst observed run had **118x** of +margin. The same case with the mutation applied -- `main`'s own clock ordering -- +measures **1.00383**, which is 237x above the honest maximum and 2.0x above the +bound. The three populations do not overlap and are not close to overlapping: + +``` +honest [0.00072 .. 0.00423] bound 0.5 defective ~1.004 +``` + +That is the shape the withdrawn bound did not have. Its honest population had a +median of 1.132 and a maximum of 4.115 against a bound of 2, so the bound sat +INSIDE the scatter and 4 runs in 45 crossed it. + +### The mutation table + +Every mutation prints its own `compile_status` and a sha256 pair, because a +mutation that fails to build and a mutation that never applied both read as a +passing test. Every one restored the tree byte-for-byte, verified by sha256, and +the first attempt at a text-reverse restore FAILED that check -- its anchor was +no longer unique once applied, because `RenderText` carries the same two lines +`WriteJson` does -- so the harness restores from a pristine byte copy instead. + +| id | mutation | verdict | +|---|---|---| +| M1 | `WriteJson` reads its clock AFTER the copy and sort, i.e. `main`'s code | RED, `head/serialize` 1.004 against 0.5 | +| M2 | the decomposition drops the FIRST gap -- the prologue, 92% of a real residue | RED on the gap count | +| M3 | the decomposition counts NESTED records as leaves | RED on all three: a negative gap, the identity, the count | +| M7 | the tail gap reported as zero, count and names untouched | RED on the identity alone | +| M8 | each gap measured to the leaf's END rather than its START | RED on the identity alone | +| M4 | every instrument interval charged to the TABLE, never to a leaf | RED on 4 assertions across 2 cases | +| M5 | a SPAN absorbs the charge, so the residue's explanation vanishes into a number `Sum` skips | RED on the span assertion | +| M6 | the per-record charge is not emitted | RED on 2 assertions across 2 cases | +| R1 | the production emitter stops writing `gaps` -- run against the RENDER case | RED at `REQUIRE(table.contains("gaps"))` | +| R2 | `ChargeLocked` charges nothing anywhere -- run against the RENDER case | RED at `REQUIRE(instrument > 0.0)` | + +R1 and R2 are the reachability half. Both were run against +`ltx2 video: a render through the ABI emits a phase table that SUMS to wall`, +which enters through `vllm_video_engine_load` and `vllm_video_generate`, so what +they prove is that a RENDER reaches this code and not that the class works. + +M3's verdict is itself a repair. On its first run the case aborted at a fatal +count `REQUIRE` placed above the loop, so the negative gap that same mutation +produces was never observed and two of the case's three assertions were unproven +while the case reddened. The count moved below the loop and became a `CHECK`. + +### What the decomposition found on its first real render + +On the 64x64x9 ABI render, at wall 21.89 s on a loaded box: a residue of +2.013 ms over 21 gaps, of which **0.944 ms -- 47% -- is charged to the +instrument itself**. That is the quantity #1439 asked to have beside the ratio, +and this is the first table that carries it. + +The largest remaining gap is **`load.dit` -> `load.video_vae`, 0.627 ms**. That +is exactly the region `load.dit_config` names, which is item 1 of #1668. The +decomposition pointed at the next un-named region on its first run, from the +emitted file, with no script -- which is the whole of what #1571 asked for. + +The load's prologue, which held 92% of this residue when #1556 measured it, no +longer appears: `519303d15` named it `load.open`. + +## Outcome + +**Closed: #1569 and #1571.** #1668 keeps items 1 to 3 and stays open. #1570, +#1568 and #1567 stay open and are recorded under `## Owed` with what each still +needs. + +What was measured, and what was rejected: + +- **`residue <= 2 * instrument` was not re-proposed.** It was not re-measured + either. `ltx25-phase-residue.md` `## Design` 3 already measured it across four + sites and hundreds of runs, and re-deriving a settled negative result is the + cost that record exists to remove. +- **The one new constant is 0.5 and it is not a tolerance.** Its derivation is + in `## Design` 5: the two orderings differ by exactly one copy and one sort, + so the defective value is at least 1.0 by definition and any constant inside + `(0, 1)` separates them. The measurement's job was to confirm the separation, + not to choose the number, and it confirmed 237x. +- **The estimator carries the argument, not the constant.** Contention is + one-sided, so a minimum over K probes strips the sporadic term from the honest + side and cannot strip the deterministic term from the defective side. A gate + whose noise is one-sided AWAY from red does not need a tail budget. +- **`serialize > 1e-5` is a precondition and not decoration.** #1569 exists + because a three-record table made the two orderings indistinguishable, and a + gate that silently loses its discriminator is a mute switch. Measured + headroom on this tree: 255x. +- **The gap decomposition is arithmetic, not a measurement.** That is why it is + the strongest thing in this row. Five of the ten mutations above are caught by + a comparison with no clock in it. + +What a reader should NOT conclude: that either floor is now honest at 21 B +scale. `leaves >= 0.95 * wall` still decides by box load at small wall and still +permits minutes of un-named time at large wall. This row gives a reader the +quantity that would settle it -- the residue, split by region, with the +instrument's own share subtracted -- and asserts an identity over it. #1439 +stays open because a quantity a reader can see is not yet a budget a gate holds. + +## Now + +Landed. #1569 and #1571 closed; #1668 keeps items 1 to 3. diff --git a/.agents/specs/ltx25-phase-residue.md b/.agents/specs/ltx25-phase-residue.md index e83e3535e..aec31fd1b 100644 --- a/.agents/specs/ltx25-phase-residue.md +++ b/.agents/specs/ltx25-phase-residue.md @@ -231,9 +231,9 @@ once, at `tests/vllm/multimodal/test_ltx2_video.cpp:4325`, asking for it. | [#1668](https://github.com/mudler/vllm.cpp/issues/1668) | **the three anchors and the instrument self-cost, as one implementable unit.** `load.dit_config`, `artifacts.mux`, `denoise.update` plus `Ltx2ConditioningTrace::sampler_updates`, and `Record::instrument_seconds` with its conservation invariant. The reference implementation, the gate report and the mutation table stay readable at `refs/pull/1556/head` = `b45ea3bbb` | | [#1567](https://github.com/mudler/vllm.cpp/issues/1567) | the res_2s arm's `denoise.update` anchor. `Ltx2Res2sDenoisingLoop` runs its own post-process and step behind `Ltx2Res2sHooks`, so the anchor needs a hook rather than a statement. It lives in `ltx2_samplers.cpp`, is declared in `ltx2_samplers.h` beside the hooks struct, and is called from `ltx2_video.cpp`. **NOT `ltx2_res2s.cpp`**: #1556's spec named that file and it has never existed here, which `git log --all --diff-filter=A` confirms; #1567's forge text names no file at all, so the wrong anchor came from the spec rather than from the issue. No gate in this tree renders on that arm, so landing it beside the first-order arm would land dead code | | [#1568](https://github.com/mudler/vllm.cpp/issues/1568) | the `denoise.step` / `denoise.update` seconds transfer. (1b') compares `start_seconds` only, so leaving `denoise.step` open across the post-process and emitting `denoise.update` empty after it preserves the alternation, both counters, containment, non-overlap, exclusivity, (1c) and (2), while moving 100% of the decomposed seconds onto one name. No (2b) floor separates it: the honest share of `denoise.update` runs 0.45% to 11.15% across four boxes and a transfer puts it at ~0%. Closing it needs an anchor INSIDE the callee | -| [#1569](https://github.com/mudler/vllm.cpp/issues/1569) | a gate on `WriteJson`'s clock ORDERING, **measured green under its own mutation**. Restoring the old order left the conservation case GREEN 10 of 10, at `wall 0.0608987s, unaccounted 0.000534223s, table charge 0.000301655s`, because the copy and sort of a three-record table are nanoseconds. Gating it needs a table with enough records for the sort to be measurable | +| [#1569](https://github.com/mudler/vllm.cpp/issues/1569) | **CLOSED by `LTX25-PHASE-INSTRUMENT`** ([`ltx25-phase-instrument.md`](ltx25-phase-instrument.md)), which gates it over a 4000-record table where the copy and the sort are a measurable event, against a discriminator measured in the same run rather than written down as a constant. Restoring the old order now reds it at a ratio of 1.004 against a 50-run honest maximum of 0.0042 under load 103-131. What it originally owed: a gate on `WriteJson`'s clock ORDERING, **measured green under its own mutation**. Restoring the old order left the conservation case GREEN 10 of 10, at `wall 0.0608987s, unaccounted 0.000534223s, table charge 0.000301655s`, because the copy and sort of a three-record table are nanoseconds. Gating it needs a table with enough records for the sort to be measurable | | [#1570](https://github.com/mudler/vllm.cpp/issues/1570) | an upper bound on the instrument's own share of a leaf. `uncovered <= 2 * leaf_instrument` is stricter than the floor it replaces only while `leaf_instrument` stays small, and nothing bounds it. Moving the DiT `Tick` out of `Evaluate` would charge ~110 flushed writes to `denoise` and widen the gate while printing a small number | -| [#1571](https://github.com/mudler/vllm.cpp/issues/1571) | a per-gap decomposition IN the emitted table. The 92% region above was found with a scratch script; a reader of `phase-log.json` still cannot see it without one, and the same investigation will be re-derived the next time the residue moves | +| [#1571](https://github.com/mudler/vllm.cpp/issues/1571) | **CLOSED by `LTX25-PHASE-INSTRUMENT`** ([`ltx25-phase-instrument.md`](ltx25-phase-instrument.md)). `phase-log.json` carries `gaps`, and the gate over it is an accounting identity rather than a tolerance: the gaps add to `unaccounted_seconds` by construction. On the fixture render it immediately named the NEXT region, `load.dit` -> `load.video_vae` at 0.627 ms, which is the `load.dit_config` anchor #1668 owes. What it originally owed: a per-gap decomposition IN the emitted table. The 92% region above was found with a scratch script; a reader of `phase-log.json` still cannot see it without one, and the same investigation will be re-derived the next time the residue moves | | [#1572](https://github.com/mudler/vllm.cpp/issues/1572) | assertion (1c)'s span slack reds intermittently on `main` — `decode.video` at `0.00256913` against a `0.00075` bound, 3.4x. Pre-existing from `6b48edb2c` and not this row's | | [#1619](https://github.com/mudler/vllm.cpp/issues/1619) | **the `merge=union` driver duplicates a row, MEASURED on this row's own merges.** Both sides appended before the same trailing anchor rather than at the true end, so the driver concatenated two regions that each carried `#1546` and the resolved index held it TWICE, byte-identical, at 538 lines where the correct union is 537. `git merge-tree` called that merge clean and `check-issue-index-append-only.py` passed it, because a duplicate is an ADDITION and that checker only collects removals. `check-agent-record.py` did NOT pass it -- a claim #1556's spec made and this row REFUTED by reproduction: regenerating the raw driver output and running that same tree's checker returns rc=1 with `issue #1546 listed twice`, and the refusal has existed since `8dd6508da` (2026-08-09), before the merge. So the blind gate is exactly one checker, not two, and the gap is narrower than #1556 recorded. The de-duplication half is CONDITIONAL, and the condition is what #1556's spec omitted: the checker reds a repair only when the DUPLICATE IS ALREADY IN THE BASE. Measured at three pairings -- `--base e2a9e035d` against the real canonical 537-line file rc=0, against a synthetic 537 rc=0, and `--base --head <537 de-dup>` rc=1. It diffs `merge-base..HEAD`, so when the base predates the duplicate the addition and the removal CANCEL and it passes. Since `origin/main` is preflight's base, and is the shape this branch used, the gate does NOT red someone who repairs driver output before committing it -- only someone repairing a corruption that already landed. The same range property is why relocating a base-reachable row DOES red it: moving row `#168` to the end gives rc=1 and a `removed:` line naming it. So "de-duplicating in place FAILS the checker", as #1556's spec put it, is false unqualified and true once the duplicate is base-reachable. #1556's spec added that the same driver dropped `#838` on a later re-merge, making this a recurring class; that is WITHDRAWN as unreproducible. Re-running `git merge-file --union` at every later merge where `#838` was on a side leaves it present in all of them, and `git log -S` finds it absent from no committed state -- mechanically a union driver cannot drop a line that is an addition on one side. If it ever went missing, that points at a wholesale take-ours resolution rather than at the driver | | [#1439](https://github.com/mudler/vllm.cpp/issues/1439) | **NOT closed by this row, and it must not be.** See `## Risks and decisions` D4 | diff --git a/docs/models/ltx-2-5.md b/docs/models/ltx-2-5.md index 70480802e..908ab7689 100644 --- a/docs/models/ltx-2-5.md +++ b/docs/models/ltx-2-5.md @@ -242,6 +242,18 @@ Use `sum_leaf_seconds` for the accounted total. `unaccounted_seconds` reports time outside named phases. The file labels itself as diagnostic output, not a benchmark. +`gaps` says WHERE that un-named time is. It holds one interval before each named +leaf and one after the last, each carrying the two names it lies between, and +they add to `unaccounted_seconds` exactly. Sort it and read the top entry: the +largest gap is the next region worth naming. `` and `` are the ends +of the timeline. + +`instrument_seconds` says how much of the residue the instrument itself spent — +the mutex wait before a phase starts, and the flushed progress line after it +ends. Subtract it before calling what is left a phase nobody named. Every record +carries its own `instrument_seconds` too, which is what that phase paid for the +boundaries of its own sub-scopes. + Set `VLLM_RENDER_PHASE_LOG_STDERR=1` to print the phase table. Set `VLLM_RENDER_PHASE_SAMPLER=0` to disable the 100 ms memory sampler. The normal `[render]` lines print phase boundaries and DiT-forward progress. diff --git a/include/vllm/multimodal/render_phase_log.h b/include/vllm/multimodal/render_phase_log.h index aa0c553fc..c3a64f554 100644 --- a/include/vllm/multimodal/render_phase_log.h +++ b/include/vllm/multimodal/render_phase_log.h @@ -62,6 +62,12 @@ struct Record { int64_t peak_device_bytes = -1; // -1 => no device probe was installed on this arm bool span = false; // printed for context, never summed bool nested = false; // opened while another leaf was open; excluded from the sum + // HOW MUCH OF THIS RECORD'S OWN DURATION THE INSTRUMENT SPENT, outside every + // child of it. Row LTX25-PHASE-INSTRUMENT, issue #1668. See the note on + // `PhaseLog::Instrument` below: this is the number that separates "a phase + // nobody named" from "the cost of naming the phases", and until it existed + // nothing could tell the two apart. + double instrument_seconds = 0.0; }; // Resident set size in bytes, or -1 where the platform publishes none. @@ -120,6 +126,34 @@ class PhaseLog { std::vector Records() const; int64_t Samples() const; + // ── WHAT THE INSTRUMENT ITSELF COST (row LTX25-PHASE-INSTRUMENT, #1668) ─── + // + // The wall this instrument spent inside its own entry points while NO leaf + // was live — the process-wide mutex wait before `Open` stamps a start, the + // flushed progress line and the vector erase after `Close` stamps an end. It + // is therefore the part of `unaccounted_seconds` this instrument produced + // rather than the render. + // + // WHY IT IS PUBLIC AND NOT A DETAIL. Until it existed, a reader of the table + // — and every gate over it — could only compare the residue against a SHARE + // of the render's wall, and a share is a property of the fixture rather than + // of the code: [#1439](https://github.com/mudler/vllm.cpp/issues/1439) + // measured the same 95% floor deciding by box load at 64x64x9, while the same + // residue would be invisible on the 21 B render this instrument exists for. + // The per-record half is `Record::instrument_seconds`, and the two partition + // every interval this instrument spends: whatever a live leaf does not + // absorb is charged here. + // + // IT IS NOT A BUDGET, AND THAT IS A DECISION WITH EVIDENCE BEHIND IT. The + // obvious use — `residue <= 2 * instrument`, a scale-free replacement for the + // two wall-clock ratios — was measured over hundreds of runs and WITHDRAWN: + // the un-instrumented remainder of a boundary dilates FASTER than the + // instrumented part under contention, so that comparison has a heavy right + // tail (4 red in 45 runs at load 88, max 4.115). It is recorded in + // `.agents/specs/ltx25-phase-residue.md` `## Design` 3. Read that before + // putting this quantity in a denominator. + double Instrument() const; + // Write the table as JSON. Returns false with *why set on an IO failure — a // render must not fail because its instrument could not write. bool WriteJson(const std::string& path, const std::string& family, diff --git a/src/vllm/multimodal/render_phase_log.cpp b/src/vllm/multimodal/render_phase_log.cpp index fab62f6ec..d77a8e4aa 100644 --- a/src/vllm/multimodal/render_phase_log.cpp +++ b/src/vllm/multimodal/render_phase_log.cpp @@ -97,6 +97,8 @@ struct PhaseLog::Impl { // adding it to the sum would make the residue negative rather than visible. struct Open { size_t handle = 0; + // THE INSTRUMENT'S OWN WALL, charged to this record. See `ChargeLocked`. + double instrument = 0.0; std::string name; int64_t render = 0; double start = 0.0; @@ -112,6 +114,10 @@ struct PhaseLog::Impl { int64_t render = 0; size_t next_handle = 1; int64_t samples = 0; + // The instrument's own wall that no LEAF absorbed, i.e. the part of + // `unaccounted_seconds` this instrument spent rather than the render. See + // `ChargeLocked`. + double instrument_gap = 0.0; std::vector open; // Per-unit tick clock for the live lane, so `last=` is the interval between // two occurrences of the SAME unit rather than since any other line. @@ -145,9 +151,65 @@ struct PhaseLog::Impl { std::fflush(stderr); } + // ── THE INSTRUMENT'S OWN WALL (row LTX25-PHASE-INSTRUMENT, #1668) ───────── + // + // WHY THIS EXISTS. `unaccounted_seconds` and the uncovered part of a leaf both + // contain a term this instrument creates and never reported: the wall it + // spends inside its own entry points while no record — or no CHILD of the + // record — is open. `Open` stamps `start` after taking this mutex, so the + // mutex wait is before the new record begins; `Close` stamps `end` before it + // prints its progress line and erases the entry, so that tail is after the + // record ends. Both land outside every record, and until this row nothing + // could tell them from a phase nobody named. Two gates were comparing that + // mixture against a share of the render's wall, which is why both decided by + // box load at fixture scale (#1439, #1494, #1470, #1536). + // + // THE RULE IS ONE SENTENCE: every interval of the instrument's own wall is + // charged to the innermost live NON-SPAN record at the moment it is spent, and + // to the table when none is live. A span is excluded because `Sum` excludes + // spans, so time inside a span but outside a leaf is exactly the residue — + // charging it to the enclosing `load` or `generate` span would hide it in a + // number nothing adds up. + // + // "INNERMOST" IS THE LAST LIVE NON-SPAN ENTRY, because `open` is pushed in + // open order: a nested sub-scope is appended after the leaf that contains it. + // Caller holds `mu`. + void ChargeLocked(double from, double to) { + // A NEGATIVE `from` IS REFUSED RATHER THAN CLAMPED, and the polarity is the + // reason. `Open` reads its clock BEFORE it takes this mutex, so a `Begin` on + // another thread between those two points moves the origin under it and the + // offset comes out negative. Clamping to zero would then charge the whole + // timeline so far, and a charge that grows LOOSENS every bound that has this + // quantity in a denominator — a defect that makes a gate pass is the one + // nobody finds. The interval is not attributable to this timeline, so it is + // dropped. + if (from < 0.0) return; + if (!(to > from)) return; + for (size_t i = open.size(); i > 0; --i) { + Open& o = open[i - 1]; + if (!o.live || o.span) continue; + o.instrument += to - from; + return; + } + instrument_gap += to - from; + } + // Caller holds `mu`. Reads both counters once and folds them into every open // scope, so a nested span sees the peak its children reached. + // + // IT CHARGES ITSELF. A sample is taken at every boundary, by the 100 ms + // worker, and by hand from inside the denoise loop; the last two land inside + // the innermost record and outside its children, which is uncovered time this + // instrument produced. `Open` and `Close` call it with the record they are + // opening or closing already innermost, so those two charge to themselves and + // the charge is inside that record's own duration. void SampleLocked() { + const double entered = running ? Now() : 0.0; + SampleUnchargedLocked(); + if (running) ChargeLocked(entered, Now()); + } + + void SampleUnchargedLocked() { const int64_t host = HostResidentBytes(); int64_t device = -1; if (device_probe) { @@ -238,6 +300,7 @@ void PhaseLog::Begin() { impl_->running = true; impl_->render = 0; impl_->samples = 0; + impl_->instrument_gap = 0.0; impl_->device_probe = DeviceByteProbe(); } @@ -265,7 +328,14 @@ double PhaseLog::Elapsed() const { } size_t PhaseLog::Open(const std::string& name, bool span) { + // THE HEAD OF THE BOUNDARY, taken before the process-wide mutex. Everything + // between here and `o.start` below — the lock wait, which the 100 ms worker + // can hold, and the sampler start — is wall this instrument spends BEFORE the + // new record begins, so it lands in the gap before it. Row + // LTX25-PHASE-INSTRUMENT charges it to whatever encloses that gap. + const std::chrono::steady_clock::time_point entered = std::chrono::steady_clock::now(); std::lock_guard lock(impl_->mu); + const bool was_running = impl_->running; if (!impl_->running) { impl_->origin = std::chrono::steady_clock::now(); impl_->running = true; @@ -285,8 +355,22 @@ size_t PhaseLog::Open(const std::string& name, bool span) { o.nested = leaf_already_open && !span; const double opened_at = o.start; const std::string opened_name = o.name; + // Charged BEFORE the new entry is pushed, so `ChargeLocked` resolves the + // innermost live leaf to this record's PARENT — which is where the head of + // this boundary was actually spent. Skipped when this `Open` started the + // timeline, because then the origin IS `o.start` and there is no gap. + if (was_running) { + impl_->ChargeLocked( + std::chrono::duration(entered - impl_->origin).count(), opened_at); + } impl_->open.push_back(std::move(o)); impl_->SampleLocked(); + // THE TAIL OF THIS BOUNDARY. Everything from here to the return runs INSIDE + // the record just opened and BEFORE any child of it, so it is uncovered time + // this instrument produced — the same quantity `Close`'s tail is, on the other + // side of the boundary. `SampleLocked` above charges itself; the flushed + // progress line below is the most expensive statement in the function. + const double after_sample = impl_->Now(); // W0-live (#1413): the OPEN line, which is the load-bearing half. It means the // last line printed names the phase that is CURRENTLY RUNNING, and that is the // whole difference between a working render and a hung one. A close-only @@ -298,6 +382,10 @@ size_t PhaseLog::Open(const std::string& name, bool span) { opened_at); impl_->EmitLocked(text); } + // Charged to the record just opened, which `ChargeLocked` resolves as the + // innermost live leaf. It is inside that record's own duration and outside + // every child of it, which is exactly where the coverage bound looks. + impl_->ChargeLocked(after_sample, impl_->Now()); return impl_->open.back().handle; } @@ -312,9 +400,19 @@ void PhaseLog::Close(size_t handle) { // and the `generate` span each stay open across everything beneath them, so // the scope stack is empty only BETWEEN a load and a generation. std::thread victim; + // The clock at the end of the locked block, kept so the sampler JOIN below can + // be charged too. See the note beside it. + double left_lock_at = -1.0; { std::lock_guard lock(impl_->mu); impl_->SampleLocked(); + // WHERE THIS RECORD ENDED, kept outside the loop so the TAIL of the boundary + // can be charged after the entry is erased. Row LTX25-PHASE-INSTRUMENT: the + // progress line, the record push and the vector erase all run after `r.end` + // is stamped, so they are wall this instrument spends AFTER the record ends + // and they land in the gap after it. Erasing first is what makes + // `ChargeLocked` resolve the innermost live leaf to this record's PARENT. + double closed_at = -1.0; for (size_t i = 0; i < impl_->open.size(); ++i) { Impl::Open& o = impl_->open[i]; if (o.handle != handle || !o.live) continue; @@ -323,10 +421,12 @@ void PhaseLog::Close(size_t handle) { r.render = o.render; r.start = o.start; r.end = impl_->Now(); + closed_at = r.end; r.peak_host_bytes = o.peak_host; r.peak_device_bytes = o.peak_device; r.span = o.span; r.nested = o.nested; + r.instrument_seconds = o.instrument; // W0-live (#1413): what the phase COST, on the line, at the moment it ends. // A reader of a killed run's log takes every completed phase's duration off // this without waiting for a table that will never be written. @@ -351,10 +451,25 @@ void PhaseLog::Close(size_t handle) { break; } if (!impl_->AnythingLive()) victim = impl_->TakeSamplerLocked(); + if (closed_at >= 0.0) { + left_lock_at = impl_->Now(); + impl_->ChargeLocked(closed_at, left_lock_at); + } } if (victim.joinable()) { impl_->stop_cv.notify_all(); victim.join(); + // AND THE JOIN IS CHARGED TOO, which costs a second lock acquisition and is + // worth it. This is the LAST close of a timeline, so nothing is live and the + // whole notify-and-join lands in `unaccounted_seconds` — uncharged, it reads + // as time nobody named. Measured at about 117 us per join on a contended x86 + // box against a residue of 346 us: leaving it out made a two-scope timeline + // whose gaps contain NOTHING report a residue three times the instrument's + // own charge, which is exactly the reading a real un-named phase produces. + // The LTX-2.5 driver pays it twice per process, once when the `load` span + // closes and once when `generate` does. + std::lock_guard lock(impl_->mu); + if (left_lock_at >= 0.0 && impl_->running) impl_->ChargeLocked(left_lock_at, impl_->Now()); } } @@ -365,7 +480,15 @@ void PhaseLog::Sample() { void PhaseLog::Tick(const std::string& unit, int64_t index, const std::string& detail) { if (!ProgressEnabled()) return; + // Charged like a boundary (row LTX25-PHASE-INSTRUMENT): a tick is a held + // global lock plus a FLUSHED `fwrite`, it runs ~110 times per render from + // inside the denoise loop, and it lands inside the innermost record and + // outside its children — i.e. it is uncovered time this instrument produced. + const std::chrono::steady_clock::time_point entered = std::chrono::steady_clock::now(); std::lock_guard lock(impl_->mu); + const bool charge = impl_->running; + const double entered_at = + charge ? std::chrono::duration(entered - impl_->origin).count() : 0.0; // A tick before any scope opened starts the timeline, exactly as `Open` does. // Returning silently instead would make the first unit of work of a render // that took no scope disappear, which is the failure this lane exists to stop. @@ -391,6 +514,7 @@ void PhaseLog::Tick(const std::string& unit, int64_t index, const std::string& d } impl_->last_tick[unit] = now; impl_->EmitLocked(text); + if (charge) impl_->ChargeLocked(entered_at, impl_->Now()); } std::vector PhaseLog::Records() const { @@ -398,6 +522,11 @@ std::vector PhaseLog::Records() const { return impl_->records; } +double PhaseLog::Instrument() const { + std::lock_guard lock(impl_->mu); + return impl_->instrument_gap; +} + int64_t PhaseLog::Samples() const { std::lock_guard lock(impl_->mu); return impl_->samples; @@ -412,6 +541,7 @@ void PhaseLog::Reset() { impl_->running = false; impl_->render = 0; impl_->samples = 0; + impl_->instrument_gap = 0.0; impl_->device_probe = DeviceByteProbe(); } @@ -450,12 +580,75 @@ Totals Sum(const std::vector& records, double wall) { return t; } +// ── WHERE THE RESIDUE ACTUALLY IS (row LTX25-PHASE-INSTRUMENT, #1571) ─────── +// +// WHY THIS IS IN THE FILE AND NOT IN A SCRIPT. `unaccounted_seconds` shipped as +// an AGGREGATE, and four issues -- #1439, #1470, #1494, #1536 -- argued about +// whether its 95% floor was the right tolerance without anyone splitting it into +// the gaps between consecutive leaves. Splitting it took ONE pass over the table +// the render already writes and settled the question immediately: 92% of the +// residue was a single gap, the load's prologue from the timeline's origin to +// `Open("load.dit")`, 17.661 ms of 19.178 ms, while the sixteen gaps between +// adjacent named phases held 6.8 us each. That pass was a scratch script that +// was never shipped, so a reader of `phase-log.json` still could not see it and +// the same investigation would be re-derived the next time the residue moved. +// +// IT IS ALSO AN ACCOUNTING IDENTITY, which is the half a gate can hold. `Sum` +// adds the records with `span == false && nested == false`, and `Open` marks a +// leaf `nested` whenever another leaf is already live, so those records are +// non-overlapping and -- after `ByStart` -- ordered. The complement of their +// union inside `[0, wall]` is therefore exactly `wall - sum_leaf_seconds`, which +// is `unaccounted_seconds`. The gaps below add to it by construction rather than +// by tolerance, so a gate over that sum is arithmetic and cannot move with box +// load. That is the difference between this and every bound this table has +// carried. +// +// A NEGATIVE GAP IS EMITTED RATHER THAN CLAMPED. It cannot arise while the +// non-overlap invariant above holds, so clamping it would hide a broken +// instrument inside a number that still adds up. +nlohmann::json GapsBetweenLeaves(const std::vector& records, double wall) { + nlohmann::json gaps = nlohmann::json::array(); + double cursor = 0.0; + std::string previous = ""; + for (const Record& r : records) { + if (r.span || r.nested) continue; + nlohmann::json g; + g["after"] = previous; + g["before"] = r.name; + g["start_seconds"] = cursor; + g["end_seconds"] = r.start; + g["seconds"] = r.start - cursor; + gaps.push_back(std::move(g)); + cursor = r.end; + previous = r.name; + } + nlohmann::json tail; + tail["after"] = previous; + tail["before"] = ""; + tail["start_seconds"] = cursor; + tail["end_seconds"] = wall; + tail["seconds"] = wall - cursor; + gaps.push_back(std::move(tail)); + return gaps; +} + } // namespace bool PhaseLog::WriteJson(const std::string& path, const std::string& family, const std::string& device, std::string* why) const { + // THE CLOCK IS READ FIRST, AND THE ORDER IS THE WHOLE CONTENT OF THIS LINE. + // `Records()` copies the record vector under the process-wide mutex and + // `ByStart` stable-sorts the copy. Reading `Elapsed()` after them charged this + // WRITER's own serialization to the RENDER's wall, and therefore to + // `unaccounted_seconds` — a residue the render did not produce. This table + // measures the render, so the writer's clock stops before the writer works. + // Row LTX25-PHASE-INSTRUMENT, issue #1569: the gate that holds this ordering + // is `the emitter reads its clock BEFORE it serialises the table` in + // `tests/vllm/multimodal/test_render_phase_log.cpp`, and it needs a table of + // thousands of records to see the difference at all. + const double wall = Elapsed(); const std::vector records = ByStart(Records()); - const Totals totals = Sum(records, Elapsed()); + const Totals totals = Sum(records, wall); nlohmann::json out; out["schema"] = "vllm.cpp render phase log v1"; @@ -464,6 +657,14 @@ bool PhaseLog::WriteJson(const std::string& path, const std::string& family, out["wall_seconds"] = totals.wall; out["sum_leaf_seconds"] = totals.leaves; out["unaccounted_seconds"] = totals.unaccounted; + // HOW MUCH OF `unaccounted_seconds` THIS INSTRUMENT SPENT (row + // LTX25-PHASE-INSTRUMENT, #1668). Without it the residue can only be compared + // against a SHARE of the render's wall, and that share is a property of the + // fixture: #1439 measured a 95% floor deciding by box load at 64x64x9 while + // the same residue is invisible on the 21 B render this table exists for. With + // it, a reader subtracts the cost of naming the phases before calling what is + // left a phase nobody named. + out["instrument_seconds"] = Instrument(); out["host_bytes_source"] = #if defined(__linux__) "/proc/self/statm"; @@ -516,9 +717,22 @@ bool PhaseLog::WriteJson(const std::string& path, const std::string& family, e["peak_device_bytes"] = r.peak_device_bytes; e["span"] = r.span; e["nested"] = r.nested; + // The other half of `instrument_seconds` above: how much of THIS record's + // own duration the instrument spent, outside every child of it. It is what + // separates "this leaf encloses a phase nobody named" from "this leaf paid + // for its own sub-scope boundaries" — a distinction the coverage gate had no + // way to make (#1494). + e["instrument_seconds"] = r.instrument_seconds; phases.push_back(std::move(e)); } out["phases"] = std::move(phases); + out["gaps"] = GapsBetweenLeaves(records, totals.wall); + out["gap_rule"] = + "gaps decomposes unaccounted_seconds. The leaves that sum_leaf_seconds adds are " + "non-overlapping and start-ordered, so the complement of their union inside " + "[0, wall_seconds] is exactly the residue: there is one gap before each leaf and one " + "after the last, and their seconds add to unaccounted_seconds. `after` and `before` " + "name the leaves a gap lies between; and are the ends of the timeline."; // THE CONSOLE COPY GOES FIRST, and the order is the whole point of it. // diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index a744167a9..a35fd28ea 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -284,6 +284,14 @@ target_include_directories(test_video_engine PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/vllm/models) target_compile_definitions(test_video_engine PRIVATE MINIMAX_H3_VIDEO_FOLD_FIXTURE_DIR="${CMAKE_SOURCE_DIR}/tests/vllm/models/fixtures/minimax_h3_video_fold") +# The render phase INSTRUMENT, on its own, over synthetic timelines (row +# LTX25-PHASE-INSTRUMENT, #1668/#1569/#1571). Its own executable rather than a +# block inside `test_ltx2_video`, because two of its cases need a table of +# thousands of records that no render produces, and because an instrument +# question should not cost a model fixture build. The reachability half — that a +# render through the ABI actually emits what these cases pin — stays in +# `test_ltx2_video`, which is the only place that can prove it. +vllm_cpp_add_test(test_render_phase_log vllm/multimodal/test_render_phase_log.cpp) # LTX-2.5 L7: the family behind the VideoEngine seam and the driving loop, run # over a reduced-dimension checkpoint set written in the SHIPPED file format. vllm_cpp_add_test(test_ltx2_video vllm/multimodal/test_ltx2_video.cpp) diff --git a/tests/vllm/multimodal/test_ltx2_video.cpp b/tests/vllm/multimodal/test_ltx2_video.cpp index 9443c00c2..29b27cef4 100644 --- a/tests/vllm/multimodal/test_ltx2_video.cpp +++ b/tests/vllm/multimodal/test_ltx2_video.cpp @@ -3268,6 +3268,82 @@ TEST_CASE("ltx2 video: a render through the ABI emits a phase table that SUMS to << "s of wall. The missing time is a phase " "nobody named, and W0 iterates until it is"); + // (4b) AND THE RESIDUE SAYS WHICH GAP IT IS IN, on the table a RENDER wrote. + // + // Row LTX25-PHASE-INSTRUMENT (#1668, #1571). `unaccounted_seconds` above is an + // aggregate, and four issues -- #1439, #1470, #1494, #1536 -- argued about + // whether the floor above it was the right tolerance without anyone splitting + // it into the gaps between consecutive leaves. Splitting it settled the + // question in one pass: 92% of it was ONE gap, the load's prologue, 17.661 ms + // of a 19.178 ms residue, while the sixteen gaps between adjacent named phases + // held 6.8 us each. `phase-log.json` now carries that decomposition, and + // `instrument_seconds` says how much of the residue this instrument spent + // rather than the render. + // + // THIS BLOCK IS HERE FOR REACHABILITY AND FOR NOTHING ELSE. The semantics -- + // the attribution rule, the conservation invariant, the writer's clock + // ordering -- are held in `tests/vllm/multimodal/test_render_phase_log.cpp` + // over synthetic timelines, because two of those cases need thousands of + // records and none of them needs a render. What only THIS case can prove is + // that a render through `vllm_video_generate` reaches any of it. Every + // assertion below is arithmetic over numbers already in the file, so a loaded + // box cannot move the verdict. + REQUIRE_MESSAGE(table.contains("instrument_seconds"), + "the render's own table carries no `instrument_seconds`, so the residue above " + "can only be compared against a share of the wall -- which is what four " + "issues spent days arguing about"); + const double instrument = table["instrument_seconds"].get(); + REQUIRE_MESSAGE(instrument > 0.0, + "the instrument charged itself NOTHING across a render of " << names.size() + << " phases, so `PhaseLog::ChargeLocked` is not running on the production " + "path at all"); + CHECK_MESSAGE(instrument <= unaccounted + 1e-9, + "the table reports " << unaccounted << "s of un-named time and claims " + << instrument + << "s of it is this instrument's own. A charge larger than the residue it " + "is part of means intervals inside a leaf are being charged to the table"); + REQUIRE_MESSAGE(table.contains("gaps"), "the render's table carries no gap decomposition"); + double gap_total = 0.0; + size_t gap_count = 0; + double largest_gap = -1.0; + std::string largest_between; + for (const nlohmann::json& g : table["gaps"]) { + REQUIRE(g.contains("after")); + REQUIRE(g.contains("before")); + const double seconds = g["seconds"].get(); + INFO("gap " << g["after"].get() << " -> " << g["before"].get()); + CHECK_MESSAGE(seconds >= 0.0, + "a gap between two leaves the emitter treats as non-overlapping is " + << seconds << "s, so they overlap and every sum in this table is the " + "residue of double counting"); + gap_total += seconds; + ++gap_count; + if (seconds > largest_gap) { + largest_gap = seconds; + largest_between = + g["after"].get() + " -> " + g["before"].get(); + } + } + // ONE GAP BEFORE EACH LEAF AND ONE AFTER THE LAST, counted by the same rule + // `Sum` uses, so this is the emitter's own partition read back. + size_t leaf_records = 0; + for (const nlohmann::json& entry : table["phases"]) { + if (entry.value("span", false) || entry.value("nested", false)) continue; + ++leaf_records; + } + CHECK_MESSAGE(gap_count == leaf_records + 1, + "the render's table names " << leaf_records << " leaves and reports " << gap_count + << " gaps, so the decomposition is not a partition of this render's " + "timeline"); + MESSAGE("residue: " << unaccounted << "s over " << gap_count << " gaps, instrument " + << instrument << "s, largest gap " << largest_gap << "s (" + << largest_between << ")"); + CHECK_MESSAGE(std::fabs(gap_total - unaccounted) < 1e-6, + "the gaps of this render add to " << gap_total << "s and it reports " + << unaccounted + << "s of un-named time. A decomposition that does not reconcile with the " + "quantity it decomposes sends the next reader after the wrong region"); + // (5) THE ABI CARRIES IT. `examples/ltx2_gen` is a client of `vllm.h` and // nothing else, so a client that never guesses a filename beside the frames // can still name the table it was handed. diff --git a/tests/vllm/multimodal/test_render_phase_log.cpp b/tests/vllm/multimodal/test_render_phase_log.cpp new file mode 100644 index 000000000..608609c0b --- /dev/null +++ b/tests/vllm/multimodal/test_render_phase_log.cpp @@ -0,0 +1,546 @@ +// THE RENDER PHASE INSTRUMENT, held to what its own numbers claim. +// +// Row LTX25-PHASE-INSTRUMENT, issues #1668, #1569, #1571. Spec: +// `.agents/specs/ltx25-phase-instrument.md`. +// +// WHY THIS FILE IS NOT IN `test_ltx2_video.cpp`. The cases below are about the +// INSTRUMENT rather than about LTX-2.5: they build synthetic timelines whose +// leaves contain a `sleep` and nothing else, because the question is where a +// charge LANDS and what the emitter writes, not what a render does. Two of them +// need a table of thousands of records, which no render produces. Keeping them +// beside a 5000-line model suite that renders a fixture would make an instrument +// question cost a model build, and it would put them in the file three other +// issues are actively editing. +// +// WHAT IS STILL GATED IN `test_ltx2_video.cpp`, and has to be. Everything here +// calls `PhaseLog` directly, which proves the class works and never that a +// render reaches it. The reachability half — that `vllm_video_generate` emits a +// table carrying `instrument_seconds` and `gaps` — is asserted on the table the +// ABI writes, in `a render through the ABI emits a phase table that SUMS to +// wall`. Neither file is sufficient alone. +// +// THE ONE NUMBER THIS FILE REFUSES TO ASSERT is a residue measured against the +// instrument's own charge. `.agents/specs/ltx25-phase-residue.md` `## Design` 3 +// records three fresh reviews measuring `residue <= 2 * instrument` red 4 times +// in 45 runs at load 88 (max 4.115) and 28 times in 160 at load 125 (max 5.55), +// because the UN-instrumented remainder of a boundary dilates faster than the +// instrumented part when the box slows. Every bound below is either an +// accounting identity, which no scheduler can move, or a one-sided comparison +// whose noise can only push it AWAY from red. Read that section before adding a +// ratio here. + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include + +#include +#include + +#include "vllm/multimodal/render_phase_log.h" + +namespace { + +namespace phase = vllm::multimodal::phase; + +std::string ReadAll(const std::string& path) { + std::ifstream in(path, std::ios::binary); + std::ostringstream buffer; + buffer << in.rdbuf(); + return buffer.str(); +} + +// A temporary directory and the table written inside it, removed on the way out. +// Every case here writes a real file because `WriteJson` is what is under test: +// the emitted table is the artifact a reader gets, and asserting on an in-memory +// record vector would skip the half of the code these cases exist for. +class TableFile { + public: + TableFile() { + std::snprintf(dir_, sizeof(dir_), "/tmp/vllm_phase_unit_XXXXXX"); + REQUIRE(::mkdtemp(dir_) != nullptr); + path_ = std::string(dir_) + "/phase-log.json"; + } + ~TableFile() { + ::unlink(path_.c_str()); + ::rmdir(dir_); + } + TableFile(const TableFile&) = delete; + TableFile& operator=(const TableFile&) = delete; + + const std::string& path() const { return path_; } + + nlohmann::json Write(const phase::PhaseLog& log) const { + std::string why; + REQUIRE_MESSAGE(log.WriteJson(path_, "unit", "cpu", &why), why); + return nlohmann::json::parse(ReadAll(path_)); + } + + private: + char dir_[64] = {}; + std::string path_; +}; + +void SleepMs(int ms) { std::this_thread::sleep_for(std::chrono::milliseconds(ms)); } + +} // namespace + +// ─── the instrument charges its OWN cost to the right place (#1668) ────────── +// +// The rule under test is one sentence from `render_phase_log.cpp`: every +// interval of the instrument's own wall is charged to the innermost live +// NON-SPAN record at the moment it is spent, and to the table when none is live. +// Three consequences, and each one is a different defect if it is wrong: +// +// * A CHILD'S BOUNDARY IS THE PARENT'S COST. Opening and closing a nested +// scope costs wall that lies inside the parent and outside the child, which +// is precisely the uncovered time the coverage gate reads. Charged to the +// table instead, that gate would have nothing to subtract and the number +// would say the parent encloses a phase nobody named. +// * A BOUNDARY WITH NOTHING LIVE IS THE TABLE'S COST. That is the residue the +// sum gate reads, and it is the whole of `unaccounted_seconds`'s +// explanation. +// * A SPAN IS NOT A LEAF. `Sum` skips spans, so time inside a span and outside +// every leaf IS the residue; charging it to the enclosing span would hide it +// in a number nothing adds up. This is the case the LTX-2.5 driver actually +// hits, because `load` and `generate` are spans that stay open across +// everything beneath them. +// +// NOTHING HERE IS A DURATION COMPARISON. The three assertions are "it moved", +// "it did not move at all" and "it is positive", which is why a loaded box +// cannot change the verdict. +TEST_CASE("ltx2 phase log: the instrument charges its own cost to the innermost LEAF") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + + // (1) A SPAN THAT ENCLOSES EVERYTHING, exactly as the driver's `load` does. + const size_t span = log.Open("unit.span", /*span=*/true); + // (2) A BOUNDARY WITH NO LEAF LIVE. Only the span is open, so this pair is + // charged to the TABLE and not to the span. + const double before_gap = log.Instrument(); + { const phase::Scope gap_probe("unit.gap_probe"); } + const double after_gap = log.Instrument(); + CHECK_MESSAGE(after_gap > before_gap, + "opening and closing a leaf under a SPAN charged the table nothing, so either " + "the instrument is not measuring its own boundaries or it charged them to the " + "span. A span is not summed, so that time would vanish from the table"); + + // (3) A LEAF WITH A NESTED CHILD. The child's boundaries are wall spent inside + // the parent and outside the child. + const size_t parent = log.Open("unit.parent", /*span=*/false); + const double table_before_child = log.Instrument(); + for (int i = 0; i < 8; ++i) { + const phase::Scope child("unit.child"); + } + const double table_after_child = log.Instrument(); + // EXACTLY EQUAL, not `Approx`. `doctest::Approx` scales its epsilon by + // `max(1, |value|)`, so on a quantity of ~1e-4 s it tolerates 1.19e-5 s — + // 11.9 us, which is about one whole boundary. That is the size of the leak + // this line exists to detect, so the tolerance would have been the blind spot. + // Nothing here may charge the table AT ALL while a leaf is live, so the two + // reads are the same double. + CHECK_MESSAGE(table_after_child == table_before_child, + "eight nested boundaries moved the TABLE's charge by " + << (table_after_child - table_before_child) + << "s while a leaf was live. They belong to the leaf that contains them; " + "charging them to the table would report the parent as enclosing a " + "phase nobody named"); + log.Close(parent); + log.Close(span); + + const std::vector records = log.Records(); + double parent_instrument = -1.0; + double parent_duration = -1.0; + double child_total = 0.0; + int64_t children = 0; + for (const phase::Record& r : records) { + if (r.name == "unit.parent") { + parent_instrument = r.instrument_seconds; + parent_duration = r.end - r.start; + } + if (r.name == "unit.child") { + child_total += r.end - r.start; + ++children; + CHECK_MESSAGE(r.nested, "'unit.child' opened inside a live leaf and is not marked nested"); + } + } + REQUIRE(children == 8); + REQUIRE(parent_duration > 0.0); + CHECK_MESSAGE(parent_instrument > 0.0, + "the parent leaf was charged " << parent_instrument + << "s although eight children opened and closed inside it. This is the " + "quantity a reader of the coverage ratio subtracts"); + + // AND WHAT IS **NOT** ASSERTED HERE, because a fresh review of the withdrawn + // design measured it. This case shipped twice with a bound on + // `uncovered / parent_instrument`, and the shipped binary reddened 2 of 200 + // consecutive runs at load 85, while a standalone probe of this exact shape + // reddened 28 of 160 at load 125 and reached 14.1 under ASan. Decomposing the + // parent's uncovered time explains it: fast, the inter-child gaps are 9-20 us + // over seven boundaries against a 13-22 us charge; slow, the gaps are + // 91-105 us against a 52-61 us charge. The UN-instrumented part of a boundary + // — the `lock_guard` release, the `Close` return, the `Scope` destructor and + // constructor, the call into `Open` up to its clock read — dilates faster than + // the instrumented part. Eight bare scopes carry neither a `Tick` nor a + // `/proc/self/statm` read inside the instrumented region, which makes this the + // worst-conditioned probe of that ratio anywhere, not the tightest. It is + // reported so a reader can see it move, and asserted nowhere. + const double uncovered = parent_duration - child_total; + MESSAGE("unit.parent = " << parent_duration << "s, children " << child_total + << "s, uncovered " << uncovered << "s, charged " << parent_instrument + << "s (ratio " << (uncovered / parent_instrument) + << ", REPORTED not asserted -- see the note above)"); + log.Reset(); +} + +// ─── the accounting is CONSERVED (#1668) ───────────────────────────────────── +// +// `instrument_seconds` at the top of the table and `instrument_seconds` on each +// record are ONE quantity split two ways, so a charge that reached neither would +// be an unmeasured cost invisible to every reader of either number. Everything +// asserted here is an inequality between two numbers in the same file: +// non-negative, no record charged more than its own duration, and the table's +// share no larger than the residue it claims to be part of. A box under load +// moves every one of these numbers and moves none of these verdicts. +TEST_CASE("ltx2 phase log: the instrument's own cost is CONSERVED across the table and its records") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + { + const phase::Scope one("unit.one"); + SleepMs(30); + { const phase::Scope inner("unit.one.inner"); } + } + { + const phase::Scope two("unit.two"); + SleepMs(30); + } + + const TableFile file; + const nlohmann::json table = file.Write(log); + + REQUIRE(table.contains("instrument_seconds")); + const double table_charge = table["instrument_seconds"].get(); + CHECK(table_charge >= 0.0); + double record_charge = 0.0; + for (const nlohmann::json& e : table["phases"]) { + REQUIRE_MESSAGE(e.contains("instrument_seconds"), + "the record for '" << e["name"].get() + << "' carries no instrument charge"); + const double c = e["instrument_seconds"].get(); + CHECK_MESSAGE(c >= 0.0, "'" << e["name"].get() << "' was charged " << c << "s"); + CHECK_MESSAGE(c <= e["duration_seconds"].get() + 1e-9, + "'" << e["name"].get() << "' was charged " << c + << "s of its own " << e["duration_seconds"].get() + << "s duration, which is more instrument than record"); + record_charge += c; + } + MESSAGE("instrument: table " << table_charge << "s + records " << record_charge << "s"); + CHECK_MESSAGE(record_charge > 0.0, + "no record carries any instrument charge, so the per-record half of the " + "accounting is not reaching the emitted table"); + + const double wall = table["wall_seconds"].get(); + const double unaccounted = table["unaccounted_seconds"].get(); + MESSAGE("wall " << wall << "s, unaccounted " << unaccounted << "s, table charge " + << table_charge << "s"); + REQUIRE(wall > 0.0); + CHECK_MESSAGE(table_charge > 0.0, + "the table's own instrument charge is " << table_charge + << "s across a timeline that opened and closed three scopes with nothing " + "live between the last two, so `ChargeLocked` never reached the `no live " + "leaf` arm. That arm is the whole of `unaccounted_seconds`'s explanation"); + CHECK_MESSAGE(unaccounted >= table_charge - 1e-9, + "the table reports " << unaccounted << "s of un-named time and claims " + << table_charge + << "s of it is this instrument's own. A charge larger than the residue it " + "is part of means the accounting is charging intervals that are inside a " + "leaf to the table, which would make every residue bound too loose"); + log.Reset(); +} + +// ─── the residue is DECOMPOSED into the gaps that make it (#1571) ──────────── +// +// `unaccounted_seconds` shipped as an aggregate, and four issues — #1439, #1470, +// #1494 and #1536 — argued about whether its 95% floor was the right tolerance +// without anyone splitting it into the gaps between consecutive leaves. +// Splitting it took one pass over the table the render already writes and +// settled the question: **92% of the residue was ONE gap**, the load's prologue +// from the timeline's origin to `Open("load.dit")`, 17.661 ms of 19.178 ms, +// while the sixteen gaps between adjacent named phases held 6.8 us each. That +// pass was a scratch script nobody shipped. +// +// THE IDENTITY IS THE GATE, and it is arithmetic rather than a tolerance. The +// leaves `Sum` adds are non-overlapping and start-ordered, so the complement of +// their union inside `[0, wall]` is exactly `wall - sum_leaf_seconds`. The gaps +// therefore add to `unaccounted_seconds` by construction, and a decomposition +// that dropped one, double counted one or mis-ordered the leaves fails by an +// amount no box load can supply. +// +// THE ONE DURATION HERE IS A LOWER BOUND ON A SLEEP, which is the only shape of +// wall-clock assertion contention cannot break: `sleep_for` returns no earlier +// than its argument and a loaded box only makes it later. +TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gaps between leaves") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + + // THE PROLOGUE, which is the shape of the defect this decomposition was + // written to find: time before the first named leaf, inside no leaf, invisible + // in every aggregate. A span is open across it exactly as the driver's `load` + // span is, so this gap is inside a span and outside every leaf — the position + // `Sum` cannot see. + const int kPrologueMs = 60; + const phase::Scope enclosing("unit.enclosing", /*span=*/true); + SleepMs(kPrologueMs); + { const phase::Scope a("unit.a"); SleepMs(5); } + SleepMs(5); // an interior gap, between two adjacent named leaves + { + const phase::Scope b("unit.b"); + SleepMs(5); + // A nested child, so the decomposition has to skip a record that is inside a + // leaf rather than between two. Counting it would produce a negative gap. + const phase::Scope inner("unit.b.inner"); + SleepMs(1); + } + SleepMs(5); // the tail gap, before the writer reads the clock + + const TableFile file; + const nlohmann::json table = file.Write(log); + + REQUIRE_MESSAGE(table.contains("gaps"), + "the emitter writes `unaccounted_seconds` as an aggregate and nothing else, " + "so a reader still cannot see WHICH gap holds it without writing a script -- " + "which is how four issues argued about a tolerance instead (#1571)"); + REQUIRE(table["gaps"].is_array()); + REQUIRE(table.contains("gap_rule")); + CHECK(!table["gap_rule"].get().empty()); + + // The leaves the decomposition must lie between, in the emitter's own order. + std::vector leaf_names; + for (const nlohmann::json& e : table["phases"]) { + if (e.value("span", false) || e.value("nested", false)) continue; + leaf_names.push_back(e["name"].get()); + } + REQUIRE(leaf_names.size() == 2); + + const nlohmann::json& gaps = table["gaps"]; + REQUIRE(!gaps.empty()); + + // (1) NO GAP IS NEGATIVE, AND THEY ADD TO THE RESIDUE. Both come first and + // neither is fatal, so one broken decomposition reports every way it is + // broken rather than the first one. THE ORDER HERE IS A REPAIR: the count + // below was a `REQUIRE` above this loop, and a mutation that counted NESTED + // records as leaves aborted the case on the count and never reached these two + // — so the negative gap that same mutation produces went unobserved, and two + // of this case's three assertions were unproven while the case reddened. + double gap_total = 0.0; + for (size_t i = 0; i < gaps.size(); ++i) { + const nlohmann::json& g = gaps[i]; + REQUIRE(g.contains("after")); + REQUIRE(g.contains("before")); + REQUIRE(g.contains("seconds")); + const double seconds = g["seconds"].get(); + INFO("gap " << i << " = " << g["after"].get() << " -> " + << g["before"].get()); + CHECK_MESSAGE(seconds >= 0.0, + "gap " << i << " between '" << g["after"].get() << "' and '" + << g["before"].get() << "' is " << seconds + << "s. A negative gap means two records the emitter is treating as " + "non-overlapping leaves overlap, which would make every sum in this " + "table the residue of double counting"); + gap_total += seconds; + } + + // THE IDENTITY. No tolerance beyond double rounding over a handful of + // additions: this is the same arithmetic `Sum` does, read from the other side. + const double unaccounted = table["unaccounted_seconds"].get(); + MESSAGE("gaps sum " << gap_total << "s against an unaccounted " << unaccounted << "s over " + << gaps.size() << " gaps"); + CHECK_MESSAGE(std::fabs(gap_total - unaccounted) < 1e-9, + "the gaps add to " << gap_total << "s and the table reports " << unaccounted + << "s of un-named time. A decomposition that does not reconcile with the " + "quantity it decomposes sends the next reader after the wrong region"); + + // (2) ONE GAP BEFORE EACH LEAF AND ONE AFTER THE LAST. A decomposition with a + // different count is not a partition of the timeline, whatever its sum says. + CHECK_MESSAGE(gaps.size() == leaf_names.size() + 1, + "the table names " << leaf_names.size() << " leaves and reports " << gaps.size() + << " gaps. A partition of `[0, wall]` by N non-overlapping leaves has " + "exactly N+1 complementary intervals"); + + // (3) AND EACH GAP NAMES THE TWO LEAVES IT LIES BETWEEN, which is the half a + // reader uses. A sum that reconciles while the names are wrong points the next + // investigation at the wrong region, which is the failure #1571 is about. + // Guarded on the count, because the pairing below is only defined when the + // decomposition IS a partition — and the guard is announced rather than + // silent, since an assertion that turned itself off would look exactly like + // one that passed. + if (gaps.size() != leaf_names.size() + 1) { + MESSAGE(" the gap/leaf pairing is SKIPPED: the counts above already disagree, so there is " + "no pairing to check. The count assertion is what speaks here."); + } else { + for (size_t i = 0; i < gaps.size(); ++i) { + const std::string after = gaps[i]["after"].get(); + const std::string before = gaps[i]["before"].get(); + const std::string expect_after = i == 0 ? std::string("") : leaf_names[i - 1]; + const std::string expect_before = + i == leaf_names.size() ? std::string("") : leaf_names[i]; + INFO("gap " << i); + CHECK_MESSAGE(after == expect_after, + "gap " << i << " says it follows '" << after + << "' and the table's leaf order says '" << expect_after << "'"); + CHECK_MESSAGE(before == expect_before, + "gap " << i << " says it precedes '" << before + << "' and the table's leaf order says '" << expect_before << "'"); + } + } + + // (4) AND THE PROLOGUE IS THE ONE A READER NEEDS TO SEE. `sleep_for` returns + // no earlier than its argument, so this lower bound is one contention can only + // move away from red. Before this decomposition existed, exactly this region + // was 92% of a real render's residue and no reader of the file could name it. + const double prologue = gaps[0]["seconds"].get(); + CHECK_MESSAGE(prologue >= 0.001 * static_cast(kPrologueMs) - 1e-3, + "the timeline slept " << kPrologueMs + << "ms inside a span and outside every leaf, and the decomposition reports " + << prologue + << "s before the first leaf. The prologue is the region that held 92% of " + "the LTX-2.5 load's residue, and a decomposition that cannot see it is " + "the aggregate it replaced"); + log.Reset(); +} + +// ─── the writer's clock stops BEFORE the writer works (#1569) ──────────────── +// +// `PhaseLog::WriteJson` reads `Elapsed()` before it copies and sorts the record +// vector, so the writer's own serialization is not charged to `wall_seconds` and +// therefore not to `unaccounted_seconds`. That table measures the RENDER. +// +// **NOTHING ASSERTED IT, AND ITS OWN MUTATION STAYED GREEN 10 OF 10.** A fresh +// review of #1556 restored the late clock read and the case that claimed to pin +// the ordering passed every time, at `wall 0.0608987s, unaccounted 0.000534223s, +// table charge 0.000301655s`, because the copy and the sort of a THREE-record +// table are nanoseconds — far below the slack in any bound that case carried. +// An instrument whose own mutation cannot fail is not an instrument (#1569). +// +// WHAT MAKES IT GATEABLE IS A TABLE BIG ENOUGH FOR THE SORT TO EXIST, and a +// discriminator measured in the same run rather than written down as a constant. +// The case builds `kRecords` leaves, then measures two quantities K times: +// +// * `head` — the elapsed clock read by this case immediately before the call, +// against the `wall_seconds` the writer recorded. With the clock read first +// the writer's clock is one function call and one uncontended mutex behind +// this case's own, i.e. the instrument's resolution. With it read late the +// head contains a whole copy and a whole `stable_sort`. +// * `serialize` — that same copy and that same sort, performed by this case +// through the same public `Records()`, on the same data, on this box, in +// this run. It is the size of the defect, measured rather than assumed. +// +// AND THE ESTIMATOR IS A MINIMUM, WHICH IS WHY THIS IS NOT THE WITHDRAWN BOUND +// AGAIN. Contention is ONE-SIDED: it can only make a measured interval longer, +// never shorter. The honest head is a floor of ~1e-7 s plus a preemption that +// lands in it sometimes; the mutated head has a HARD floor of one serialization, +// which is present in every single iteration. A minimum over K iterations +// therefore strips the sporadic term from the honest side and cannot strip the +// deterministic term from the defective side. That is the difference between +// this and `residue <= 2 * instrument`: there, both sides were single +// measurements of comparable magnitude and the tail decided the gate; here the +// two sides differ by orders of magnitude and the estimator removes the tail by +// construction. +// +// THE FACTOR IS 0.5 AND IT IS NOT A TOLERANCE. Under the correct ordering the +// head contains ZERO copies and ZERO sorts. Under the mutated ordering it +// contains exactly one of each, so it is at least 1.0 x `serialize` by the +// definition of the two quantities. Any constant strictly between 0 and 1 +// separates them; 0.5 is the midpoint, and the measured separation on this tree +// is about five orders of magnitude rather than a factor of two. +TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the table") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + + // ENOUGH RECORDS FOR THE SORT TO BE A MEASURABLE EVENT. Three records made + // this ungateable; the sort is `n log n` on a vector of records carrying a + // `std::string`, so the discriminator grows with `kRecords` while the honest + // head does not depend on it at all. + const int kRecords = 4000; + // ONE SPAN HELD OPEN ACROSS THE BUILD, for two reasons. It stops the sampler + // thread from being created and joined once per leaf, which would dominate the + // build; and closing it before the measurement leaves NOTHING live, so the + // 100 ms worker is not running while the clocks below are read. + { + const phase::Scope holder("unit.holder", /*span=*/true); + for (int i = 0; i < kRecords; ++i) { + const phase::Scope leaf("unit.leaf"); + } + } + + const TableFile file; + const int kProbes = 5; + double head = -1.0; + double serialize = -1.0; + int64_t emitted = 0; + for (int k = 0; k < kProbes; ++k) { + const double before_call = log.Elapsed(); + const nlohmann::json table = file.Write(log); + const double writer_clock = table["wall_seconds"].get(); + emitted = static_cast(table["phases"].size()); + const double this_head = writer_clock - before_call; + if (head < 0.0 || this_head < head) head = this_head; + + // THE DISCRIMINATOR, MEASURED THE SAME WAY THE WRITER DOES IT. `Records()` + // returns a copy taken under the process-wide mutex and `ByStart` sorts that + // copy; this is the same copy and the same sort through the same public + // entry point, so it is the cost the writer would pay after its clock read + // rather than a number quoted from another box. + const double before_sort = log.Elapsed(); + std::vector copy = log.Records(); + std::stable_sort(copy.begin(), copy.end(), + [](const phase::Record& a, const phase::Record& b) { + return a.start < b.start; + }); + const double this_serialize = log.Elapsed() - before_sort; + // Kept from being optimised away: the sorted copy has to be observed. + REQUIRE(!copy.empty()); + if (serialize < 0.0 || this_serialize < serialize) serialize = this_serialize; + } + + REQUIRE_MESSAGE(emitted >= kRecords, + "the timeline was built with " << kRecords << " leaves and the table carries " + << emitted << " records, so the discriminator below was measured over a " + "table that is not the one this case built"); + // THE INSTRUMENT'S OWN PRECONDITION, and it is what stops this case from being + // a mute switch. If the copy and the sort cost nothing measurable, then the + // bound below is `head < 0` and no ordering can satisfy it — but equally, a + // `serialize` that collapsed toward the clock's resolution would make the + // comparison meaningless in the other direction. It has to be an event. + REQUIRE_MESSAGE(serialize > 1e-5, + "copying and sorting " << emitted << " records measured " << serialize + << "s, which is at or below this clock's own resolution. The difference " + "between the two orderings is that copy and that sort, so a table this " + "cheap to serialise cannot separate them -- which is exactly why the " + "three-record case in #1569 stayed green under its own mutation"); + MESSAGE("writer clock lag " << head << "s against a serialization cost of " << serialize + << "s over " << emitted << " records (min of " << kProbes + << " probes, ratio " << (head / serialize) << ")"); + CHECK_MESSAGE(head < 0.5 * serialize, + "`WriteJson` recorded a wall " << head + << "s later than the clock this case read immediately before calling it, " + "against a measured copy-and-sort of " + << serialize << "s over " << emitted + << " records. The writer is reading its clock AFTER it serialises the " + "table, so its own copy and sort are charged to `wall_seconds` and " + "therefore to `unaccounted_seconds`. This table measures the render"); + log.Reset(); +}