From 826bfc99442cc27feee8112497cf6c26c46d4943 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sat, 22 Aug 2026 15:23:09 +0000 Subject: [PATCH 01/12] spec(LTX25-PHASE-INSTRUMENT): the instrument measures its own cost, and the residue says which gap it is in (#1668, #1569, #1571) `ltx25-phase-residue.md` records a body 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: `Record::instrument_seconds`, `WriteJson` reading its clock before it serialises, and the residue decomposed into the gaps between adjacent leaves inside the emitted file. The three driver anchors stay out. They are one unit with `denoise.update`, which #1568 and #1570 both need before they can be closed, and bundling them here would make one reviewer read two unrelated changes. Two things this spec says NO to, and each is written down because each is the obvious move. `instrument_seconds` never appears in a denominator: three fresh reviews measured `residue <= 2 * instrument` red 4 times in 45 runs at load 88 and 28 times in 160 at load 125, because the un-instrumented remainder of a boundary dilates faster than the instrumented part when the box slows. And neither existing floor is widened, in form or in constant. The one new bound is derived rather than tuned. Under the correct clock ordering `WriteJson`'s wall is one function call behind the caller's; under the mutated ordering it is a whole copy plus a whole `stable_sort` behind it, and the case measures that copy and that sort in the same run rather than quoting a constant. The estimator is a minimum over probes because contention is one-sided, which is what separates this from the bound that was withdrawn. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/specs/ltx25-phase-instrument.md | 248 ++++++++++++++++++++++++ 1 file changed, 248 insertions(+) create mode 100644 .agents/specs/ltx25-phase-instrument.md diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md new file mode 100644 index 000000000..a876b0199 --- /dev/null +++ b/.agents/specs/ltx25-phase-instrument.md @@ -0,0 +1,248 @@ +# `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 + +Filled by the run that lands this row. See `## Outcome`. + +## Now + +Spec committed. Implementation follows in the same pull request, and the commit +order proves the spec came first. From ed60f82cfad6ef3583a4d291b22db02ca092b3bd Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sat, 22 Aug 2026 16:13:58 +0000 Subject: [PATCH 02/12] feat(LTX25-PHASE-INSTRUMENT): the phase table charges its own cost and names the gap its residue is in (#1569, #1571) `unaccounted_seconds` shipped as one number, and four issues argued about the tolerance over it without anyone splitting it into the gaps between consecutive leaves. Splitting it is one pass over the table the render already writes, and it settles the argument: on the first ABI render after this change, 47% of a 2.013 ms residue is charged to the instrument itself and the largest remaining gap is `load.dit` -> `load.video_vae` at 0.627 ms -- which is the `load.dit_config` anchor #1668 still owes, found from the emitted file with no script. Three things land. `Record::instrument_seconds` and `PhaseLog::Instrument()` charge every interval the instrument spends inside its own entry points to the innermost live non-span record, and to the table when none is live, ported behaviour-identically from `refs/pull/1556/head` = `b45ea3bbb`. `WriteJson` reads its clock before it copies and sorts, so the writer stops charging its own serialization to the render. And `gaps` decomposes the residue in the file, one interval before each leaf and one after the last, each naming the two leaves it lies between. THE GAP GATE IS ARITHMETIC, NOT A MEASUREMENT, and that is the point. The leaves `Sum` adds are non-overlapping, so their complement inside `[0, wall]` is exactly `unaccounted_seconds`. The gaps reconcile to it by construction, which no box load can move. Five of the ten mutations recorded in the spec are caught by a comparison with no clock in it. #1569's own mutation used to stay green 10 of 10, because the copy and sort of a three-record table are nanoseconds. It now reds: over a 4000-record table the two clock orderings differ by one whole copy and one whole sort, and the case measures that copy and that sort in the same run rather than quoting a constant. 50 consecutive runs at load 103-131 read a max of 0.004228 against a bound of 0.5, and the mutation reads 1.004. Contention is one-sided, so a minimum over probes strips the sporadic term from the honest side and cannot strip the deterministic term from the defective side. `instrument_seconds` appears in no denominator anywhere. `residue <= 2 * instrument` was measured red 4 times in 45 runs and withdrawn before this row started, and re-deriving a settled negative result is what the record exists to prevent. Neither existing floor is touched, in form or constant. The instrument's own cases go in a new `test_render_phase_log` executable: two of them need thousands of records that no render produces, and three other issues are editing `test_ltx2_video` right now. Reachability stays where only it can be proved -- deleting the emitted `gaps`, and disabling charging entirely, each red the ABI render case. `docs/USAGE.md` and `docs/models/ltx-2-5.md` both gain the two new fields, because a reader who opens `phase-log.json` is the person these numbers exist for. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/specs/ltx25-phase-instrument.md | 118 +++- .agents/specs/ltx25-phase-residue.md | 4 +- docs/USAGE.md | 12 + docs/models/ltx-2-5.md | 12 + include/vllm/multimodal/render_phase_log.h | 34 ++ src/vllm/multimodal/render_phase_log.cpp | 216 ++++++- tests/CMakeLists.txt | 8 + tests/vllm/multimodal/test_ltx2_video.cpp | 76 +++ .../vllm/multimodal/test_render_phase_log.cpp | 546 ++++++++++++++++++ 9 files changed, 1020 insertions(+), 6 deletions(-) create mode 100644 tests/vllm/multimodal/test_render_phase_log.cpp diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index a876b0199..08f769604 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -240,9 +240,121 @@ FAILURE TEXT rather than by job name. ## Evidence -Filled by the run that lands this row. See `## Outcome`. +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 -Spec committed. Implementation follows in the same pull request, and the commit -order proves the spec came first. +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/USAGE.md b/docs/USAGE.md index ce40d20f3..9a31f8f48 100644 --- a/docs/USAGE.md +++ b/docs/USAGE.md @@ -307,6 +307,18 @@ thread count they actually got beside the count that was asked for. than `max_model_len` tokens and would be refused after tokenizing anyway. Send a shorter prompt, or load a checkpoint with a longer context. +- A video render writes `/phase-log.json` beside its frames, and + `unaccounted_seconds` there is time the render spent inside no named phase. + Read `gaps` to find out WHERE: it holds one interval before each named phase + and one after the last, each naming the two phases it lies between, and they + add to `unaccounted_seconds` exactly. The largest entry is the region worth + naming next. Subtract `instrument_seconds` first — that is what the + instrument itself spent on its own phase boundaries, and on a short render it + can be about half the residue. Every phase record carries its own + `instrument_seconds` too, which is what that phase paid for the boundaries of + its sub-phases. The C ABI hands back the same file's path through + `vllm_video_last_phase_log`. + ## Find a focused guide [Task guides](guides/README.md) cover workflows that apply to more than one 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(); +} From a5d41d18ef46d047258740a61a3cedd8f09a8999 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sat, 22 Aug 2026 20:21:40 +0000 Subject: [PATCH 03/12] fix(LTX25-PHASE-INSTRUMENT): the charge is disjoint, the budget is the cheaper step, the gap endpoints are read, and the console copy says the same thing (#1718, #1719, #1720) The fresh review of this row returned four findings and three gates it could not make honest. This is the repair for the four, the mutation that holds each one, and the three issues that carry the rest. F1. `instrument_seconds <= duration_seconds` was asserted, documented as an invariant, and was not one. `Open` and `Tick` read their clock BEFORE taking the process-wide mutex, so the interval they charge to a record spans a window in which another thread, holding that mutex, charges the SAME record. Both charges are individually correct, they overlap, and the sum of overlapping intervals is not bounded by the interval containing them: 24 threads inside one live leaf drove the ratio to 1.914, red in 3 runs of 5. `ChargeLocked` now clamps each charge to the end of the last one that reached the same target and seeds that mark with the record's own `start`, so every charged interval lies inside `[start, end]` and no two overlap. The sum is at most the duration by construction rather than by hoping the box stays quiet. It can under-count, and that direction is deliberate because this quantity is in no denominator anywhere. F2. The #1569 bound's one-number budget missed a PARTIAL regression. It bounded the writer's clock lag against `copy + sort` together, which holds only when both move; hoisting `Records()` above the clock read and leaving `ByStart` below it kept the bound GREEN at 0.0588, because the copy is about 6% of copy-plus-sort. The budget is now `min(copy, sort)`, measured as two separate steps in the same run, and that same partial regression reds at 1.024. The constant did not move; the quantity under it got smaller, which is the only direction a repair may take a bound. F3. The gaps' `start_seconds` and `end_seconds` were emitted and asserted nowhere: zeroing both left the file green. They are the half a reader uses to LOCATE a region, and locating one was the whole content of #1571. Each gap's endpoints must now agree with its own `seconds`, the first must start at the origin, the last must end at `wall`, and each must start no earlier than the previous one ended. The identity's comment is corrected too: the gap sum telescopes to `wall - sum(durations)` for ANY sequence, so it never caught a mis-ordering, and the tiling assertions are where the order actually lives. F4. `phase-log.json` carried `instrument_seconds` and `RenderText` did not, so a reader watching a terminal saw the residue with no way to subtract the cost of naming the phases. The line is added and gated against `Instrument()` to 5e-4, which is that line's own `%10.3f` resolution by the definition of the conversion, not a tolerance. The whole mutation set was re-run against the repaired tree rather than carried over, because three of these repairs change what the suite can see. Eighteen mutations, each printing `compile_status` and `git diff --numstat`, each asserting its anchor matched exactly once, each restored from a pristine byte copy verified by sha256. Fifteen RED, three GREEN and printed as green, because a mutation table that lists only its successes is an argument and not a measurement. One staging of N6 failed to compile under `-Werror` and was re-staged rather than recorded, since a mutation that fails to build reads exactly like a passing test. The three greens are #1718: the charge sites are gated only in aggregate. #1719 is the reason the per-site gate could not be made honest -- `Close`'s pre-lock wait is charged to nobody, and it inflates the closing record's uncovered time, which is the quantity the coverage floor reads. #1720 is the cost of F2's repair recorded rather than hidden: `WriteJson` now takes the mutex twice, so wall and the record set are two snapshots. All three are listed under this row's spec `## Owed`. Measured over 45 consecutive runs of the whole suite on a box at load average 71 to 113, every run's case and assertion counts recorded because a `-tc` filter that matches nothing prints `0 cases ran` and `Status: SUCCESS!`. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [Claude Code] --- .agents/issue-index.md | 3 + .agents/specs/ltx25-phase-instrument.md | 240 ++++++++++-- src/vllm/multimodal/render_phase_log.cpp | 78 +++- .../vllm/multimodal/test_render_phase_log.cpp | 360 ++++++++++++++++-- 4 files changed, 603 insertions(+), 78 deletions(-) diff --git a/.agents/issue-index.md b/.agents/issue-index.md index f6586d3b0..a4839529c 100644 --- a/.agents/issue-index.md +++ b/.agents/issue-index.md @@ -626,3 +626,6 @@ rather than merged. `scripts/check-agent-record.py` gates both. | [#1661](https://github.com/mudler/vllm.cpp/issues/1661) | `TEST-SHELLCHECK-SKIP-GUARD` | **`test_script_stays_shellcheck_clean` ERRORs instead of skipping on hosts without the shellcheck binary: the guard probes `returncode`, but a missing binary raises `FileNotFoundError` before a returncode exists**, so the `tools suites` preflight gate is red on such hosts (`thalia`, aarch64). The test predates the window (last touched `b95543c44`); it surfaced when current main's preflight started running the module. FIXED IN FLOW by the same change: the probe gains the `except FileNotFoundError` skip arm (message unchanged), and both arms are proven — no-binary host skips via the new arm, a PATH-shim `shellcheck` exiting 3 still skips via the returncode arm, and unmodified main reds on this host | bug | | [#1690](https://github.com/mudler/vllm.cpp/issues/1690) | `DOC-README-ABI-LANDING-SOURCE` | **`check-doc-checkpoint.py`'s `LANDING_SOURCE_FILES` omitted `include/vllm.h`, so a commit that bumps `VLLM_ABI_VERSION` could never repair the README claim it invalidated.** Found by the review of [PR #1655](https://github.com/mudler/vllm.cpp/pull/1655). The README `## Use it as a library (C API)` block quotes the ABI version out of the header; the header was in `USER_USAGE_FILES` (so an ABI change owes `docs/USAGE.md`) but not in `LANDING_SOURCE_FILES`, and the README rule refuses a claim change unaccompanied by a landing source. The claim could therefore be invalidated but not repaired by the same edit, which is how the README reached `VLLM_ABI_VERSION 21` against a header reading `23`, alongside a stale "46 exported functions" for a header declaring 47. That second half is stale by one rather than by six -- an earlier review figure of 51/52 swept in the `#define VLLM_API` visibility block and counted `vllm_*` identifiers that are typedefs and struct fields rather than exported functions -- so the case for deleting the count is that a live count of one file stored in another goes stale on any ABI addition, not that it is badly wrong. The set's own criterion already admitted it -- the checker's comment says every member is "something the README QUOTES" -- and the header was the only such source missing. FIXED IN FLOW: `include/vllm.h` is added to the set, red-before/green-after pinned by `test_the_c_abi_header_is_a_landing_source`, with `test_the_c_abi_header_permits_but_does_not_demand_readme` proving no new README obligation and the pre-existing no-class tests still green | bug | | [#1692](https://github.com/mudler/vllm.cpp/issues/1692) | `KERNEL-ACCEL-PROVIDER-DECLINE-EXACT` | **[#1584](https://github.com/mudler/vllm.cpp/issues/1584) is FIXED by this row, and its gate is CPU-only: both production call sites need a GPU and neither arm was executed.** The fix adds `GetOpFallbackUncounted`, sharing one body with `GetOpFallback` so resolution order, the reference-tier install, the drain and every throw stay identical and only the `fetch_add` is conditional -- in its existing position, BEFORE the "nothing below" check, because a decline that throws is still a decline. The two SHAPE-GATED providers that hoist the lookup into a function-local static switch to it: `cuda_attention_cross.cu` `BlockedFallback` and `metal_mlx_provider.mm` `MlxFallback`. **Candidate 1 of #1584 -- drop the count from `GetOpFallback` -- was REJECTED and measured rather than argued:** it edits five per-call sites (`vulkan_ops.cpp:950,1067,1488,1509`, `tenstorrent_ops.cpp:1341`), one already gated on an exact value at `test_vulkan_backend.cpp:2901` (`after.declines == before.declines + 1`), and its failure mode for a future caller is silent UNDER-counting, the Risk 4 the seam exists to expose. Net blast radius is ZERO backends, not the four #1584 estimated; exactly two providers change what they report, by one. #1555's `WarmDeclineOnce` workaround is REMOVED. **What this issue owns is the missing EXECUTION:** `test_ops_attention_cross` on CUDA (20 cases, ALL 20 SKIP on a CPU-only build -- 32 assertions, every one the skip guard, so that suite gives the change no coverage here), `test_metal_backend` on a `VLLM_CPP_MLX` build, and the `.agents/reachability.md` mutation on `BlockedFallback()` / `MlxFallback()`. The CUDA COMPILE is covered by the `-DVLLM_CPP_CUDA=ON` `vllm`-target job in `.github/workflows/ci.yml`; the Metal `.mm` file is compiled by NO job in this repository, because MLX needs `MLX_ROOT`. Red-before/green-after and the mutation table in [op-provider-decline-exact.md](specs/op-provider-decline-exact.md) | bug | +| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | `LTX25-PHASE-INSTRUMENT` | **`PhaseLog`'s instrument-charge attribution is gated only in AGGREGATE: deleting any ONE of the five charge sites leaves the whole suite green.** The sites in `src/vllm/multimodal/render_phase_log.cpp` are `Open`'s pre-lock mutex wait (the `entered` clock read, which the row's `## Design` 1 names as the reason the mechanism exists), `Open`'s tail after `SampleLocked`, `Close`'s tail, the sampler join, and `SampleLocked`'s own self-charge. Measured by mutation at the head of [PR #1711](https://github.com/mudler/vllm.cpp/pull/1711), each printing `compile_status`, `git diff --numstat` and the doctest `test cases:` / `assertions:` lines, tree restored from a pristine byte copy and verified by sha256: `N6` (`Open`'s pre-lock charge replaced by a `(void)` cast of the same expression) GREEN, `N4` (`ChargeLocked`'s `if (from < 0.0) return;` becomes a clamp to zero, which the comment beside it argues at length is the defect that makes a gate pass) GREEN, `NNOSORT` (`ByStart` stable-sorts an empty range, i.e. does not sort at all) GREEN. Only `R2`, which makes `ChargeLocked` return immediately so nothing anywhere is charged, reds -- at `REQUIRE(instrument > 0.0)` in the render case. `NREVSORT` beside `NNOSORT` says exactly how much of `ByStart` is held: a DESCENDING sort reds at `CHECK(seconds >= 0.0)` on -16.996 ms and a REMOVAL does not, because every timeline this suite builds is already start-ordered. N6's first staging is itself worth recording: written as `if (false) { ... }` it left `entered` unused, failed `-Werror`, and printed `compile_status=1` -- a mutation that fails to build reads exactly like a passing test and only the printed status separated them. NOT FIXED IN FLOW, and the reason is measured rather than asserted: a per-site case was written and run THREE times and does not measure the site. `PhaseLog::Records()` is the only public entry point that holds the process-wide mutex without charging itself, which is what makes it usable as a hold at all, and contention staged through it lands mostly in `PhaseLog::Close`'s lock wait -- charged to nobody ([#1719](https://github.com/mudler/vllm.cpp/issues/1719)) and inside the CHILD's duration rather than the parent's charge. The case passed in ISOLATION at a separation of 615x and failed 5 of 5 inside the suite, twice because no reader held the lock at all and three times because a contended parent that took 21 ms was charged 112 us. A flaky gate over an instrument whose whole subject is flaky gates is the failure this cluster exists to stop, and [#1569](https://github.com/mudler/vllm.cpp/issues/1569) is the standing record of what an instrument whose own mutation cannot fail costs. What would settle it: a probe that holds the mutex through an entry point that does not charge itself AND lands the wait on the site under test, which needs #1719 first. Owned by [`ltx25-phase-instrument.md`](specs/ltx25-phase-instrument.md) `## Owed` | verification | +| [#1719](https://github.com/mudler/vllm.cpp/issues/1719) | `LTX25-PHASE-INSTRUMENT` | **`PhaseLog::Close`'s pre-lock wait is charged to nobody, so it inflates the closing record's UNCOVERED time -- the quantity the coverage floor reads.** `PhaseLog::Open` reads a clock BEFORE it takes the process-wide mutex (`const std::chrono::steady_clock::time_point entered = std::chrono::steady_clock::now();`, `src/vllm/multimodal/render_phase_log.cpp`) and charges that lock wait to whatever encloses the gap before the new record. `Close` has no such read: it takes the mutex and only then stamps `r.end`, so the wall between a scope's last statement and its recorded end is instrument time that no record and no table absorbs -- not in `Record::instrument_seconds`, not in `PhaseLog::Instrument()`, and therefore not in `unaccounted_seconds`'s explanation. It is not cosmetic: that interval lies inside the CLOSING record's own duration and outside every child of it, which is exactly what `covered >= min_coverage * leaf_seconds` reads -- the floor [#1439](https://github.com/mudler/vllm.cpp/issues/1439), [#1470](https://github.com/mudler/vllm.cpp/issues/1470), [#1494](https://github.com/mudler/vllm.cpp/issues/1494) and [#1536](https://github.com/mudler/vllm.cpp/issues/1536) have spent months arguing about. A `Close` that waits on a contended mutex therefore makes that floor see an un-named phase, and the number a reader would subtract to see through it does not include this wait. [#1668](https://github.com/mudler/vllm.cpp/issues/1668) item 4 landed `instrument_seconds` precisely so the residue could be split into "the render did not name this" and "the instrument spent this"; this wait falls into neither. Found by the fresh review of [PR #1711](https://github.com/mudler/vllm.cpp/pull/1711) as a by-product of attempting the per-site charge gate of [#1718](https://github.com/mudler/vllm.cpp/issues/1718), and it is why that attempt could not be made honest. NOT FIXED IN FLOW: a production change to a shared instrument that four render paths run through, owing its own red-first evidence and its own mutation. It also interacts with the charge clamp #1711 lands -- a `Close` that charges a pre-lock interval charges it to the record about to end, so the per-target high-water mark seeded at `o.start` is what keeps the charge inside `[start, end]` and the conservation invariant intact; doing it before that clamp existed would have broken the invariant again. Owned by [`ltx25-phase-instrument.md`](specs/ltx25-phase-instrument.md) `## Owed` | bug | +| [#1720](https://github.com/mudler/vllm.cpp/issues/1720) | `LTX25-PHASE-INSTRUMENT` | **`WriteJson` reads `Elapsed()` and `Records()` under TWO separate acquisitions of the process-wide mutex, so `wall_seconds` and the record set are no longer one snapshot.** [PR #1711](https://github.com/mudler/vllm.cpp/pull/1711) moves `PhaseLog::WriteJson`'s clock read ABOVE its `ByStart(Records())` so the writer's own copy and sort stop being charged to the render's wall and therefore to `unaccounted_seconds` -- the defect [#1569](https://github.com/mudler/vllm.cpp/issues/1569) tracks -- and this issue is the cost of that repair recorded rather than hidden. Under the previous order the pair was effectively one snapshot in the direction that matters, because the clock was read LAST and `wall >= max(end_seconds)` held by construction; it no longer does. The observable if it broke is a NEGATIVE tail gap, which `gaps` reports and which `ltx2 phase log: the emitted table DECOMPOSES its residue into the gaps between leaves` refuses at `CHECK(seconds >= 0.0)`, so the table would say so rather than pass quietly. It is UNREACHABLE on the shipped path, and that is a property of the CALL SITE rather than of the function: both `WritePhaseLog` calls in `src/vllm/multimodal/ltx2_video.cpp` run after `generate_span.Close()`, that span is the last live scope, and `PhaseLog::Close` stops and JOINS the sampler before it returns when nothing is left live, so no thread can close a scope between those two lines on any path this project ships. A fresh review also failed to stage the inversion adversarially: 27,471 probes of a churn thread against a replica of the two statements produced zero. NOT FIXED IN FLOW: the real repair is to make the pair a single locked snapshot, and `Elapsed()` and `Records()` are separate public entry points on `PhaseLog`, so a combined one is a public API change and owes its own row, spec and red-first evidence rather than being smuggled into a repair commit for a different defect. Owned by [`ltx25-phase-instrument.md`](specs/ltx25-phase-instrument.md) `## Owed` | bug | diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 08f769604..2753e3801 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -44,7 +44,7 @@ OUT OF SCOPE, and each is named because each was tempting: - **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. +- **Any bound with `instrument_seconds` in a denominator.** See `## Design` 5. ## Our baseline @@ -108,7 +108,30 @@ 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 +### 4. The charges to one record are DISJOINT, so the conservation invariant is one + +`instrument_seconds <= duration_seconds` was asserted from the first version of +this row and it was **not an invariant**. `Open` and `Tick` read their clock +BEFORE taking the process-wide mutex, so the interval they charge to a record +spans a window in which another thread, holding that mutex, charges the SAME +record. Both charges are individually correct and they OVERLAP, and the sum of +overlapping intervals is not bounded by the interval that contains them. A fresh +review drove the ratio to **1.914** with 24 threads inside one live leaf, red in +3 runs of 5. + +`ChargeLocked` now clamps each charge to the end of the last one that reached +the same target, and seeds that mark with the record's own `start`. Every +charged interval then lies inside `[start, end]` and no two of them overlap, so +the sum is at most the duration **by construction**. Reproduced and gated: the +same shape now measures 0.09 to 0.996 over 45 runs and the mutation that removes +the clamp measures 4.0, 20.3 and 22.0. + +It can under-count, and that direction is deliberate: two charges arriving out +of order lose the earlier one. Under-counting is safe here only because this +quantity is in no denominator anywhere, which `## Design` 5 below is the reason +for. If it ever enters one, this clamp becomes a defect. + +### 5. 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) @@ -123,7 +146,7 @@ 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 +### 6. 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: @@ -137,11 +160,21 @@ numerator. 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 +copies and ZERO sorts; under any wrong order it holds at least ONE of the two in +full, so it is at least `1.0 * min(copy, sort)` **by the definition of the 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. +midpoint. + +**THE FIRST VERSION OF THIS PARAGRAPH WAS FALSE AND A FRESH REVIEW MEASURED IT.** +It bounded the head against `copy + sort` TOGETHER, on the argument that the +mutated head contains one of each. That holds only when both move. The reviewer +hoisted `Records()` above the clock read and left `ByStart` below it -- the +natural shape of a partial regression, and the exact edit somebody makes while +moving one line -- and the bound stayed GREEN at a ratio of 0.0588, because the +copy is about 6% of copy-plus-sort. Against `min(copy, sort)` that same mutation +is red -- **1.035** on the review's own run and **1.024** on the full re-run +against the repaired tree. The constant did not move; the quantity under it got +smaller. **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 @@ -153,6 +186,23 @@ 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. +### 7. The console copy answers the same question as the file copy + +A fresh review found the two had diverged. `phase-log.json` carried +`instrument_seconds` and `PhaseLog::RenderText` printed `sum(leaf)`, +`unaccounted` and `WALL` without it, so a reader watching a terminal saw the +residue with no way to subtract the cost of naming the phases from it -- which +is the whole reason that number exists. `RenderText` now prints it. + +The gate over it is not a measurement. `RenderText` formats every total with +`%10.3f`, so the printed value differs from the number it was given by strictly +less than half of the last digit -- 5e-4 seconds -- **by the definition of the +conversion**. The case reads that line back and compares it with `Instrument()` +through the public entry point. Nothing in it is timed, both sides read the same +number through two different code paths, and no box load can move the verdict. +Without it the added line is a production statement nothing reaches; `NTEXT` +deletes it and the case reds. + `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 @@ -233,10 +283,76 @@ FAILURE TEXT rather than by job name. | 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 | +| [#1570](https://github.com/mudler/vllm.cpp/issues/1570) | the bound on `instrument_seconds / duration_seconds`. It needs `instrument_seconds`, which this row lands. **Set it on a CARRYING LEAF, not per record.** See `### The instrument share, measured before it was proposed` below: on a leaf holding seconds of work the honest share is ~1e-4 and the margin is enormous, which is where #1570's actual concern lives -- an instrument that got ten times more expensive would be visible there. On a sub-scope of tens of microseconds it is not a gate at all | +| [#1568](https://github.com/mudler/vllm.cpp/issues/1568) | the `denoise.step` / `denoise.update` seconds transfer. `denoise.update` does not exist yet -- **and the obvious closure is now MEASURED SHUT.** See below | | [#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` | +| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | the charge sites are gated only in AGGREGATE. Three of this row's own mutations -- N4, N6 and NNOSORT -- are GREEN, and they are printed in the mutation table rather than left out | +| [#1719](https://github.com/mudler/vllm.cpp/issues/1719) | `PhaseLog::Close`'s pre-lock wait is charged to nobody, so it inflates the closing record's UNCOVERED time -- which is the quantity the coverage floor reads. It has to land before #1718 can, because it is where staged contention actually goes | +| [#1720](https://github.com/mudler/vllm.cpp/issues/1720) | `WriteJson` now takes the process-wide mutex TWICE, so `wall_seconds` and the record set are two snapshots rather than one. Unreachable on the shipped path and argued in the function's own comment; the repair is a single locked snapshot, which is a public API change | + +### Owed out of the fresh review + +Filed by the fresh review of this row and left open ON PURPOSE, with what each +one would take. None of them is a defect in what landed; each is a gate this row +could not make honest. + +| what | why it is not here | +|---|---| +| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) -- **a per-site charge gate.** Deleting any ONE charge site -- `Open`'s pre-lock mutex wait, `Open`'s tail, `Close`'s tail, the sampler join, `SampleLocked`'s self-charge -- leaves the suite green; only deleting every site reddens it. The worst is the pre-lock wait, which `## Design` 1 names as the reason the mechanism exists | A case for it was written and run THREE times and it does not measure the site. `PhaseLog::Records()` is the only public entry point that holds the mutex without charging itself, and contention through it lands mostly in `PhaseLog::Close`'s lock wait -- which is charged to nobody and lies inside the CHILD's duration, not the parent's charge. The case passed in isolation at 615x and failed 5 of 5 inside the suite. The full account is in the comment where it would have been | +| [#1719](https://github.com/mudler/vllm.cpp/issues/1719) -- **`Close`'s pre-lock wait is charged to nobody.** Found by the attempt above. `Open` reads a clock before its lock and `Close` does not, so the wait before a record's `end` is stamped is instrument wall that no record and no table absorbs | It is a production change to a shared instrument and it owes its own red-first evidence. It inflates the closing record's UNCOVERED time, which is the quantity the coverage floor reads | +| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) -- **`ChargeLocked`'s `if (from < 0.0) return;` is ungated.** Changing it to a clamp reddens nothing, although the comment beside it argues at length that clamping is the defect that makes a gate pass | Staging it needs a `Begin()` on another thread between `Open`'s clock read and its lock acquisition, which is a race this row could not make deterministic | +| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) -- **`ByStart`'s REMOVAL is held by nothing, although its INVERSION now is.** `NNOSORT` leaves the suite green and `NREVSORT` reds it | It cannot matter for the decomposition -- non-nested leaves are strictly sequential and already close in start order -- but `## Design` 3 leans on it and the emitted table's monotone-start assertion lives in `test_ltx2_video` | +| **The new suite writes about 8000 flushed `[render]` lines per run.** The live lane is on by the shipped default (#1413) and the #1569 case builds 8000 leaves | Silencing it needs `VLLM_RENDER_PROGRESS=0` at process start, and that would take the flushed progress line -- the most expensive statement in `Open`, and one of the charge sites -- out of everything this file measures | +| **A gap's `after` and `before` are ambiguous when a name repeats.** `decode.video` opens more than once per render, so two gaps can carry the same pair of names | The pairing assertion accepts it, and a reader wanting the exact region has `start_seconds` and `end_seconds`, which this row's repair made gated | + +### The instrument share, measured before it was proposed + +The natural way to close #1568 and #1570 at once, once `instrument_seconds` +exists, is a ceiling on `instrument_seconds / duration_seconds` per record: an +empty scope is nothing but its own boundaries, so its ratio approaches 1, while +a scope carrying work sits far below. #1568's R1b transfer leaves +`denoise.update` empty, so one ceiling would catch it. + +**That was measured on this tree before it was proposed, and at +`denoise.update`'s real scale it does not work.** A standalone probe opens two +nested scopes inside one parent -- one empty, one holding a sleep -- and reports +both ratios from one process. `VLLM_RENDER_PROGRESS=0`, this branch's binary, +`build/libvllm.a`: + +| work scope | n | EMPTY min | EMPTY median | WORK median | WORK max | separated? | +|---|---:|---:|---:|---:|---:|---| +| 5 ms | 60 | 0.3656 | 0.8520 | 0.0045 | 0.0097 | yes, 38x | +| ~1.1 ms | 60 | -- | -- | 0.0195 | 0.0528 | yes | +| ~134 us | 80 | 0.3914 | 0.8418 | 0.1248 | 0.2500 | barely, 1.57x | +| ~134 us | **200** | **0.0804** | 0.8487 | 0.1255 | **0.8930** | **NO -- they overlap completely** | + +The 80-sample row says the populations are separated by 1.57x. The 200-sample +row, same probe, same box, says the honest maximum (0.8930) is ELEVEN TIMES the +defective minimum (0.0804). **A small sample of this quantity does not see the +tail that decides the gate**, which is the same finding +[`ltx25-phase-residue.md`](ltx25-phase-residue.md) `## Design` 3 records for the +withdrawn bound, reached independently by a different route. + +The mechanism is the same one too, and its direction is worth stating. The part +of a boundary this instrument CANNOT measure -- the `lock_guard` release, the +`Close` return, the `Scope` destructor and constructor, the call into `Open` up +to its clock read -- dilates faster under contention than the part it can. It +sits inside the record and outside the charge, so a preemption there drives an +EMPTY scope's ratio DOWN toward an honest one's, and a preemption inside a tiny +honest scope's own boundaries drives it UP toward an empty one's. Both +populations move toward each other, and at 49 to 343 us -- which is what +`denoise.update` measures -- they meet. + +So #1568 stays open, and its own text was right for a reason it did not name: +"the honest distribution's bottom touches the defective value". It does, in this +formulation as well as in a coverage floor. + +#1570 survives, on a LEAF rather than a record. `denoise` is seconds of work +against an instrument charge measured in microseconds, so a ceiling there has +four orders of magnitude of margin and would still catch the ten-times-more- +expensive instrument #1570 is about. The row that lands `denoise.update` owes +that measurement on the real leaf. ## Evidence @@ -245,32 +361,62 @@ Measured on this branch, on an x86_64 box at load average 103 to 131 -- which is 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 two bounds, over 310 runs across five load regimes + +Every run's `test cases:` line was recorded, because a `-tc` filter that matches +nothing prints `0 cases ran` and `Status: SUCCESS!` and is indistinguishable +from a green run in a log or an `&&` chain. Every run of the whole suite also +read `assertions: N | N passed | 0 failed`. + +**Before the fresh review**, on the one-number `copy + sort` budget: + +| population | n | load | min | median | p90 | max | +|---|---:|---|---:|---:|---:|---:| +| the #1569 case alone | 50 | 103-131 | 0.000716 | 0.002308 | 0.003115 | **0.004228** | +| the whole suite | 60 | 20-28 | 0.000320 | 0.000759 | 0.001145 | 0.001894 | +| the #1569 case alone | 50 | 57-83 | 0.001650 | 0.002600 | 0.003648 | 0.004197 | +| the whole suite | 60 | 35-48 | 0.000320 | 0.000759 | 0.001145 | 0.001894 | + +**After it**, on the repaired `min(copy, sort)` budget, which is about ten times +smaller and therefore about ten times tighter: -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`. +| population | n | load | min | median | p90 | max | margin | +|---|---:|---|---:|---:|---:|---:|---:| +| `head / min(copy, sort)` | 45 | 58-85 | 0.00198 | 0.00444 | 0.00654 | **0.00958** | **52x** | +| `instrument / duration`, 24 threads | 45 | 58-85 | 0.0904 | 0.9920 | 0.9945 | **0.9961** | bound 1.0 | -| 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 | +**And re-measured over 45 further runs of the WHOLE suite against the tree that +actually lands**, which is not the tree the two rows above were taken on: the +`RenderText` gate is new, and it is the only quantity a re-run could have moved. -**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: +| population | n | load | min | median | p90 | max | margin | +|---|---:|---|---:|---:|---:|---:|---:| +| `head / min(copy, sort)` | 45 | 56-113 | 0.003744 | 0.006467 | 0.010502 | **0.018123** | **27.6x** | +| `instrument / duration`, 24 threads | 45 | 56-113 | 0.0723 | 0.9928 | 0.9962 | **0.99756** | bound 1.0 | + +All 45 read `test cases: 5 | 5 passed | 0 failed` and +`assertions: 93 | 93 passed | 0 failed` -- the SAME string on every run, which is +what rules out a filter that matched nothing. The margin is 27.6x rather than +52x because this population is a load regime higher, and that is the direction a +reader should expect: the honest head grows with contention and the budget under +it does not. + +**0 red in 310.** And the defective values are not near either bound: ``` -honest [0.00072 .. 0.00423] bound 0.5 defective ~1.004 +#1569 honest [0.0037 .. 0.0181] bound 0.5 main's order 17.2, partial regression 1.024 +conservation honest [0.072 .. 0.99756] bound 1.0 no clamp 21.97 ``` -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 conservation ratio sits just under its bound BY CONSTRUCTION and a reader +should not read that as a bound about to flap. That leaf is 24 threads ticking +and almost nothing else, so almost all of it IS instrument. It cannot cross 1.0 +on a slow box, because the charges to one record are disjoint intervals inside +it: the arithmetic holds it, not the margin. + +Contrast the withdrawn bound: 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 its own scatter +and 4 runs in 45 crossed it. ### The mutation table @@ -281,18 +427,44 @@ 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. +THE WHOLE SET WAS RE-RUN AGAINST THE REPAIRED TREE, not carried over from the +run that preceded the fresh review, because three of the repairs change what the +suite can see. Every entry below is from that re-run. + | 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 | +| M1 | `WriteJson` reads its clock AFTER the copy and sort, i.e. `main`'s code | RED, head 8.331 ms against a budget of 0.484 ms -- 17.2x | +| N11 | the clock read moves BELOW the copy and stays ABOVE the sort -- a PARTIAL regression, which the one-number budget missed at 0.0588 | RED, 1.024 | +| NCLAMP | the per-target high-water mark is removed, so overlapping charges are counted twice again | RED, charged 9.491 s of a 0.432 s record -- 21.97 | +| M2 | the decomposition drops the FIRST gap -- the prologue, 92% of a real residue | RED on 4: the first gap's origin, the identity, the count, and the prologue's own floor | +| M3 | the decomposition counts NESTED records as leaves | RED on 3: a negative gap at -1.198 ms, the identity, the count | +| M7 | the tail gap reported as zero, count and names untouched | RED on 2: the endpoint agreement and the identity | | 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 | +| M6 | the per-record charge is not emitted | RED at `REQUIRE(e.contains("instrument_seconds"))` | +| NEND | every gap's `start_seconds` and `end_seconds` zeroed, `seconds` untouched | RED on 4 -- and GREEN before this row's repair, which is why the endpoints are now read | +| NREVSORT | `ByStart` orders the table by DESCENDING start | RED at `CHECK(seconds >= 0.0)` on -16.996 ms | +| NTEXT | `RenderText` stops printing the instrument charge, so the console and the file copies answer different questions | RED at `REQUIRE(at != std::string::npos)` | | 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)` | +| N4 | `ChargeLocked`'s negative-`from` refusal becomes a clamp | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | +| N6 | `Open`'s pre-lock wait is computed and charged to nothing | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | +| NNOSORT | `ByStart` stable-sorts an empty range, i.e. does not sort at all | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | + +THE THREE GREENS ARE THE POINT OF PRINTING THEM. A mutation table that lists +only its successes is an argument and not a measurement, and these three are +what [#1718](https://github.com/mudler/vllm.cpp/issues/1718) is. `NREVSORT` +beside `NNOSORT` says exactly how much of `ByStart` is held: an inversion is +caught and a removal is not, because every timeline this suite builds is already +start-ordered. + +N6's FIRST STAGING DID NOT COMPILE, and that is worth a line because it is the +trap this project keeps walking into. Written as `if (false) { ... }` it left +`entered` unused and failed `-Werror` with `compile_status=1`. A mutation that +fails to build reads exactly like a passing test; only the printed compile +status separated the two. Re-staged as a `(void)` cast of the same expression it +compiles, and it is green. 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`, @@ -332,7 +504,7 @@ What was measured, and what was rejected: 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, + in `## Design` 6: 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. diff --git a/src/vllm/multimodal/render_phase_log.cpp b/src/vllm/multimodal/render_phase_log.cpp index d77a8e4aa..ebd5a26ea 100644 --- a/src/vllm/multimodal/render_phase_log.cpp +++ b/src/vllm/multimodal/render_phase_log.cpp @@ -99,6 +99,11 @@ struct PhaseLog::Impl { size_t handle = 0; // THE INSTRUMENT'S OWN WALL, charged to this record. See `ChargeLocked`. double instrument = 0.0; + // The end of the last interval charged to this record, so two overlapping + // charges cannot be counted twice. Seeded with the record's own `start`, so + // a charge whose clock read happened BEFORE this record existed cannot reach + // back past it either. See `ChargeLocked`. + double instrument_charged_to = 0.0; std::string name; int64_t render = 0; double start = 0.0; @@ -118,6 +123,8 @@ struct PhaseLog::Impl { // `unaccounted_seconds` this instrument spent rather than the render. See // `ChargeLocked`. double instrument_gap = 0.0; + // The same high-water mark for the table's own share. See `ChargeLocked`. + double instrument_gap_charged_to = 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. @@ -185,13 +192,50 @@ struct PhaseLog::Impl { // dropped. if (from < 0.0) return; if (!(to > from)) return; + // ── WHY EACH TARGET CARRIES A HIGH-WATER MARK ──────────────────────────── + // + // A fresh review broke the invariant `instrument_seconds <= duration_seconds` + // and it took no race to do it. `Open` and `Tick` read their clock BEFORE + // they take this mutex, so the interval they charge to a record spans a + // window in which ANOTHER thread — the 100 ms sampler, or a second caller — + // can hold the mutex and charge the SAME record. Both charges are correct + // individually and they OVERLAP, so their sum exceeded the record's own + // single-threaded duration: 24 threads calling `SampleNow()` inside one live + // leaf drove that ratio to 1.914, red in 3 runs of 5. + // + // Clamping `from` to the end of the last interval already charged to this + // target makes the charges disjoint, so their sum is at most the UNION of + // the intervals. The mark starts at the record's OWN `start`, so the union + // also cannot reach back before the record began -- which a `Tick` whose + // clock read predates the record and whose lock acquisition follows it would + // otherwise do. Every charged interval then lies inside `[start, end]` and + // no two of them overlap, so `instrument_seconds <= duration_seconds` holds + // by construction rather than by hoping the box stays quiet. + // + // IT CAN UNDER-COUNT, and that direction is deliberate. Two charges that + // arrive out of order — a later `to` first, then an earlier interval — lose + // the earlier one entirely. Under-counting the instrument is the safe + // direction here BECAUSE this quantity is in no denominator anywhere: a + // smaller charge makes every gate that reads it stricter, never looser, and + // `.agents/specs/ltx25-phase-residue.md` `## Design` 3 is why it is in no + // denominator. The opposite choice — counting the overlap — makes a bound + // pass, and a defect that makes a gate pass is the one nobody finds. for (size_t i = open.size(); i > 0; --i) { Open& o = open[i - 1]; if (!o.live || o.span) continue; - o.instrument += to - from; + const double start = from > o.instrument_charged_to ? from : o.instrument_charged_to; + if (to > start) { + o.instrument += to - start; + o.instrument_charged_to = to; + } return; } - instrument_gap += to - from; + const double start = + from > instrument_gap_charged_to ? from : instrument_gap_charged_to; + if (to > start) { + instrument_gap += to - start; + instrument_gap_charged_to = to; + } } // Caller holds `mu`. Reads both counters once and folds them into every open @@ -301,6 +345,7 @@ void PhaseLog::Begin() { impl_->render = 0; impl_->samples = 0; impl_->instrument_gap = 0.0; + impl_->instrument_gap_charged_to = 0.0; impl_->device_probe = DeviceByteProbe(); } @@ -346,6 +391,7 @@ size_t PhaseLog::Open(const std::string& name, bool span) { o.name = name; o.render = impl_->render; o.start = impl_->Now(); + o.instrument_charged_to = o.start; o.span = span; o.live = true; bool leaf_already_open = false; @@ -542,6 +588,7 @@ void PhaseLog::Reset() { impl_->render = 0; impl_->samples = 0; impl_->instrument_gap = 0.0; + impl_->instrument_gap_charged_to = 0.0; impl_->device_probe = DeviceByteProbe(); } @@ -646,6 +693,25 @@ bool PhaseLog::WriteJson(const std::string& path, const std::string& family, // 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. + // + // AND THE COST OF THAT ORDER, WHICH A FRESH REVIEW ASKED FOR IN WRITING. The + // wall below and the records on the next line are taken under TWO separate + // acquisitions of the process-wide mutex, so they are no longer one snapshot. + // Before this order they were effectively one in the direction that matters: + // the clock was read last, so `wall >= max(end_seconds)` held by + // construction. It no longer does, and the observable if it broke is a + // NEGATIVE tail gap, which `gaps` reports and the unit case refuses. + // + // IT IS UNREACHABLE ON THE SHIPPED PATH, and that is a property of the CALL + // SITE rather than of this function. Both `WritePhaseLog` calls in + // `ltx2_video.cpp` run after `generate_span.Close()`, that span is the last + // live scope, and `PhaseLog::Close` stops and JOINS the sampler before it + // returns when nothing is left live. So no thread can close a scope between + // these two lines on any path this project ships. A fresh review also failed + // to stage an inversion adversarially: 27,471 probes of a churn thread + // against a replica of these two statements produced zero. Making the pair a + // single locked snapshot is the real repair and it is a public API change; + // it is recorded as owed rather than smuggled in here. const double wall = Elapsed(); const std::vector records = ByStart(Records()); const Totals totals = Sum(records, wall); @@ -789,6 +855,14 @@ std::string PhaseLog::RenderText(const std::string& family, const std::string& d out += line; std::snprintf(line, sizeof(line), " %-4s %-30s %10s %10.3f\n", "", "WALL", "", totals.wall); out += line; + // AND WHAT THE INSTRUMENT CHARGED ITSELF, so the console copy and the file + // copy answer the same question. A fresh review found the two had diverged: + // `phase-log.json` carried `instrument_seconds` and this block did not, so a + // reader watching a terminal saw a residue with no way to subtract the cost of + // naming the phases from it -- which is the whole reason that number exists. + std::snprintf(line, sizeof(line), " %-4s %-30s %10s %10.3f\n", "", "instrument", "", + Instrument()); + out += line; return out; } diff --git a/tests/vllm/multimodal/test_render_phase_log.cpp b/tests/vllm/multimodal/test_render_phase_log.cpp index 608609c0b..2a786589b 100644 --- a/tests/vllm/multimodal/test_render_phase_log.cpp +++ b/tests/vllm/multimodal/test_render_phase_log.cpp @@ -30,6 +30,7 @@ // ratio here. #include +#include #include #include #include @@ -266,6 +267,191 @@ TEST_CASE("ltx2 phase log: the instrument's own cost is CONSERVED across the tab << "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"); + + // AND THE CONSOLE COPY ANSWERS THE SAME QUESTION AS THE FILE. `RenderText` is + // what a reader watching a terminal gets, and it printed `sum(leaf)`, + // `unaccounted` and `WALL` while the file alone carried `instrument_seconds` + // — so the residue was on screen with no way to subtract the cost of naming + // the phases from it, which is the whole reason that number exists. This + // assertion is the only thing holding the two copies together, and without it + // the line is a production statement nothing reaches. + // + // THE TOLERANCE IS THE FORMAT'S OWN RESOLUTION AND NOT A MEASUREMENT. + // `RenderText` prints every total with `%10.3f`, so the printed value differs + // from the number it was given by strictly less than half of the last digit, + // 5e-4 seconds, by the definition of the conversion. No box load can move + // that, because nothing here is timed: both sides read the SAME `Instrument()` + // through two different code paths. + const std::string text = log.RenderText("unit", "cpu"); + const std::string::size_type at = text.find("instrument"); + REQUIRE_MESSAGE(at != std::string::npos, + "`RenderText` prints sum(leaf), unaccounted and WALL and no instrument " + "charge, so the console copy of this table cannot separate the residue the " + "render produced from the residue this instrument produced. The file copy " + "carries it and they have to answer the same question:\n" + << text); + const double printed = std::strtod(text.c_str() + at + std::string("instrument").size(), + nullptr); + CHECK_MESSAGE(std::fabs(printed - log.Instrument()) < 5e-4, + "`RenderText` prints " << printed << "s of instrument charge and `Instrument()` " + << "returns " << log.Instrument() + << "s. The console copy is printing some other number, and 5e-4 is this " + "line's own %10.3f resolution rather than a tolerance:\n" + << text); + log.Reset(); +} + +// ─── WHY THERE IS NO PER-SITE CHARGE CASE HERE (F1, and it was TRIED) ─────── +// +// A fresh review found that the attribution rule is gated only in AGGREGATE: +// deleting any ONE charge site -- `Open`'s pre-lock mutex wait, `Open`'s tail, +// `Close`'s tail, the sampler join, `SampleLocked`'s self-charge -- leaves this +// whole file green, and only deleting every site at once reddens it. The worst +// of those is the pre-lock wait, because `## Design` 1 and `Open`'s own comment +// both name that interval as the reason `instrument_seconds` exists. +// +// A case for it was written and run, three times, and it is NOT here because it +// does not measure that site. What each cut found: +// +// 1. Two parents, one contended by a reader thread, compared by charge. The +// QUIET parent was slower, because it ran first and paid for the record +// vector's reallocation -- a copy that happens under the mutex inside +// `Close` and is charged to the parent. +// 2. With a warm-up parent absorbing the growth, the reader thread had not +// reached its first copy before the 330 us measurement window closed. +// 3. With four readers, a 16 MiB critical section and a start barrier, the +// case passed in ISOLATION at a separation of 615x -- and failed 5 of 5 +// runs inside this suite, twice because no reader held the lock at all and +// three times because a contended parent that took 21 ms was charged +// 112 us. +// +// THAT LAST NUMBER IS THE FINDING. Contention through `Records()` -- the only +// public entry point that holds this mutex without charging itself, which is +// what makes it usable as a hold at all -- lands mostly in `PhaseLog::Close`'s +// lock wait. `Close` has no pre-lock clock read, so that wait is charged to +// NOBODY, and it lies inside the CHILD's own duration rather than in the +// parent's charge. So a parent-against-parent comparison does not track the +// site under test, however the contention is arranged. +// +// Both halves are recorded under `## Owed` in +// `.agents/specs/ltx25-phase-instrument.md`: the per-site gate, and the +// uncharged `Close` wait this attempt found. A flaky gate over an instrument +// whose whole subject is flaky gates would be the joke that writes itself. + +// ─── the accounting stays CONSERVED when several threads charge one record ─── +// +// F3 of the fresh review, and it was a real defect rather than a missing test. +// `instrument_seconds <= duration_seconds` was asserted, documented as an +// invariant, and was NOT one: `Open` and `Tick` read their clock before taking +// the mutex, so their charge to a record spans a window in which another thread +// holding the mutex charges the SAME record. The sum was over OVERLAPPING +// intervals while the duration is one wall interval, and 24 threads calling +// `SampleNow()` inside one live leaf drove the ratio to 1.914, red in 3 runs of +// 5. +// +// `ChargeLocked` now clamps each charge to the end of the last one that reached +// the same target, so the charges are disjoint and their sum is at most their +// union. This case is what holds that, and it is the reviewer's own probe shape. +TEST_CASE("ltx2 phase log: a record charged from MANY THREADS is still charged less than it lasted") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + + // THE HAMMER TICKS, AND WHICH ENTRY POINT IT USES IS THE WHOLE REPRODUCTION. + // + // * `PhaseLog::Sample` reads its clock INSIDE the mutex, so concurrent + // samples are serialised and their charges are already disjoint. A first + // cut of this case used one and measured 0.29 -- and stayed GREEN under + // the very mutation it was written for, which is the trap this whole + // cluster is about. + // * Opening SIBLING scopes does not work either: while several siblings are + // live, "the innermost live non-span record" resolves to a sibling rather + // than to the leaf under test, so the overlapping charges land somewhere + // else. + // * `PhaseLog::Tick` reads its clock BEFORE the mutex and pushes nothing, so + // the innermost live record stays the leaf. N threads blocked on the same + // acquisition each charge their OWN full wait to it, and those waits + // overlap by construction. That is the shape that breaks the invariant. + // AND A BLOCKER MAKES THE PILE-UP DETERMINISTIC. `SetDeviceProbe` installs a + // callback that `SampleLocked` runs WHILE HOLDING the mutex, so a probe that + // sleeps holds it for a known time. Without one the ticking threads spread out + // and mostly do not queue: the unclamped tree measured 1.85 on one run and + // 0.29 on the next, so the mutation that removes the repair went GREEN. A + // detector that fires sometimes is exactly what #1569 is about. + std::atomic blocking(false); + log.SetDeviceProbe([&blocking]() -> int64_t { + if (blocking.load(std::memory_order_relaxed)) { + std::this_thread::sleep_for(std::chrono::milliseconds(2)); + } + return -1; + }); + + const size_t leaf = log.Open("unit.hammered", /*span=*/false); + const int kThreads = 24; + const int kRounds = 12; + std::atomic ready(0); + std::atomic stop_blocker(false); + blocking.store(true, std::memory_order_relaxed); + std::thread blocker([&stop_blocker]() { + while (!stop_blocker.load(std::memory_order_relaxed)) phase::SampleNow(); + }); + std::vector hammers; + hammers.reserve(kThreads); + for (int t = 0; t < kThreads; ++t) { + hammers.emplace_back([&ready, kRounds, t]() { + ready.fetch_add(1, std::memory_order_relaxed); + for (int i = 0; i < kRounds; ++i) { + phase::Tick("unit.hammer", static_cast(t), "concurrent"); + } + }); + } + for (std::thread& h : hammers) h.join(); + stop_blocker.store(true, std::memory_order_relaxed); + blocker.join(); + blocking.store(false, std::memory_order_relaxed); + log.SetDeviceProbe(phase::DeviceByteProbe()); + log.Close(leaf); + REQUIRE(ready.load() == kThreads); + // THE LIVE LANE HAS TO BE ON FOR THIS CASE TO MEAN ANYTHING. `Tick` returns + // immediately when `VLLM_RENDER_PROGRESS=0`, so a process that silenced it + // would run this case as 24 threads doing nothing at all. + REQUIRE_MESSAGE(phase::ProgressEnabled(), + "VLLM_RENDER_PROGRESS is off in this process, so `phase::Tick` returned " + "without taking the mutex and the 24 threads above contended over nothing. " + "This case measured an instrument that is switched off"); + + double charge = -1.0; + double duration = -1.0; + for (const phase::Record& r : log.Records()) { + if (r.name != "unit.hammered") continue; + charge = r.instrument_seconds; + duration = r.end - r.start; + } + REQUIRE(duration > 0.0); + // THE RATIO SITS JUST UNDER 1 ON PURPOSE, and a reader should not read that as + // a bound about to flap. Measured over 45 runs at load 58-85: median 0.9920, + // maximum 0.9961. This leaf is 24 threads ticking and almost nothing else, so + // almost all of it IS instrument -- that is what the case constructs. The + // bound cannot be crossed by a slow box, because the charges to one record are + // disjoint intervals inside it: the arithmetic, not the margin, is what holds. + MESSAGE("unit.hammered = " << duration << "s, charged " << charge << "s by " << kThreads + << " threads (ratio " << (charge / duration) << ")"); + // THE PRECONDITION. If the hammer threads charged nothing, the bound below is + // satisfied by an instrument that is not running. + REQUIRE_MESSAGE(charge > 0.0, + "24 threads ticked inside a live leaf and it was charged nothing, so this " + "case is measuring an instrument that is switched off rather than an " + "invariant"); + // AND NO TOLERANCE, BEYOND THE ONE THE SUM OF DOUBLES NEEDS. This is not a + // measurement: the charges to one record are disjoint intervals inside it, so + // their sum cannot exceed it. A box under load moves both numbers and moves + // neither verdict -- which is what the previous version of this claim said and + // was wrong about, before the clamp existed. + CHECK_MESSAGE(charge <= duration + 1e-9, + "'unit.hammered' lasted " << duration << "s and was charged " << charge + << "s, which is more instrument than record. Charges to one record must be " + "disjoint; overlapping ones are being counted twice, and every reader " + "who subtracts this number from a residue would subtract too much"); log.Reset(); } @@ -280,12 +466,23 @@ TEST_CASE("ltx2 phase log: the instrument's own cost is CONSERVED across the tab // 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 IDENTITY IS ARITHMETIC RATHER THAN A TOLERANCE, AND IT HOLDS EXACTLY ONE +// THING. A fresh review did the algebra: the gap sum telescopes to +// `wall - sum(durations)` for ANY record sequence -- ordered or not, overlapping +// or not -- so the identity cannot see a reordering, and the reviewer confirmed +// it by execution, reversing the record order and watching the identity stay +// green while two other assertions fired. The comment here used to claim it +// caught a mis-ordering. It does not. +// +// WHAT IT DOES HOLD is that `GapsBetweenLeaves` and `Sum` select the SAME +// records: both skip `span` and both skip `nested`. A decomposition that walked +// a different population -- one that counted a nested record, or dropped one, or +// stopped short of `wall` -- fails by an amount no box load can supply. That is +// the whole of it, it is worth having, and three of this file's mutations are +// caught by nothing else. +// +// The ORDER, the POSITIONS and the NAMES are held below by (1), (2) and (3), +// which is where those claims belong. // // 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 @@ -337,20 +534,32 @@ TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gap 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. + // (1) NO GAP IS NEGATIVE, EACH ONE'S SECONDS ARE ITS OWN ENDPOINTS, AND THEY + // ADD TO THE RESIDUE. All non-fatal and all first, 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 — so the negative gap that same mutation produces went + // unobserved, and two of this case's assertions were unproven while the case + // reddened. + // + // THE ENDPOINTS ARE READ, WHICH A FRESH REVIEW FOUND THEY WERE NOT. They were + // emitted and asserted nowhere: zeroing both left this whole file green. They + // are the half a reader uses to LOCATE a region, and locating one was the + // entire content of #1571 — 92% of a residue sat at one position, and a + // decomposition that says how long a gap is but not where it starts sends the + // reader back to the script it replaced. 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")); + REQUIRE(g.contains("start_seconds")); + REQUIRE(g.contains("end_seconds")); const double seconds = g["seconds"].get(); + const double from = g["start_seconds"].get(); + const double to = g["end_seconds"].get(); INFO("gap " << i << " = " << g["after"].get() << " -> " << g["before"].get()); CHECK_MESSAGE(seconds >= 0.0, @@ -359,8 +568,35 @@ TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gap << "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"); + CHECK_MESSAGE(std::fabs((to - from) - seconds) < 1e-9, + "gap " << i << " runs from " << from << "s to " << to << "s, a span of " + << (to - from) << "s, and reports " << seconds + << "s. A reader who sorts by `seconds` and then looks up the region at " + "those endpoints would be sent somewhere else"); gap_total += seconds; } + // AND THE GAPS TILE THE TIMELINE, WHICH IS WHERE THE ORDER IS ACTUALLY HELD. + // Each gap starts where the previous one ended plus the leaf between them, the + // first starts at the origin, and the last ends at `wall`. The identity below + // cannot see any of that — it telescopes for any sequence at all. + CHECK_MESSAGE(gaps.front()["start_seconds"].get() == 0.0, + "the first gap starts at " << gaps.front()["start_seconds"].get() + << "s rather than at the timeline's origin, so whatever ran before it is " + "outside the decomposition entirely"); + CHECK_MESSAGE(std::fabs(gaps.back()["end_seconds"].get() - + table["wall_seconds"].get()) < 1e-9, + "the last gap ends at " << gaps.back()["end_seconds"].get() + << "s and the render's wall is " << table["wall_seconds"].get() + << "s, so the tail of the timeline is outside the decomposition"); + for (size_t i = 1; i < gaps.size(); ++i) { + INFO("gap " << i); + CHECK_MESSAGE(gaps[i]["start_seconds"].get() >= + gaps[i - 1]["end_seconds"].get() - 1e-9, + "gap " << i << " starts at " << gaps[i]["start_seconds"].get() + << "s, BEFORE gap " << (i - 1) << " ended at " + << gaps[i - 1]["end_seconds"].get() + << "s. The decomposition is not walking the timeline in order"); + } // THE IDENTITY. No tolerance beyond double rounding over a handful of // additions: this is the same arithmetic `Sum` does, read from the other side. @@ -443,9 +679,20 @@ TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gap // 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. +// * `copy` and `sort` — those two steps, performed by this case through the +// same public `Records()`, on the same data, on this box, in this run. +// MEASURED SEPARATELY, and the bound is against the SMALLER of them. +// +// THE TWO ARE SEPARATE BECAUSE A FRESH REVIEW BROKE THE ONE-NUMBER FORM. This +// case first bounded the head against `copy + sort` together, on the argument +// that the mutated head contains one of each and is therefore at least 1.0x +// their sum. That is true only when BOTH move. The reviewer hoisted `Records()` +// above the clock read and left `ByStart` below it -- the natural shape of a +// partial regression, and the exact edit somebody makes while "just moving one +// line" -- and the bound stayed GREEN at a ratio of 0.0588, because the copy is +// about 6% of copy-plus-sort on this data. Against `min(copy, sort)` that same +// mutation is red. The constant did not move; the quantity under it got smaller, +// which is the only direction a repair may take a bound. // // 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, @@ -460,11 +707,12 @@ TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gap // 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. +// head contains ZERO copies and ZERO sorts. Under any wrong ordering it contains +// at least ONE of the two steps in full, so it is at least +// `1.0 x min(copy, sort)` by the definition of the quantities. Any constant +// strictly between 0 and 1 separates them; 0.5 is the midpoint. What the +// measurement decides is not the constant but whether the separation is real, +// and it is: see `## Evidence` in the row's spec. TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the table") { phase::PhaseLog& log = phase::PhaseLog::Instance(); log.Reset(); @@ -474,7 +722,22 @@ TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the // 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; + // 8000 RATHER THAN 4000, and the reason is the budget below rather than the + // sort. The bound is against the CHEAPER of the writer's two post-clock steps, + // which is the copy, and the copy is linear in the record count while the + // honest head does not depend on it at all. Doubling the table doubles the + // margin. Three records made this ungateable in the first place (#1569). + const int kRecords = 8000; + // AND A NAME LONGER THAN THE SMALL-STRING BUFFER, which is not decoration. + // The budget below is the CHEAPER of the writer's two post-clock steps, and + // with a short name the copy is a flat memcpy while the sort is `n log n`, so + // the copy is the cheap one by a factor of twenty and it sets the whole + // budget. A name past `std::string`'s inline buffer makes the copy allocate + // once per record, which is what the LTX-2.5 table's own names + // (`decode.video.chunk`, `artifacts.frames.ppm`) do anyway. The two steps then + // sit within one order of magnitude of each other and the budget stops being + // decided by an implementation detail of `std::string`. + const std::string kLeafName = "unit.leaf.with.a.name.past.the.small.string.buffer"; // 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 @@ -482,14 +745,15 @@ TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the { const phase::Scope holder("unit.holder", /*span=*/true); for (int i = 0; i < kRecords; ++i) { - const phase::Scope leaf("unit.leaf"); + const phase::Scope leaf(kLeafName); } } const TableFile file; const int kProbes = 5; double head = -1.0; - double serialize = -1.0; + double copy_cost = -1.0; + double sort_cost = -1.0; int64_t emitted = 0; for (int k = 0; k < kProbes; ++k) { const double before_call = log.Elapsed(); @@ -499,22 +763,30 @@ TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the 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(); + // THE DISCRIMINATOR, MEASURED THE SAME WAY THE WRITER DOES IT, AND IN THE + // SAME TWO STEPS. `Records()` returns a copy taken under the process-wide + // mutex and `ByStart` stable-sorts that copy; this is the same copy and the + // same sort through the same public entry point, so these are the costs the + // writer would pay after its clock read rather than numbers quoted from + // another box. + const double before_copy = log.Elapsed(); std::vector copy = log.Records(); + const double after_copy = log.Elapsed(); 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; + const double after_sort = log.Elapsed(); // 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; + const double this_copy = after_copy - before_copy; + const double this_sort = after_sort - after_copy; + if (copy_cost < 0.0 || this_copy < copy_cost) copy_cost = this_copy; + if (sort_cost < 0.0 || this_sort < sort_cost) sort_cost = this_sort; } + // THE SMALLER OF THE TWO STEPS IS THE BUDGET. A wrong ordering puts at least + // one of them after the clock read, so the head is at least this large. + const double serialize = copy_cost < sort_cost ? copy_cost : sort_cost; REQUIRE_MESSAGE(emitted >= kRecords, "the timeline was built with " << kRecords << " leaves and the table carries " @@ -526,19 +798,23 @@ TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the // `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) << ")"); + "the CHEAPER of the writer's two post-clock steps over " << emitted + << " records measured " << serialize + << "s (copy " << copy_cost << "s, sort " << sort_cost + << "s), which is at or below this clock's own resolution. A wrong " + "ordering is detected by whichever step it moves, so a step this cheap " + "cannot be detected at all -- which is exactly why the three-record " + "case in #1569 stayed green under its own mutation"); + MESSAGE("writer clock lag " << head << "s against copy " << copy_cost << "s and sort " + << sort_cost << "s over " << emitted << " records (min of " + << kProbes << " probes, budget " << serialize << "s, 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 + "against the cheaper of its two measured post-clock steps at " + << serialize << "s (copy " << copy_cost << "s, sort " << sort_cost + << "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"); From 27f17d14f5a7201a0dbb94761bd4c72ff23deb80 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sat, 22 Aug 2026 21:18:53 +0000 Subject: [PATCH 04/12] fix(LTX25-PHASE-INSTRUMENT): the console gate was VACUOUS, the table arm was ungated, and two gap assertions were tautologies A second fresh review of this branch returned one blocking finding and three that measured assertions this row had already added. All four are repaired here. B1, BLOCKING. The gate for the console copy was vacuous. It compared `RenderText`'s printed instrument charge with `Instrument()` inside the conservation case, whose three-scope timeline charges the table 2.80e-4 to 2.95e-4 s -- SMALLER than the 5e-4 tolerance the `%10.3f` format defines. So `0.000` is what the honest value prints, and the comparison was satisfied by anything in (-5e-4, +5e-4), the literal 0.0 included: replacing `Instrument()` with `0.0` in the production line left the whole file green at 5 cases and 93 assertions. That is #1569's own failure reproduced inside #1569's own repair. The gate moves to its own case with 4000 sequential scopes, where the table's share measures 0.40 to 0.44 s -- about 800x the format's last digit -- and a `REQUIRE` refuses to assert when the quantity is below the resolution of the thing it reads, exactly as #1569's `serialize > 1e-5` does. N1. `ChargeLocked` has two targets and only the RECORD arm was gated: removing the TABLE arm's high-water mark left the suite green, because every case charged the table from one thread, where the intervals are already disjoint. A case now hammers `Tick` from 24 threads with NOTHING live, so every charge lands on the table, and asserts `Instrument() <= wall`. That is arithmetic rather than a measurement, and it holds at 0.993 honest. That mutation's first run is itself worth recording: the new case's name carried a COMMA, doctest's `-tc` filter splits on commas, and the run printed `test cases: 0 | 0 passed | 0 failed | 7 skipped` with `Status: SUCCESS!` at rc=0. Only the printed case count separated it from a mutation the suite genuinely does not catch. The comma is gone. N4. Two of the four gap assertions added for the endpoints finding were tautologies. Inside this emitter `gaps[i].start >= gaps[i-1].end` reduces to a non-negative leaf duration, and `gaps.front().start == 0.0` is constant-true unless the first gap is dropped, because `cursor` is initialised to that literal. The reviewer staged `cursor = r.start`, so every gap swallows the leaf before it, and both passed. They are replaced by one comparison with power: each gap's endpoints are checked against the leaf records it lies between, read out of the same emitted table, and that mutation cannot survive it. NSEED stays GREEN and is recorded rather than left out: the per-record mark's SEED, the half that stops a charge reaching back before the record began, is held by nothing, because staging it needs a `Tick` whose clock read predates a record and whose lock acquisition follows it. It is added to #1718, and #1720 now also names `RenderText`, which takes the mutex three times for one table. The whole mutation set was re-run against this tree: 17 red, 4 green and printed as green. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [Claude Code] --- .agents/specs/ltx25-phase-instrument.md | 72 +++++- .../vllm/multimodal/test_render_phase_log.cpp | 229 +++++++++++++++--- 2 files changed, 257 insertions(+), 44 deletions(-) diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 2753e3801..3a2966754 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -200,8 +200,46 @@ less than half of the last digit -- 5e-4 seconds -- **by the definition of the conversion**. The case reads that line back and compares it with `Instrument()` through the public entry point. Nothing in it is timed, both sides read the same number through two different code paths, and no box load can move the verdict. -Without it the added line is a production statement nothing reaches; `NTEXT` -deletes it and the case reds. + +**AND THE QUANTITY HAS TO BE ABOVE THAT RESOLUTION, WHICH A SECOND FRESH REVIEW +MEASURED THAT IT WAS NOT.** The first version of this gate lived inside the +conservation case, on its three-scope timeline, where `Instrument()` is +**2.80e-4 to 2.95e-4 s -- SMALLER than the tolerance**. `%10.3f` therefore +prints `0.000` for the honest value and the comparison is satisfied by anything +in `(-5e-4, +5e-4)`, the literal `0.0` included. The reviewer replaced +`Instrument()` with `0.0` in the production line and the whole file stayed GREEN +at `5 | 5 passed` and `93 | 93 passed`. + +That is #1569's own failure reproduced inside #1569's own repair: a +discriminator below the instrument's resolution cannot discriminate. The repair +is the one #1569 itself took -- make the quantity an EVENT and REFUSE to assert +when it is not. The gate now has its own case with 4000 sequential scopes, where +the table's own share measures **0.40 to 0.44 s, about 800x the format's last +digit**, and a `REQUIRE` above it says so out loud rather than passing quietly +on a table too cheap to print. `NTEXTZERO` reds there; so does `NTEXT`, which +deletes the line. + +### 8. The table's own charge is disjoint too, and that is a SECOND arm + +`ChargeLocked` has two targets and the clamp landed on both, but the second +review found only the RECORD arm was gated: removing the TABLE arm's high-water +mark left the whole file green, because every other case charges the table from +ONE thread, where the intervals are already disjoint. + +The shape that breaks it is the hammer with NOTHING LIVE. `Tick` reads its clock +before taking the process-wide mutex, so N threads blocked on the same +acquisition each charge their own full wait, and with no leaf open they all land +on `instrument_gap`. The bound is the timeline itself and it is arithmetic: +`Instrument()` is a sum of intervals inside `[0, wall]`, so if they are disjoint +their sum is at most `wall`. Measured 0.993 honest, and `NTABLECLAMP` reds it. + +**That mutation's FIRST run is worth recording, because it is the trap this +project keeps hitting from a new direction.** The new case's name contained a +COMMA -- `... is disjoint, so it cannot exceed the timeline` -- and doctest's +`-tc` filter SPLITS ON COMMAS, so the filter matched nothing and the run printed +`test cases: 0 | 0 passed | 0 failed | 7 skipped` and `Status: SUCCESS!` at +`rc=0`. Only the harness printing the case count separated that from a mutation +the suite genuinely does not catch. The comma is gone from the name. `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 @@ -444,20 +482,46 @@ suite can see. Every entry below is from that re-run. | 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 at `REQUIRE(e.contains("instrument_seconds"))` | | NEND | every gap's `start_seconds` and `end_seconds` zeroed, `seconds` untouched | RED on 4 -- and GREEN before this row's repair, which is why the endpoints are now read | +| NCURSOR | each gap starts at the PREVIOUS LEAF'S START, so every gap swallows the leaf before it | RED -- and GREEN against the first repair for it, see `### 9` | | NREVSORT | `ByStart` orders the table by DESCENDING start | RED at `CHECK(seconds >= 0.0)` on -16.996 ms | | NTEXT | `RenderText` stops printing the instrument charge, so the console and the file copies answer different questions | RED at `REQUIRE(at != std::string::npos)` | +| NTEXTZERO | `RenderText` prints a hardcoded `0.0` instead of `Instrument()` | RED -- and **GREEN against the first version of that gate**, see `### 7` | +| NTABLECLAMP | the TABLE arm's high-water mark is removed | RED -- and **GREEN before `### 8`'s case existed**; its own first run printed `0 cases ran` and `SUCCESS!` | +| NSEED | the per-record mark is seeded with `0.0` instead of the record's own `start` | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | | 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)` | | N4 | `ChargeLocked`'s negative-`from` refusal becomes a clamp | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | | N6 | `Open`'s pre-lock wait is computed and charged to nothing | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | | NNOSORT | `ByStart` stable-sorts an empty range, i.e. does not sort at all | **GREEN** -- [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | -THE THREE GREENS ARE THE POINT OF PRINTING THEM. A mutation table that lists +### 9. Two of the first four gap assertions were TAUTOLOGIES + +The first answer to the endpoints finding added four assertions and a second +fresh review measured that two of them have no power. Inside this emitter +`gaps[i].start == records[i-1].end` and `gaps[i-1].end == records[i-1].start`, +so `gaps[i].start >= gaps[i-1].end` reduces to `records[i-1].end >= +records[i-1].start` -- a non-negative leaf duration, which a monotone clock +guarantees unconditionally. And `gaps.front().start == 0.0` is constant-true +unless the first gap is dropped, because `cursor` is initialised to the literal +`0.0`. The reviewer staged `cursor = r.start` instead of `r.end`, so every gap +swallows the leaf before it, and BOTH passed; only the pre-existing identity +fired. + +Both are replaced by one comparison that has power: each gap's endpoints are +checked against **the leaf records it lies between, read out of the same emitted +table**. `NCURSOR` cannot survive that, and it needs no tolerance beyond double +rounding because both numbers come out of the same file. + +THE FOUR GREENS ARE THE POINT OF PRINTING THEM. A mutation table that lists only its successes is an argument and not a measurement, and these three are what [#1718](https://github.com/mudler/vllm.cpp/issues/1718) is. `NREVSORT` beside `NNOSORT` says exactly how much of `ByStart` is held: an inversion is caught and a removal is not, because every timeline this suite builds is already -start-ordered. +start-ordered. `NSEED` is the fourth, found by the second review: the per-record +mark's SEED -- the half that stops a charge reaching back before the record +began -- is held by nothing, because staging it needs a `Tick` whose clock read +predates a record and whose lock acquisition follows it, which this row could +not make deterministic. N6's FIRST STAGING DID NOT COMPILE, and that is worth a line because it is the trap this project keeps walking into. Written as `if (false) { ... }` it left diff --git a/tests/vllm/multimodal/test_render_phase_log.cpp b/tests/vllm/multimodal/test_render_phase_log.cpp index 2a786589b..1a874eaad 100644 --- a/tests/vllm/multimodal/test_render_phase_log.cpp +++ b/tests/vllm/multimodal/test_render_phase_log.cpp @@ -268,20 +268,142 @@ TEST_CASE("ltx2 phase log: the instrument's own cost is CONSERVED across the tab "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"); - // AND THE CONSOLE COPY ANSWERS THE SAME QUESTION AS THE FILE. `RenderText` is - // what a reader watching a terminal gets, and it printed `sum(leaf)`, - // `unaccounted` and `WALL` while the file alone carried `instrument_seconds` - // — so the residue was on screen with no way to subtract the cost of naming - // the phases from it, which is the whole reason that number exists. This - // assertion is the only thing holding the two copies together, and without it - // the line is a production statement nothing reaches. - // - // THE TOLERANCE IS THE FORMAT'S OWN RESOLUTION AND NOT A MEASUREMENT. - // `RenderText` prints every total with `%10.3f`, so the printed value differs - // from the number it was given by strictly less than half of the last digit, - // 5e-4 seconds, by the definition of the conversion. No box load can move - // that, because nothing here is timed: both sides read the SAME `Instrument()` - // through two different code paths. + log.Reset(); +} + +// ─── and the TABLE's own share is disjoint too, which is a SECOND arm ──────── +// +// `ChargeLocked` has two targets and the clamp landed on both, but only the +// record arm was gated: a second fresh review removed the TABLE arm's +// high-water mark and the whole file stayed green, because every other case +// charges the table from ONE thread, where the intervals are already disjoint. +// +// The shape that breaks it is the hammer above with NOTHING LIVE. `Tick` reads +// its clock before taking the process-wide mutex, so N threads blocked on the +// same acquisition each charge their own full wait — and with no leaf open they +// all land on `instrument_gap`. Overlapping charges to one counter then sum past +// the timeline that contains them. +// +// THE BOUND IS THE TIMELINE ITSELF and it is not a measurement. `Instrument()` +// is a sum of intervals inside `[0, wall]`; if they are disjoint their sum is at +// most `wall`, by arithmetic. A slow box moves both numbers and moves no +// verdict. +TEST_CASE("ltx2 phase log: the TABLE's own charge is disjoint so it cannot exceed the timeline") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + + // The same deterministic blocker the record-arm case uses: a device probe that + // sleeps WHILE HOLDING the mutex makes the pile-up happen every run rather + // than sometimes, and a detector that fires sometimes is what #1569 is about. + std::atomic blocking(true); + log.SetDeviceProbe([&blocking]() -> int64_t { + if (blocking.load(std::memory_order_relaxed)) { + std::this_thread::sleep_for(std::chrono::milliseconds(2)); + } + return -1; + }); + + const int kThreads = 24; + const int kRounds = 12; + std::atomic stop_blocker(false); + std::thread blocker([&stop_blocker]() { + while (!stop_blocker.load(std::memory_order_relaxed)) phase::SampleNow(); + }); + std::vector hammers; + hammers.reserve(kThreads); + for (int t = 0; t < kThreads; ++t) { + hammers.emplace_back([kRounds, t]() { + for (int i = 0; i < kRounds; ++i) { + phase::Tick("unit.table.hammer", static_cast(t), "concurrent"); + } + }); + } + for (std::thread& h : hammers) h.join(); + stop_blocker.store(true, std::memory_order_relaxed); + blocker.join(); + blocking.store(false, std::memory_order_relaxed); + log.SetDeviceProbe(phase::DeviceByteProbe()); + + // NOTHING WAS EVER LIVE, so every charge above went to the table. + const double charge = log.Instrument(); + const double wall = log.Elapsed(); + MESSAGE("table charge " << charge << "s over a timeline of " << wall << "s by " << kThreads + << " threads (ratio " << (charge / wall) << ")"); + REQUIRE_MESSAGE(phase::ProgressEnabled(), + "VLLM_RENDER_PROGRESS is off in this process, so `phase::Tick` returned " + "without taking the mutex and the threads above contended over nothing"); + REQUIRE_MESSAGE(charge > 0.0, + "no leaf was ever live and " << kThreads + << " threads ticked, and the table was charged nothing. This case is " + "measuring an instrument that is switched off"); + CHECK_MESSAGE(charge <= wall + 1e-9, + "the table charged itself " << charge << "s inside a timeline of " << wall + << "s. Charges to the table must be disjoint; overlapping ones are counted " + "twice, and every reader who subtracts this number from a residue would " + "subtract more than the residue holds"); + log.Reset(); +} + +// ─── the CONSOLE copy answers the same question as the FILE copy ───── +// +// `RenderText` is what a reader watching a terminal gets, and it printed +// `sum(leaf)`, `unaccounted` and `WALL` while the file alone carried +// `instrument_seconds` — so the residue was on screen with no way to subtract +// the cost of naming the phases from it, which is the whole reason that number +// exists. This case is the only thing holding the two copies together; without +// it the added line is a production statement nothing reaches. +// +// THE TOLERANCE IS THE FORMAT'S OWN RESOLUTION AND NOT A MEASUREMENT. +// `RenderText` prints every total with `%10.3f`, so the printed value differs +// from the number it was given by strictly less than half of the last digit -- +// 5e-4 seconds, by the definition of the conversion. Nothing here is timed: +// both sides read the SAME `Instrument()` through two different code paths, so +// no box load can move the verdict. +// +// ── AND THE QUANTITY HAS TO BE ABOVE THAT RESOLUTION, WHICH IS THE WHOLE CASE +// +// The first version of this gate lived inside the conservation case above, on +// its three-scope timeline, and a fresh review measured it VACUOUS. There +// `Instrument()` is 2.80e-4 to 2.95e-4 s — SMALLER than the tolerance — so +// `%10.3f` prints `0.000` for the honest value and the comparison is satisfied +// by anything in `(-5e-4, +5e-4)`, the literal `0.0` included. Mutation +// `NTEXTZERO` replaced `Instrument()` with `0.0` in the production line and the +// whole file stayed GREEN at `5 | 5 passed` and `93 | 93 passed`. +// +// That is #1569's own failure reproduced inside #1569's own repair: a +// discriminator below the instrument's resolution cannot discriminate. The fix +// is the same one #1569 took — make the quantity an EVENT, and REFUSE to assert +// when it is not. The table's own share accrues one boundary at a time in the +// gaps where no leaf is live, so a few thousand sequential scopes put it three +// orders of magnitude above the format's last digit, and the `REQUIRE` below +// says so out loud rather than passing quietly on a table too cheap to print. +TEST_CASE("ltx2 phase log: the CONSOLE copy carries the same instrument charge as the FILE copy") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Reset(); + log.Begin(); + // SEQUENTIAL AND NOT NESTED, because it is the gaps BETWEEN leaves that the + // table's own share is made of: `ChargeLocked` reaches `instrument_gap` only + // when no leaf is live. + const int kScopes = 4000; + for (int i = 0; i < kScopes; ++i) { + const phase::Scope leaf("unit.console.leaf"); + } + + // `%10.3f` rounds to the nearest millisecond, so half of the last digit is + // the largest error the conversion can introduce. Both numbers below are the + // same `double`, so this is the only difference that can exist between them. + const double kFormatResolution = 5e-4; + const double charge = log.Instrument(); + REQUIRE_MESSAGE(charge > 20.0 * kFormatResolution, + "the table charged itself " << charge << "s over " << kScopes + << " scopes, which `RenderText`'s `%10.3f` cannot distinguish from zero at " + "its own " << kFormatResolution + << "s resolution. A gate over a quantity below the resolution of the " + "thing it reads is satisfied by a hardcoded zero -- which is exactly " + "how #1569's three-record case stayed green under its own mutation, and " + "how the first version of THIS case did too"); + const std::string text = log.RenderText("unit", "cpu"); const std::string::size_type at = text.find("instrument"); REQUIRE_MESSAGE(at != std::string::npos, @@ -289,15 +411,17 @@ TEST_CASE("ltx2 phase log: the instrument's own cost is CONSERVED across the tab "charge, so the console copy of this table cannot separate the residue the " "render produced from the residue this instrument produced. The file copy " "carries it and they have to answer the same question:\n" - << text); + << text.substr(0, 400)); const double printed = std::strtod(text.c_str() + at + std::string("instrument").size(), nullptr); - CHECK_MESSAGE(std::fabs(printed - log.Instrument()) < 5e-4, + MESSAGE("console instrument " << printed << "s against Instrument() " << charge << "s over " + << kScopes << " scopes"); + CHECK_MESSAGE(std::fabs(printed - charge) < kFormatResolution, "`RenderText` prints " << printed << "s of instrument charge and `Instrument()` " - << "returns " << log.Instrument() - << "s. The console copy is printing some other number, and 5e-4 is this " - "line's own %10.3f resolution rather than a tolerance:\n" - << text); + << "returns " << charge + << "s. The console copy is printing some other number, and " + << kFormatResolution + << " is this line's own %10.3f resolution rather than a tolerance"); log.Reset(); } @@ -525,9 +649,13 @@ TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gap // The leaves the decomposition must lie between, in the emitter's own order. std::vector leaf_names; + std::vector leaf_starts; + std::vector leaf_ends; for (const nlohmann::json& e : table["phases"]) { if (e.value("span", false) || e.value("nested", false)) continue; leaf_names.push_back(e["name"].get()); + leaf_starts.push_back(e["start_seconds"].get()); + leaf_ends.push_back(e["start_seconds"].get() + e["duration_seconds"].get()); } REQUIRE(leaf_names.size() == 2); @@ -575,27 +703,48 @@ TEST_CASE("ltx2 phase log: the emitted table DECOMPOSES its residue into the gap "those endpoints would be sent somewhere else"); gap_total += seconds; } - // AND THE GAPS TILE THE TIMELINE, WHICH IS WHERE THE ORDER IS ACTUALLY HELD. - // Each gap starts where the previous one ended plus the leaf between them, the - // first starts at the origin, and the last ends at `wall`. The identity below - // cannot see any of that — it telescopes for any sequence at all. - CHECK_MESSAGE(gaps.front()["start_seconds"].get() == 0.0, - "the first gap starts at " << gaps.front()["start_seconds"].get() - << "s rather than at the timeline's origin, so whatever ran before it is " - "outside the decomposition entirely"); - CHECK_MESSAGE(std::fabs(gaps.back()["end_seconds"].get() - - table["wall_seconds"].get()) < 1e-9, - "the last gap ends at " << gaps.back()["end_seconds"].get() - << "s and the render's wall is " << table["wall_seconds"].get() - << "s, so the tail of the timeline is outside the decomposition"); - for (size_t i = 1; i < gaps.size(); ++i) { + // AND EACH GAP'S ENDPOINTS ARE THE TWO RECORDS IT LIES BETWEEN, read out of + // the SAME table. This is where the order is held, and getting here took two + // wrong answers worth recording. + // + // THE IDENTITY BELOW HOLDS ONE THING AND IT IS NOT THE ORDER. A fresh review + // did the algebra: the gap sum telescopes to `wall - sum(durations)` for ANY + // record sequence, ordered or not, overlapping or not, and confirmed it by + // execution -- reversing the record order left the identity green while two + // other assertions fired. What it does hold is that `GapsBetweenLeaves` and + // `Sum` select the SAME records: both skip `span` and both skip `nested`. + // + // AND THE FIRST REPAIR FOR IT WAS TWO TAUTOLOGIES, which a SECOND fresh + // review measured. `gaps[i].start >= gaps[i-1].end` reduces, inside this + // emitter, to `records[i-1].end >= records[i-1].start` -- a non-negative leaf + // duration, which a monotone clock guarantees unconditionally. And + // `gaps.front().start == 0.0` is constant-true unless the first gap is + // dropped, because `cursor` is initialised to the literal `0.0`. The reviewer + // staged `cursor = r.start` instead of `r.end`, so every gap swallows the leaf + // before it, and BOTH of those passed; only the pre-existing identity fired. + // + // Comparing each endpoint against the leaf record it is supposed to touch is + // what that mutation cannot survive, and it needs no tolerance beyond double + // rounding because both numbers come out of the same emitted file. + REQUIRE(gaps.size() == leaf_names.size() + 1); + for (size_t i = 0; i < gaps.size(); ++i) { + const double from = gaps[i]["start_seconds"].get(); + const double to = gaps[i]["end_seconds"].get(); + const double expect_from = i == 0 ? 0.0 : leaf_ends[i - 1]; + const double expect_to = + i == leaf_names.size() ? table["wall_seconds"].get() : leaf_starts[i]; INFO("gap " << i); - CHECK_MESSAGE(gaps[i]["start_seconds"].get() >= - gaps[i - 1]["end_seconds"].get() - 1e-9, - "gap " << i << " starts at " << gaps[i]["start_seconds"].get() - << "s, BEFORE gap " << (i - 1) << " ended at " - << gaps[i - 1]["end_seconds"].get() - << "s. The decomposition is not walking the timeline in order"); + CHECK_MESSAGE(std::fabs(from - expect_from) < 1e-9, + "gap " << i << " starts at " << from << "s and the record before it ends at " + << expect_from + << "s. A gap that does not begin where the previous leaf ended is " + "either overlapping that leaf or skipping part of the timeline, and " + "the sum can still reconcile while it does"); + CHECK_MESSAGE(std::fabs(to - expect_to) < 1e-9, + "gap " << i << " ends at " << to << "s and the record after it starts at " + << expect_to + << "s. A reader who looks up the region at those endpoints would be " + "sent somewhere else"); } // THE IDENTITY. No tolerance beyond double rounding over a handful of From 03f0535808e0f5b695d9ccb458b32d45111c4cac Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sat, 22 Aug 2026 21:26:41 +0000 Subject: [PATCH 05/12] spec(LTX25-PHASE-INSTRUMENT): the 45-run distribution taken on the tree that actually lands The two populations already recorded were taken before the second fresh review, so neither is a statement about this tree: the console gate has moved into its own case, the table arm has gained one, and two gap tautologies have been replaced. 45 further consecutive runs of the whole suite, one pinned binary, loadavg 13.4 to 23.8, every run reading `test cases: 7 | 7 passed | 0 failed` and `assertions: 100 | 100 passed | 0 failed` -- the same string on every one, which is what rules out a filter that matched nothing. 0 red in 45, and 0 red in 355 across all six populations. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [Claude Code] --- .agents/specs/ltx25-phase-instrument.md | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 3a2966754..300c679d2 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -399,7 +399,7 @@ Measured on this branch, on an x86_64 box at load average 103 to 131 -- which is Build: `cmake -S . -B build -DVLLM_CPP_BUILD_TESTS=ON`, no `CMAKE_BUILD_TYPE`, which is what `build-test-cpu` configures. -### The two bounds, over 310 runs across five load regimes +### The two bounds, over 355 runs across six load regimes Every run's `test cases:` line was recorded, because a `-tc` filter that matches nothing prints `0 cases ran` and `Status: SUCCESS!` and is indistinguishable @@ -439,7 +439,20 @@ what rules out a filter that matched nothing. The margin is 27.6x rather than reader should expect: the honest head grows with contention and the budget under it does not. -**0 red in 310.** And the defective values are not near either bound: +**And once more against the tree that finally lands**, which is neither of the +trees above: the console gate moved into its own case, the table arm gained one, +and two gap tautologies were replaced. + +| population | n | load | min | median | p90 | max | margin | +|---|---:|---|---:|---:|---:|---:|---:| +| `head / min(copy, sort)` | 45 | 13-24 | 0.003355 | 0.006841 | 0.008413 | **0.010226** | **48.9x** | +| `instrument / duration`, 24 threads | 45 | 13-24 | 0.9898 | 0.9958 | 0.9967 | **0.99686** | bound 1.0 | + +All 45 read `test cases: 7 | 7 passed | 0 failed` and +`assertions: 100 | 100 passed | 0 failed` -- the SAME string on every run, which +is what rules out a filter that matched nothing. + +**0 red in 355.** And the defective values are not near either bound: ``` #1569 honest [0.0037 .. 0.0181] bound 0.5 main's order 17.2, partial regression 1.024 From c7ca0142aa10e0c0f49952a5c2b30e900b00ec54 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 01:20:36 +0000 Subject: [PATCH 06/12] record(LTX25-PHASE-INSTRUMENT): the suite grew to seven cases and `## Tests` still described four MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three record repairs, none of which touches a line of product code or a test. `## Tests` opened with "four cases" and listed four rows. The tree has SEVEN: `### 7` added the console gate its own case, `### 8` added the table arm one, and the many-threads reproduction is a third. A reader checking this row against the suite would have found three cases the spec does not mention, and — worse — the count is the one thing that separates a real green from a `-tc` filter that matched nothing and printed `Status: SUCCESS!` at rc=0. The section now names the count, says why it is written down, and describes all seven. `## Gates` asserted that `main` is red on `build-test-cpu` and both `sanitize-cpu` arms. That was true at `019f66c1a` and is false now: main landed the `test_runner.cpp:1557` repair (#1602, #1608) and all three are green on this branch. What is left is `windows-msvc-*` (#1649, which refuses before any translation unit is read) and `agent-record`, whose failure text was an issue-index duplicate main repaired in `6354755ba`. The `rot 37` line printed beside it is the budget being MET. Both are named by FAILURE TEXT, because `agent-record` is a records gate on a records-heavy branch and the job name alone would have been waved through. `## Evidence` gains the merging session's own re-run, because a reviewer report is an input and never a gate result. 23 mutations, each printing `compile_status` and `git diff --numstat` and each restored from a pristine byte copy: 19 red, 4 green, and the four green are exactly the four already filed under #1718. M3's anchor was NOT unique — the same line occurs in `Sum` and in `GapsBetweenLeaves` — so the harness refused rather than mutating whichever came first, and both sites were then run separately and both are held. And the measurement this row exists for. #1569's defect is a mutation that stayed GREEN 10 of 10, so the repaired case was run 10 consecutive times against each ordering: `M1` red 10/10 and the PARTIAL regression `N11` red 10/10, against 45 honest runs green 45/45. The honest maximum is 0.0276 and the worst defective run of the harder mutation is 0.892, a factor of 32 apart with the bound between them. The distribution is reported as n, median, p90, p95 and max, and the margin is quoted at the MAX, because a heavy right tail is exactly what a median does not see. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/specs/ltx25-phase-instrument.md | 91 +++++++++++++++++++++++-- 1 file changed, 87 insertions(+), 4 deletions(-) diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 300c679d2..2c055a178 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -282,12 +282,20 @@ is the failure #1668 was filed to prevent. ## Tests -`tests/vllm/multimodal/test_render_phase_log.cpp`, four cases: +`tests/vllm/multimodal/test_render_phase_log.cpp`, SEVEN cases. It was four when +this section was first written; `### 7` and `### 8` each added one and the +many-threads reproduction added a third, and the count is written out here +because a `-tc` filter that matches nothing prints `Status: SUCCESS!` at `rc=0`. +Every run recorded below reads `test cases: 7 | 7 passed` and +`assertions: 100 | 100 passed`, and a run that does not is not evidence. | 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 TABLE's own charge is disjoint so it cannot exceed the timeline | the second arm of the clamp, `### 8`. N threads blocked on one acquisition with NOTHING live all land on `instrument_gap`, and disjoint intervals inside `[0, wall]` cannot sum past `wall` | arithmetic over the timeline, not a tolerance. `NTABLECLAMP` reds it | +| the CONSOLE copy carries the same instrument charge as the FILE copy | `### 7`. 4000 sequential scopes make the table's share ~0.4 s against the `%10.3f` format's 5e-4 last digit, and a `REQUIRE` above that resolution refuses to assert when the quantity is too small to discriminate | reads the printed line back and compares it with `Instrument()` through the public entry point. Nothing is timed. `NTEXT` and `NTEXTZERO` red it | +| a record charged from MANY THREADS is still charged less than it lasted | the record arm of the clamp. 24 threads ticking inside one live leaf drove `instrument / duration` to 1.914 before it, red 3 runs in 5 | `instrument_seconds <= duration_seconds`, held by the disjointness construction rather than by margin. `NCLAMP` reds it | | 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 | @@ -300,9 +308,30 @@ those gaps reconcile to that render's own `unaccounted_seconds`. That is D3. `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. +Inheritance is established by FAILURE TEXT rather than by job name, and the +inherited set MOVED under this branch while it was open. At `019f66c1a` `main` +was red on `build-test-cpu`, both `sanitize-cpu` arms and both `windows-msvc-*`. +By `6354755ba` three of those five are GREEN again on this branch: +`build-test-cpu` and both sanitizers passed once `main` landed the +`test_runner.cpp:1557` repair ([#1602](https://github.com/mudler/vllm.cpp/issues/1602), +[#1608](https://github.com/mudler/vllm.cpp/issues/1608)), which this branch +inherits by merge and not by any edit of its own. + +What is left on this branch is two jobs, and NEITHER is this row's: + +- `windows-msvc-cpu` and `windows-msvc-vulkan` — the + [#1649](https://github.com/mudler/vllm.cpp/issues/1649) `/W4 /WX` refusal, + which fires BEFORE any translation unit is read and so carries no + `error C####`. Nothing this row touches is compiled when it fails. +- `agent-record` — read the TEXT, because the job name alone would have been + waved through here and it is a records gate on a records-heavy branch. Its + failure was `ERROR: .agents/issue-index.md: issue #1649 listed twice`, a + `merge=union` duplicate that `main` repaired in `6354755ba` and that this + branch inherits by merge. The `record anchors ... -> rot 37` line printed + beside it is the rot budget being MET, not exceeded: `check-agent-record.py` + prints `ANCHOR-ROT=37` and exits 0 on `main` and on this branch alike. + Verified locally on the merged tree rather than inferred from the job turning + green. ## Stop conditions @@ -469,6 +498,60 @@ Contrast the withdrawn bound: 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 its own scatter and 4 runs in 45 crossed it. +### The operator's own re-run, on the tree that is merged + +`## How work gets done` 4: an implementer or reviewer report is an input, never +a gate result. Everything below was re-run by the merging session on the tree +that carries the `origin/main` merge, after `git status` confirmed `src/`, +`include/` and `tests/` clean and `render_phase_log.cpp` matched sha256 +`e490ccc390b845aa0795bb60b70fbc9567575d23532e7a1f5a1faf64f0834224`. + +**The whole mutation set, 23 mutations.** Each printed its own +`git diff --numstat`, its `compile_status`, both doctest count lines, and a +`restore_sha256_ok` against a pristine byte copy. 23 of 23 restored true, 23 of +23 compiled at `compile_status=0`, and no numstat was empty. **19 RED, 4 GREEN**, +and the four green are exactly the four this row already files under +[#1718](https://github.com/mudler/vllm.cpp/issues/1718) — `NSEED`, `N4`, `N6`, +`NNOSORT`. No mutation the table calls red came back green. + +**`M3`'s anchor was NOT unique, and the harness refused rather than mutating the +wrong function.** `if (r.span || r.nested) continue;` occurs TWICE — once in +`Sum` and once in `GapsBetweenLeaves` — so a text replace would have silently hit +whichever came first. Re-run against each site separately: the decomposition site +reds on a `-1.232 ms` gap and `REQUIRE(gaps.size() == leaf_names.size() + 1)` at +`4 == 3`, and the `Sum` site reds on the identity at `0.00114164 < 1e-9`. Both +arms are held; only the harness was ambiguous. This is why an anchor is asserted +UNIQUE rather than merely present. + +**#1569's mutation can now fail, which is the whole point of the case.** The +defect this row exists to close is that #1569's mutation stayed GREEN 10 of 10. +Both orderings were therefore re-run 10 consecutive times each, under load, with +the doctest case count asserted on every single run: + +| tree | n | verdict | ratio min | ratio max | bound | +|---|---:|---|---:|---:|---:| +| honest | 45 | GREEN 45/45 | 0.009467 | **0.027616** | 0.5 | +| `M1`, `main`'s clock order | 10 | **RED 10/10** | **2.080** | 3.418 | 0.5 | +| `N11`, the PARTIAL regression | 10 | **RED 10/10** | **0.892** | 1.145 | 0.5 | + +All 65 runs printed the identical string `test cases: 1 | 1 passed | 0 failed`, +which is what rules out a `-tc` filter that matched nothing and reported +`SUCCESS!`. + +**The two populations do not touch.** The honest maximum over 45 runs is 0.0276 +and the WORST defective run of the harder mutation is 0.892 — a factor of **32** +between them, with the bound at 0.5 sitting between the two with 18.1x of +headroom below it and 1.78x above. That separation is the property `## Design` 6 +argues for from the definition of the quantities, measured rather than asserted. + +**The honest distribution, full, not a median.** n=45, loadavg 19.40-26.42, +min 0.009467, median 0.015184, p90 0.021052, p95 0.025348, **max 0.027616**. The +margin is quoted at the MAX and not at the median, because the failure this +cluster exists to stop is a heavy right tail that a median never sees. This run +is a lower load regime than the 13-24 population below and a tighter margin than +its 48.9x, which is the direction a reader should expect and the reason both are +kept rather than the better one. + ### The mutation table Every mutation prints its own `compile_status` and a sha256 pair, because a From 610517577db7838aabde26ba9949344319b5369d Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 02:27:40 +0000 Subject: [PATCH 07/12] fix(#1755): the sibling emitter kept #1569's defect, and the console format could not print it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `WriteJson` reads its clock before it copies and sorts the record table, so the writer's own serialization is not charged to the render's wall. That is #1569, and this row gates it. `RenderText` — the same table, the same two statements, the copy a reader watching a terminal actually gets — was left alone. It read `Elapsed()` after `ByStart(Records())`, so its own copy and its own sort landed inside the `WALL` it printed and inside the `unaccounted` row above it. The call site was the larger half. The console block stood at the END of `WriteJson`, after the whole `nlohmann` object was assembled, so the console copy also absorbed the JSON build while the file copy did not. Over five `WriteJson` calls on the 8001-record unit timeline the console's `sum(leaf)` held at 0.189 s while its `unaccounted` climbed 0.065 -> 0.134 -> 0.200 -> 0.265 -> 0.329 s. About 66 ms of writer work per call, charged to a render that had not run. Two statements repair it. `RenderText` reads its clock first, and the console block moves to immediately after `WriteJson`'s own clock read — above the copy, the sort and the build — so the two emitters' clock reads are one `getenv` apart and the two copies of one table describe one instant. Nothing could have caught it, and that is the part worth reading. `RenderText` prints every total with `%10.3f`, and a copy and a sort of 8000 records is 0.12 ms: a quarter of one step of that format. Applying #1569's own one-line repair to its sibling left the suite at `7 | 7` and `100 | 100`, which is the mute switch `### 7` and `### 6` each already record, met a third time on a third quantity. So the new case takes its bound from the format instead of from a stopwatch. `kFormatResolution` is half of `%10.3f`'s last digit, read off the emitter's own format string; the bound is ONE FULL step of it, and the honest side is held under that by arithmetic rather than by margin, because the two clock reads being compared are one function call apart and the whole difference between them is the rounding. There is no ratio anywhere in it: `ltx25-phase-residue.md` `## Design` 3 measured the withdrawn one and #1668 forbids re-proposing it. Both arms carry a precondition measured inside the same run, through the same public entry points, as a minimum over probes, and each demands two full steps of the format so a defect on the floor still clears the one-step bound by 1.5x. Arm (B) uses the cheaper of `Records()` and `stable_sort` over 250000 records — cheaper, because a partial regression moves only one of the two, which is the shape a fresh review of #1569 actually produced. Arm (A) uses the writer's own per-record `phases` array over 16000. Two tables rather than one because `WriteJson` holds about 3.3 KB of `nlohmann` per record while it dumps, so a single table big enough for (B) costs a gigabyte through (A). FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- src/vllm/multimodal/render_phase_log.cpp | 56 ++- .../vllm/multimodal/test_render_phase_log.cpp | 330 ++++++++++++++++++ 2 files changed, 371 insertions(+), 15 deletions(-) diff --git a/src/vllm/multimodal/render_phase_log.cpp b/src/vllm/multimodal/render_phase_log.cpp index ebd5a26ea..949a47fa6 100644 --- a/src/vllm/multimodal/render_phase_log.cpp +++ b/src/vllm/multimodal/render_phase_log.cpp @@ -713,6 +713,34 @@ bool PhaseLog::WriteJson(const std::string& path, const std::string& family, // single locked snapshot is the real repair and it is a public API change; // it is recorded as owed rather than smuggled in here. const double wall = Elapsed(); + + // THE CONSOLE COPY GOES FIRST, and "first" now means BEFORE THIS WRITER DOES + // ANY WORK AT ALL rather than merely before the two failure returns below. + // + // `VLLM_RENDER_PHASE_LOG_STDERR` exists for the run whose table cannot reach a + // file: an unwritable `--output-dir`, a read-only mount, a full disk. Emitted + // after those returns it was silent in exactly that case, and + // `docs/ENVIRONMENT.md`'s "also prints" described something the code did not + // do. Emitting it here also means a process that dies during the write has + // still said what it measured. + // + // AND IT SITS ABOVE THE COPY, THE SORT AND THE WHOLE JSON BUILD BECAUSE THOSE + // WERE BEING CHARGED TO IT (issue #1755). `RenderText` reads the clock ITSELF, + // so wherever this block stands is the instant the console's `WALL` reports. + // Standing after `out` was assembled, the console copy of a render quoted a + // wall that contained this writer's own serialization: on the 8001-record unit + // timeline `sum(leaf)` held at 0.189 s across five calls while the console's + // `unaccounted` climbed 0.065 -> 0.134 -> 0.200 -> 0.265 -> 0.329 s, about + // 66 ms of writer work per call charged to the render. That is #1569's defect + // on #1569's own sibling emitter: the file copy was repaired and the console + // copy a reader watches was not. Here the two clock reads are one `getenv` + // apart, so the console copy and the file copy describe the same instant. + if (StderrEnabled()) { + const std::string block = RenderText(family, device); + std::fwrite(block.data(), 1, block.size(), stderr); + std::fflush(stderr); + } + const std::vector records = ByStart(Records()); const Totals totals = Sum(records, wall); @@ -800,20 +828,6 @@ bool PhaseLog::WriteJson(const std::string& path, const std::string& family, "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. - // - // `VLLM_RENDER_PHASE_LOG_STDERR` exists for the run whose table cannot reach a - // file: an unwritable `--output-dir`, a read-only mount, a full disk. Emitted - // after the two failure returns below it was silent in exactly that case, and - // `docs/ENVIRONMENT.md`'s "also prints" described something the code did not - // do. Hoisting it also means a process that dies during the write has still - // said what it measured. - if (StderrEnabled()) { - const std::string block = RenderText(family, device); - std::fwrite(block.data(), 1, block.size(), stderr); - std::fflush(stderr); - } - std::ofstream f(path, std::ios::binary | std::ios::trunc); if (!f.good()) { if (why != nullptr) *why = "cannot open " + path; @@ -830,8 +844,20 @@ bool PhaseLog::WriteJson(const std::string& path, const std::string& family, } std::string PhaseLog::RenderText(const std::string& family, const std::string& device) const { + // THE CLOCK IS READ FIRST HERE TOO, FOR THE REASON `WriteJson` GIVES ABOVE + // (issue #1755). `Records()` copies the record vector under the process-wide + // mutex and `ByStart` stable-sorts the copy; reading `Elapsed()` after them + // charged THIS emitter's own serialization to the RENDER's wall, and so to the + // `unaccounted` line printed three lines below it. #1569 repaired that + // ordering in the file emitter and left its sibling alone, and nothing noticed + // because the console prints every total with `%10.3f` while a copy and a sort + // of a few thousand records are tenths of a millisecond. + // + // The cost of the order is the one `WriteJson` records: the wall and the + // records below are two acquisitions of the mutex rather than one snapshot. + const double wall = Elapsed(); const std::vector records = ByStart(Records()); - const Totals totals = Sum(records, Elapsed()); + const Totals totals = Sum(records, wall); const double kGiB = 1024.0 * 1024.0 * 1024.0; std::string out = "\nRENDER PHASE LOG family=" + family + " device=" + device + "\n"; char line[256]; diff --git a/tests/vllm/multimodal/test_render_phase_log.cpp b/tests/vllm/multimodal/test_render_phase_log.cpp index 1a874eaad..467a8a3c1 100644 --- a/tests/vllm/multimodal/test_render_phase_log.cpp +++ b/tests/vllm/multimodal/test_render_phase_log.cpp @@ -41,6 +41,7 @@ #include #include +#include #include #include @@ -93,6 +94,81 @@ class TableFile { void SleepMs(int ms) { std::this_thread::sleep_for(std::chrono::milliseconds(ms)); } +// The `WALL` total out of a `RenderText` block, at the resolution that block +// prints it. Returns a NEGATIVE sentinel when the block carries no such row or +// carries two, and every caller REQUIREs on that: a capture that caught nothing +// would otherwise read exactly like a comparison that passed, and a second +// occurrence of the label would mean this is reading some other row's number. +double WallFromBlock(const std::string& block) { + const std::string::size_type at = block.find("WALL"); + if (at == std::string::npos) return -1.0; + if (block.find("WALL", at + 1) != std::string::npos) return -2.0; + return std::strtod(block.c_str() + at + 4, nullptr); +} + +// FD 2, pointed somewhere else and put back. The last case below needs it for +// two opposite reasons: to READ what the instrument printed, and to keep what +// the instrument prints off the harness's own stderr. `PhaseLog::Close` flushes +// one progress line per scope, and a table of a hundred thousand scopes is +// mostly flushed writes into whatever stderr is attached to -- 3.81 s against +// 0.65 s over 120000 scopes on the box this was written on, with the whole +// difference in that pipe. `ProgressEnabled()` reads its environment variable +// ONCE per process, so a `setenv` from inside a case cannot turn it off: by the +// time any case runs, an earlier one has already latched it. +class StderrTo { + public: + explicit StderrTo(const std::string& path) { + saved_ = ::dup(STDERR_FILENO); + sink_ = ::open(path.c_str(), O_WRONLY | O_CREAT | O_TRUNC, 0600); + if (saved_ >= 0 && sink_ >= 0) ok_ = ::dup2(sink_, STDERR_FILENO) >= 0; + } + ~StderrTo() { Restore(); } + StderrTo(const StderrTo&) = delete; + StderrTo& operator=(const StderrTo&) = delete; + + bool ok() const { return ok_; } + + void Restore() { + if (saved_ < 0) return; + std::fflush(stderr); + ::dup2(saved_, STDERR_FILENO); + ::close(saved_); + if (sink_ >= 0) ::close(sink_); + saved_ = -1; + sink_ = -1; + } + + private: + int saved_ = -1; + int sink_ = -1; + bool ok_ = false; +}; + +// One path, gone on the way out. +class RemoveOnExit { + public: + explicit RemoveOnExit(const std::string& path) : path_(path) {} + ~RemoveOnExit() { ::unlink(path_.c_str()); } + RemoveOnExit(const RemoveOnExit&) = delete; + RemoveOnExit& operator=(const RemoveOnExit&) = delete; + + private: + std::string path_; +}; + +// N sequential leaves under one held span, with the build's own progress lines +// pointed at `sink`. The span is what stops the 100 ms sampler being created +// and joined once per leaf, and closing it leaves nothing live, so no worker is +// running while the clocks in the case are read. +void BuildLeaves(int n, const std::string& sink) { + const std::string kLeafName = "unit.leaf.with.a.name.past.the.small.string.buffer"; + const StderrTo quiet(sink); + const phase::Scope holder("unit.holder", /*span=*/true); + for (int i = 0; i < n; ++i) { + const phase::Scope leaf(kLeafName); + } +} + } // namespace // ─── the instrument charges its OWN cost to the right place (#1668) ────────── @@ -969,3 +1045,257 @@ TEST_CASE("ltx2 phase log: the emitter reads its CLOCK before it serialises the "therefore to `unaccounted_seconds`. This table measures the render"); log.Reset(); } + +// ─── the console copy reports the wall this emitter was ENTERED at (#1755) ─── +// +// `PhaseLog::RenderText` is `WriteJson`'s SIBLING and it carried #1569's defect +// unrepaired: it read `Elapsed()` AFTER `ByStart(Records())`, so its own copy +// and its own sort were charged to the `WALL` it printed and therefore to the +// `unaccounted` row above it. And the call site made that worse. The console +// block stood at the END of `WriteJson`, after the whole `nlohmann` object was +// assembled, so the console copy also absorbed the JSON build: over five +// `WriteJson` calls on the 8001-record timeline of the case above, `sum(leaf)` +// held at 0.189 s while the console's `unaccounted` climbed 0.065 -> 0.134 -> +// 0.200 -> 0.265 -> 0.329 s. About 66 ms of writer work per call, charged to +// the render, on the copy of the table a reader actually watches. +// +// WHY NOTHING SAW IT. `RenderText` prints every total with `%10.3f`. A copy and +// a sort of a few thousand records are tenths of a millisecond, so the whole +// defect fits inside the last printed digit, and applying #1569's own one-line +// repair to this emitter left the suite at `7 | 7` and `100 | 100`. That is the +// mute switch `### 7` and `## Design` 6 are each about, met a third time. +// +// WHAT THIS CASE IS. Two comparisons against ONE structurally derived constant. +// `kFormatResolution` is half of `%10.3f`'s last digit, read off the emitter's +// own format string: a printed total differs from the number it was given by +// strictly less than that, by the definition of the conversion. The bound is +// ONE FULL step of that format, `2 * kFormatResolution`, which is the smallest +// bound the rounding itself cannot break. The honest side is held under it by +// ARITHMETIC and not by margin -- the two clock reads being compared are one +// function call apart, so the whole difference between them is the rounding -- +// and the defective side is pushed over it by a quantity measured in the same +// run. Nothing here is a wall-clock tolerance and nothing here is a ratio: +// `ltx25-phase-residue.md` `## Design` 3 records the withdrawn one and #1668 +// forbids re-proposing it. +// +// (A) THE SHIPPED PATH, on a table small enough to serialise. `WriteJson` +// with `VLLM_RENDER_PHASE_LOG_STDERR=1`, against the clock read +// immediately before the call. Under the old call site the block was +// rendered after the copy, the sort AND the whole JSON build, and that +// build is what makes this arm's discriminator large. It is measured +// here, in this run, by assembling the same per-record objects through +// the same library. +// (B) THE PUBLIC ENTRY POINT, on a table big enough for the copy alone to +// cross the last printed digit. `RenderText` against the clock read +// immediately before it. This is the arm that holds the ORDERING inside +// the emitter, and it needs the bigger table because a wrong ordering +// moves only the copy and the sort -- 0.12 ms over 8000 records, a +// quarter of one step of `%10.3f`, which is precisely why this defect +// survived the row that repaired its sibling. +// +// BOTH LAGS ARE MINIMA OVER PROBES, and that is what makes them safe on a +// loaded box. Contention is one-sided: it can only make a measured interval +// longer, so a minimum strips a preemption that lands between two adjacent +// statements from the honest side, and cannot strip the deterministic +// serialization from the defective side. Each `REQUIRE` refuses to assert at +// all when its discriminator has collapsed under the format's resolution, +// because a gate that silently loses its discriminator is the defect this case +// exists to close rather than a run of good luck. Two full steps is what each +// one demands, so a defect sitting exactly on that floor still exceeds the +// one-step bound by 1.5x after the worst rounding. +TEST_CASE("ltx2 phase log: the console copy reports the wall this emitter was ENTERED at") { + phase::PhaseLog& log = phase::PhaseLog::Instance(); + const TableFile file; + const std::string sink = file.path() + ".stderr"; + // `TableFile` removes its own directory and would fail to while this one + // still holds a file, so the sink is removed on every exit including the + // throw a failed `REQUIRE` takes. + const RemoveOnExit sink_cleanup(sink); + + // Half of `%10.3f`'s last digit. Not a measurement and not a tolerance: it is + // the largest error the conversion itself can introduce, and the neighbouring + // console case reads the same number off the same format string. + const double kFormatResolution = 5e-4; + const double kStep = 2.0 * kFormatResolution; + const int kProbes = 3; + + // ── (A) THE SHIPPED PATH ──────────────────────────────────────────────── + log.Reset(); + log.Begin(); + const int kSmall = 16000; + BuildLeaves(kSmall, sink); + + // THE DISCRIMINATOR FOR THIS ARM, MEASURED THE WAY THE WRITER BUILDS IT. + // These are the same per-record objects `WriteJson` assembles into `phases`, + // through the same library, on the same data, on this box, in this run -- + // the work that stood between the writer's clock read and the console block + // it rendered afterwards. + double build_cost = -1.0; + for (int k = 0; k < kProbes; ++k) { + const std::vector recs = log.Records(); + const double before = log.Elapsed(); + nlohmann::json phases = nlohmann::json::array(); + for (const phase::Record& r : recs) { + nlohmann::json e; + e["name"] = r.name; + e["render"] = r.render; + e["start_seconds"] = r.start; + e["end_seconds"] = r.end; + e["duration_seconds"] = r.end - r.start; + e["peak_host_bytes"] = r.peak_host_bytes; + e["peak_device_bytes"] = r.peak_device_bytes; + e["span"] = r.span; + e["nested"] = r.nested; + e["instrument_seconds"] = r.instrument_seconds; + phases.push_back(std::move(e)); + } + const double this_build = log.Elapsed() - before; + // Kept from being optimised away: the array has to be observed. + REQUIRE(phases.size() == recs.size()); + if (build_cost < 0.0 || this_build < build_cost) build_cost = this_build; + } + MESSAGE("the writer's per-record JSON build over " << kSmall << " records is " << build_cost + << "s = " << (build_cost / kStep) + << " steps of the printed format"); + REQUIRE_MESSAGE(build_cost > 2.0 * kStep, + "assembling the writer's own `phases` array over " << kSmall + << " records measured " << build_cost + << "s, which `RenderText`'s `%10.3f` cannot separate from zero. This arm " + "detects a console block rendered after that build, so a build this " + "cheap cannot be detected at all"); + + ::setenv("VLLM_RENDER_PHASE_LOG_STDERR", "1", 1); + double console_lag = -1.0; + double console_wall = -1.0; + double console_clock = -1.0; + for (int k = 0; k < kProbes; ++k) { + bool wrote = false; + std::string why; + double before_write = 0.0; + { + const StderrTo capture(sink); + // The clock is read INSIDE the redirect, because opening and truncating + // the sink is itself milliseconds once the build has filled it, and this + // arm's whole subject is a millisecond. + before_write = log.Elapsed(); + wrote = log.WriteJson(file.path(), "unit", "cpu", &why); + } + REQUIRE_MESSAGE(wrote, why); + const std::string block = ReadAll(sink); + const double printed = WallFromBlock(block); + REQUIRE_MESSAGE(printed >= 0.0, + "`VLLM_RENDER_PHASE_LOG_STDERR=1` produced no block carrying a unique " + "`WALL` row, so the comparison below has no number to make and this arm " + "would pass on a capture that caught nothing. Captured " + << block.size() << " bytes ending:\n" + << block.substr(block.size() > 400 ? block.size() - 400 : 0)); + const double lag = std::fabs(printed - before_write); + if (console_lag < 0.0 || lag < console_lag) { + console_lag = lag; + console_wall = printed; + console_clock = before_write; + } + } + ::unsetenv("VLLM_RENDER_PHASE_LOG_STDERR"); + MESSAGE("console WALL " << console_wall << "s against a clock read " << console_clock + << "s immediately before WriteJson, lag " << console_lag + << "s (min of " << kProbes << " probes, build " << build_cost + << "s, bound " << kStep << "s)"); + CHECK_MESSAGE(console_lag <= kStep, + "`VLLM_RENDER_PHASE_LOG_STDERR` printed a WALL of " << console_wall + << "s and this case read the clock at " << console_clock + << "s immediately before calling `WriteJson`, a lag of " << console_lag + << "s against ONE step of that line's own `%10.3f`, with the writer's own " + "per-record JSON build measured at " << build_cost + << "s. The console copy is being rendered AFTER this writer has already " + "copied, sorted and serialised the table, so the residue a reader " + "watches on a terminal contains the writer that printed it"); + + // ── (B) THE PUBLIC ENTRY POINT ────────────────────────────────────────── + // + // A SECOND TABLE RATHER THAN A BIGGER FIRST ONE, and the reason is memory. + // `WriteJson` holds one `nlohmann` object per record while it dumps, about + // 3.3 KB per record on this box, so a table big enough for this arm costs a + // gigabyte through arm (A) and 140 MB through this one, which never + // serialises to JSON at all. + log.Reset(); + log.Begin(); + const int kBig = 250000; + BuildLeaves(kBig, sink); + + double copy_cost = -1.0; + double sort_cost = -1.0; + for (int k = 0; k < kProbes; ++k) { + // MEASURED THE WAY THE EMITTER DOES IT AND IN THE SAME TWO STEPS, through + // the same public entry point. They are measured SEPARATELY and the budget + // is the SMALLER, because a partial regression moves only one of them -- + // the shape a fresh review of #1569 actually produced against the + // one-number form of its budget. + const double before_copy = log.Elapsed(); + std::vector copy = log.Records(); + const double after_copy = log.Elapsed(); + std::stable_sort(copy.begin(), copy.end(), + [](const phase::Record& a, const phase::Record& b) { + return a.start < b.start; + }); + const double after_sort = log.Elapsed(); + // Kept from being optimised away: the sorted copy has to be observed. + REQUIRE(!copy.empty()); + const double this_copy = after_copy - before_copy; + const double this_sort = after_sort - after_copy; + if (copy_cost < 0.0 || this_copy < copy_cost) copy_cost = this_copy; + if (sort_cost < 0.0 || this_sort < sort_cost) sort_cost = this_sort; + } + const double serialize = copy_cost < sort_cost ? copy_cost : sort_cost; + MESSAGE("copy " << copy_cost << "s sort " << sort_cost << "s over " << kBig + << " records (min of " << kProbes << " probes, budget " << serialize + << "s = " << (serialize / kStep) << " steps of the printed format)"); + REQUIRE_MESSAGE(serialize > 2.0 * kStep, + "the CHEAPER of this emitter's two post-clock steps over " << kBig + << " records measured " << serialize << "s (copy " << copy_cost + << "s, sort " << sort_cost + << "s), which `RenderText`'s own `%10.3f` cannot separate from zero. A " + "wrong ordering is detected by whichever step it moves, so a step " + "this cheap cannot be detected at all -- which is exactly how this " + "defect survived #1569, and how #1569's own three-record case stayed " + "green under its own mutation"); + + double render_lag = -1.0; + double render_wall = -1.0; + double render_clock = -1.0; + for (int k = 0; k < kProbes; ++k) { + double before_render = 0.0; + std::string text; + { + const StderrTo quiet(sink); + before_render = log.Elapsed(); + text = log.RenderText("unit", "cpu"); + } + const double printed = WallFromBlock(text); + REQUIRE_MESSAGE(printed >= 0.0, + "`RenderText` returned a block carrying no unique `WALL` row, so the " + "comparison below has no number to make -- and a block that carried " + "nothing would read exactly like a comparison that passed:\n" + << text.substr(0, 400)); + const double lag = std::fabs(printed - before_render); + if (render_lag < 0.0 || lag < render_lag) { + render_lag = lag; + render_wall = printed; + render_clock = before_render; + } + } + MESSAGE("RenderText printed WALL " << render_wall << "s against a clock read " << render_clock + << "s immediately before the call, lag " << render_lag + << "s (min of " << kProbes << " probes, budget " + << serialize << "s, bound " << kStep << "s)"); + CHECK_MESSAGE(render_lag <= kStep, + "`RenderText` printed a WALL of " << render_wall + << "s and this case read the clock at " << render_clock + << "s immediately before calling it, a lag of " << render_lag + << "s against ONE step of that line's own `%10.3f`, with the cheaper of " + "its two post-clock steps measured at " << serialize + << "s. The emitter is reading its clock AFTER it copies and sorts the " + "table, so its own serialization is charged to the WALL it prints and " + "to the `unaccounted` above it. This table measures the render"); + log.Reset(); +} From b527509d9fbff21f66c7f86bcdd7b79a5a07c155 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 02:37:59 +0000 Subject: [PATCH 08/12] record(LTX25-PHASE-INSTRUMENT): four numbers this row asserted that its own `## Evidence` does not carry MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A fresh review read `## Outcome` against `## Evidence` and found three claims the evidence contradicts, plus a fourth in the residue spec. None of them is a rounding difference; each names a quantity that was never measured on the tree it is written on. **"it confirmed 237x."** `## Evidence` measures the separation between the honest and defective populations at 32x — an honest maximum of 0.027616 over 45 runs against 0.892, the worst run of the harder mutation, over 10 — with the 0.5 bound sitting 18.1x above one side and 1.78x below the other. The three `head / min(copy, sort)` populations quote 52x, 27.6x and 48.9x at their own maxima. 237x is none of these. **"Measured headroom on this tree: 255x"** for `serialize > 1e-5`. That headroom is the whole argument that the precondition is not a mute switch, and it is 12.0x to 13.5x, not 255x: `serialize` read 1.2008e-4 to 1.3535e-4 s over six consecutive runs on this box, and the fresh review measured 1.22e-4 to 1.41e-4 independently. An order of magnitude, not two. **"Five of the ten mutations above."** The table enumerates twenty-two rows, and the claim is about the gap decomposition, which catches eight of them: `M2`, both `M3` arms, `M7`, `M8`, `NEND`, `NCURSOR` and `NREVSORT`, with `R1` a ninth against the render case. **Twenty-two rows against a stated twenty-three.** `M3`'s anchor occurs at both the `GapsBetweenLeaves` site and the `Sum` site, the harness refused the ambiguous replace, and `## Evidence` already records that each site was mutated separately with a different red. Carried as one row it made the table disagree with the count above it by exactly one. It is now two rows and 19 RED + 4 GREEN reconciles. **And the `## Tests` row for the #1569 case cited `## Design` 5.** That section is the prohibition on putting `instrument_seconds` in a denominator; the bound's derivation is `### 6`. Lines 47 and 131 cite `## Design` 5 correctly and are left alone. In `ltx25-phase-residue.md`, the row marking #1569 closed described a superseded tree twice over: "a 4000-record table" is the console case's timeline and the #1569 case builds 8000, and "a ratio of 1.004 against a 50-run honest maximum of 0.0042" belonged to the WITHDRAWN one-number `copy + sort` budget that a fresh review broke. On the tree that lands, `M1` reds 10 of 10 at 2.080 to 3.418 and `N11` at 0.892 to 1.145, against an honest 45-run maximum of 0.027616. Only that row is touched; #1572 and #1470 are byte-for-byte unchanged because another branch is editing them. This change also records #1755 where the protocol requires it: `## Scope`, `### 10`, the `## Tests` table and count, its own `## Evidence` block, `## Now`, and an appended row in `.agents/issue-index.md` naming this row as owner. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/issue-index.md | 1 + .agents/specs/ltx25-phase-instrument.md | 174 +++++++++++++++++++++--- .agents/specs/ltx25-phase-residue.md | 2 +- 3 files changed, 156 insertions(+), 21 deletions(-) diff --git a/.agents/issue-index.md b/.agents/issue-index.md index 47251f1e1..f37881f20 100644 --- a/.agents/issue-index.md +++ b/.agents/issue-index.md @@ -639,3 +639,4 @@ rather than merged. `scripts/check-agent-record.py` gates both. | [#1725](https://github.com/mudler/vllm.cpp/issues/1725) | `BACKEND-CUDA-SM110` | `kMatmulFp8Cutlass` and `kMatmulFp8BlockScaled` fall through to the portable CPU tier and SEGFAULT on sm_110 (`test_ops_fp8_cutlass:191`, `test_ops_matmul_fp8_block_cuda:345`, measured at `0764ded2b`). The sm_110 baseline attributed them to [#960](https://github.com/mudler/vllm.cpp/issues/960), which was CLOSED COMPLETED three days earlier by `d607fec4c` -- that fix covered `QuantFp8Static` only, while these two ops are registered from TUs `CMakeLists.txt:1790-1791` builds solely for `VT_CUTLASS_FP8_ARCHS`. `cuda_matmul_fp8_block_cutlass.cu:56-58` asserts they refuse by name instead, which the measurement contradicts; `cffe59b02` has since rewritten that dispatch, and no CI lane can see either way because `cutlass-fp8` is ENABLED on the GB10 gate host | bug | | [#1731](https://github.com/mudler/vllm.cpp/issues/1731) | `ENG-RECORD-CONFLICT-SURFACES` | `check-agent-record` is RED on `main`: `#1649` is listed twice in `.agents/issue-index.md`, at `:592` (added by `a7bb3130b`, the lane that FILED it) and `:632` (added by `2f2a70925`, the lane that FIXED it). Neither is wrong and neither could see the other -- `merge=union` combines two appends silently, so a duplicate is the ordinary outcome when filing and fixing happen on different branches, and the checker only notices once both have landed on main, where every later PR inherits the red. Not repaired in flow: the index preamble forbids editing or deleting a row, and the two bodies carry different facts (`:632` has a second red and the mutation evidence, `:592` has the attribution to `a50c57d69`), so choosing which survives is a judgement | bug | | [#1733](https://github.com/mudler/vllm.cpp/issues/1733) | `ENG-RECORD-CONFLICT-SURFACES` | CLOSED as a duplicate of [#1731](https://github.com/mudler/vllm.cpp/issues/1731), filed seventeen minutes after it against the same red, and recorded here rather than left unindexed because its one MEASURED claim is FALSE and an append-only row cannot be corrected in place later. Both issues report that `.agents/issue-index.md` lists [#1649](https://github.com/mudler/vllm.cpp/issues/1649) twice on `main` at `038ff61e5`, at `:592` from `a7bb3130b` (the lane that FILED it) and at `:632` from `2f2a70925` (the lane that FIXED it). #1731 is the earlier filing, already carries an index row, and is the record. #1733 adds one thing #1731 does not, and it is wrong: "the repair is measured and it is NOT blocked", on the evidence that removing one of the two rows in a worktree and running both checkers gives `agent record OK: ENGINE=170 MODEL=377 ...` and `OK: issue index append-only`. The second half is an artefact of the instrument. `scripts/check-issue-index-append-only.py:50-51` diffs `merge-base(origin/main, HEAD)..HEAD`, which reads COMMITS, so an UNCOMMITTED deletion is invisible to it. Measured on `row/FIX-ISSUE-INDEX-1649-DUP` at base `038ff61e5`: deleting `:592` in the WORKING TREE alone returns `OK: issue index append-only` at rc 0 with `git diff --numstat 038ff61e5..HEAD -- .agents/issue-index.md` EMPTY, and committing the byte-identical deletion turns the same checker rc 1 with a `removed:` line naming the row. #1733's own quoted `agent record OK: ENGINE=170 MODEL=377` is the tell, because that is the working-tree reading and the committed tree cannot produce it while the duplicate stands. So the duplicate IS base-reachable, the two checkers ARE in genuine contradiction on this tree, and the repair is the argued exception #1731's row anticipated rather than the free edit #1733 reported | bug | +| [#1755](https://github.com/mudler/vllm.cpp/issues/1755) | `LTX25-PHASE-INSTRUMENT` | `PhaseLog::RenderText` read `Elapsed()` AFTER `ByStart(Records())`, so the CONSOLE copy of a phase table charged its own copy and its own sort to the `WALL` it printed and to the `unaccounted` row above it. That is [#1569](https://github.com/mudler/vllm.cpp/issues/1569)'s defect on #1569's own sibling emitter: the file copy was repaired and the copy a reader watching a terminal gets was not. The call site was the larger half -- the console block stood at the END of `WriteJson`, after the whole `nlohmann` object was assembled, so it absorbed the JSON build as well: over five `WriteJson` calls on the 8001-record unit timeline `sum(leaf)` held at 0.189 s while the console's `unaccounted` climbed 0.065 -> 0.134 -> 0.200 -> 0.265 -> 0.329 s, about 66 ms of writer work per call charged to a render that had not run. NOTHING COULD SEE IT: `RenderText` prints every total with `%10.3f` and a copy and a sort of 8000 records is 0.12 ms, a quarter of one step of that format, so applying #1569's own one-line repair to its sibling left the suite at `7 \| 7 passed` and `100 \| 100 passed`. Found by the fresh review of [PR #1711](https://github.com/mudler/vllm.cpp/pull/1711) and fixed in the same flow: the clock is read first in both emitters, the console block moves above the copy, the sort and the build, and the gate takes its bound from `%10.3f`'s own last digit rather than from a wall-clock ratio, over a table large enough for the defect to cross it | bug | diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 2c055a178..5de4d012e 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -32,6 +32,10 @@ IN SCOPE: 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. +4. **`RenderText` reads its clock before it serialises, and the console block + is emitted before this writer does any work at all**, plus the gate that + holds both. [#1755](https://github.com/mudler/vllm.cpp/issues/1755), found + by the fresh review of this row and fixed in the same flow. `### 10`. OUT OF SCOPE, and each is named because each was tempting: @@ -247,6 +251,65 @@ to serialise cannot separate the two orderings at all, which is precisely why precondition that fails loudly is the difference between a gate and a mute switch. +### 10. The CONSOLE emitter had the same defect, and the call site made it worse + +`### 6` repaired `WriteJson`'s clock ordering and left its sibling alone. +`RenderText` read `Elapsed()` AFTER `ByStart(Records())`, so the console copy of +a table charged its own copy and its own sort to the `WALL` it printed and to +the `unaccounted` row above it. A fresh review of this row measured it and filed +[#1755](https://github.com/mudler/vllm.cpp/issues/1755). + +The call site was the larger half. The console block stood at the END of +`WriteJson`, after the whole `nlohmann` object was assembled, so the console copy +also absorbed the JSON build while the file copy did not. Over five `WriteJson` +calls on the 8001-record unit timeline the console's `sum(leaf)` held at 0.189 s +while its `unaccounted` climbed 0.065 -> 0.134 -> 0.200 -> 0.265 -> 0.329 s. +About 66 ms of writer work per call, on the copy of the table a reader watching a +terminal actually gets. + +**The repair is two statements.** `RenderText` reads its clock first, mirroring +`### 6`. And the console block moves to immediately after `WriteJson`'s own clock +read, above the copy, the sort and the build, so the two emitters' clock reads +are one `getenv` apart and the two copies describe one instant. + +**The bound is the FORMAT'S resolution and there is no ratio in it.** +`RenderText` prints every total with `%10.3f`, so a printed total differs from +the number it was given by strictly less than 5e-4 s by the definition of the +conversion. The gate compares the printed `WALL` against the clock the case read +immediately before the call, against ONE FULL step of that format, `1e-3` s. The +honest side is held under that by ARITHMETIC rather than by margin: the two clock +reads are one function call apart, so the whole difference between them IS the +rounding. This is the same constant `### 7` reads off the same format string, and +it is deliberately not the withdrawn ratio that `ltx25-phase-residue.md` +`## Design` 3 measured and #1668 forbids re-proposing. + +**And the table has to be big enough for the defect to cross that last digit, +which is the whole reason this case is not three records.** This is `### 6`'s +mute-switch argument on a coarser instrument: a copy and a sort of 8000 records +is 0.12 ms, a QUARTER of one step of `%10.3f`, so applying the one-line repair to +`RenderText` on the old test suite left it at `7 | 7` and `100 | 100`. The two +arms therefore carry two preconditions, each measured in the same run through the +same public entry points, each a MINIMUM over probes, and each demanding TWO full +steps of the format so that a defect sitting exactly on the floor still exceeds +the one-step bound by 1.5x: + +- arm (B), the ordering: the CHEAPER of `Records()` and `stable_sort` over + 250000 records. Smaller because a partial regression moves only one of them, + which is the shape a fresh review of `### 6` actually produced. +- arm (A), the call site: the writer's own per-record `phases` array, assembled + by the case through the same library over 16000 records. + +**Two tables rather than one, and the reason is memory.** `WriteJson` holds one +`nlohmann` object per record while it dumps, about 3.3 KB per record, so a single +table big enough for arm (B) costs a gigabyte of resident set through arm (A). +Arm (B) never serialises to JSON and costs 140 MB at 250000 records. + +**The build's progress lines go to a sink.** `PhaseLog::Close` flushes one line +per scope, and on this box 120000 scopes cost 3.81 s through a pipe against +0.65 s to a file. `ProgressEnabled()` latches its environment variable once per +process, so a `setenv` inside a case cannot turn it off; redirecting fd 2 can, +and the same mechanism is what reads the console block back. + ## Dependencies None. `LTX25-DEVICE-RESIDENCY` owns `render_phase_log.{h,cpp}`'s existence and @@ -282,12 +345,14 @@ is the failure #1668 was filed to prevent. ## Tests -`tests/vllm/multimodal/test_render_phase_log.cpp`, SEVEN cases. It was four when -this section was first written; `### 7` and `### 8` each added one and the -many-threads reproduction added a third, and the count is written out here -because a `-tc` filter that matches nothing prints `Status: SUCCESS!` at `rc=0`. -Every run recorded below reads `test cases: 7 | 7 passed` and -`assertions: 100 | 100 passed`, and a run that does not is not evidence. +`tests/vllm/multimodal/test_render_phase_log.cpp`, EIGHT cases. It was four when +this section was first written; `### 7` and `### 8` each added one, the +many-threads reproduction added a third and `### 10` added a fourth, and the +count is written out here because a `-tc` filter that matches nothing prints +`Status: SUCCESS!` at `rc=0`. Every run recorded under `### The two bounds` reads +`test cases: 7 | 7 passed` and `assertions: 100 | 100 passed`; every run recorded +under `### The console emitter` reads `test cases: 8 | 8 passed` and +`assertions: 120 | 120 passed`. A run that reads neither is not evidence. | Case | What it holds | Shape | |---|---|---| @@ -297,7 +362,8 @@ Every run recorded below reads `test cases: 7 | 7 passed` and | the CONSOLE copy carries the same instrument charge as the FILE copy | `### 7`. 4000 sequential scopes make the table's share ~0.4 s against the `%10.3f` format's 5e-4 last digit, and a `REQUIRE` above that resolution refuses to assert when the quantity is too small to discriminate | reads the printed line back and compares it with `Instrument()` through the public entry point. Nothing is timed. `NTEXT` and `NTEXTZERO` red it | | a record charged from MANY THREADS is still charged less than it lasted | the record arm of the clamp. 24 threads ticking inside one live leaf drove `instrument / duration` to 1.914 before it, red 3 runs in 5 | `instrument_seconds <= duration_seconds`, held by the disjointness construction rather than by margin. `NCLAMP` reds it | | 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 | +| the emitter reads its CLOCK before it serialises the table | #1569 | `### 6` | +| the console copy reports the wall this emitter was ENTERED at | `### 10`. #1755. Two arms: `RenderText` against the clock read immediately before it over 250000 records, and the `VLLM_RENDER_PHASE_LOG_STDERR` block across `WriteJson` over 16000 | the printed `WALL` against ONE step of that line's own `%10.3f`, with each arm's discriminator measured in the same run and each lag a minimum over probes. `M-RT`, `M-RT-PARTIAL`, `M-SITE` and `M-BOTH` red it | Plus, in `tests/vllm/multimodal/test_ltx2_video.cpp`, inside the existing ABI render case: the emitted table carries `instrument_seconds`, carries `gaps`, and @@ -552,6 +618,49 @@ is a lower load regime than the 13-24 population below and a tighter margin than its 48.9x, which is the direction a reader should expect and the reason both are kept rather than the better one. +### The console emitter, measured by the session that repaired it + +`### 10`, issue [#1755](https://github.com/mudler/vllm.cpp/issues/1755). A +SEPARATE population from the 23 above, on a later tree, so the counts in +`### The operator's own re-run` still reconcile against +`### The mutation table`. Same x86_64 box, loadavg 11 to 21, Release build with +`-DVLLM_CPP_BUILD_TESTS=ON`. Every run below printed its own doctest count lines +and they are quoted rather than summarised, because a `-tc` filter that matches +nothing prints `Status: SUCCESS!` at `rc=0`. + +The honest tree reads `test cases: 8 | 8 passed | 0 failed` and +`assertions: 120 | 120 passed | 0 failed`. `main`'s code — both halves — reads +`8 | 7 passed | 1 failed` and `120 | 118 passed | 2 failed`. + +**0 RED IN 45 HONEST RUNS.** Ten of the whole suite at `8 | 8 passed` and +`120 | 120 passed`, and thirty-five of the case alone at +`test cases: 1 | 1 passed | 0 failed | 7 skipped` and +`assertions: 20 | 20 passed | 0 failed`. Every one printed `Status: SUCCESS!` and +the identical count strings, which is what rules out a `-tc` filter that matched +nothing. The measured lags on the honest tree ran 7.1e-5 to 4.7e-4 s against the +1e-3 s bound, and their ceiling is the rounding rather than the scatter: the two +clock reads each comparison spans are one function call apart. + +The discriminators on this box, at 250000 and 16000 records: `min(copy, sort)` +4.22e-3 to 5.11e-3 s, i.e. 4.2 to 5.1 steps of the printed format against a +precondition of 2; the writer's per-record `phases` build 6.7e-3 to 9.3e-3 s, +i.e. 6.7 to 9.3 steps against the same precondition. + +| id | mutation | verdict | +|---|---|---| +| M-RT | `RenderText` reads its clock AFTER the copy and the sort, i.e. `main`'s code | RED 10/10 on arm (B) | +| M-RT-PARTIAL | the clock read moves BELOW the copy and stays ABOVE the sort — a PARTIAL regression, the shape that broke `### 6`'s one-number budget | RED 10/10 on arm (B) | +| M-SITE | the console block returns to the END of `WriteJson`, after the whole JSON object, i.e. `main`'s call site | RED 10/10 on arm (A) | +| M-BOTH | both halves reverted, i.e. `c7ca0142a` | RED 10/10 on both arms | +| N-BOUND | the bound alone widened a thousandfold — a control that the two `CHECK`s and not the `REQUIRE`s are what red | GREEN, which is what makes M-BOTH's red a bound rather than a precondition | +| N-PRECOND | arm (B)'s table shrinks to three records, the shape #1569 could not gate | RED at the `serialize` `REQUIRE`, loudly, rather than passing quietly | + +The numbers each arm ran against are in the run log the repair session returned. +Nothing in this block is a ratio, and the two discriminators — the cheaper of +`Records()` and `stable_sort` over 250000 records, and the writer's own +per-record `phases` array over 16000 — are measured inside every run rather than +quoted from another box. + ### The mutation table Every mutation prints its own `compile_status` and a sha256 pair, because a @@ -565,13 +674,19 @@ THE WHOLE SET WAS RE-RUN AGAINST THE REPAIRED TREE, not carried over from the run that preceded the fresh review, because three of the repairs change what the suite can see. Every entry below is from that re-run. +TWENTY-THREE ROWS, and `M3` is two of them. Its anchor occurs at both the +`GapsBetweenLeaves` site and the `Sum` site, the harness refused the ambiguous +replace, and each site was mutated separately with a different red. Carrying it +as one row is what made this table read 22 against the 23 counted above it. + | id | mutation | verdict | |---|---|---| | M1 | `WriteJson` reads its clock AFTER the copy and sort, i.e. `main`'s code | RED, head 8.331 ms against a budget of 0.484 ms -- 17.2x | | N11 | the clock read moves BELOW the copy and stays ABOVE the sort -- a PARTIAL regression, which the one-number budget missed at 0.0588 | RED, 1.024 | | NCLAMP | the per-target high-water mark is removed, so overlapping charges are counted twice again | RED, charged 9.491 s of a 0.432 s record -- 21.97 | | M2 | the decomposition drops the FIRST gap -- the prologue, 92% of a real residue | RED on 4: the first gap's origin, the identity, the count, and the prologue's own floor | -| M3 | the decomposition counts NESTED records as leaves | RED on 3: a negative gap at -1.198 ms, the identity, the count | +| M3 | the decomposition counts NESTED records as leaves, at the `GapsBetweenLeaves` site | RED on 3: a negative gap at -1.232 ms, the identity, and the count at `4 == 3` | +| M3 | the same edit at the `Sum` site, run separately because the anchor `if (r.span \|\| r.nested) continue;` occurs at BOTH | RED on the identity at `0.00114164 < 1e-9` | | M7 | the tail gap reported as zero, count and names untouched | RED on 2: the endpoint agreement and the identity | | 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 | @@ -653,9 +768,16 @@ 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. +**Closed: #1569, #1571 and +[#1755](https://github.com/mudler/vllm.cpp/issues/1755).** #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. + +#1755 is the fresh review's own finding on this row: `### 6` repaired the file +emitter's clock ordering and its SIBLING kept the defect, at a scale the console +format could not print. It is filed and fixed in the same flow, per +`## Every change starts from an issue`, because the fix is two statements and +the argument for them is `### 6`'s argument. What was measured, and what was rejected: @@ -664,21 +786,33 @@ What was measured, and what was rejected: 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` 6: 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. + in `### 6`: 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 `### The operator's own re-run` measures that + separation at **32x** — an honest maximum of 0.027616 over 45 runs against + 0.892, the worst run of the harder mutation, over 10. The bound at 0.5 sits + 18.1x above the honest side and 1.78x below the defective one. The three + `head / min(copy, sort)` populations in `## Evidence` quote their own margins + at their own maxima, 52x, 27.6x and 48.9x, and none of them is 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. + gate that silently loses its discriminator is a mute switch. Measured headroom + is **12.0x to 13.5x**, not the 255x this bullet used to claim: `serialize` read + 1.2008e-4, 1.2587e-4, 1.2782e-4, 1.3237e-4, 1.3252e-4 and 1.3535e-4 s over six + consecutive runs of the case alone, on the x86_64 box this branch is built on, + at loadavg 11 to 21, on the tree carrying the `### 10` repair. A fresh review + measured the same quantity at 1.22e-4 to 1.41e-4 independently. The headroom is + an order of magnitude and it is not two. - **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. + the strongest thing in this row. **Eight** of the twenty-three rows in + `### The mutation table` are caught by its assertions, and none of those + assertions contains a clock: `M2`, both `M3` arms, `M7`, `M8`, `NEND`, + `NCURSOR` and `NREVSORT`. `R1` is a ninth against the render case. 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 @@ -689,4 +823,4 @@ 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. +Landed. #1569, #1571 and #1755 closed; #1668 keeps items 1 to 3. diff --git a/.agents/specs/ltx25-phase-residue.md b/.agents/specs/ltx25-phase-residue.md index aec31fd1b..8ef320827 100644 --- a/.agents/specs/ltx25-phase-residue.md +++ b/.agents/specs/ltx25-phase-residue.md @@ -231,7 +231,7 @@ 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) | **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 | +| [#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 an 8000-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. On the tree that lands, restoring `main`'s clock order (`M1`) reds it 10 runs of 10 at ratios of 2.080 to 3.418, and the partial regression (`N11`) reds it 10 of 10 at 0.892 to 1.145, against a bound of 0.5 and an honest 45-run maximum of 0.027616 at loadavg 19-26 — 0.018123 in a higher 56-113 regime. The earlier "1.004 against 0.0042" belonged to the WITHDRAWN one-number `copy + sort` budget, which a fresh review broke and `### 6` replaced with `min(copy, sort)`. 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) | **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 | From 61c3f0a75a708be94e486ec2dc270283dd807a1f Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 02:49:05 +0000 Subject: [PATCH 09/12] record(LTX25-PHASE-INSTRUMENT): the control mutation and the defective-suite counts, measured rather than described MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two entries in `### The console emitter` said more than the run log behind them. The control was recorded as "the bound alone widened a thousandfold". Widening `kStep` alone does not isolate the bounds, because that constant also feeds both preconditions: it reds at the `REQUIRE`s, at five assertions, before either `CHECK` is reached. The control that answers the question is M-BOTH with the two `CHECK` bounds widened and nothing else, and it is GREEN 3 of 3 at `20 | 20 passed`. So M-BOTH's red comes from the bounds. Both readings are kept, because the first one is the trap a reader would fall into next. And the defective-suite counts were quoted without a whole-suite run behind them. Measured now, 3 of 3: `test cases: 8 | 7 passed | 1 failed` and `assertions: 120 | 118 passed | 2 failed`. The other seven cases stay green under `main`'s code, which is the finding restated rather than a footnote — the suite this row already carries cannot see this defect at all. This is the same failure the commit before it repairs, caught inside its own evidence block before it landed. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/specs/ltx25-phase-instrument.md | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 5de4d012e..1d7d35878 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -629,8 +629,11 @@ and they are quoted rather than summarised, because a `-tc` filter that matches nothing prints `Status: SUCCESS!` at `rc=0`. The honest tree reads `test cases: 8 | 8 passed | 0 failed` and -`assertions: 120 | 120 passed | 0 failed`. `main`'s code — both halves — reads -`8 | 7 passed | 1 failed` and `120 | 118 passed | 2 failed`. +`assertions: 120 | 120 passed | 0 failed`. `main`'s code — both halves, `M-BOTH` +— reads `test cases: 8 | 7 passed | 1 failed` and +`assertions: 120 | 118 passed | 2 failed`, measured on the WHOLE suite 3 runs of +3. The other seven cases stay green under it, which is the finding restated: the +suite this row already carries cannot see this defect. **0 RED IN 45 HONEST RUNS.** Ten of the whole suite at `8 | 8 passed` and `120 | 120 passed`, and thirty-five of the case alone at @@ -652,7 +655,7 @@ i.e. 6.7 to 9.3 steps against the same precondition. | M-RT-PARTIAL | the clock read moves BELOW the copy and stays ABOVE the sort — a PARTIAL regression, the shape that broke `### 6`'s one-number budget | RED 10/10 on arm (B) | | M-SITE | the console block returns to the END of `WriteJson`, after the whole JSON object, i.e. `main`'s call site | RED 10/10 on arm (A) | | M-BOTH | both halves reverted, i.e. `c7ca0142a` | RED 10/10 on both arms | -| N-BOUND | the bound alone widened a thousandfold — a control that the two `CHECK`s and not the `REQUIRE`s are what red | GREEN, which is what makes M-BOTH's red a bound rather than a precondition | +| N-BOUND-ON-BOTH | M-BOTH plus the two `CHECK` bounds widened a thousandfold and NOTHING else — the control asking whether M-BOTH's red comes from the bounds or from the preconditions | **GREEN 3/3** at `20 \| 20 passed`, so the bounds are what red. Widening `kStep` instead reds at the `REQUIRE`s, because that constant feeds the preconditions too | | N-PRECOND | arm (B)'s table shrinks to three records, the shape #1569 could not gate | RED at the `serialize` `REQUIRE`, loudly, rather than passing quietly | The numbers each arm ran against are in the run log the repair session returned. From 825f1e3da601435a1830d5d4a0dae80a104a7490 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 04:04:17 +0000 Subject: [PATCH 10/12] test(#1755): the console case set an env var that a thrown precondition leaked into every later case `::setenv("VLLM_RENDER_PHASE_LOG_STDERR", "1", 1)` and the matching `::unsetenv` had two `REQUIRE_MESSAGE` standing between them, and a failed `REQUIRE` throws. The `unsetenv` would then never run and the variable would survive into every case that ran afterwards in the same process, turning one failed precondition into a second, unrelated failure somewhere a reader would have to work backwards from. Nothing is wrong on this tree only because that case is last in the file and `StderrEnabled()` re-reads `getenv` per call rather than latching it the way `ProgressEnabled()` does. Both are properties of the file as it stands right now: `--order-by=rand` breaks the first, and appending a case below breaks it too. The file already reasons about exactly this throw at the `RemoveOnExit` beside it, and already uses RAII for the same job in `TableFile`, `StderrTo` and `RemoveOnExit`, so the repair is one more guard in that shape. It restores the PREVIOUS value rather than simply unsetting, because a guard that unsets what it found set is a leak in the other direction. MEASURED, not asserted. A scratch copy forced the arm-(A) precondition to throw on the first probe and appended an observer case that reads the variable back: pre-repair, bare setenv/unsetenv: 9 cases, 2 failed, and the observer printed `VLLM_RENDER_PHASE_LOG_STDERR leaked with value 1` repaired, the RAII guard: 9 cases, 1 failed -- only the forced throw -- and no leak message Both arms printed `compile_status=0` and a non-empty `git diff --numstat`, and the tree was restored from a pristine byte copy at `restore_sha256_ok=True`. Focused gate on the restored tree: `test cases: 8 | 8 passed | 0 failed` and `assertions: 120 | 120 passed | 0 failed`. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .../vllm/multimodal/test_render_phase_log.cpp | 100 +++++++++++++----- 1 file changed, 72 insertions(+), 28 deletions(-) diff --git a/tests/vllm/multimodal/test_render_phase_log.cpp b/tests/vllm/multimodal/test_render_phase_log.cpp index 467a8a3c1..e870679f4 100644 --- a/tests/vllm/multimodal/test_render_phase_log.cpp +++ b/tests/vllm/multimodal/test_render_phase_log.cpp @@ -156,6 +156,47 @@ class RemoveOnExit { std::string path_; }; +// One environment variable, restored on the way out -- and RAII for the same +// reason `StderrTo` and `RemoveOnExit` are. +// +// The pair this replaces was a bare `::setenv` and a bare `::unsetenv` with two +// `REQUIRE_MESSAGE` standing BETWEEN them, and a failed `REQUIRE` throws. The +// `unsetenv` would then never run, and `VLLM_RENDER_PHASE_LOG_STDERR=1` would +// survive into every case that ran afterwards in the same process -- turning one +// failed precondition into a second, unrelated failure somewhere a reader would +// have to work backwards from. Nothing is wrong today only because that case is +// last in the file and `StderrEnabled()` re-reads `getenv` per call rather than +// latching it the way `ProgressEnabled()` does. Both of those are properties of +// the file as it stands right now: `--order-by=rand` breaks the first, and +// appending a case below breaks it too. +// +// The PREVIOUS value is put back rather than the variable simply removed, +// because a guard that unsets what it found set is a leak in the other +// direction. +class EnvVar { + public: + EnvVar(const char* name, const char* value) : name_(name) { + const char* previous = std::getenv(name); + had_ = previous != nullptr; + if (had_) previous_ = previous; + ::setenv(name_, value, 1); + } + ~EnvVar() { + if (had_) { + ::setenv(name_, previous_.c_str(), 1); + } else { + ::unsetenv(name_); + } + } + EnvVar(const EnvVar&) = delete; + EnvVar& operator=(const EnvVar&) = delete; + + private: + const char* name_; + std::string previous_; + bool had_ = false; +}; + // N sequential leaves under one held span, with the build's own progress lines // pointed at `sink`. The span is what stops the 100 ms sampler being created // and joined once per leaf, and closing it leaves nothing live, so no worker is @@ -1164,39 +1205,42 @@ TEST_CASE("ltx2 phase log: the console copy reports the wall this emitter was EN "detects a console block rendered after that build, so a build this " "cheap cannot be detected at all"); - ::setenv("VLLM_RENDER_PHASE_LOG_STDERR", "1", 1); double console_lag = -1.0; double console_wall = -1.0; double console_clock = -1.0; - for (int k = 0; k < kProbes; ++k) { - bool wrote = false; - std::string why; - double before_write = 0.0; - { - const StderrTo capture(sink); - // The clock is read INSIDE the redirect, because opening and truncating - // the sink is itself milliseconds once the build has filled it, and this - // arm's whole subject is a millisecond. - before_write = log.Elapsed(); - wrote = log.WriteJson(file.path(), "unit", "cpu", &why); - } - REQUIRE_MESSAGE(wrote, why); - const std::string block = ReadAll(sink); - const double printed = WallFromBlock(block); - REQUIRE_MESSAGE(printed >= 0.0, - "`VLLM_RENDER_PHASE_LOG_STDERR=1` produced no block carrying a unique " - "`WALL` row, so the comparison below has no number to make and this arm " - "would pass on a capture that caught nothing. Captured " - << block.size() << " bytes ending:\n" - << block.substr(block.size() > 400 ? block.size() - 400 : 0)); - const double lag = std::fabs(printed - before_write); - if (console_lag < 0.0 || lag < console_lag) { - console_lag = lag; - console_wall = printed; - console_clock = before_write; + { + // Scoped, because the two `REQUIRE_MESSAGE` below throw on a failed + // precondition and a bare `unsetenv` after them would not run. + const EnvVar stderr_on("VLLM_RENDER_PHASE_LOG_STDERR", "1"); + for (int k = 0; k < kProbes; ++k) { + bool wrote = false; + std::string why; + double before_write = 0.0; + { + const StderrTo capture(sink); + // The clock is read INSIDE the redirect, because opening and truncating + // the sink is itself milliseconds once the build has filled it, and this + // arm's whole subject is a millisecond. + before_write = log.Elapsed(); + wrote = log.WriteJson(file.path(), "unit", "cpu", &why); + } + REQUIRE_MESSAGE(wrote, why); + const std::string block = ReadAll(sink); + const double printed = WallFromBlock(block); + REQUIRE_MESSAGE(printed >= 0.0, + "`VLLM_RENDER_PHASE_LOG_STDERR=1` produced no block carrying a unique " + "`WALL` row, so the comparison below has no number to make and this arm " + "would pass on a capture that caught nothing. Captured " + << block.size() << " bytes ending:\n" + << block.substr(block.size() > 400 ? block.size() - 400 : 0)); + const double lag = std::fabs(printed - before_write); + if (console_lag < 0.0 || lag < console_lag) { + console_lag = lag; + console_wall = printed; + console_clock = before_write; + } } } - ::unsetenv("VLLM_RENDER_PHASE_LOG_STDERR"); MESSAGE("console WALL " << console_wall << "s against a clock read " << console_clock << "s immediately before WriteJson, lag " << console_lag << "s (min of " << kProbes << " probes, build " << build_cost From f60b298c52d425a1e09bcb277691a4f3b8665694 Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 04:04:39 +0000 Subject: [PATCH 11/12] record(LTX25-PHASE-INSTRUMENT): the `### 10` gate holds two thirds of its own repair, and the serialize headroom spans more than one regime Two honest corrections to what this row claims, both measured by the session that writes them rather than quoted from another report. THE SURVIVING MUTATION (#1760, new). `### 10`'s repair is three things -- the console block moves above the copy, above the sort AND above the JSON build -- and the composite case holds two of them. `M-SITE-MID` slides the `StderrEnabled()` block BELOW `ByStart(Records())` and `Sum(...)` while leaving it ABOVE the `nlohmann` build, which is #1755's own class in the third arm (A) does not cover, and it survived 19 of 20 runs. Staged with `anchor_occurrences=1`, `git diff --numstat` `3 3`, `compile_status=0`, `restore_sha256_ok=True` against a pristine byte copy and an EMPTY numstat after the restore; nineteen runs at `test cases: 8 | 8 passed` and `assertions: 120 | 120 passed`, one at `8 | 7 passed`. A mutation a gate catches once in twenty is one the gate does not catch, and it is worse than a clean survivor because the single red is a flake a later session will reasonably discount. The cause is arm (A)'s table SIZE and not its bound, and that is why this is a recorded limit rather than a to-do. At 16000 records the writer's per-record `phases` build -- the discriminator arm (A) is sized to -- measures 6.5388e-3 to 7.2559e-3 s, 6.54 to 7.26 steps of `%10.3f`. The copy and the sort at that same size measure 3.8975e-4 to 1.0344e-3 s, 0.39 to 1.03 steps, straddling the one-step bound rather than clearing it. An order of magnitude separates the two quantities at one table size, so a table sized to the larger cannot separate the smaller. Enlarging it is measured shut at about a gigabyte of resident set through an arm that already costs 141 MB and 2.2 s in CI, and a new wall-clock tolerance is forbidden by #1668. `M-SITE-MID` is therefore printed as a GREEN row in the console mutation table with all twenty of its lags, because a mutation table listing only its successes is an argument and not a measurement. The `19 RED + 4 GREEN = 23` arithmetic still reconciles and now says which population it counts: those 23 were measured on a tree that pre-dates this repair, so the call site `M-SITE-MID` mutates did not exist on it. The console table is seven rows, six RED and one GREEN. Across both, 30 mutations, 25 RED and 5 GREEN, each green one named beside the issue that owns it. #1760 is filed rather than folded into #1718, which is the `instrument_seconds` charge-site class and not a call-site ordering one. THE SERIALIZE RANGE (R3). The `serialize > 1e-5` bullet quoted 12.0x to 13.5x from one population. A second box and load regime read 1.3094e-4 to 2.1012e-4, and eight consecutive runs of the case alone on this box at loadavg 8.35 to 8.41 read 1.15782e-4 to 1.29198e-4, every one printing `test cases: 1 | 1 passed | 0 failed | 7 skipped` and `assertions: 14 | 14 passed | 0 failed`. The union is 11.6x to 21.0x, and it is restated as three populations with their regimes rather than as one number, because `serialize` is a wall-clock quantity and a single regime's spread understates it. The bullet's substantive claim is unchanged either way: the headroom is an order of magnitude and it is not two. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/issue-index.md | 1 + .agents/specs/ltx25-phase-instrument.md | 125 ++++++++++++++++++++++-- 2 files changed, 119 insertions(+), 7 deletions(-) diff --git a/.agents/issue-index.md b/.agents/issue-index.md index f37881f20..e38770284 100644 --- a/.agents/issue-index.md +++ b/.agents/issue-index.md @@ -640,3 +640,4 @@ rather than merged. `scripts/check-agent-record.py` gates both. | [#1731](https://github.com/mudler/vllm.cpp/issues/1731) | `ENG-RECORD-CONFLICT-SURFACES` | `check-agent-record` is RED on `main`: `#1649` is listed twice in `.agents/issue-index.md`, at `:592` (added by `a7bb3130b`, the lane that FILED it) and `:632` (added by `2f2a70925`, the lane that FIXED it). Neither is wrong and neither could see the other -- `merge=union` combines two appends silently, so a duplicate is the ordinary outcome when filing and fixing happen on different branches, and the checker only notices once both have landed on main, where every later PR inherits the red. Not repaired in flow: the index preamble forbids editing or deleting a row, and the two bodies carry different facts (`:632` has a second red and the mutation evidence, `:592` has the attribution to `a50c57d69`), so choosing which survives is a judgement | bug | | [#1733](https://github.com/mudler/vllm.cpp/issues/1733) | `ENG-RECORD-CONFLICT-SURFACES` | CLOSED as a duplicate of [#1731](https://github.com/mudler/vllm.cpp/issues/1731), filed seventeen minutes after it against the same red, and recorded here rather than left unindexed because its one MEASURED claim is FALSE and an append-only row cannot be corrected in place later. Both issues report that `.agents/issue-index.md` lists [#1649](https://github.com/mudler/vllm.cpp/issues/1649) twice on `main` at `038ff61e5`, at `:592` from `a7bb3130b` (the lane that FILED it) and at `:632` from `2f2a70925` (the lane that FIXED it). #1731 is the earlier filing, already carries an index row, and is the record. #1733 adds one thing #1731 does not, and it is wrong: "the repair is measured and it is NOT blocked", on the evidence that removing one of the two rows in a worktree and running both checkers gives `agent record OK: ENGINE=170 MODEL=377 ...` and `OK: issue index append-only`. The second half is an artefact of the instrument. `scripts/check-issue-index-append-only.py:50-51` diffs `merge-base(origin/main, HEAD)..HEAD`, which reads COMMITS, so an UNCOMMITTED deletion is invisible to it. Measured on `row/FIX-ISSUE-INDEX-1649-DUP` at base `038ff61e5`: deleting `:592` in the WORKING TREE alone returns `OK: issue index append-only` at rc 0 with `git diff --numstat 038ff61e5..HEAD -- .agents/issue-index.md` EMPTY, and committing the byte-identical deletion turns the same checker rc 1 with a `removed:` line naming the row. #1733's own quoted `agent record OK: ENGINE=170 MODEL=377` is the tell, because that is the working-tree reading and the committed tree cannot produce it while the duplicate stands. So the duplicate IS base-reachable, the two checkers ARE in genuine contradiction on this tree, and the repair is the argued exception #1731's row anticipated rather than the free edit #1733 reported | bug | | [#1755](https://github.com/mudler/vllm.cpp/issues/1755) | `LTX25-PHASE-INSTRUMENT` | `PhaseLog::RenderText` read `Elapsed()` AFTER `ByStart(Records())`, so the CONSOLE copy of a phase table charged its own copy and its own sort to the `WALL` it printed and to the `unaccounted` row above it. That is [#1569](https://github.com/mudler/vllm.cpp/issues/1569)'s defect on #1569's own sibling emitter: the file copy was repaired and the copy a reader watching a terminal gets was not. The call site was the larger half -- the console block stood at the END of `WriteJson`, after the whole `nlohmann` object was assembled, so it absorbed the JSON build as well: over five `WriteJson` calls on the 8001-record unit timeline `sum(leaf)` held at 0.189 s while the console's `unaccounted` climbed 0.065 -> 0.134 -> 0.200 -> 0.265 -> 0.329 s, about 66 ms of writer work per call charged to a render that had not run. NOTHING COULD SEE IT: `RenderText` prints every total with `%10.3f` and a copy and a sort of 8000 records is 0.12 ms, a quarter of one step of that format, so applying #1569's own one-line repair to its sibling left the suite at `7 \| 7 passed` and `100 \| 100 passed`. Found by the fresh review of [PR #1711](https://github.com/mudler/vllm.cpp/pull/1711) and fixed in the same flow: the clock is read first in both emitters, the console block moves above the copy, the sort and the build, and the gate takes its bound from `%10.3f`'s own last digit rather than from a wall-clock ratio, over a table large enough for the defect to cross it | bug | +| [#1760](https://github.com/mudler/vllm.cpp/issues/1760) | `LTX25-PHASE-INSTRUMENT` | The `### 10` console call-site gate holds only the JSON BUILD, not the copy and the sort. `M-SITE-MID` slides the `StderrEnabled()` block BELOW `ByStart(Records())` and `Sum(...)` while leaving it ABOVE the `nlohmann` build -- [#1755](https://github.com/mudler/vllm.cpp/issues/1755)'s own class, the console `WALL` charged with the writer's copy and sort -- and it survived **19 of 20 runs** at `test cases: 8 \| 8 passed` and `assertions: 120 \| 120 passed`, with one run in twenty red at `8 \| 7 passed`. A mutation a gate catches once in twenty is one the gate does not catch. The cause is arm (A)'s table SIZE and not its bound: at 16000 records the writer's per-record `phases` build measures 6.5388e-3 to 7.2559e-3 s = 6.54 to 7.26 steps of `%10.3f`, while the copy plus the sort at that same size measures 3.8975e-4 to 1.0344e-3 s = 0.39 to 1.03 steps and straddles the one-step bound. Enlarging the table is measured shut -- `WriteJson` holds ~3.3 KB of `nlohmann` per record while it dumps, so a table big enough costs ~1 GB of resident set through an arm that already costs 141 MB and 2.2 s in CI -- and a new wall-clock tolerance is forbidden by [#1668](https://github.com/mudler/vllm.cpp/issues/1668). NOT [#1718](https://github.com/mudler/vllm.cpp/issues/1718), which is the `instrument_seconds` charge-site class. What would settle it is a bound that does not go through the printed format: a structural assertion over the block's position, or a `RenderText` HANDED the wall it prints. Found by the fresh review of [PR #1711](https://github.com/mudler/vllm.cpp/pull/1711) and reproduced by the session that recorded it | bug | diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index 1d7d35878..c357a4153 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -299,6 +299,49 @@ the one-step bound by 1.5x: - arm (A), the call site: the writer's own per-record `phases` array, assembled by the case through the same library over 16000 records. +**WHAT EACH ARM SEPARATES, AND WHAT IT DOES NOT.** The repair above is three +things — the console block moves above the copy, above the sort AND above the +JSON build — and the two arms between them hold two of the three. This is a +statement about the GATE and not about the code, and it is measured rather than +argued. Issue +[#1760](https://github.com/mudler/vllm.cpp/issues/1760) owns the gap. + +- **arm (B) holds `RenderText`'s own internal ordering, including a partial + regression of it.** Its discriminator is `min(copy, sort)` over 250000 + records, and the table is sized to that quantity. `M-RT` and `M-RT-PARTIAL` + are each RED 10/10, and the partial one moves only ONE of the two steps, so + the arm is held against half a revert as well as a whole one. +- **arm (A) holds only that the console block stands above the JSON BUILD.** Its + discriminator is the writer's own per-record `phases` array over 16000 + records, and the table is sized to THAT quantity: measured in the same runs on + this box, that build is 6.5388e-3 to 7.2559e-3 s, i.e. **6.54 to 7.26 steps** + of `%10.3f`. The copy and the sort at the SAME 16000 records are roughly an + order of magnitude cheaper, and the arm cannot separate them. **`M-SITE-MID` + measures exactly that**: the console block slides BELOW `ByStart(Records())` + and `Sum(...)` and stays ABOVE the `nlohmann` build, which is #1755's own + class reintroduced in the two-thirds arm (A) does not cover, and it survived + **19 of 20 runs**. Its lags ran 3.8975e-4 to 1.0344e-3 s against the 1e-3 s + bound — **0.39 to 1.03 steps**, straddling the bound rather than clearing it, + which is why one run in twenty came back red and nineteen did not. + +So the composite case holds *"the console block sits above the JSON build"* and +*"`RenderText` reads its clock before its own copy and sort"*. It does **not** +hold *"the console block sits above the copy and the sort"*. A reader who takes +the case's own comment — "it sits above the copy, the sort and the whole JSON +build" — as a statement of what the gate covers is reading the intent rather +than the coverage. + +**ENLARGING ARM (A)'s TABLE IS MEASURED SHUT, so this is a recorded limit and +not a to-do.** `WriteJson` holds one `nlohmann` object per record while it dumps, +about 3.3 KB per record; a table big enough for the copy and the sort to cross +the last printed digit costs about a gigabyte of resident set through arm (A), +and arm (A) already costs 141 MB and 2.2 s in CI. A new wall-clock tolerance is +the other obvious move and #1668 forbids re-proposing it. What would settle +#1760 is a bound that does not go through `%10.3f` at all — a structural +assertion over the block's position, or a `RenderText` that is HANDED the wall it +prints instead of reading a clock, which deletes the ordering question. Each is a +production change to a shared emitter and owes its own red-first evidence. + **Two tables rather than one, and the reason is memory.** `WriteJson` holds one `nlohmann` object per record while it dumps, about 3.3 KB per record, so a single table big enough for arm (B) costs a gigabyte of resident set through arm (A). @@ -420,9 +463,10 @@ What is left on this branch is two jobs, and NEITHER is this row's: | [#1568](https://github.com/mudler/vllm.cpp/issues/1568) | the `denoise.step` / `denoise.update` seconds transfer. `denoise.update` does not exist yet -- **and the obvious closure is now MEASURED SHUT.** See below | | [#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` | -| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | the charge sites are gated only in AGGREGATE. Three of this row's own mutations -- N4, N6 and NNOSORT -- are GREEN, and they are printed in the mutation table rather than left out | +| [#1718](https://github.com/mudler/vllm.cpp/issues/1718) | the charge sites are gated only in AGGREGATE. Three of this row's own mutations -- N4, N6 and NNOSORT -- are GREEN, and they are printed in the mutation table rather than left out. It does NOT cover [#1760](https://github.com/mudler/vllm.cpp/issues/1760), which is a call-site ORDERING survivor rather than a charge site | | [#1719](https://github.com/mudler/vllm.cpp/issues/1719) | `PhaseLog::Close`'s pre-lock wait is charged to nobody, so it inflates the closing record's UNCOVERED time -- which is the quantity the coverage floor reads. It has to land before #1718 can, because it is where staged contention actually goes | | [#1720](https://github.com/mudler/vllm.cpp/issues/1720) | `WriteJson` now takes the process-wide mutex TWICE, so `wall_seconds` and the record set are two snapshots rather than one. Unreachable on the shipped path and argued in the function's own comment; the repair is a single locked snapshot, which is a public API change | +| [#1760](https://github.com/mudler/vllm.cpp/issues/1760) | `### 10`'s arm (A) holds only that the console block stands above the JSON BUILD, not that it stands above the copy and the sort. `M-SITE-MID` slides the block below `ByStart` and `Sum` and survives **19 of 20 runs**; it is a GREEN row in the console mutation table with its twenty measured lags beside it. The cause is arm (A)'s table SIZE -- at 16000 records the JSON build is 6.54 to 7.26 steps of `%10.3f` and the copy plus the sort is 0.39 to 1.03 -- and enlarging that table is measured shut at about a gigabyte of resident set. Settling it needs a bound that does not go through the printed format at all: a structural assertion over the block's position, or a `RenderText` HANDED the wall it prints instead of reading a clock. Both are production changes to a shared emitter and each owes its own red-first evidence | ### Owed out of the fresh review @@ -580,6 +624,19 @@ and the four green are exactly the four this row already files under [#1718](https://github.com/mudler/vllm.cpp/issues/1718) — `NSEED`, `N4`, `N6`, `NNOSORT`. No mutation the table calls red came back green. +**That `19 + 4 = 23` counts THIS population and no other, and the row's total is +five green rather than four.** These 23 were measured on the tree whose +`render_phase_log.cpp` reads sha256 `e490ccc3…`, which pre-dates the `### 10` +repair, so the call site `M-SITE-MID` mutates did not exist on it. The console +emitter carries its own separate table below — +`### The console emitter, measured by the session that repaired it`, **seven +rows, six RED and one GREEN** — and its green row is `M-SITE-MID`, filed under +[#1760](https://github.com/mudler/vllm.cpp/issues/1760) rather than under #1718, +because it is the #1755 call-site ORDERING class and not the +`instrument_seconds` charge-site class. The two tables together are **30 +mutations, 25 RED and 5 GREEN**, and every green one is named beside the issue +that owns it. + **`M3`'s anchor was NOT unique, and the harness refused rather than mutating the wrong function.** `if (r.span || r.nested) continue;` occurs TWICE — once in `Sum` and once in `GapsBetweenLeaves` — so a text replace would have silently hit @@ -657,6 +714,32 @@ i.e. 6.7 to 9.3 steps against the same precondition. | M-BOTH | both halves reverted, i.e. `c7ca0142a` | RED 10/10 on both arms | | N-BOUND-ON-BOTH | M-BOTH plus the two `CHECK` bounds widened a thousandfold and NOTHING else — the control asking whether M-BOTH's red comes from the bounds or from the preconditions | **GREEN 3/3** at `20 \| 20 passed`, so the bounds are what red. Widening `kStep` instead reds at the `REQUIRE`s, because that constant feeds the preconditions too | | N-PRECOND | arm (B)'s table shrinks to three records, the shape #1569 could not gate | RED at the `serialize` `REQUIRE`, loudly, rather than passing quietly | +| M-SITE-MID | the console block slides BELOW `ByStart(Records())` and `Sum(...)` and stays ABOVE the `nlohmann` build, so the console `WALL` is charged with the writer's own copy and sort but not its serialization -- #1755's class in the two-thirds arm (A) does not cover | **GREEN 19/20** -- [#1760](https://github.com/mudler/vllm.cpp/issues/1760) | + +**SEVEN ROWS, six RED and one GREEN, and the green one is printed here rather +than left out.** A mutation table listing only its successes is an argument and +not a measurement. `M-SITE-MID` was staged by the repair session that landed +`### 10`'s wording, on the same Release build and box, at loadavg 8.5 to 10.3, +with `anchor_occurrences=1`, `git diff --numstat` `3 3`, `compile_status=0` and +`restore_sha256_ok=True` against a pristine byte copy, and the numstat EMPTY +after the restore. Nineteen runs read `test cases: 8 | 8 passed | 0 failed` and +`assertions: 120 | 120 passed | 0 failed`; one read `8 | 7 passed | 1 failed` +and `120 | 119 passed | 1 failed`. **A mutation a gate catches once in twenty +is a mutation the gate does not catch**, and it is worse than a clean survivor +because the single red is a flake a later session will reasonably discount. The +twenty lags, each a minimum over 3 probes, against the 1e-3 s bound: + +``` +7.0954e-4 8.0859e-4 6.1208e-4 5.5063e-4 7.0809e-4 +4.4587e-4 1.0344e-3 4.8383e-4 6.9707e-4 5.2762e-4 +3.8975e-4 8.3156e-4 4.0191e-4 7.2963e-4 7.7509e-4 +7.8492e-4 4.7455e-4 9.6428e-4 6.6708e-4 7.8302e-4 +``` + +The honest tree on the same box, same session, read 7.94e-5, 1.206e-4, 2.876e-4 +and 4.492e-4 s. Why the arm cannot separate it is in `### 10` and it is the +table SIZE rather than the bound: at 16000 records the JSON build is 6.54 to +7.26 steps of `%10.3f` and the copy plus the sort is 0.39 to 1.03 steps. The numbers each arm ran against are in the run log the repair session returned. Nothing in this block is a ratio, and the two discriminators — the cheaper of @@ -775,6 +858,9 @@ longer appears: `519303d15` named it `load.open`. [#1755](https://github.com/mudler/vllm.cpp/issues/1755).** #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. +[#1760](https://github.com/mudler/vllm.cpp/issues/1760) is NEW and open: #1755's +repair landed in full, and the gate over it holds two of its three halves. See +the survivor bullet below. #1755 is the fresh review's own finding on this row: `### 6` repaired the file emitter's clock ordering and its SIBLING kept the defect, at a scale the console @@ -805,12 +891,37 @@ What was measured, and what was rejected: - **`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 - is **12.0x to 13.5x**, not the 255x this bullet used to claim: `serialize` read - 1.2008e-4, 1.2587e-4, 1.2782e-4, 1.3237e-4, 1.3252e-4 and 1.3535e-4 s over six - consecutive runs of the case alone, on the x86_64 box this branch is built on, - at loadavg 11 to 21, on the tree carrying the `### 10` repair. A fresh review - measured the same quantity at 1.22e-4 to 1.41e-4 independently. The headroom is - an order of magnitude and it is not two. + is **11.6x to 21.0x**, not the 255x this bullet used to claim — and that range + spans MORE THAN ONE load regime rather than pretending to be one number, + because `serialize` is a wall-clock quantity and a single regime's spread + understates it. Three populations, all of the case alone on the tree carrying + the `### 10` repair, all on x86_64: + + | population | loadavg | `serialize`, min to max | headroom over `1e-5` | + |---|---|---|---| + | 6 consecutive runs | 11 to 21 | 1.2008e-4 to 1.3535e-4 | 12.0x to 13.5x | + | a second box and load regime | -- | 1.3094e-4 to 2.1012e-4 | 13.1x to 21.0x | + | 8 consecutive runs, the session that recorded this | 8.35 to 8.41 | 1.15782e-4 to 1.29198e-4 | 11.6x to 12.9x | + + Every run in the third population printed + `test cases: 1 | 1 passed | 0 failed | 7 skipped` and + `assertions: 14 | 14 passed | 0 failed`, which is what rules out a `-tc` + filter that matched nothing and reported `SUCCESS!`. A fresh review measured + the same quantity at 1.22e-4 to 1.41e-4 independently, inside the union above. + **The claim the bullet makes is unchanged by any of it**: the headroom is an + order of magnitude and it is not two. +- **The `### 10` gate carries a KNOWN SURVIVOR and it is recorded rather than + closed.** `M-SITE-MID` — the console block slid below `ByStart` and `Sum` and + left above the JSON build — is GREEN in 19 of 20 runs, so #1755's own class + survives in the two-thirds of the repair arm (A) does not cover. The reason is + structural and is in `### 10`: arm (A)'s 16000-record table is sized to the + JSON-build discriminator at 6.54 to 7.26 steps of `%10.3f`, while the copy and + the sort at that same size are 0.39 to 1.03 steps and straddle the bound. The + fix a reader would reach for first — enlarging arm (A)'s table — is measured + shut at about a gigabyte of resident set, and a new wall-clock tolerance is + forbidden. **Recording the limit is the correct outcome here**, and + [#1760](https://github.com/mudler/vllm.cpp/issues/1760) owns what would settle + it. - **The gap decomposition is arithmetic, not a measurement.** That is why it is the strongest thing in this row. **Eight** of the twenty-three rows in `### The mutation table` are caught by its assertions, and none of those From 921b03d60e25f2010ba1f8873df3e1118d5038bb Mon Sep 17 00:00:00 2001 From: Ettore Di Giacinto Date: Sun, 23 Aug 2026 05:03:47 +0000 Subject: [PATCH 12/12] record(LTX25-PHASE-INSTRUMENT): the first statement of coverage overstated it, a heading misnamed its tree, and a table listed only its reds Three sentences in `.agents/specs/ltx25-phase-instrument.md` said more, or less, than the evidence in the same file supports. A fresh review of head 223810f52 raised all three as LOW findings. No code, test, or other record changes. `## Scope` item 4 said the gate holds both halves of the #1755 repair. It does not. `### 10` measures that it holds the first half and one of the second half's three parts, and #1760 owns the part it does not hold. `### 10` says this, but 260 lines later. A reader meets `## Scope` first, so the file's first statement of coverage was the one that overstated it. The item now names the limit and the issue that owns it, in one clause, and leaves the argument where it is measured. The heading `### The operator's own re-run, on the tree that is merged` contradicted its own body. That body records the 23-mutation population against `render_phase_log.cpp` at sha256 `e490ccc3...`, which is the file at `27f17d14f` and pre-dates the `### 10` repair in `610517577`. The merged tree carries `7d75b929f6...` instead. An evidence table has to name the tree it was measured on, and a heading that names the wrong one turns a true table into a false claim. The body is correct, so the heading moved to match it. The `## Tests` row for the console case listed `M-RT`, `M-RT-PARTIAL`, `M-SITE` and `M-BOTH` as reds and stopped there. That is true and one-sided. `M-SITE-MID` survives 19 runs of 20, and every other surface in the row already says so. A reader of the table alone would not learn that a survivor exists, so the row now names it beside #1760. FOLLOWING_AGENTS_PROTOCOL Following-Agents-Protocol: true AI-Assisted: true Assisted-by: AGENT:claude-opus-5 [claude-code] --- .agents/specs/ltx25-phase-instrument.md | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/.agents/specs/ltx25-phase-instrument.md b/.agents/specs/ltx25-phase-instrument.md index c357a4153..bca226e96 100644 --- a/.agents/specs/ltx25-phase-instrument.md +++ b/.agents/specs/ltx25-phase-instrument.md @@ -34,7 +34,9 @@ IN SCOPE: emitted file. #1571. 4. **`RenderText` reads its clock before it serialises, and the console block is emitted before this writer does any work at all**, plus the gate that - holds both. [#1755](https://github.com/mudler/vllm.cpp/issues/1755), found + holds both only in the two thirds `### 10` measures, with + [#1760](https://github.com/mudler/vllm.cpp/issues/1760) owning the third it + does not. [#1755](https://github.com/mudler/vllm.cpp/issues/1755), found by the fresh review of this row and fixed in the same flow. `### 10`. OUT OF SCOPE, and each is named because each was tempting: @@ -406,7 +408,7 @@ under `### The console emitter` reads `test cases: 8 | 8 passed` and | a record charged from MANY THREADS is still charged less than it lasted | the record arm of the clamp. 24 threads ticking inside one live leaf drove `instrument / duration` to 1.914 before it, red 3 runs in 5 | `instrument_seconds <= duration_seconds`, held by the disjointness construction rather than by margin. `NCLAMP` reds it | | 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 | `### 6` | -| the console copy reports the wall this emitter was ENTERED at | `### 10`. #1755. Two arms: `RenderText` against the clock read immediately before it over 250000 records, and the `VLLM_RENDER_PHASE_LOG_STDERR` block across `WriteJson` over 16000 | the printed `WALL` against ONE step of that line's own `%10.3f`, with each arm's discriminator measured in the same run and each lag a minimum over probes. `M-RT`, `M-RT-PARTIAL`, `M-SITE` and `M-BOTH` red it | +| the console copy reports the wall this emitter was ENTERED at | `### 10`. #1755. Two arms: `RenderText` against the clock read immediately before it over 250000 records, and the `VLLM_RENDER_PHASE_LOG_STDERR` block across `WriteJson` over 16000 | the printed `WALL` against ONE step of that line's own `%10.3f`, with each arm's discriminator measured in the same run and each lag a minimum over probes. `M-RT`, `M-RT-PARTIAL`, `M-SITE` and `M-BOTH` red it, and `M-SITE-MID` does NOT — [#1760](https://github.com/mudler/vllm.cpp/issues/1760) owns the third of the repair this case leaves unheld | Plus, in `tests/vllm/multimodal/test_ltx2_video.cpp`, inside the existing ABI render case: the emitted table carries `instrument_seconds`, carries `gaps`, and @@ -608,7 +610,7 @@ Contrast the withdrawn bound: 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 its own scatter and 4 runs in 45 crossed it. -### The operator's own re-run, on the tree that is merged +### The operator's own re-run, on the tree that pre-dates the `### 10` repair `## How work gets done` 4: an implementer or reviewer report is an input, never a gate result. Everything below was re-run by the merging session on the tree