Skip to content

RenderText reads its clock AFTER the copy and the sort, so the console copy of a phase table charges the writer to the render #1755

Description

@localai-bot

PhaseLog::WriteJson reads its clock before it copies and sorts the record table, so the writer's own serialization is not charged to wall_seconds and therefore not to unaccounted_seconds. That repair is #1569, and row LTX25-PHASE-INSTRUMENT (PR #1711) gates it.

Its sibling emitter never got the same repair.

src/vllm/multimodal/render_phase_log.cpp:833-834:

std::string PhaseLog::RenderText(const std::string& family, const std::string& device) const {
  const std::vector<Record> records = ByStart(Records());
  const Totals totals = Sum(records, Elapsed());

Records() copies the record vector under the process-wide mutex and ByStart stable-sorts the copy. The clock is read AFTER both, so this emitter's own copy and sort land inside the WALL it prints and inside the unaccounted row three lines above it. That table measures the render.

The call site makes it worse

RenderText is called from WriteJson:812, after the whole nlohmann object has been assembled. So the console copy absorbs the JSON build as well as its own copy and sort, while the file copy — repaired by #1569 — does not. The two copies of one table disagree about the same render, and the one that disagrees is the one a reader watching a terminal gets.

Measured by a fresh review of #1711 with VLLM_RENDER_PHASE_LOG_STDERR=1 on the 8001-record unit timeline, over five WriteJson calls in one process:

call console sum(leaf) console unaccounted
1 0.189 0.065
2 0.189 0.134
3 0.189 0.200
4 0.189 0.265
5 0.189 0.329

sum(leaf) is constant because no render happened between the calls. unaccounted climbs by about 66 ms per call, and every one of those milliseconds is the writer that printed the table.

Why nothing caught it

RenderText prints every total with %10.3f. A copy and a sort of a few thousand records are tenths of a millisecond, so the whole ordering half of the defect fits inside the last printed digit: applying #1569's identical one-line repair to RenderText leaves test_render_phase_log at test cases: 7 | 7 passed, assertions: 100 | 100 passed, Status: SUCCESS!. That is the same mute switch .agents/specs/ltx25-phase-instrument.md ### 7 and ## Design 6 each record, met a third time on a third quantity.

What closing it needs

  1. RenderText reads Elapsed() above ByStart(Records()), mirroring WriteJson.
  2. The console block is emitted before this writer does any work at all, so the console copy and the file copy describe the same instant.
  3. A gate that reds on both, against the format's own resolution rather than an invented tolerance, on a table large enough for the defect to cross %10.3f's last digit. .agents/specs/ltx25-phase-residue.md ## Design 3 and LTX-2.5: three phase anchors and the instrument's own cost accounting are measured and reviewed, and none of them is on main #1668 both forbid re-proposing a wall-clock ratio here.

Found during the fresh review of PR #1711, which closes #1569. Owning row: LTX25-PHASE-INSTRUMENT.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions