Serve qwen3_xml, not hermes: tool calling is broken in production #34
No reviewers
Labels
No labels
human-approved
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set
Reference
bitpartner/tt-stack!34
Loading…
Reference in a new issue
No description provided.
Delete branch "serving-throughput"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
The defect
Production serves Qwen3.8-27B with
--tool-call-parser hermes. The model emitsQwen XML; hermes expects JSON inside
<tool_call>. The result is not adegradation, it is a silent total failure:
content,tool_callsisnullsees an empty response
Verified fixed with
qwen3_xml: 8 tool-call deltas with name and argumentsparsed. The chat template did not need changing.
Evidence:
bench/runs/toolcall-parser-mismatch-20260918T1100Z.jsonl.Why it went unnoticed
Nothing in our benchmark suite exercised tool calling. It surfaced only when
this stack moved to
infbench, whose stage 3 gates perf behind correctness —the gate went FAIL → PASS on this one change. Every performance number this
repo recorded before
779ccbawas measured against a server whose tool callingreturned nothing.
What changed
scripts/vllm-tt-serve.sh—--tool-call-parser "${TOOL_CALL_PARSER:-qwen3_xml}"nix/production-serving-recipe.nix— both sites (serving arm, prefix-caching arm)This is the half that matters for deployment: the running
tenstorrent-servingunit still bakeshermesinto its/nix/storeExecStart,so nixos-llm must rebuild from this input before the fix reaches production.
Also in this branch
Measured on two cabled p150a cards, every result gated:
dca377d): makespan 303.63 → 80.58 s(−73.5%) and last-agent TTFT 277.93 → 14.02 s (−95.0%) at B=8 on
93,739-token prompts. The crossover is the finding — it loses at B=1
(+35.0%) and the win grows with batch, because the saving is prefill
(serialised across the batch) and the cost is decode (paid per stream).
Ranked on decode ms/token it is a 61.8% regression.
b4c10af): theprod-prefixprofile could not boot onits own defaults — GDN block 16384 against attention block 2048, which vLLM's
hybrid coordinator always rejects. Every recorded prefix run had passed both
values by hand, so the defaults were never exercised.
db6ce1a): decode trace replay and a full-shape KV pooldo not fit on the card together (card DRAM 99.66% allocated). The +4.5% cost
of tracing measured at
CTX=18432does not transfer to the target shape.f967859) on a hardware limit — markervolume, not ring size.
What is NOT claimed
Prefix caching is not deployed here. The decode regression remains unattributed
between
trace_mode=noneand the cache itself, and an unaligned-resumeequivalence test does not yet exist.
🤖 Generated with Claude Code
The ~32% cold-prefill regression on the prefix arm has been unexplained since it was measured, and it is paid on exactly the metric the owner ranks by. This closes it. Matched pair, same prompt shape (~8-9k tokens, one cold prefill, max_tokens=1), classified by bench/ab/pyspy-classify.py: production prefix arm ttnn dispatch 18.9% 61.8% host tensor marshalling 6.5% 18.0% blocked in native call 73.9% 18.1% cold prefill 3,014 tok/s 1,493 tok/s The profiles are inverted. Production's traced chunk path waits on the device; the prefix arm spends four fifths of its time in the Python interpreter. The top leaf flips from _prefill_traced_chunked_tp (model.py:2647, i.e. ttnn.synchronize_device, 403 samples) to ttnn/decorators.py:728 op dispatch (628 samples), with prefill_masked_bucket (model.py:2334) third at 111 -- the eager bucket loop named directly. That is patches/tt-metal/0017's prefill_prefix_slots looping EAGER prefill_masked_bucket(bucket=2048) per 2048 tokens instead of one execute_trace per chunk, and the audit's ~437 ms of host dispatch per eager 64-layer forward for ~40 ms of device work is the right order for what is measured here. TWO THINGS BEYOND WHAT WAS PREDICTED. The gap on this pair is -50.5%, not the ~32% the agent-shaped runs showed, so the regression is larger at this shape than the number we have been quoting. And 18.0% of the arm's samples are host tensor marshalling (to_torch 95, from_torch 92) -- the GDN snapshot/restore round trip that was flagged as an unmeasured secondary contributor. It is now measured, it is a fifth of the arm's time, and it is SEPARATE from the dispatch cost, so putting the arm on the traced chunk path does not by itself recover it. WHAT THIS LICENSES, AND WHAT IT DOES NOT. It identifies where the time goes; it does not prove the traced path can be used for a resumed prefill. That still needs the sequence-start reset skipped, the runner's trace_mode=all guard moved, and the flex-SDPA q/k-chunk rule asserted never to select 32 at a resume offset (32 silently corrupts masked SDPA -- CLAUDE.md trap). It also re-opens resume equivalence, which is 4/4 at B=1 only. n=1 per arm, two boots 30+ minutes apart rather than interleaved, and different corpus slices, so the two tok/s figures are same-shape but not same-prompt. The direction and the size of the split are far outside that noise; the exact percentages are not. Raw profiles committed next to both records. Endpoint taken down for the prefix boot under standing owner authorisation and restored afterwards. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>Measured today: the prefix arm's cold prefill is 79.8% host-bound (61.8% ttnn dispatch + 18.0% marshalling) where production is 73.9% device-bound, at 1,493 vs 3,014 tok/s on a matched pair (bench/runs/prefill-cold-pyspy-*). The cause is that prefill_prefix_slots loops EAGER prefill_masked_bucket per 2048 tokens instead of replaying the captured chunk trace. Patch 0017's stated reason for going eager -- "offset-dependent compilation is not qualified alongside parked decode traces" -- IS FALSE, and this was verified rather than assumed: the traced chunk compiles nothing per offset, because position is the runtime device tensor _chunk_start_idx_tensor and the page-table, token and cos/sin buffers are fixed-width and DMA'd. 0018 adds a module-level, ttnn-free prefill_chunk_plan(start, end, ...) returning {reset, lead, replays, tail}, threads an absolute-offset `start` through prefill_traced_chunked and both TP loops, and points prefill_prefix_slots at it. The prefix arm and production then share one prefill entry point differing only by `start`. 0006 adds QWEN36_PREFIX_PREFILL_TRACE=1 (default off) so the prefix arm warms and captures the chunk trace; trace_mode="all" stays REFUSED deliberately, because `all` also flips the generic enable_trace kwarg on prefill_dispatch, which is a larger change than the evidence supports. TWO THINGS THE ORIGINAL SCOPE MISSED, both found by reading rather than assuming. (1) Resume starts are only ATTENTION-PAGE aligned (64/128), not 2048-aligned: qwen36_prefix_cache.prepare accepts any resume where cp.end == start, and cp.end is an earlier request's prompt length. Without an eager "lead" segment up to the next chunk boundary, a resume at 2112 would replay a chunk at the wrong position. The plan emits that lead and the test covers it. (2) warmup_model_prefill returns immediately when enable_trace=False, so THE DEPLOYED PREFIX ARM WARMS NO PREFILL PROGRAMS AT ALL -- its first prefill compiles them at request time with the decode trace already parked. That is the compile-clobbers-trace hazard, live in the arm today and not introduced by this patch. k_chunk=32, which silently corrupts masked SDPA, is structurally unreachable rather than merely unlikely: the flexible branch hardcodes qk_chunk=128 and the smallest bucket is 128. The test pins both. Fidelity untouched. Offline test: 12 cases plus a working negative control that is asserted to fail on all 8 resume cases against the unpatched logic. It extracts the real functions from the deployed model.py by AST rather than testing a copy, and sets sys.dont_write_bytecode (a __pycache__ in the source tree breaks the deployment scp). Verified independently of the author: applies at -p6 to the materialized prefix source set, passes 12+control patched, exits 1 unpatched. NOTHING HERE HAS RUN ON HARDWARE. Expected 1,493 -> roughly 2,300-2,700 tok/s cold, explicitly NOT parity with production's 3,014, because the 18.0% GDN snapshot/restore marshalling is untouched by this patch and becomes the next bottleneck. Failure signature is named in advance: under ~1,800 tok/s, or a py-spy re-profile whose top leaf is still ttnn/decorators.py:728 -- which would mean the trace was not captured or not replayed, not that the mechanism is wrong. THIS RE-OPENS RESUME EQUIVALENCE. The standing 4/4 is B=1 on the eager loop and does not transfer. It gates everything downstream: a speed win here is worthless without it, and the unaligned-lead path has no equivalence coverage at all. Underrated risks, recorded so they are not rediscovered: the conv-carry restore allocates a device tensor at request time and now does so with a PREFILL trace also parked (most likely hang cause); the lead/tail now use production's _mask_bucket_for instead of the arm's hardcoded 2048, which is a second changed variable in the same A/B; and how often a real scheduler produces an unaligned resume has never been measured. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>profile flips Validation of patches tt-metal 0018 + plugin 0006 on hardware. TWO runs are recorded because the first was a real failure and its cause is worth more than its number. RUN 1 (192959Z) FAILED, and exactly in the shape the patch author predicted: prefill 781 tok/s -- WORSE than the 1,493 baseline -- no QWEN36_PREFIX_PREFILL_TRACE banner, ZERO chunk-replay lines, and the top py-spy leaf was 0018's own eager fallback _prefill_chunked_eager_tp. Cause: scripts/vllm-tt-serve.sh builds its docker -e list explicitly and never forwarded QWEN36_PREFIX_PREFILL_TRACE, so the flag never reached the container and prefill_traced_chunked fell through to its untraced path. The patch was never switched on. The serve script now forwards it, with the incident in a comment so the next person does not read an unswitched patch as an inert one. That failure leaves a REAL DEFECT ON RECORD: 0018's untraced fallback measured 781 tok/s against the 1,493 of the eager loop it replaces. If trace capture ever fails in production the arm is twice as slow as before the patch. That is not addressed here and must be before this ships. RUN 2 (193539Z), flag wired, 8,364-token cold prefill: production prefix before prefix traced ttnn dispatch 18.9% 61.8% 21.0% host tensor marshalling 6.5% 18.0% 16.2% blocked in native call 73.9% 18.1% 61.9% cold prefill 3,014 tok/s 1,493 tok/s 1,972 tok/s The banner engaged, FOUR chunk-replay lines appeared for a four-full-chunk prompt -- exactly what prefill_chunk_plan predicts -- and the top leaf flipped from ttnn/decorators.py:728 to _prefill_traced_chunked_tp, i.e. ttnn.synchronize_device. The mechanism is confirmed: dispatch fell to production's level and the arm became device-bound. +32.1%, which is BELOW the predicted 2,300-2,700 band and above the 1,800 failure threshold. Do not round this up. The prediction assumed replacing dispatch with device wait would convert at roughly its share of wall; it converted less. WHAT THE NUMBER NOW SAYS THAT IT DID NOT BEFORE. Dispatch is no longer the difference: 21.0% against production's 18.9%. Yet the arm is 1,972 against 3,014. So the remaining 35% gap is DEVICE time plus the untouched 16.2% marshalling, and whatever makes the prefix arm's device work slower than production's at the same shape is a NEW question this patch does not answer. The GDN snapshot/restore round trip was predicted to survive and did. n=1 per arm; separate boots; different corpus slices, so same-shape not same-prompt. The direction and the bucket flip are far outside that noise; the 32.1% is not. RESUME EQUIVALENCE IS NOT YET RUN and gates everything here. A 32% cold-prefill win on a resume path that returns different tokens is worth nothing. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>Three hardware attempts, three overflows of the per-RISC DRAM marker ring, and the axis I chose was wrong. Recorded so nobody pays for it again. PROGRAM_SUPPORT markers/RISC outcome 6000 72,000 overflow 0.8 s into the prefill, EngineCore dies 36000 431,912 overflow, sooner in wall terms 36000 + SUM 576,000 overflow One 64-layer 2048-token chunk emits more than 576,000 markers per RISC across the full Blackhole grid, so there is no plausible ring size for per-chunk TIMELINE capture, and TT_METAL_PROFILER_SUM did not collapse the volume as hoped. The per-chunk host drain is already the finest cadence available -- the ring fills INSIDE one chunk -- and TT_METAL_PROFILER_MID_RUN_DUMP was on for all three. TWO THINGS I HAD WRONG. An undersized ring was documented here as something that "STALLS rather than wrapping, so an undersized ring silently truncates". It does neither: the EngineCore exits with no Python traceback and the request takes an HTTP 500, i.e. it kills the arm. And PROGRAM_SUPPORT=6000 was not conservative -- at ~12 markers per program it is roughly ONE chunk, so there was never headroom. The arm's own failure text is misleading in the direction of blaming the code under test ("the prefill hook never fired ... QWEN36_PROFILER_PREFILL_CHUNKS was unset, the derived model.py was not mounted"). The hook was live and emitting the markers that overflowed; that message keys off a drain count a crash makes unreachable. Also fixed here, from attempt one: prefill-one-shot.sh hardcoded the model id "qwen3.8-27b-tt" and the path /tokenize. The profile server advertises itself as Qwen/Qwen3.8-27B-FP8, so sizing 404'd; under `set -uo pipefail` with no -e that wrote an EMPTY prompt, sent an empty completion, took a 400, and let both arms finish reporting only "the prefill hook never fired". It now discovers the id from /v1/models, probes /tokenize and /v1/tokenize, FAILS CLOSED rather than guessing a chars/token ratio, and uses the discovered id for the completion too. awk replaces bc, which is not installed on cfx-llm2. With that fixed the gate_sha control arm passes: 126,227 tokens in 52.1 s = 2,423 tok/s, against 2,366 held at 128k. NOT a reason to reopen op-count work, and not evidence about any op. The open question -- which op owns the 3.16 ms/chunk-index (25.4%) of the growing term that chunked SDPA does not accountation for -- is untouched. The approach that has actually produced an attribution is the standalone-op ladder (bench/probes/chunked_sdpa_position_scaling.py, 74.6% to chunked SDPA, linear fit, max residual 0.047 ms), which needs no profiler and no vLLM boot. Note for whoever takes it: paged_fill_cache is the WEAKER next candidate than it looks, because tp.py:722 fills from chunk_page_table, a per-chunk table of 32 blocks that does not grow with position. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>First run of the standardized harness against our own endpoint, and it failed a correctness gate our bespoke benches never had. infbench stage 3 aborts at turn 1/20 of the long-horizon agentic check: "empty across every output channel". Reproduced by hand, directly against vLLM on cfx-llm2:8000, not through Bifrost. STREAMING, tools passed, tool_choice=auto: 2 chunks, 0 content, 0 tool-call deltas. Nothing. NON-STREAMING, identical request: finish_reason=stop, tool_calls=null, 32 completion tokens, and content = <tool_call> <function=lookup_record> <parameter=record_id> R0000 </parameter> </function> </tool_call> The model emits QWEN XML tool-call syntax. Production serves `--tool-call-parser hermes`, which expects JSON inside <tool_call>. The parser never matches, so `tool_calls` is never populated: non-streaming leaks the raw XML into `content`, and streaming returns an empty response. EVERY AGENT CLIENT STREAMS AND PASSES TOOLS. On this endpoint that returns nothing. For a deployment whose stated goal is serving concurrent long-context AGENTS, this is more important than any throughput number measured this week, and every throughput number we hold was taken without tools in the request, so none of them exercised it. NOT established: the correct replacement. The image ships vllm/tool_parsers/qwen3_engine_tool_parser.py (Qwen3EngineToolParser, from Qwen3ParserToolAdapter), but its registered CLI name was not read off the registry -- importing vllm loads the TT platform plugin, which is expensive and noisy -- so confirm against `vllm serve --help` at deploy time, and check whether the chat template needs to match as well. Do not assume a flag swap is sufficient until a streamed tool call comes back parsed. Unrelated to the older gateway-side stage-3 failure (repeated_unit '!!' 96x at turn 6/8, engine=bifrost) in the harness's own bench/runs; that one is still unexplained and went through a path this one did not. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>Verified at all three layers rather than the convenient one: systemd ExecStart, the container's actual argv, and a live request that comes back with get_weather({"city": "Prague"}) parsed and nothing leaking into content. A systemd-level check alone proves the override was read, not that the server behaves. The override is deliberately volatile. The generated ExecStart hardcodes the parser in /nix/store with no env indirection and /etc/systemd/system is read-only here, so it lives in /run and dies on reboot. A copy under /etc would outlive the nixos-llm rebuild and pin a stale container spec, which fails worse and later. PR #34 is the durable fix; until it deploys, a reboot of cfx-llm2 puts production back to returning empty tool calls. Also records the reboot that cleared the pinned-page leak: MemAvailable 3.90 -> 6.73 GB, which unblocks the pass-5 preflight. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>Session update 2026-09-19 — what this branch now carries, and the numbers with it
This PR started as the
qwen3_xmlparser fix and has accumulated the serving-throughput work since. Recording the current measured state so the merge carries its own evidence.Numbers as merged
Landed this session
_slots_prefilled_since_decode): root-caused a rare-then-catastrophic bypass where a slot handed to a new request could be fed the previous occupant's token. 12/12 clean across three boots (p≈0.004). Bound, not zero (≤0.85%/request).QWEN36_SDPA_STREAMING, this commit): our chunked prefill SDPA has always taken the legacy compute kernel, becausesdpa_program_factory.cppgates streaming onreturn !fp32_dest_acc_enandCOMPUTE_HIFI2sets it True. Upstream measures that kernel ~24% slower on Blackhole. Opt-in, self-identifying, unmeasured.decode_onlyrefuted twice: forcing the skipped prefill warmup cuts corruption 27–43/32 → 1/32 but does not fix it. Production runstrace_mode=alland is unaffected.Host RAM (measured, not yet permanent)
hugepagesPerCard4 → 1 reclaims +5.9 GB of 16 (MemAvailable ~3.1 → 9.0 GB serving). UMD maps exactly 1 page/card (tt_cluster.cpp:353-355); the other 6 GiB were reserved and never touched — the direct cause of the boot OOMs that hard-froze this host twice. Applied at runtime only; a reboot reverts it until thenixos-llmchange lands.Known-not-done