diff --git a/.agents/issue-index.md b/.agents/issue-index.md index 71e04668c..cf724c0f3 100644 --- a/.agents/issue-index.md +++ b/.agents/issue-index.md @@ -464,11 +464,13 @@ rather than merged. `scripts/check-agent-record.py` gates both. | [#1394](https://github.com/mudler/vllm.cpp/issues/1394) | `ENG-CUDAGRAPH-BREAK` | The CPU paged attention reads `btab[r * bt_row + (j / block_size) * bt_col]` for every `j < seq_lens[r]` without checking that the block table has that many columns, so a caller with a short table gets an out-of-bounds read, a plausible block index out of it, and attention over the WRONG page — silently. `tests/vllm/models/test_qwen3_5_decode_graph_seam.cpp`'s `SpecAttnMeta` supplies one: hardcoded `block_table_num_cols = 1` against shape C's `seq_lens = 24` at `block_size = 16`. Found while fixing [#1380](https://github.com/mudler/vllm.cpp/issues/1380), whose `DevicePool` change moved the bytes after the table and turned the same read into a SIGSEGV on `thor:gpu0` (`gdb` at `src/vt/cpu/cpu_paged_attn.cpp:224` under `FullAttnBlockPaged`). PRE-EXISTING: the case passes at `origin/main` only because the read landed on bytes that decoded to an in-range index. FIXED IN FLOW in both halves — the kernel refuses a short table with one compare per request outside the token loop, and the helper sizes its table for the sequence length it declares. Owned by row `ENG-CUDAGRAPH-BREAK` | bug | | [#1387](https://github.com/mudler/vllm.cpp/issues/1387) | `ENG-EXPERT-STREAM-DEVICE` | `docs/FEATURES.md`'s routed-expert-streaming row still read "CPU keep-quant towers only" after W0c made the seam take the slot arm on `is_cpu()` OR `host_memory_is_device_addressable()` and W0d made the load-time fit refusal drop those towers from its bound. `AGENTS.md` routes a feature-surface change to that page, and the change that moved the surface did not write it. `scripts/check-doc-checkpoint.py` said so, on commit `939755f99` of `row/ENG-EXPERT-STREAM-DEVICE-W0`: a measurement was appended to `.agents/benchmark-record.md` with no `docs/FEATURES.md` edit beside it. The PAGE is FIXED IN FLOW while repairing the fresh review of [#1377](https://github.com/mudler/vllm.cpp/pull/1377): the row now names both the device arm ([#1124](https://github.com/mudler/vllm.cpp/issues/1124)) and the residency condition ([#1378](https://github.com/mudler/vllm.cpp/issues/1378)), and the observability detail it displaced to stay inside the 220-character cell budget is stated at `docs/USAGE.md:4598-4620`. The GATE is NOT fixed and needs a decision: the checker walks a range one COMMIT at a time, so once a commit is published on a branch that may not be force-pushed, no later commit can make it green, and `scripts/agent-preflight.sh` keeps reporting `doc-checkpoint range` red on this branch until it merges. The squashed commit that lands on `main` carries both paths and passes. Changing the walk is checker semantics and needs its own row, spec and red-first evidence per `AGENTS.md` "Changing the rules or a checker", so it is not folded in here. Spec [`expert-stream-device-slots.md`](specs/expert-stream-device-slots.md) | bug | | [#1386](https://github.com/mudler/vllm.cpp/issues/1386) | — | `tools/bench/gpu_clock_state.py`'s `QUERY_FIELDS` collects nine fields and **none of them is thermal and none is electrical**, so the driver's own `SwThermalSlowdown` label can never be checked against a die reading on any window this helper has ever recorded. The measured consequence is that the nine windows of 2026-08-19 cannot distinguish a load transition from a thermal excursion. The concrete evidence is `clock-c1-r1.samples.json` in `/mnt/nas_share/rc/q38bf16/out/bench-20260819T035148Z/`: ours c1 r1 dips five times on the same period at the same `utilization.gpu = 96` — 48.83 s / 2177 MHz, 80.60 s / 2320 MHz, 109.28 s / 2210 MHz, 137.98 s / 2359 MHz, 166.07 s / 2268 MHz — and **two of those five carry `0x0000000000000000`**, no throttle bit at all (2210 and 2359), while three carry `0x20`. The 2210 MHz unlabelled dip is deeper than two of the three labelled ones, so the driver labels comparable excursions inconsistently and the bit alone cannot decide it. What would settle it: add `temperature.gpu` and `power.draw` to `QUERY_FIELDS`. That changes the clock-record schema, so it owes its own row and spec. Split out of [#1354](https://github.com/mudler/vllm.cpp/issues/1354) and owed under `## Owed` in [lease-clock-pinning.md](specs/lease-clock-pinning.md) | gap | +| [#1413](https://github.com/mudler/vllm.cpp/issues/1413) | `LTX25-DEVICE-RESIDENCY` | The LTX-2.5 render phase table [#1408](https://github.com/mudler/vllm.cpp/pull/1408) lands for [#1010](https://github.com/mudler/vllm.cpp/issues/1010) is written by the SUCCESS PATH ONLY — `WritePhaseLog` sits after `im.trace.completed = true` at `src/vllm/multimodal/ltx2_video.cpp:4655-4658 @ 4f3c24380` — so a render that is killed, aborted by a lease governor, or still running writes no table at all. That is the population the campaign actually has: [#1375](https://github.com/mudler/vllm.cpp/issues/1375) is `ABORT[92] PROJECTED OVERRUN`, `child exit=-15`, 0 frames; [`ltx25-decode-speed.md`](specs/ltx25-decode-speed.md) rung 1 is `EXIT=137`, 0 frames; rung 2 is `EXIT=1`, 0 frames. **And nothing is emitted WHILE a render runs**: `PhaseLog::Open`/`Close` print nothing and `VLLM_RENDER_PHASE_LOG_STDERR` fires inside `WriteJson`, i.e. on the success path again, so between `ltx2-gen: family=...` and `wrote N frames` a 2.5-hour render is silent and working is byte-identical to hung. **The unit that costs the wall has no counter**: `denoise` is one leaf covering ~2.7 h, against #1375's measured ~162 s per DiT forward at 60 structural forwards (30 steps x 2 CFG legs — `cfg_scale != 1.0` forces the unconditional branch at `ltx2_pipeline.cpp:521-523`). External sampling is NOT the fallback and was tried: #1375 records `phase=OTHER` throughout because `eu-stack` unwinds ZERO frames inside the `rc` worker container, and its own text names an in-process phase marker as the way to attribute the 162 s. Owed: a stderr line on every phase open and close, so the LAST LINE PRINTED names the phase in flight, plus one tick per DiT forward carrying phase, step `k/N`, cumulative forward index, elapsed and seconds-since-previous — on the shipped default, because the failure happened on default settings and `VT_H3_PROGRESS` (`minimax_h3.cpp:776-793`) is the opt-in shape that is exactly why no LTX-2.5 run has one. Precondition for attributing #1375, which caps render resolution. Stage W0-live in [`ltx25-device-residency.md`](specs/ltx25-device-residency.md) | feature | | [#1320](https://github.com/mudler/vllm.cpp/issues/1320) | `ENG-EXPERT-STREAM-DEVICE` | `VT_CPU_QUANT_REPACK` rewrites a Q8_0 weight into the `block_q8_0x4` i8mm interleave at load, and only the CPU `MatmulBTKernel` understands that layout — the CUDA quant dot reads plain `block_q8_0` and never consults `Tensor::repacked`, so a repacked weight uploaded to a device produces WRONG TOKENS rather than a crash. Its sibling `elem_kn_repack` has BOTH a CPU-platform gate in the loader policy (`gguf_keep_quant.cpp`, `CurrentPlatform().device_type() == kCPU`) and a refusal in `ResidentWeight`; `quant_repack` had NEITHER, because it rides `vt::cpu::QuantRepackActive()`, a HOST-CPU Arm i8mm probe that says nothing about where the weight will execute. An aarch64 box doing `--device cuda` — which is exactly `dgx:gpu0`, a Grace-Blackwell GB10 — satisfies it. Currently silent rather than firing, and that is measured: eligibility is Q8_0 with `n % 4 == 0 && k % 32 == 0`, `Qwen3.8-2.4T-A95B UD-Q1_0` has exactly one Q8_0 tensor at 0.01% of parameters, and the instrumented load of that checkpoint recorded `quant_repack = 0`. Found while implementing W0f ([#1299](https://github.com/mudler/vllm.cpp/issues/1299)), which changes the same function and whose G0-CORRECT gate compares CUDA tokens against CPU tokens — precisely the instrument that would have reported this as a W0f defect. FIXED IN FLOW as the tripwire its sibling already has, placed beside it so it covers the staging branch AND W0f's aliasing branch (where the bytes live was never the question; the kernel that reads them is), gated red-first on both arms and mutation-proven. `VT_CPU_QUANT_REPACK=0` is the operator's way past it. NOT fixed here, deliberately: adding the missing CPU-platform gate to `p.quant_repack` itself is a loader-policy semantics change owned by `QUANT-GGUF-KEEPQ-LOADER`, carried under `## Owed` in [`expert-stream-device-slots.md`](specs/expert-stream-device-slots.md) | bug | | [#1426](https://github.com/mudler/vllm.cpp/issues/1426) | `LTX25-GUIDED-VIDEO` | The LTX-2.5 x0 model picks its DiT forward with one ternary on `im.on_device` (`src/vllm/multimodal/ltx2_video.cpp`), and **no test on a box without an accelerator enters the DEVICE branch**, so dropping its `perturbations` argument is undetectable. MEASURED, both mutations built clean at `compile_err=0` and both restored byte-for-byte with the target rebuilt: **D10** (drop `p` from the device branch alone, 1 insertion / 1 deletion) is **GREEN**, `test_ltx2_video` exit 0, 88 cases / 2755 assertions; **D11** (drop it from BOTH branches, 3 insertions / 2 deletions) is **RED**, exit 1, 2 cases / 3 assertions, failing `CHECK(MaxAbsDiffOf(t.video_first_perturbed, t.video_first_cond) > 1e-6 * latent_span)`, the same for `video_first_modality`, and `CHECK(n.video_first_perturbed != n.video_first_cond)`. D11 also has to be written with `(void)p;` to be a RESULT at all, because the naive form leaves the lambda parameter unused and `-Werror=unused-parameter` refuses the build - a mutation that fails to build reads exactly like a passing test. This is a missing RUNNER and not a missing test: `Ltx2VideoEngine::Load` refuses `device != 0` in three places (`ltx2_video.cpp:749-758`, `:779-788`, and the queue-creation check below them) unless a non-CPU platform resolves, registers a backend and does not decline `kLtx2VideoFamily`, and `.github/workflows/ci.yml` has no GPU runner. A SYNTHETIC accelerator is DEFERRED rather than impossible, and the PARTS ALREADY EXIST. `vt::RegisterOp(OpId, DeviceType, void*)` is public (`include/vt/op_provider.h:127`) and is exactly how `src/vt/cpu/cpu_ltx2.cpp:201-205` installs the CPU glue table, so a test can read that pointer back with `vt::GetOp(OpId::kLtx2, kCPU)` and register it for a second device type; `RegisterReferenceTier` loops EVERY OpId (`src/vt/op_provider.cpp:795-807`) and `MaybeInstallReferenceTier` copies `src->fn` verbatim (`:204-225`), which covers the `vt::` ops the staging and the forward need; `Glue()` `VT_CHECK`-refuses BY NAME and never returns nullptr (`src/vllm/model_executor/models/ltx2_device.cpp:81-86`); and the closed 7-value `DeviceType` enum (`include/vt/device.h:16-28`) is handled the way `tests/vllm/multimodal/test_diffusion_device_seam.cpp` ALREADY handles it FOR THIS FAMILY — a SEPARATE EXECUTABLE (`:19-23`, `tests/CMakeLists.txt:317`) that registers a unified-memory `FakeXpuBackend` (`:60-73`), a platform in the XPU and CUDA slots (`:116-121`) and a `device = 1` `kLtx2VideoFamily` load (`:127-133`) — which leaves `test_ltx2_video`'s 88-case baseline byte-for-byte untouched. One design fact goes with that: `Ltx2DeviceKernelsAvailable` reads `vt::OpRegistered`, which EXCLUDES the reference tier deliberately (`op_provider.cpp:677-701`, "a FALLBACK, not a native kernel"), so the glue table needs the direct `RegisterOp` and the tier serves the rest. A fake also DOES prove link B as this row defines it — the x0 model reaching `Ltx2DitForwardDevice(..., p)`, which would turn D10 RED; what it cannot prove is that a GPU runs it, which is the hardware half the leased run below closes. WHAT IT COSTS is that new executable plus a fixture DiT staged through the fake backend (`tests/vllm/multimodal/ltx2_video_fixture.h` already writes a complete reduced model). TWO gates on the route were checked and pass by construction: `vt::RegisterBackend(kXPU, ...)` writes slot 0 (`src/vt/backend.cpp:81-84`) so `:800`'s `TryGetBackend(Device{kXPU, 0})` resolves for `params.device = 1`, and `vt::CreateQueue(Device)` takes its `entry.backend->CreateQueue()` arm (`backend.cpp:146-153`) whose `q.device == device` assertion the fake satisfies. TWO are NOT verified and NOBODY HAS BUILT IT: whether `Ltx2StreamDitToDevice` (`:847`) stages the checkpoint onto that queue, and whether the bf16 render that follows (`:812`) completes through the reference tier. PLAUSIBLE, NOT PROVEN — recorded in those terms because the first draft of this row asserted the opposite three facts as measured. What IS gated: `Ltx2DitForwardDevice` honours all four perturbation fields on the CPU backend, nine mutations RED (`tests/vllm/models/test_ltx2_device.cpp`). Closes on one leased `one_stage --device cuda` run at the model's own guider defaults recording `dit_forwards == 4 * dit_evaluations`. Same shape as [#1131](https://github.com/mudler/vllm.cpp/issues/1131). Listed under `## Owed` in [`ltx25-guided-video.md`](specs/ltx25-guided-video.md) §12.8 link B | bug | | [#1396](https://github.com/mudler/vllm.cpp/issues/1396) | `MODEL-FP8-BLOCK-WEIGHT` | Eight comments and one spec `## Owed` asserted that the block-wise FP8 forward wiring was still owed, after it landed. All were last written by M3 (`09597106e`, MODEL-FP8-BLOCK-WEIGHT) and none was revisited when M4 (`281b4bc76`, the linear method and the dense forward that reads the weight), M5 (`489a9a4c0`, the mainloop-scaled CUTLASS kernel) and M6 (`836c13c35`, the merged `gate_up` and QKV) landed. The tree disagreed with them in two directions: `qwen3_5.cpp` calls the block-scaled GEMMs at TEN sites -- the attention `o_proj`; q/k/v once on the split path, where one `project` lambda serves q, k and v alike, and once more on the merged one; the GDN `in_proj`'s `qkv` and `z` halves; the GDN `out_proj` in each of its three block arms (`GdnBlock`, `GdnBlockPagedMixedSpec`, `GdnBlockPaged`); and the dense MLP's merged `gate_up` and its `down_proj` -- which is eight `MatmulFp8BlockScaledD`, one `MatmulFp8BlockMergedD` and one `Fp8BlockGateUpSwiGLUD`, so `NOTHING CONSUMES THIS YET` was false; and `RefuseUnrunnableQwen3_5DenseFp8Block` had already been narrowed by M4 to refuse a DEVICE with no block-scaled GEMM rather than the weight, so `Deleted by M5` and `Milestone M5 removes this` were false in the other direction -- M5 narrowed the refusal to a CUDA arch outside `VT_CUTLASS_FP8_ARCHS` (12.0a, 12.1a) rather than deleting it. Both available readings of the stale text are costly: re-implement a delivered milestone, or refuse to use a working arm. FIXED IN FLOW, comment and spec text only, no behaviour change. The change deliberately does NOT narrow the real debt, which is unchanged and recorded in [`vt-matmul-fp8-block-cuda.md`](specs/vt-matmul-fp8-block-cuda.md) `## Owed`: the CUDA kernel has never executed on hardware and there is no token gate against `Qwen/Qwen3.8-27B-FP8`. No gate can hold this class -- no checker here compares a comment against the code it annotates -- so the reviewer's check is those ten call sites and the body of `ModelRegistry::Prepare` | bug | | [#1411](https://github.com/mudler/vllm.cpp/issues/1411) | `FIX-FP8-BLOCKWISE-REFUSAL` | Eight more places say the block-wise FP8 CUDA kernel is owed, three of them LIVE refusal messages a user reads. Found by the fresh review of [#1399](https://github.com/mudler/vllm.cpp/pull/1399), the pull request for [#1396](https://github.com/mudler/vllm.cpp/issues/1396), and outside the eight comment anchors that change corrected. The three message strings tell a user on an unsupported CUDA arch to wait for milestone M5, which LANDED at `489a9a4c0`: `layers/quantization/fp8_block_quant.cpp:187-189`, and `models/dense_fp8_block_gemm.h:200-202` in the `MatmulFp8BlockScaledD` guard and `:428-430` in the shared `CheckFp8BlockMergedActivation` helper that BOTH merged entry points call, so that second message also fires on the merged `gate_up` path and not only on QKV. The honest reason is that the arch is outside the `VT_CUTLASS_FP8_ARCHS` cell (12.0a, 12.1a) M5 registered the kernel for, not that no kernel exists; the same build runs the checkpoint on `sm_120a`, on `sm_121a` and on CPU. The five comments are `include/vt/ops.h:1637,1658`, `src/vt/cpu/cpu_ops.cpp:668`, `include/vt/merged_gemm.h:92`, `src/vllm/model_executor/models/qwen3_5_dense_weights.cpp:604` and `tests/vllm/model_executor/models/test_fp8_block_linear.cpp:267`. ONE of those needs care rather than a rewrite: `include/vt/ops.h:1637` names a measurement that is still GENUINELY OWED, so its defect is tense alone. A NINTH place, the `RefuseUnrunnableQwen3_5DenseFp8Block` comment block in `qwen3_5_dense_weights.cpp`, WAS fixed in flow by #1396 and is no longer owed -- no line anchor, because #1396 edits that block itself: it was an entry-point count, saying `MatmulFp8BlockScaledD` reads the weights at each of the ten projections when it reads EIGHT, because `qwen3_5.cpp` reaches those ten through THREE entry points -- `Fp8BlockGateUpSwiGLUD` is the only reader of `gate_proj_fp8_block` and `up_proj_fp8_block`, and `MatmulFp8BlockMergedD` reads q/k/v as one operand. NOT FIXED IN FLOW for the remaining eight, deliberately: #1396 is a comment-and-spec-text change and editing eight more places across `vt`, the quantization layer and a test would widen it past what its fresh review read. The debt itself is NOT narrowed by this issue -- the CUDA kernel has never executed on hardware and there is no token gate against `Qwen/Qwen3.8-27B-FP8`, recorded in [`vt-matmul-fp8-block-cuda.md`](specs/vt-matmul-fp8-block-cuda.md) `## Owed`. No gate can hold this class, because no checker here compares a comment or a message string against the code it annotates. `docs/FEATURES.md` carries the same staleness and is tracked separately by [#1275](https://github.com/mudler/vllm.cpp/issues/1275). Owed under `## Owed` in [`fp8-blockwise-refusal.md`](specs/fp8-blockwise-refusal.md) | bug | | [#1299](https://github.com/mudler/vllm.cpp/issues/1299) | `ENG-EXPERT-STREAM-DEVICE` | `Qwen3.8-2.4T-A95B UD-Q1_0` (369.97 GiB) now LOADS on `--device cuda` on a 119.631 GiB GB10 — `ENG-EXPERT-STREAM-DEVICE` W0 works, the slot store builds and the #1123 refusal correctly does not fire — and then exhausts the machine inside the FIRST forward, producing zero decode steps. Measured on `dgx:gpu0` inside one `rc hold` at source `95883dcae`, production stack (CUTLASS 4.5.0 found, `cutlass-fp8`/`cutlass-nvfp4`/`fa2` ENABLED for `[121a]`, Triton AOT `sm_121a`). Seven attempts, all identical: load 255-272 s, RSS after load 61.20 GiB, 0 decode steps, peak system `used` 118-120 GiB with 28-31 GiB of swap consumed. The slot arena is NOT the cost, and that is measured rather than argued: a **64-slot 0.15 GiB** arena dies exactly where an 8000-slot 18.55 GiB one does, and a 1-token prompt (protected set 2,790 slices, which fits 3500 slots with no in-place tower fallback at all) behaves exactly like a 5-token one. The growth is ANONYMOUS, not file-backed, so the GPU is not pinning the mapping's pages: `RssAnon` climbs 8.1 -> 61.4 GB through the load while `RssFile` stays at 0.1-0.2 GB, then `VmSwap` climbs 0 -> 31.0 GB inside the forward. Host `RssAnon` + `VmSwap` reaches ~65 GB while system `used` sits at ~119 GB, and the ~42 GiB difference is device memory the process RSS does not account for on this unified part — so the non-expert weights are resident TWICE, once as the host-side `OwnedTensor` and once as the `ResidentWeight` device staging copy. `.agents/specs/expert-streaming.md` measured the host half already: the GDN V-head reorder makes `attn_qkv` and `ssm_out` `kTransformedWeight`, which expands them from ~5.5 bits to bf16, about 50 GiB of the 61.20. The CPU arm pays it once and serves (32 tokens, steady 11.05 s/token at 4000 slots, decode-phase `exhausted` delta 0); the CUDA arm pays it twice and cannot. NOT #1123, whose refusal fired at load and no longer applies, and NOT a defect in W0b/W0c/W0d, which do what their spec says. This is the device-side half of the sentence `expert-streaming.md` already carries: "Whoever takes this needs BOTH: the streaming lane for the ~330 GiB of experts, and a transformed-weight path that does not expand." Owed under `## Owed` in [`expert-stream-device-slots.md`](specs/expert-stream-device-slots.md) | bug | | [#1433](https://github.com/mudler/vllm.cpp/issues/1433) | `MODEL-DIFFUSION-LTX25` | `Lightricks/LTX-2` is the repository the WHOLE LTX-2.5 lane mirrors — ten `.agents/specs/ltx25-*.md` files and `.agents/porting-inventory.md` carry the revision string `fd4ded7f`, and every `file:line` upstream anchor in that lane resolves there — and it has NO registry row in `AGENTS.md`, NO `.agents/oracles/.md` file, and NO recorded pin. Measured at `2da236832`: `scripts/check-oracle-pins.py` reports `oracle-pins ok (9 oracles pinned)` — `diffusers`, `llama-cpp`, `llama-cpp-unsloth`, `sglang`, `sglang-omni`, `transformers`, `tt-forge`, `vllm`, `vllm-omni` — and it reads `.agents/oracles/*.md` with a GLOB, so an oracle with no file is INVISIBLE to it. The green line is what an unpinned upstream looks like from inside the gate, which is the failure `AGENTS.md` "Pin every oracle" names: "An unpinned upstream is a moving target, not an oracle. Its measurements are not reproducible." `vllm-omni` does NOT already cover it: `.agents/oracles/vllm-omni.md:5` names LTX-2.5 in scope and is the right home for the MIRRORING relationship (`vllm-project/vllm-omni` is the structure this project mirrors), but it is not the repository the specs READ — that is a THIRD repository — and `vllm-omni` is itself `pin = UNPINNED` under [#633](https://github.com/mudler/vllm.cpp/issues/633), so the lane's actual reference source is unpinned twice over, once knowingly and once with no record at all. PRE-EXISTING and NOT caused by [#1428](https://github.com/mudler/vllm.cpp/pull/1428): the `fd4ded7f` anchoring dates to the original port `cefacd2d0` (2026-08-13, #435 / #641), first carried by `f193eaf75`, `742e38acf` and `0541cbeaa`. NOT FIXED IN FLOW because adding a row to the `AGENTS.md` oracle table is a POLICY edit, which `AGENTS.md` "Changing the rules or a checker" routes to its own row, spec and fresh review. Found while repairing the fresh review of #1428. Owned by row `MODEL-DIFFUSION-LTX25`; spec [`ltx-2-5.md`](specs/ltx-2-5.md) | gap | +| [#1439](https://github.com/mudler/vllm.cpp/issues/1439) | `LTX25-DEVICE-RESIDENCY` | `ltx2 video: a render through the ABI emits a phase table that SUMS to wall` asserts `CHECK(leaves >= 0.95 * wall)` (`tests/vllm/multimodal/test_ltx2_video.cpp:2854`) and is **RED on `origin/main`**, not on the branch that found it. MEASURED on one x86 box, one build directory, `CMAKE_BUILD_TYPE` empty as CI has it, with this lane's four files reverted so the binary IS main at `89261c955`: six in-suite runs read 94.32%, 95.20%, 93.74%, 94.20%, 94.69% and one `-tc` run 94.19% - **five of six red**, 93 cases / 3321 assertions / 1 failed, exit 1. The W0-live merge reads 93.82%, 93.68%, 94.34%, 94.62%, 94.39% in-suite (96 cases / 3555 assertions / 1 failed) and 94.12% with `VLLM_RENDER_PROGRESS=0`, so neither the new emitter nor its call site is the term; one `-tc` run passed at 95.40%. It is NOT box contention, and the run that disproves that is main's single green: it had `wall=0.579684s`, more than double every other run, because the box was LOADED - a slower render passes, since the un-named residue grows more slowly than the wall it is divided by. The residue is 4.80% to 6.32% of `wall` across all twelve runs (0.0128 s to 0.0278 s against a `wall` of 0.220 s to 0.580 s), so a 95% floor sits INSIDE the measurement's own range at the 64x64 / 9-frame FIXTURE scale and the case decides by coin flip, mostly red. The tolerance was argued for the 21.004 B render, where the same residue would be a far smaller fraction. NOT FIXED IN FLOW, deliberately: naming the un-named time, or bounding `unaccounted_seconds` beside the ratio so the assertion says the same thing at both scales, is a change to a gate's semantics and needs its own row, spec and red-first evidence per `AGENTS.md` "Changing the rules or a checker". Found while merging `origin/main` into `row/LTX25-RESIDENCY-W0-LIVE` after [#1419](https://github.com/mudler/vllm.cpp/pull/1419) was auto-closed by its base branch being deleted. Listed under `## Owed` in [`ltx25-device-residency.md`](specs/ltx25-device-residency.md) | bug | | [#1435](https://github.com/mudler/vllm.cpp/issues/1435) | `VT-MATMUL-FP8-BLOCK-CUDA` | **A CUDA build without CUTLASS headers segfaults on the block-wise FP8 path instead of refusing by name, and configure reports the feature ENABLED anyway.** Measured 2026-08-20 on `dgx:gpu0` (GB10, cc 12.1) in an `rc` lease at `63d87805c`. `src/vt/cuda/cuda_matmul_fp8_block_cutlass.cu` is the only TU that registers `kMatmulFp8BlockScaled` for `kCUDA` and it reaches `target_sources(vllm PRIVATE ... ${_FP8_CUTLASS_SOURCES})` only through TWO nested conditions in `CMakeLists.txt` -- the outer `if(VLLM_CPP_CUTLASS)` (one occurrence in the file) and, inside it, the `if(VT_CUTLASS_FP8_ARCHS)` that SETS `_FP8_CUTLASS_SOURCES` -- so with no CUTLASS headers the op is unregistered, a device tensor reaches the portable HOST kernel, and the process SIGSEGVs while the reference tier prints `correct but slow`. Anchored by SYMBOL rather than by line on purpose, and the reason is measured on this very row: the guard sat at `CMakeLists.txt:1695@63d87805c` -- the only line number in this row, sha-qualified so it stays resolvable -- and by the time this row was written that number was already stale, then rotted AGAIN by four lines when `origin/main` was merged into the row's own branch mid-review. Two rots inside one pull request. A bare head-relative number here would be permanent, because this index is append-only and no checker scans it, and it would resolve to plausible unrelated code rather than to nothing: at `63d87805c` that line was the guard, and two trees later it was an NCCL include directory. Resolve the anchors above by grepping the symbols; do not trust any number quoted for them. Reachable on a default build: `VLLM_CPP_CUTLASS_FETCH` defaults OFF (the single `option(VLLM_CPP_CUTLASS_FETCH ...)` line, `OFF` at its default argument) and CUTLASS is not a submodule. This contradicts the design note in `cuda_matmul_fp8_block_cutlass.cu`, which states an unsupported build `keeps refusing by name -- which is the honest answer and not the #960/#844 fall-through`: the refusal IS real on the model path (`RefuseUnrunnableQwen3_5DenseFp8Block`, plus the two `VT_CHECK`s) but a caller entering through the op registry, which is what the ported upstream test does, bypasses all three. Second, smaller defect in the same run: `vt_cuda_report_feature` printed `CUDA feature cutlass-fp8: ENABLED for [121a]` for a build whose `build.ninja` contains ZERO references to either FP8 CUTLASS TU, because the report runs on the arch intersection alone, before CUTLASS-header detection. `cmake/CudaArchFeatures.cmake` opens by naming this exact class as what the feature table exists to prevent. NOT fixed in flow: both are code changes on a CUDA path needing their own row, spec and hardware re-gate. Owned by row `VT-MATMUL-FP8-BLOCK-CUDA`, under `## Owed` in [`vt-matmul-fp8-block-cuda.md`](specs/vt-matmul-fp8-block-cuda.md) | bug | | [#1437](https://github.com/mudler/vllm.cpp/issues/1437) | `VT-MATMUL-FP8-BLOCK-CUDA` | **The mainloop-scaled CUTLASS block-wise FP8 GEMM throws `cutlass Invalid status` on upstream's own ported case, on the arch it targets.** FIRST on-hardware execution of #1189 M5 (`489a9a4c0`), measured 2026-08-20 on `dgx:gpu0` (GB10, driver 580.173.02, compute capability 12.1) in an `rc` lease at `63d87805c`, CUDA 13.0 Release, `-DVLLM_CPP_CUDA_ARCHITECTURES=121a -DVLLM_CPP_CUTLASS_FETCH=ON`. G2 (upstream's `test_w8a8_block_fp8_cutlass_matmul` ported whole: M=32, N=576, K=7168, block [128,128], bf16 out) and G7 both THROW from `gemm_op.can_implement(args)`, so CUTLASS rejects the configuration before any launch -- not a numerical disagreement and not a launch failure. G6, G8 and G9 PASS. That this was an EXECUTION and not a skip rests on the throw TEXT, not on a count: `vt cuda: matmul_fp8_block_scaled: cutlass Invalid status` is assembled by the `VT_CUTLASS_CHECK` macro in `src/vt/cuda/cuda_matmul_fp8_block_cutlass.cu`, and the message prefix `matmul_fp8_block_scaled: cutlass ` occurs in NO other translation unit (the per-tensor sibling `cuda_matmul_fp8_cutlass.cu` defines a same-named macro but writes a different message), in a TU compiled only when CUTLASS is found, so no host fallback can produce that string; the run also logged ZERO `[vt reference-tier]` lines, and artifact provenance was confirmed by `cuobjdump --list-elf` reporting `cuda_matmul_fp8_block_cutlass.cu.1.sm_121a.cubin`. Suite: 5 cases, 3 passed, 2 failed, **34 assertions, 0 failed** -- recorded, but attributed rather than leaned on, because **27** of the 34 are G6, which has no `HasCuda()` guard and prints identically on a GPU-less box (8 grid entries x 3 `CHECK` + 3 tile-config `CHECK`s); the device-only remainder is G8's 2 and G9's 5, and a pure skip of this file prints 27. NO shape has had its output compared with the CPU reference: G2 and G7 are the only two cases that make that comparison and BOTH threw before their first assertion -- G7 aborted at `Grid()[0]`, the same M=32 N=576 K=7168 case, so its other seven shapes, including the second ragged-N entry M=8 N=576 K=1024, were never attempted -- and G8 compares a device f32 out against a device bf16 out, which is the kernel against ITSELF. Hypothesis recorded in the issue and explicitly NOT isolated: N=576 is 4*128+64, a ragged final scale block, which the test header records as upstream's reason for choosing it; G8 passing makes the failure shape-dependent rather than universal. This moves the row from `unmeasured` to `measured and failing`, a worse position than the spec previously described. NO speed claim: the lease took no clock control and recorded no contention. Owned by row `VT-MATMUL-FP8-BLOCK-CUDA`, under `## Owed` in [`vt-matmul-fp8-block-cuda.md`](specs/vt-matmul-fp8-block-cuda.md) | measurement | diff --git a/.agents/specs/ltx25-device-residency.md b/.agents/specs/ltx25-device-residency.md index 7c9d86b81..01821cf9c 100644 --- a/.agents/specs/ltx25-device-residency.md +++ b/.agents/specs/ltx25-device-residency.md @@ -636,7 +636,8 @@ its phase table lands, and W5 owes one when its wall is accepted. |---|---|---| | [#1264](https://github.com/mudler/vllm.cpp/issues/1264) | this row: the staged campaign spec | closed by this row landing | | [#1010](https://github.com/mudler/vllm.cpp/issues/1010) | W0 | **closed, for a run that FINISHES.** The render writes a phase table on the shipped default and the ABI names it through `vllm_video_last_phase_log` (v23). Read the row below it before quoting that as "the render is instrumented" | -| **a table on a run that does NOT finish** | [#1413](https://github.com/mudler/vllm.cpp/issues/1413), stage W0-live | **owed, and W0 does not narrow it.** `WritePhaseLog` has exactly two call sites (`ltx2_video.cpp:2259` audio-only, `:4677` video) and both sit immediately before a successful `return`, three lines after `im.trace.completed = true`. Nineteen `VT_CHECK` sites throw out of `Ltx2VideoEngine::Generate` above them and that body contains no `try` and no `catch`; `vllm_video_generate`'s own two catches set an error and return, and `engine->last_phase_log` is assigned on the success path only. **So a render that is killed, aborted by a lease governor, refused by a guard, or still running leaves no `phase-log.json` at all** — not a truncated one, not an empty one, nothing. The mutation is the demonstration: deleting the video call site removes the file entirely and the W0 gate goes red on `REQUIRE(probe.good())`. That matters here more than anywhere, because the runs this campaign has are the ones that died: [#1375](https://github.com/mudler/vllm.cpp/issues/1375) is `child exit=-15` at 0 frames, and [`ltx25-decode-speed.md`](ltx25-decode-speed.md)'s two rungs are `EXIT=137` and `EXIT=1` at 0 frames. A reader who takes "the render writes a phase table" at face value will expect a 2.5 h render that is killed at 2.4 h to leave a table naming where it was. It leaves none. #1413 closes the LIVE half — a line per phase boundary and per DiT forward, so a killed run is legible from its stderr; a signal handler that flushed a PARTIAL table on abort is a separate change with its own re-entrancy argument and is not owed by either | +| [#1413](https://github.com/mudler/vllm.cpp/issues/1413) | W0-live | **closed by `## W0-live` below.** W0's table is written by the success path only, and nothing at all is emitted while a render runs, so an aborted render and a working one both report nothing and the ~162 s DiT forward of [#1375](https://github.com/mudler/vllm.cpp/issues/1375) has no in-process counter | +| **a table on a run that does NOT finish** | [#1413](https://github.com/mudler/vllm.cpp/issues/1413), stage W0-live | **the LIVE half is closed by this change; a PARTIAL TABLE on abort is still owed and has no issue.** `WritePhaseLog` has exactly two call sites (`ltx2_video.cpp:2259` audio-only, `:4677` video) and both sit immediately before a successful `return`, three lines after `im.trace.completed = true`. Nineteen `VT_CHECK` sites throw out of `Ltx2VideoEngine::Generate` above them and that body contains no `try` and no `catch`; `vllm_video_generate`'s own two catches set an error and return, and `engine->last_phase_log` is assigned on the success path only. **So a render that is killed, aborted by a lease governor, refused by a guard, or still running leaves no `phase-log.json` at all** — not a truncated one, not an empty one, nothing. The mutation is the demonstration: deleting the video call site removes the file entirely and the W0 gate goes red on `REQUIRE(probe.good())`. That matters here more than anywhere, because the runs this campaign has are the ones that died: [#1375](https://github.com/mudler/vllm.cpp/issues/1375) is `child exit=-15` at 0 frames, and [`ltx25-decode-speed.md`](ltx25-decode-speed.md)'s two rungs are `EXIT=137` and `EXIT=1` at 0 frames. A reader who takes "the render writes a phase table" at face value will expect a 2.5 h render that is killed at 2.4 h to leave a table naming where it was. It leaves none. #1413 CLOSED the live half, in `## W0-live` below — a line per phase boundary and per DiT forward, so a killed run is legible from its stderr; a signal handler that flushed a PARTIAL table on abort is a separate change with its own re-entrancy argument and is not owed by either | | the phase table's DEVICE column | W1, and it needs [#1126](https://github.com/mudler/vllm.cpp/issues/1126) first | **owed, and a LEASE WILL NOT CLOSE IT.** The column is defined as the driver's live in-use bytes, read per phase through `vt::Backend::DeviceMemoryInfo`. It reports the `-1` no-probe sentinel in W0's artifact, and there are TWO reasons stacked, only one of which is a scheduling problem. **(1)** The render W0 could take was the CPU arm, where the sentinel is correct — `dgx:gpu0` was busy with two queued jobs and `orin:gpu0`, the one free device, holds no LTX-2.5 checkpoints. **(2)** The one that matters: **`CudaBackend` does not override `DeviceMemoryInfo` at all**, which is [#1126](https://github.com/mudler/vllm.cpp/issues/1126), and `grep -rn 'DeviceMemoryInfo' src/vt include/vt` returns exactly the base declaration at `include/vt/backend.h:94` and one override, `src/vt/rocm/rocm_backend.hip:358`. So a CUDA render on `dgx:gpu0` would print `-1` in every row of this column too, and it would print it for a reason no lease can fix. **What the column cannot report today, stated as three things:** how many device bytes the DiT staging leaves resident; whether the denoise grows device residency across steps; and whether the ~59 GiB #1014 asks about is device-class at all. **Why W0 did not just wire it:** `include/vllm/platforms/interface.h:68-72` records that CUDA's absence from that seam is load-bearing — `Gemma4MoE`'s device-expert LRU is the seam's only consumer and is DEAD on CUDA. Narrowed, because the broad form of this sentence is wrong: the bf16 arm `EnsureGemma4Fp8ExpertOnDevice` (`gemma4_moe.cpp:548`) is dead for a SECOND, independent reason — it refuses at `:571` on `vt::HasMatmulBTAlphaBeta`, implemented only by ROCm ([#1205](https://github.com/mudler/vllm.cpp/issues/1205)) — so the override alone would not wake it. The arm the override WOULD wake is the FP8-native one, `EnsureGemma4Fp8NativeOnDevice` (`:611-628`), which reaches `MakeRoom` behind no device gate but the probe, with a 2048 MiB fill-only budget by default (`:416-432`). One named arm, not every CUDA model — and still a behaviour change with its own measurement. That is #1126's change to make, not an instrument's. **What W1 does instead, until #1126 lands:** sample `nvidia-smi --query-compute-apps=used_memory` per phase beside the table — the fallback this spec's W6 row already names, and the one instrument GB10 answers, since `--query-gpu=memory.used` returns `[N/A]` there. On GB10 the peak HOST column is not a poor substitute either: the pool is unified, so host resident bytes and device bytes are the same 119 GiB arena, and that column does report | | [#1040](https://github.com/mudler/vllm.cpp/issues/1040) | W0 (contract) + W1 (closes) | contract half **met** — the table is a file beside the frames rather than a console line, and it is retrievable from this repo at `benchmarks/demo/`. The closing half is W1's | | [#1024](https://github.com/mudler/vllm.cpp/issues/1024) | W1 | owed; its `utilization.gpu` positive control is still unrecorded in this tree | @@ -650,6 +651,7 @@ its phase table lands, and W5 owes one when its wall is accepted. | [#1014](https://github.com/mudler/vllm.cpp/issues/1014) | W6 | owed, conditional | | [#1012](https://github.com/mudler/vllm.cpp/issues/1012) | O1 | owed | | [#1202](https://github.com/mudler/vllm.cpp/issues/1202) | deferred behind W1 | owed, with a number: 2.3% of one pass | +| [#1439](https://github.com/mudler/vllm.cpp/issues/1439) | W0 (its own gate) | **owed, and RED on `main` rather than on any branch.** `CHECK(leaves >= 0.95 * wall)` in `ltx2 video: a render through the ABI emits a phase table that SUMS to wall` is a RATIO, and the un-named residue is 4.80% to 6.32% of `wall` across twelve runs on one x86 box - so the 95% floor sits INSIDE the measurement's own range at the 64x64 / 9-frame fixture scale, and the case decides by coin flip, mostly red. With this lane's four files reverted so the binary is main at `89261c955`, six runs read 94.32%, 95.20%, 93.74%, 94.20%, 94.69%, 94.19%; the W0-live merge reads 93.82%, 93.68%, 94.34%, 94.62%, 94.39%, and 94.12% with `VLLM_RENDER_PROGRESS=0`, which exonerates the live emitter. Box contention is NOT the cause and main's one green disproves it: that run had `wall=0.579684s`, more than double the others, because the box was loaded - a SLOWER render passes. The tolerance was argued for the 21.004 B render, where the residue is a far smaller fraction of the wall. Naming the un-named time, or bounding `unaccounted_seconds` beside the ratio so the assertion says the same thing at both scales, is gate semantics and owes its own row | | [#1164](https://github.com/mudler/vllm.cpp/issues/1164) | W7 decision point | not owed here — owned by `ENG-CUDAGRAPH-DIFFUSION`; this row owns its unblock order | **[#1009](https://github.com/mudler/vllm.cpp/issues/1009) is not owed. It @@ -1113,3 +1115,156 @@ which is where this spec's `### Decisions taken here` already said they would be is the only leaf whose sole reader is the DFR case, because every other render in `test_ltx2_video` pins `max_phase = 0`, where the input transform is never the spatial upsample. + +## W0-live — the lane that runs while the render is alive (#1413) + +W0 above landed the table. This section is the half of #1010 that table does not +reach, filed separately as +[#1413](https://github.com/mudler/vllm.cpp/issues/1413) so the two are +attributable to the two changes that made them. + +### The gap, in one sentence each + +**The table is written by the success path only.** `WritePhaseLog` is reached +after `im.trace.completed = true`, so a render that is killed, aborted by a lease +governor, or still running writes nothing. That is not a corner: #1375 is +`ABORT[92] PROJECTED OVERRUN`, `child exit=-15`, **0 frames**; the spike's rung 1 +is `EXIT=137`, 0 frames; rung 2 is `EXIT=1`, 0 frames. The instrument reports on +the runs that finish, and the runs the campaign has are the ones that do not. + +**Nothing at all is emitted while the render runs.** `PhaseLog::Open` and +`PhaseLog::Close` record and print nothing, and `VLLM_RENDER_PHASE_LOG_STDERR` +fires inside `WriteJson`, i.e. on the success path again. Between +`ltx2-gen: family=...` and `wrote N frames` a 2.5-hour render is silent, so +**working and hung are byte-identical from outside**, and hours of GPU lease have +been spent telling them apart. + +**The unit that costs the wall has no counter.** `denoise` is one leaf. #1375 +measures **~162 s per DiT forward** at 21.004 B with **60 forwards structural** +(30 steps x 2 CFG legs — `cfg_scale != 1.0` forces the unconditional branch at +`ltx2_pipeline.cpp:521-523`). ~2.7 h inside one leaf that reports one number, at +the end, if the run survives to write it. + +### Why an external sampler is not the fallback + +It was tried and it does not work. #1375 records `phase=OTHER` throughout, +because **`eu-stack` unwinds zero frames inside the `rc` worker container**; +`dit_runs=0` is that blind counter and is not evidence of absence. The 162 s is a +wall-clock interval between GPU busy/idle edges, not a profile, and #1375's own +"What is NOT established" names an in-process phase marker as the way to +attribute it. This lane is that marker. + +### The shape, and why it is this shape + +Two emitters, both on stderr, both on the shipped default. + +1. **A boundary line on open and on close.** `+name` when a phase opens, + `-name` when it closes with its duration and its peak host bytes. The open + line is the load-bearing one: it means **the last line printed names the phase + that is currently running**, which is the whole difference between a hang and + work. A close-only emitter would have printed nothing for the 3002 s + conditioning stretch, because that stretch never closed. + +2. **A tick per DiT forward**, carrying the recipe phase, the sampler step + `k/N`, the cumulative forward index, elapsed, and `last=` — the seconds since + the previous tick of the same unit. That `last=` is the per-forward cost + #1375 could only obtain as an interval between GPU edges, and it is now a + number the process itself reports, per forward, on every run including the + ones that die. + + **The tick fires BEFORE the forward, not after.** After is the obvious + placement and it is wrong here: the line a reader most needs is the one naming + the forward that is in flight when the run stops. The cost of that choice is + stated rather than hidden — the last forward of a completed render has no + `last=` line of its own, and its cost is inside the `-denoise` boundary line. + +**Cadence.** 60 tick lines and ~50 boundary lines over 2.7 h. Not chatty enough +to drown a log; not quiet enough that a 162 s forward reads as a hang. That 60 +is #1375's config and it moved while this lane was in review: +[#1092](https://github.com/mudler/vllm.cpp/issues/1092) gave +`Ltx2DitForwardDevice` its `perturbations` argument, so the device-resident arm +runs up to four forwards per step rather than two and the same geometry emits +up to 120 ticks. Neither number is printed and neither had to be re-derived: +the forward counter carries no denominator by the paragraph below, and the step +fraction reads this recipe phase's own `sigmas`. + +**No denominator on the forward counter, deliberately.** 60 = 30 x 2 is true of +the config #1375 measured and it is not structural in this code: the sampler +decides how many denoiser calls happen and `Ltx2GuidedDenoise` decides how many +forwards each call is (one to four — cond, uncond, ptb, mod). The **step** +counter carries the honest fraction `k/N`, because `sigmas.size() - 1` is exact +and in scope. Printing `forward 24/60` would be an instrument guessing, and this +row exists because guessing is what the campaign has been doing. + +### Not behind a flag, and the reason is measured + +`VT_H3_PROGRESS` is the existing shape for this in the tree +(`minimax_h3.cpp:776-793`): per-step forward seconds, on stderr, for the +MiniMax-H3 denoise loop. It is **opt-in**, and that is exactly why no LTX-2.5 run +has one — the runs whose profile is needed are the long ones, on a leased box, by +somebody who did not know they would need the number until afterwards. The +failure this closes happened on default settings. + +`VLLM_RENDER_PROGRESS=0` silences it, in the same measurement-lane shape +`VLLM_RENDER_PHASE_SAMPLER` and `VLLM_LTX2_POOL_DRAIN` already take here: it +exists so an A/B over what the emitter itself costs runs on ONE binary. It is +never a configuration and nothing in the tree sets it. + +### Cost + +One `std::fprintf` to stderr per phase boundary and per DiT forward, flushed, +under the process-wide phase mutex the 100 ms sampler also takes — so a tick is a +held global lock plus a flushed write rather than a bare `fprintf`, which at ~110 +lines per render is a footnote and is written down rather than left in a profile. +On the 21.004 B geometry that is ~110 writes against 2.7 h of wall. There is **no +per-token and no per-tile emission**: the VAE decode's tile loop and the frame +writer's inner loop are untouched, and the decode's per-chunk boundary lines are +bounded by the chunk count, which is bounded by the frame count. + +**`VLLM_RENDER_PROGRESS=0` costs one `getenv` per process, and that took a second +edit to become true.** `ProgressEnabled()` caches the read and `Tick` returns on +its first line, but the `detail` argument is built by the CALLER and was built +unconditionally: a `std::string` from a literal, three `std::to_string`s and four +concatenations, per DiT forward. Against a 162 s forward the magnitude is +nothing; the sentence was still false as written, and a cost claim that is false +in the small is the shape that gets quoted in the large. The call site now asks +`phase::ProgressEnabled()` before it formats anything, which is why that function +is declared in the header instead of living in an anonymous namespace. + +### Gate + +`ltx2 video: a render through the ABI PRINTS its progress while it runs`, in +`tests/vllm/multimodal/test_ltx2_video.cpp`. It captures **real stderr** with +`dup`/`dup2` across `vllm_video_engine_load` and `vllm_video_generate` — not a +test-only sink — so what it asserts is exactly what a user sees on default +settings, and there is no seam that could be armed in the test and absent in +production. It asserts: + +* the boundary lines for `load.dit`, `denoise`, `decode.video` and + `artifacts.frames` appear, each with a matching `+` and `-`; +* `+denoise` precedes every `dit forward` tick and `-denoise` follows every one + of them, which is what says the ticks are inside the phase they claim; +* at least two ticks, with **strictly increasing** forward indices — the step + count moves; +* every tick from the second onward carries `last=`; +* `t=` is non-decreasing over the whole capture. + +The strictly-increasing assertion is the non-vacuous half. An emitter that +printed a constant `forward 1` would satisfy "the marker appears" and would +report nothing, which is the failure mode the spike's sampler already had. + +### Owed out of W0-live + +* **A capture from a real 21.004 B render.** Every number in this section about + what the lane prints at that scale is derived from #1375's measured 162 s, not + observed. W1's lease closes it, and the format is fixed here so that run does + not have to negotiate one. +* **The last forward of a completed render has no `last=` line**, by the + before-the-forward placement argued above. Its cost is inside `-denoise` and a + reader who needs it per-forward has n-1 samples, not n. +* **`GenerateAudioOnly` emits boundary lines and no ticks**, because the t2a arm + reaches the same `Evaluate`. Unverified: no t2a case captures stderr. +* **Nothing writes a partial table on abort.** This lane makes the *phases* + visible on a killed run; it does not make `phase-log.json` appear for one. A + signal handler that flushed the table is a separate change with its own + re-entrancy argument, and it is not this one. diff --git a/docs/ENVIRONMENT.md b/docs/ENVIRONMENT.md index e048721b4..dcbee45e2 100644 --- a/docs/ENVIRONMENT.md +++ b/docs/ENVIRONMENT.md @@ -252,6 +252,7 @@ Read-only observability; none change output. | `VLLM_LTX2_POOL_DRAIN` | on | `=0` suppresses the LTX-2.5 render's per-phase device scratch-pool drain. The drain is on by default and there is no supported reason to turn it off: a denoise phase leaves the pool holding every activation size class it touched, the next phase (twice the resolution) and the VAE decode allocate different classes, and on an uncapped pool those blocks are headroom the next stage never gets. This exists so the A/B that MEASURES what the drain is worth runs on ONE binary, which is what a same-binary A/B requires. Not a configuration | | `VLLM_RENDER_PHASE_LOG_STDERR` | unset | `=1` also prints the render phase table as a fixed-width block to stderr. The table itself is written to `/phase-log.json` on the shipped default whatever this is set to (issue [#1010](https://github.com/mudler/vllm.cpp/issues/1010)); this only adds a copy somebody watching a terminal can read. **The copy is INDEPENDENT of the file write**: it is emitted whether the file was written or not, because an unwritable `--output-dir` is exactly the run where a console copy is the only evidence left, and a lane gated on the write would be silent in the one case it exists for. Off by default because a render that writes its table beside its frames does not need to shout, and a suite that runs ninety of them would print ninety | | `VLLM_RENDER_PHASE_SAMPLER` | on | `=0` stops the render phase log's 100 ms sampler thread. The phase table is still written and every phase still carries a byte count taken at its own boundaries; what is lost is the INTERIOR peak of a long phase, which is the half a minutes-long denoise needs. A MEASUREMENT LANE in the same shape as `VLLM_LTX2_POOL_DRAIN` above — it exists so the A/B over what the sampler costs runs on one binary — and never a configuration | +| `VLLM_RENDER_PROGRESS` | on | `=0` silences the LTX-2.5 render's live progress lines on stderr — one `[render] + ` when a phase opens, one `[render] - ... dur=` when it closes, and one `[render] dit forward N phase P step k/N t=.. last=..` per DiT forward. ON by default and that is the whole point (issue [#1413](https://github.com/mudler/vllm.cpp/issues/1413)): the phase TABLE is written only by a generation that returns, so a render that is killed or aborted writes nothing, and between the load banner and `wrote N frames` a 2.5-hour render was silent — working and hung were the same observation. The open line means the LAST LINE PRINTED names the phase in flight, and `last=` is the per-forward cost [#1375](https://github.com/mudler/vllm.cpp/issues/1375) could otherwise only get as an interval between GPU busy/idle edges from outside the process. A MEASUREMENT LANE in the same shape as `VLLM_LTX2_POOL_DRAIN` above — it exists so the A/B over what the emitter costs runs on one binary — and never a configuration | | `VT_TTFT_DUMP` | unset | `=1` prints one `TTFTSPLIT rid=... intake=.. queued=.. prefill=.. decode=.. e2e=..` line per finished request to stderr, reconstructing the per-request timing split from the event-populated `req_state` timestamps. The async serving frontend otherwise tracks no per-request stats (passes `iteration_stats=nullptr` and never stamps `EngineCoreOutputs.timestamp`); under this flag both are wired so a serving TTFT attribution can read the queue-vs-execution split against vLLM's own `request_{queue,prefill,decode}_time_seconds`. Generation is byte-identical when unset (the default path is instruction-identical to production); the durable replacement is the async `/metrics` stat logger | | `VT_LOOP_TRACE` | unset | `=1` prints one `LOOPTRACE ...` line per ~1 s window to stderr from the engine busy loop: the full-iteration cadence (`interval`), `process_engine_step` wall (`step`), per-window admits, input-queue residence (`resid` = enqueue-to-drain, the same endpoints `VT_TTFT_DUMP`'s `intake` measures), per-drain admit max and max backlog depth. Diagnoses whether the admission wait is one busy-loop iteration or the input queue is backing up (it attributed the 35B INTAKE deficit to bursty arrival during long prefill steps). Byte-identical when unset: every trace read is guarded, and the enqueue timestamp is stamped only under the flag | | `VT_H3_GAUSSIAN_NOISE` | unset | `minimax-h3-gen` only: `=1` seeds the diffusion initial noise from Box-Muller GAUSSIAN N(0,1) (what a flow-matching model is trained on) instead of the historical uniform[-1,1] draw. A/B knob for the render-coherence investigation; the exact values still do not match torch's RNG (that only selects WHICH sample), but the DISTRIBUTION does | diff --git a/docs/USAGE.md b/docs/USAGE.md index 8160ae769..1c02ad949 100644 --- a/docs/USAGE.md +++ b/docs/USAGE.md @@ -1143,6 +1143,74 @@ The timeline starts at the **engine load**, because on a 22B checkpoint the DiT staging is minutes paid at the front of every render. A process that loads a second engine starts a new timeline, so the table describes the last load. +### While the render runs: the `[render]` lines + +The table above is written by a generation that **returns**. A render that is +killed, aborted by a lease governor, or still going writes none, so LTX-2.5 also +narrates itself on stderr as it goes, on the shipped default and behind no flag: + +```text +[render] + load t=0.000s +[render] + load.dit t=0.001s +[render] - load.dit t=0.002s dur=0.001s host=0.01GiB +... +[render] - load t=0.027s dur=0.027s host=0.02GiB +[render] + generate t=0.027s +... +[render] + denoise t=0.027s +[render] + denoise.step t=0.027s +[render] dit forward 1 phase 0 step 1/8 t=0.027s +[render] - denoise.step t=0.065s dur=0.038s host=0.02GiB +[render] + denoise.step t=0.066s +[render] dit forward 2 phase 0 step 2/8 t=0.066s last=0.038s +[render] - denoise.step t=0.069s dur=0.003s host=0.02GiB +... +[render] - denoise t=0.146s dur=0.118s host=0.02GiB +[render] + decode.video t=0.146s +[render] - decode.video t=0.147s dur=0.001s host=0.02GiB +[render] + artifacts.frames t=0.147s +... +[render] + decode.audio t=0.148s +[render] + decode.audio.mel t=0.148s +[render] - decode.audio.mel t=0.155s dur=0.008s host=0.02GiB +[render] + decode.audio.vocoder t=0.155s +[render] - decode.audio.vocoder t=0.236s dur=0.081s host=0.02GiB +[render] - decode.audio t=0.236s dur=0.089s host=0.02GiB +[render] - generate t=0.237s dur=0.209s host=0.02GiB +``` + +**That is a real capture**, from the CPU gate render at 64x64 over 9 frames — the +seconds and the byte counts are that render's, on a contended box, and nothing +here is a benchmark. It is shown at this scale on purpose. The same lines from a +21.004 B render would carry a `load.dit` of minutes and a `last=` on the order of +[#1375](https://github.com/mudler/vllm.cpp/issues/1375)'s measured 162 s per DiT +forward, and **no such render has been captured yet** — that is W1's lease. A +worked example at that scale would be a projection, and a projection printed in a +public document gets quoted back as a measurement. + +Read it as three things: + +* **The last line names what is running.** A phase prints when it opens, not + only when it finishes, so a run that stops inside a phase still says which one. + Between the banner and `wrote N frames` there was previously nothing at all, + and a working render and a hung one were the same observation. +* **`last=` is the per-forward cost.** Seconds since the previous DiT forward, + measured by the process doing the work rather than inferred from outside it. +* **`step k/N` is exact; the forward counter has no denominator.** The sampler + decides how many denoiser calls a step takes and the guider decides how many + forwards each call is (one to four), so a total would be a guess. Two forwards + per step is what `cfg_scale != 1.0` alone buys; a guider that also runs the + STG and modality legs does four, which is what the device-resident arm does + now that [#1092](https://github.com/mudler/vllm.cpp/issues/1092) gave + `Ltx2DitForwardDevice` its `perturbations` argument. The `k/N` fraction is + unaffected either way: it reads the recipe phase's own `sigmas`. + +`VLLM_RENDER_PROGRESS=0` silences them. It is a measurement lane so an A/B over +what the emitter costs runs on one binary, not a setting to turn off: the cost is +one flushed `fprintf` per phase boundary and per forward — on the order of a +hundred writes against hours of wall — and nothing is emitted per token or per +VAE tile. + Add `--first-frame frame.ppm --image-crf 0` for image-to-video. The PPM is binary P6 at maxval 255 (no PNG/JPEG codec is vendored); `--image-crf 0` is required and is not the default, because omitting it resolves the checkpoint's diff --git a/include/vllm/multimodal/render_phase_log.h b/include/vllm/multimodal/render_phase_log.h index ed429f95f..aa0c553fc 100644 --- a/include/vllm/multimodal/render_phase_log.h +++ b/include/vllm/multimodal/render_phase_log.h @@ -112,6 +112,11 @@ class PhaseLog { // interior peak the boundaries would miss. void Sample(); + // The live lane's counter line. See the free `Tick` at the bottom of this + // header for what it prints and why it is called before the work rather than + // after it. + void Tick(const std::string& unit, int64_t index, const std::string& detail); + std::vector Records() const; int64_t Samples() const; @@ -156,6 +161,87 @@ class Scope { // One sample, from inside a loop. Cheap enough for a per-step call. void SampleNow(); +// ─── THE LIVE LANE (issue #1413) ───────────────────────────────────────────── +// +// The table above is written by the SUCCESS PATH ONLY — `WritePhaseLog` sits +// after `im.trace.completed = true` — so a render that is killed, aborted by a +// lease governor, or still running writes nothing at all. That is not a corner +// case here: #1375 is `ABORT[92] PROJECTED OVERRUN` / `child exit=-15` / 0 +// frames, and `ltx25-decode-speed.md`'s two rungs are `EXIT=137` / 0 frames and +// `EXIT=1` / 0 frames. An instrument that reports on completion reported on none +// of the runs this campaign has. +// +// So these functions emit as the render RUNS, to stderr, on the shipped default. +// `PhaseLog::Open` and `PhaseLog::Close` print a boundary line each, and `Tick` +// prints one line per repeated unit of work inside a phase. +// +// THE OPEN LINE IS THE LOAD-BEARING ONE. It means the LAST LINE PRINTED names +// the phase that is currently running, which is the entire difference between a +// working render and a hung one — two states that were byte-identical from +// outside for 2.5 hours at a time. A close-only emitter would still have printed +// nothing for the 3002 s conditioning stretch, because that stretch never +// closed. +// +// NOT BEHIND A FLAG. `VT_H3_PROGRESS` is the existing shape for this in the tree +// (`minimax_h3.cpp:776-793`) and it is opt-in, which is exactly why no LTX-2.5 +// run has one: the runs whose profile is needed are the long ones, on a leased +// box, by somebody who did not know they would need the number until afterwards. +// `VLLM_RENDER_PROGRESS=0` silences it, in the measurement-lane shape +// `VLLM_RENDER_PHASE_SAMPLER` and `VLLM_LTX2_POOL_DRAIN` already take here — it +// exists so an A/B over what the emitter itself costs runs on ONE binary, and +// nothing in this tree sets it. + +// Whether the live lane is on for this process. Read once, from +// `VLLM_RENDER_PROGRESS`, and cached. +// +// PUBLIC BECAUSE A CALLER HAS TO BUILD `detail` BEFORE IT CAN PASS IT. `Tick` +// returns immediately when the lane is off, but the argument is already built by +// then — a `std::string` and three `std::to_string`s per DiT forward at the +// LTX-2.5 call site. That is negligible against a 162 s forward and it is not +// nothing, so the claim "`VLLM_RENDER_PROGRESS=0` costs one `getenv` per +// process" is only true if the call site skips the formatting too. This is how +// it does that. +bool ProgressEnabled(); + +// One progress line for the `index`-th occurrence of a repeating unit of work. +// The emitter appends the elapsed clock and `last=`, the seconds since the +// previous tick of the SAME unit, which is the per-forward cost #1375 could +// only obtain as a wall-clock interval between GPU busy/idle edges. `detail` is +// free text printed after the counter. +// +// CALL IT BEFORE THE WORK, NOT AFTER. After is the obvious placement and it is +// wrong: the line a reader most needs is the one naming the unit that was in +// flight when the run stopped. The cost is that the last unit of a completed +// run has no line of its own, and its duration is inside the enclosing phase's +// close line. +// +// AND SAY WHAT THE GATE CAN SEE OF THAT, because the choice is presented above +// as though it were checked. On a render that COMPLETES the two placements are +// indistinguishable end to end: same ticks, same intervals, same ordering +// relative to the phase boundaries. Moving the production call below the forward +// leaves `test_ltx2_video` green. The two differ only on a run that dies inside +// a unit, which no gate here can stage through the ABI. What IS gated is this +// function's own contract — that the line reaches fd 2, FLUSHED, before the +// caller's next statement runs, so that a `SIGKILL` between the two leaves the +// announcement behind (`a live tick is FLUSHED BEFORE the work it announces`). +// The production placement rests on that contract plus a reading of the call +// site, and this comment is the whole of the evidence for it. +// +// `last=` IS KEYED BY `unit`, and the key's lifetime is the RENDER. The map is +// cleared by `Begin`, by `Reset` and by `SetRender`, so the first tick of each +// generation has no `last=` rather than one spanning the gap since the previous +// generation ended. Two units ticking in the same phase keep independent clocks. +// +// THE LINE IS WRITTEN UNDER THE PROCESS-WIDE PHASE MUTEX — the same one the +// 100 ms sampler thread takes. So the cost of a tick is a held global lock plus +// a flushed `fwrite`, not a bare `fprintf`, and a tick can briefly block a +// sample. That is the price of emitting the interval and the elapsed clock from +// the same guarded state the table is built from; at this lane's cadence +// (~110 lines per render) it is not a contention story, and it is written down +// here rather than left to be discovered from a profile. +void Tick(const std::string& unit, int64_t index, const std::string& detail); + + } // namespace phase } // namespace multimodal } // namespace vllm diff --git a/src/vllm/multimodal/ltx2_video.cpp b/src/vllm/multimodal/ltx2_video.cpp index 24e824d16..59bc73488 100644 --- a/src/vllm/multimodal/ltx2_video.cpp +++ b/src/vllm/multimodal/ltx2_video.cpp @@ -3996,6 +3996,39 @@ VideoResult Ltx2VideoEngine::Generate(const VideoGenParams& gen) { // owed a leased run rather than left implied. const Ltx2X0Model x0_model = [&](const Ltx2ModalityInput* v, const Ltx2ModalityInput* a, const Ltx2DitPerturbation* p) { + // W0-live (#1413): THE tick, and it fires BEFORE the forward rather than + // after it. At #1375's measured ~162 s per forward on the 21.004 B model + // this line is the only output the process produces for minutes at a + // time, so it has to name the forward that is IN FLIGHT — otherwise a run + // killed inside forward 37 says 36 and a reader has to guess whether the + // missing one ran. The cost of that choice: the last forward of a + // completed render has no line of its own, and its duration is inside the + // `- denoise` boundary line. + // + // NO DENOMINATOR ON THE FORWARD COUNTER, deliberately. 60 = 30 x 2 is + // true of the config #1375 measured and is not structural here: the + // sampler decides how many denoiser calls happen and `Ltx2GuidedDenoise` + // decides how many forwards each call is (one to four — cond, uncond, + // ptb, mod, denoisers.py:100-137). The STEP fraction is exact, because + // `sigmas` is this recipe phase's own schedule; note that the res_2s + // substep passes a literal 0 and its terminal evaluation passes + // `n_full_steps`, so on that arm the step number is the DENOISER's index + // and not a monotone loop counter. The forward counter is the monotone + // one, which is why the progress claim rests on it. + // + // GUARDED AT THE CALL SITE, not only inside `Tick`. `Tick` returns on + // its first line when the lane is off, but `detail` is already built by + // then: one `std::string` from a literal, three `std::to_string`s and + // four concatenations, per forward. Negligible against 162 s and not + // zero, and the spec claims `VLLM_RENDER_PROGRESS=0` costs one `getenv` + // per process — which is true only with this `if` here. + if (::vllm::multimodal::phase::ProgressEnabled()) { + ::vllm::multimodal::phase::Tick( + "dit forward", im.trace.dit_forwards + 1, + "phase " + std::to_string(phase_index) + " step " + + std::to_string(step_index + 1) + "/" + + std::to_string(static_cast(sigmas.size()) - 1)); + } const Ltx2DitOutputs velocity = im.on_device ? Ltx2DitForwardDevice(*im.queue, im.dit.params, im.dit.weights, v, a, im.compute_dtype, /*cache=*/nullptr, p) diff --git a/src/vllm/multimodal/render_phase_log.cpp b/src/vllm/multimodal/render_phase_log.cpp index 131ca6b7f..fab62f6ec 100644 --- a/src/vllm/multimodal/render_phase_log.cpp +++ b/src/vllm/multimodal/render_phase_log.cpp @@ -7,6 +7,7 @@ #include #include #include +#include #include #include @@ -64,8 +65,30 @@ bool StderrEnabled() { return on != nullptr && on[0] != '0'; } +// THE LIVE LANE'S OWN SWITCH (#1413), and it is ON unless somebody turns it off. +// +// A measurement lane in the shape `VLLM_RENDER_PHASE_SAMPLER` and +// `VLLM_LTX2_POOL_DRAIN` already take here: it exists so an A/B over what the +// emitter itself costs runs on ONE binary. It is never a configuration, and +// nothing in this tree sets it. The polarity is the point — `VT_H3_PROGRESS` is +// the same instrument for MiniMax-H3 and it is opt-in, which is exactly why no +// LTX-2.5 run has ever had one. +// +// READ ONCE. This is consulted at every phase boundary and every DiT forward, so +// a `getenv` per call would put a process-environment lookup inside the +// instrument whose cost this row claims is negligible. } // namespace +// Defined outside the anonymous namespace because the LTX-2.5 call site has to +// ask BEFORE it formats `detail`; see the declaration in the header. +bool ProgressEnabled() { + static const bool on = []() { + const char* off = std::getenv("VLLM_RENDER_PROGRESS"); + return off == nullptr || off[0] != '0'; + }(); + return on; +} + struct PhaseLog::Impl { mutable std::mutex mu; @@ -90,6 +113,9 @@ struct PhaseLog::Impl { size_t next_handle = 1; int64_t samples = 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. + std::map last_tick; std::vector records; DeviceByteProbe device_probe; @@ -110,6 +136,15 @@ struct PhaseLog::Impl { return std::chrono::duration(std::chrono::steady_clock::now() - origin).count(); } + // Caller holds `mu`. FLUSHED ON EVERY LINE, because the whole population this + // lane exists for is runs that are killed: a line still sitting in a stdio + // buffer when the process takes a SIGKILL is a line nobody gets, and it is the + // last one — the one naming the phase that was running. + void EmitLocked(const char* text) { + std::fputs(text, stderr); + std::fflush(stderr); + } + // Caller holds `mu`. Reads both counters once and folds them into every open // scope, so a nested span sees the peak its children reached. void SampleLocked() { @@ -198,6 +233,7 @@ void PhaseLog::Begin() { std::lock_guard lock(impl_->mu); impl_->records.clear(); impl_->open.clear(); + impl_->last_tick.clear(); impl_->origin = std::chrono::steady_clock::now(); impl_->running = true; impl_->render = 0; @@ -213,6 +249,13 @@ void PhaseLog::SetDeviceProbe(DeviceByteProbe probe) { void PhaseLog::SetRender(int64_t render) { std::lock_guard lock(impl_->mu); impl_->render = render; + // The per-unit tick clock belongs to ONE generation. A process that renders + // twice calls this between them, and carrying `last_tick` across would give + // the second render's first DiT forward a `last=` measuring the gap between + // two renders — a number that looks exactly like a very slow forward. `Begin` + // and `Reset` clear it for the same reason; this is the third door into a new + // timeline and it was the one left open. + impl_->last_tick.clear(); } double PhaseLog::Elapsed() const { @@ -240,8 +283,21 @@ size_t PhaseLog::Open(const std::string& name, bool span) { if (other.live && !other.span) leaf_already_open = true; } o.nested = leaf_already_open && !span; + const double opened_at = o.start; + const std::string opened_name = o.name; impl_->open.push_back(std::move(o)); impl_->SampleLocked(); + // 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 + // emitter would have printed nothing at all for the 3002 s conditioning + // stretch, because that stretch never closed. + if (ProgressEnabled()) { + char text[256]; + std::snprintf(text, sizeof(text), "[render] + %-24s t=%.3fs\n", opened_name.c_str(), + opened_at); + impl_->EmitLocked(text); + } return impl_->open.back().handle; } @@ -271,6 +327,25 @@ void PhaseLog::Close(size_t handle) { r.peak_device_bytes = o.peak_device; r.span = o.span; r.nested = o.nested; + // 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. + if (ProgressEnabled()) { + const double kGiB = 1024.0 * 1024.0 * 1024.0; + const double host = r.peak_host_bytes < 0 ? -1.0 + : static_cast(r.peak_host_bytes) / kGiB; + char text[320]; + if (r.peak_device_bytes >= 0) { + std::snprintf(text, sizeof(text), + "[render] - %-24s t=%.3fs dur=%.3fs host=%.2fGiB dev=%.2fGiB\n", + r.name.c_str(), r.end, r.end - r.start, host, + static_cast(r.peak_device_bytes) / kGiB); + } else { + std::snprintf(text, sizeof(text), "[render] - %-24s t=%.3fs dur=%.3fs host=%.2fGiB\n", + r.name.c_str(), r.end, r.end - r.start, host); + } + impl_->EmitLocked(text); + } impl_->records.push_back(std::move(r)); impl_->open.erase(impl_->open.begin() + static_cast(i)); break; @@ -288,6 +363,36 @@ void PhaseLog::Sample() { impl_->SampleLocked(); } +void PhaseLog::Tick(const std::string& unit, int64_t index, const std::string& detail) { + if (!ProgressEnabled()) return; + std::lock_guard lock(impl_->mu); + // 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. + if (!impl_->running) { + impl_->origin = std::chrono::steady_clock::now(); + impl_->running = true; + } + const double now = impl_->Now(); + const std::map::const_iterator previous = impl_->last_tick.find(unit); + char text[384]; + if (previous == impl_->last_tick.end()) { + std::snprintf(text, sizeof(text), "[render] %s %lld %s t=%.3fs\n", unit.c_str(), + static_cast(index), detail.c_str(), now); + } else { + // `last=` IS THE DELIVERABLE. #1375 could only obtain the per-forward cost as + // a wall-clock interval between GPU busy/idle edges from outside the process, + // because `eu-stack` unwinds zero frames inside the `rc` worker container. + // This is the same quantity, measured by the thing doing the work, on every + // run including the ones that die. + std::snprintf(text, sizeof(text), "[render] %s %lld %s t=%.3fs last=%.3fs\n", + unit.c_str(), static_cast(index), detail.c_str(), now, + now - previous->second); + } + impl_->last_tick[unit] = now; + impl_->EmitLocked(text); +} + std::vector PhaseLog::Records() const { std::lock_guard lock(impl_->mu); return impl_->records; @@ -303,6 +408,7 @@ void PhaseLog::Reset() { std::lock_guard lock(impl_->mu); impl_->records.clear(); impl_->open.clear(); + impl_->last_tick.clear(); impl_->running = false; impl_->render = 0; impl_->samples = 0; @@ -485,6 +591,10 @@ void Scope::Close() { void SampleNow() { PhaseLog::Instance().Sample(); } +void Tick(const std::string& unit, int64_t index, const std::string& detail) { + PhaseLog::Instance().Tick(unit, index, detail); +} + } // namespace phase } // namespace multimodal } // namespace vllm diff --git a/tests/vllm/multimodal/test_ltx2_video.cpp b/tests/vllm/multimodal/test_ltx2_video.cpp index fb8d73b64..b7f6bba12 100644 --- a/tests/vllm/multimodal/test_ltx2_video.cpp +++ b/tests/vllm/multimodal/test_ltx2_video.cpp @@ -3323,6 +3323,431 @@ TEST_CASE("ltx2 phase log: the last Close stops the sampler") { log.Reset(); } +// ─── W0-live: the lane that runs WHILE the render is alive (issue #1413) ───── +// +// WHAT THIS GATES, and why the table above does not already gate it. That case +// reads `phase-log.json`, which `Ltx2VideoEngine::Generate` writes after +// `im.trace.completed = true` — the SUCCESS PATH ONLY. A render that is killed, +// aborted by a lease governor, or still running writes no table at all, and that +// is the population this campaign actually has: #1375 is `ABORT[92] PROJECTED +// OVERRUN` / `child exit=-15` / 0 frames, and `ltx25-decode-speed.md`'s two +// rungs are `EXIT=137` / 0 frames and `EXIT=1` / 0 frames. An instrument that +// reports on completion reported on none of them. +// +// So the deliverable here is different in kind: a line emitted AS EACH PHASE +// STARTS, so that the last line printed names the phase that is currently +// running. That is the whole difference between a working render and a hung one, +// which were byte-identical from outside for 2.5 hours at a time, and it is the +// difference a close-only emitter would still not make — the 3002 s conditioning +// stretch never closed. +// +// AND IT CAPTURES REAL STDERR, with `dup`/`dup2`, rather than installing a +// test-only sink. A sink would be a seam that could be armed here and absent in +// production, which is the exact defect class `.agents/reachability.md` is +// about; what is asserted below is what a user sees on the shipped default with +// nothing set. +// +// THE NON-VACUOUS HALF is the strictly-increasing forward index. An emitter that +// printed a constant `dit forward 1` would satisfy "the marker appears" and would +// report nothing — which is what the spike's external sampler did, and why +// #1375's `dit_runs=0` is not evidence of absence. The count has to MOVE. +// +// Nothing between the redirect and its restore may assert: a doctest `REQUIRE` +// that aborted the case in there would leave the process with stderr pointed at +// a temporary file for every case that follows. +#if !defined(_WIN32) +TEST_CASE("ltx2 video: a render through the ABI PRINTS its progress while it runs") { + Workspace ws; + const std::string audio_embeds = ws.paths.audio_embeds; + const std::string max_phase = "0"; + const char* keys[] = {vllm::multimodal::kLtx2AudioPromptEmbedsExtra, + vllm::multimodal::kLtx2MaxPhaseExtra}; + const char* values[] = {audio_embeds.c_str(), max_phase.c_str()}; + + vllm_video_model_params mp = vllm_video_model_params_default(); + mp.dit_path = ws.paths.dit.c_str(); + mp.video_vae_path = ws.paths.video_vae.c_str(); + mp.audio_vae_path = ws.paths.audio_vae.c_str(); + mp.prompt_embeds_path = ws.paths.video_embeds.c_str(); + mp.extra_keys = keys; + mp.extra_values = values; + mp.n_extras = 2; + mp.device = 0; + + const std::string out_dir = ws.root + "/progress_out"; + vllm_video_params gen = vllm_video_params_default(); + gen.width = 64; + gen.height = 64; + gen.num_frames = 9; + gen.seed = 7; + gen.has_seed = 1; + gen.output_dir = out_dir.c_str(); + + vllm_video_engine* engine = nullptr; + vllm_video_result result; + std::memset(&result, 0, sizeof(result)); + vllm_status loaded = VLLM_OK; + vllm_status generated = VLLM_OK; + std::string engine_error; + std::string captured; + + // The LOAD is inside the capture as well as the generation: the timeline + // starts at the load because the DiT staging is minutes at 22B, and a lane + // that only spoke after the load would be silent for the phase #1021 is about. + { + std::FILE* cap = std::tmpfile(); + REQUIRE(cap != nullptr); + std::fflush(stderr); + const int saved = ::dup(STDERR_FILENO); + REQUIRE(saved >= 0); + REQUIRE(::dup2(::fileno(cap), STDERR_FILENO) >= 0); + + loaded = vllm_video_engine_load(&mp, &engine); + if (loaded == VLLM_OK && engine != nullptr) { + generated = vllm_video_generate(engine, &gen, &result); + } + if (vllm_last_error() != nullptr) engine_error = vllm_last_error(); + + std::fflush(stderr); + const int restored = ::dup2(saved, STDERR_FILENO); + ::close(saved); + std::rewind(cap); + char buf[4096]; + size_t n = 0; + while ((n = std::fread(buf, 1, sizeof(buf), cap)) > 0) captured.append(buf, n); + std::fclose(cap); + REQUIRE(restored >= 0); + } + + INFO(engine_error); + REQUIRE(loaded == VLLM_OK); + REQUIRE(engine != nullptr); + REQUIRE(generated == VLLM_OK); + + // ── the lines ──────────────────────────────────────────────────────────── + std::vector lines; + { + std::istringstream stream(captured); + std::string line; + while (std::getline(stream, line)) { + if (line.rfind("[render] ", 0) == 0) lines.push_back(line); + } + } + MESSAGE("captured " << lines.size() << " [render] lines of " << captured.size() + << " bytes of stderr"); + REQUIRE_MESSAGE(!lines.empty(), + "the render printed NOTHING while it ran; a working render and a hung one " + "are still the same observation (#1413)"); + + // Every line carries the elapsed clock, and it never goes backwards. A `t=` + // that reset would mean two timelines interleaved in one capture. + double previous_t = -1.0; + for (const std::string& line : lines) { + INFO(line); + const size_t at = line.find(" t="); + REQUIRE_MESSAGE(at != std::string::npos, "a progress line carries no elapsed clock"); + const double t = std::atof(line.c_str() + at + 3); + CHECK(t >= previous_t); + previous_t = t; + } + + // ── the boundaries, opened AND closed ──────────────────────────────────── + // + // The OPEN marker is the one that matters and it is asserted by name: a close + // marker alone names only phases that finished, and every render this row + // exists for stopped inside a phase that never did. + auto index_of = [&lines](const std::string& needle) -> long { + for (size_t i = 0; i < lines.size(); ++i) { + if (lines[i].find(needle) != std::string::npos) return static_cast(i); + } + return -1; + }; + // MATCH THE WHOLE NAME FIELD, NOT A PREFIX OF IT. The emitter writes the name + // with `%-24s`, so every phase shorter than 24 characters is followed by at + // least one space, and `"- denoise "` cannot match `- denoise.step`. Written as + // a helper because a prefix match here is not a stylistic point: W0's anchor + // scopes added `denoise.step` and `decode.video.chunk` beneath the two leaves + // this case asserts against, and a bare `find("- denoise")` then resolved to + // the FIRST sub-scope close, several lines before the forwards it was supposed + // to bracket. The case failed on seven true statements about the wrong line. + auto phase_line = [&index_of](const char* sign, const std::string& name) -> long { + return index_of(std::string(sign) + " " + name + " "); + }; + for (const std::string name : {"load.dit", "denoise", "decode.video", "artifacts.frames"}) { + // `std::string`, never `const char*`: doctest stringifies a streamed `char*` + // as a BOOL, so a failure here would have printed "no '1' line". + CHECK_MESSAGE(phase_line("+", name) >= 0, "no OPEN line for phase '" << name << "'"); + CHECK_MESSAGE(phase_line("-", name) >= 0, "no CLOSE line for phase '" << name << "'"); + CHECK_MESSAGE(phase_line("-", name) > phase_line("+", name), + "phase '" << name << "' closed before it opened"); + } + + // A close line reports what the phase cost, which is the number a reader takes + // off a killed run's log without waiting for a table that will never be + // written. + const long dit_close = phase_line("-", "load.dit"); + REQUIRE(dit_close >= 0); + CHECK_MESSAGE(lines[static_cast(dit_close)].find(" dur=") != std::string::npos, + "a phase closed without saying what it cost: " + << lines[static_cast(dit_close)]); + + // ── the per-forward counter, and the proof that it MOVES ───────────────── + std::vector forward_indices; + std::vector forward_lines; + for (size_t i = 0; i < lines.size(); ++i) { + const size_t at = lines[i].find("dit forward "); + if (at == std::string::npos) continue; + forward_indices.push_back(std::atol(lines[i].c_str() + at + 12)); + forward_lines.push_back(i); + } + REQUIRE_MESSAGE(forward_indices.size() >= 2, + "the denoise loop printed " << forward_indices.size() + << " forward lines; #1375 measures ~162 s per " + "forward and 60 of them is structural, so a " + "loop that prints once is a loop that hangs"); + for (size_t i = 1; i < forward_indices.size(); ++i) { + INFO(lines[forward_lines[i]]); + CHECK_MESSAGE(forward_indices[i] > forward_indices[i - 1], + "the forward counter did not move: " << forward_indices[i - 1] << " then " + << forward_indices[i]); + // `last=` is the per-forward cost #1375 could only get as a wall-clock + // interval between GPU busy/idle edges. Absent on the first tick by + // construction, required on every one after it. + CHECK_MESSAGE(lines[forward_lines[i]].find(" last=") != std::string::npos, + "a forward tick carries no per-forward cost: " << lines[forward_lines[i]]); + } + // The sampler step, as a FRACTION. Without the denominator a reader knows the + // render moved and not whether it is a tenth or nine tenths of the way. + // + // Two statements rather than one `&&`: doctest's expression decomposer + // static-asserts "Expression Too Complex Please Rewrite As Binary Comparison" + // on a conjunction, so the compound form does not build — and a mutation that + // fails to build reads exactly like a passing test. + const std::string first_tick = lines[forward_lines[0]]; + CHECK_MESSAGE(first_tick.find(" step ") != std::string::npos, + "a forward tick names no sampler step: " << first_tick); + CHECK_MESSAGE(first_tick.find("/") != std::string::npos, + "the sampler step carries no /N denominator, so a reader knows the render " + "moved and not whether it is a tenth or nine tenths of the way: " + << first_tick); + + // ── the ticks are INSIDE the phase they claim ──────────────────────────── + const long denoise_open = phase_line("+", "denoise"); + const long denoise_close = phase_line("-", "denoise"); + REQUIRE(denoise_open >= 0); + REQUIRE(denoise_close >= 0); + for (size_t i = 0; i < forward_lines.size(); ++i) { + const long at = static_cast(forward_lines[i]); + // Two comparisons, never one `&&`: doctest static-asserts on a conjunction. + CHECK_MESSAGE(at > denoise_open, + "a DiT forward tick was printed BEFORE the denoise phase opened: " + << lines[forward_lines[i]]); + CHECK_MESSAGE(at < denoise_close, + "a DiT forward tick was printed AFTER the denoise phase closed: " + << lines[forward_lines[i]]); + } + + vllm_video_result_free(&result); + vllm_video_engine_free(engine); +} +#endif // !_WIN32 + +// ─── the tick's OWN contract: emitted at the call, not at the return ──────── +// +// WHY THIS CASE EXISTS. The case above renders through the ABI and asserts that +// the ticks appear, that the counter moves and that they sit inside `denoise`. +// It cannot see the decision the design rests on. On a render that COMPLETES, +// calling `Tick` before the forward and calling it after produce the same lines, +// the same intervals and the same ordering against the phase boundaries — moving +// the production call below the forward leaves that case green. The two +// placements differ only on a run that dies mid-unit, and no gate here can stage +// a `SIGKILL` inside `Ltx2DitForwardDevice` through `vllm.h`. +// +// So this pins the half that IS testable, which is the half the production +// placement rests on: `Tick` reaches the real fd 2 and FLUSHES before the +// caller's next statement runs. If the line were buffered, or emitted lazily, or +// deferred to the end of the phase, then announcing a unit before starting it +// would buy nothing — the announcement would die in the buffer with the process. +// Below, a fake unit of work writes its own marker to the same stream, and the +// tick has to be there first every time. +// +// AND THE SHAPE THAT MATTERS IS THE LAST ONE. The loop announces unit 4 and then +// stops without finishing it, which is what a killed render looks like from +// stderr: the log's last word is the unit that was in flight. Under an +// after-the-work emitter that capture would end at unit 3, and #1375 would still +// be un-attributed. +// +// Nothing between the redirect and its restore may assert, for the reason the +// case above gives: a `REQUIRE` that aborted in there would leave every later +// case writing stderr into a temporary file. +#if !defined(_WIN32) +TEST_CASE("ltx2 phase log: a live tick is FLUSHED BEFORE the work it announces") { + namespace phase = vllm::multimodal::phase; + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Begin(); + + const int kFinished = 3; // units 1..3 complete; unit 4 is announced and never does + std::string captured; + { + std::FILE* cap = std::tmpfile(); + REQUIRE(cap != nullptr); + std::fflush(stderr); + const int saved = ::dup(STDERR_FILENO); + REQUIRE(saved >= 0); + REQUIRE(::dup2(::fileno(cap), STDERR_FILENO) >= 0); + + for (int k = 1; k <= kFinished; ++k) { + phase::Tick("unit", k, "step " + std::to_string(k) + "/4"); + // The work. It writes its own marker to the SAME stream, so the ordering + // question is answered by the bytes rather than by a clock. + std::fprintf(stderr, "[work] unit %d finished\n", k); + std::fflush(stderr); + } + // Announced, then the "process dies" here. No marker follows. + phase::Tick("unit", kFinished + 1, "step 4/4"); + + std::fflush(stderr); + const int restored = ::dup2(saved, STDERR_FILENO); + ::close(saved); + std::rewind(cap); + char buf[4096]; + size_t n = 0; + while ((n = std::fread(buf, 1, sizeof(buf), cap)) > 0) captured.append(buf, n); + std::fclose(cap); + REQUIRE(restored >= 0); + } + log.Reset(); + + MESSAGE("captured " << captured.size() << " bytes of stderr from the tick contract case"); + REQUIRE_MESSAGE(!captured.empty(), "phase::Tick emitted nothing at all"); + + std::vector lines; + { + std::istringstream stream(captured); + std::string line; + while (std::getline(stream, line)) { + if (line.rfind("[render] ", 0) == 0) lines.push_back(line); + if (line.rfind("[work] ", 0) == 0) lines.push_back(line); + } + } + auto index_of = [&lines](const std::string& needle) -> long { + for (size_t i = 0; i < lines.size(); ++i) { + if (lines[i].find(needle) != std::string::npos) return static_cast(i); + } + return -1; + }; + + // Each announcement precedes the work it announces. `std::string` and never a + // `char*` in a stream: doctest stringifies a streamed `char*` as a bool. + for (int k = 1; k <= kFinished; ++k) { + const std::string tick = "unit " + std::to_string(k) + " "; + const std::string work = "[work] unit " + std::to_string(k) + " finished"; + const long at_tick = index_of(tick); + const long at_work = index_of(work); + CHECK_MESSAGE(at_tick >= 0, "no tick line for unit " << k); + CHECK_MESSAGE(at_work >= 0, "no work marker for unit " << k); + CHECK_MESSAGE(at_tick < at_work, + "the tick for unit " << k << " was not flushed before the work it announces"); + } + + // The killed-run shape: unit 4 was announced, never finished, and the capture + // still names it — and names it LAST. + const long announced = index_of("unit 4 "); + CHECK_MESSAGE(announced >= 0, + "the unit that was in flight when the run stopped is missing from the log, " + "which is what an after-the-work emitter produces"); + CHECK_MESSAGE(index_of("[work] unit 4 finished") < 0, + "the case did not stage an unfinished unit, so it proves nothing"); + REQUIRE(!lines.empty()); + CHECK_MESSAGE(lines.back().find("unit 4 ") != std::string::npos, + "the last line of the capture is not the unit in flight: " << lines.back()); + + // `last=` is the per-unit interval, absent on the first tick by construction + // and present on every one after it. + const long first = index_of("unit 1 "); + REQUIRE(first >= 0); + CHECK(lines[static_cast(first)].find(" last=") == std::string::npos); + const long second = index_of("unit 2 "); + REQUIRE(second >= 0); + CHECK_MESSAGE(lines[static_cast(second)].find(" last=") != std::string::npos, + "the second tick of a unit carries no interval: " + << lines[static_cast(second)]); +} +#endif // !_WIN32 + +// ─── `last=` belongs to ONE generation ─────────────────────────────────────── +// +// The per-unit tick clock is keyed by unit NAME and lives in the `PhaseLog`, so +// its lifetime is a decision rather than an accident. `Begin` and `Reset` clear +// it. `SetRender` — the call a driver makes between two generations in one +// process — did not, so the second render's first DiT forward would have carried +// a `last=` measuring the gap between two renders. That number is shaped exactly +// like one very slow forward, on the lane whose entire deliverable is per-forward +// seconds, in a process (a server) that renders more than once. +// +// The wait is what makes this refutable. Without it the stale interval would be +// microseconds and indistinguishable from a fresh one; 150 ms of sleep between +// the two renders means an uncleared clock reports a number nobody could mistake +// for a forward. +#if !defined(_WIN32) +TEST_CASE("ltx2 phase log: a SECOND render's first tick carries no interval from the first") { + namespace phase = vllm::multimodal::phase; + phase::PhaseLog& log = phase::PhaseLog::Instance(); + log.Begin(); + + std::string captured; + { + std::FILE* cap = std::tmpfile(); + REQUIRE(cap != nullptr); + std::fflush(stderr); + const int saved = ::dup(STDERR_FILENO); + REQUIRE(saved >= 0); + REQUIRE(::dup2(::fileno(cap), STDERR_FILENO) >= 0); + + log.SetRender(1); + phase::Tick("dit forward", 1, "render one"); + phase::Tick("dit forward", 2, "render one"); + // The gap between two generations, long enough to be unmistakable. + std::this_thread::sleep_for(std::chrono::milliseconds(150)); + log.SetRender(2); + phase::Tick("dit forward", 1, "render two"); + + std::fflush(stderr); + const int restored = ::dup2(saved, STDERR_FILENO); + ::close(saved); + std::rewind(cap); + char buf[4096]; + size_t n = 0; + while ((n = std::fread(buf, 1, sizeof(buf), cap)) > 0) captured.append(buf, n); + std::fclose(cap); + REQUIRE(restored >= 0); + } + log.Reset(); + + std::vector lines; + { + std::istringstream stream(captured); + std::string line; + while (std::getline(stream, line)) { + if (line.rfind("[render] ", 0) == 0) lines.push_back(line); + } + } + MESSAGE("captured " << lines.size() << " tick lines across two renders"); + REQUIRE(lines.size() == 3); + + // THE INSTRUMENT'S OWN PRECONDITION: the second tick of render one DOES carry + // an interval, so "no `last=`" below is a cleared clock and not a lane that is + // switched off. `VLLM_RENDER_PROGRESS=0` would have failed the size check above + // rather than passing this one silently. + REQUIRE_MESSAGE(lines[1].find(" last=") != std::string::npos, + "the second tick of the FIRST render carries no interval, so this case cannot " + "observe whether the clock is cleared: " << lines[1]); + CHECK_MESSAGE(lines[2].find(" last=") == std::string::npos, + "the first tick of the SECOND render carries an interval spanning the gap since " + "the first render ended, which reads as one very slow forward: " << lines[2]); +} +#endif // !_WIN32 + // ─── the SHIPPED checkpoints, when the box has them ───────────────────────── // // Everything above runs over a reduced fixture, which proves the composition and