Issues / #1869
#1869 [Bug]: BDONE replaces the request's accumulated decode_ms/generated — every finish=stop request reports a single-step decode time
closed · @sdjger-xiaoniu · 1 comments · View on GitHub
BenchmarksServer & APIMulti-GPUNVIDIA / CUDAModels & quants
Description
### What happened
Requests that end with `finish=stop` report a **single-step** decode time instead of the request's accumulated decode time, so `predicted_ms`/`predicted_per_second` are wrong by ~100-200x. `finish=length` requests are fine, which is why this hides for a while.
Measured on 0.1.41, `qwen3.8-flash-next-iq3_s` (IQ3_S), 2x RTX 2080Ti 22GB, layer split, `--slots 2`, MTP `spec=6`.
The same finished request, two numbers from the engine itself:
```
/metrics history row:
output_tokens 135 | engine_generated 1 | prompt_ms 3794.7 | decode_ms 18.4 | decode_tok_s 54.3
/v1/status last_timings (same request):
predicted_n 135 | predicted_ms 18.4 | predicted_per_second 54.3 <- rate and ms disagree
```
`decode_tok_s` comes out sane by accident: it is computed as `generated / (decode_ms/1000)` = `1 / 0.0184`, i.e. **one token in one inter-token interval**, which happens to be the right order of magnitude for a decode rate. Any client that computes `completion_tokens / predicted_ms` (the llama.cpp convention, and what the `timings` block is for) gets **7,337 tok/s** for a 135-token answer at ~54 tok/s.
`finish=length` rows are consistent (`256 tokens / 7925.5 ms -> 32.3 tok/s`), so the bad value is specific to the stop path: `/metrics` rows for stop-finished requests are `decode_ms` 18.4 / 18.5 / 18.8 / 19.3 / 19.4 / 22.2 / 22.5 / 24.7 ms with `engine_generated` 1, while length-finished ones carry real totals.
### Where it comes from
`serve/server.py`, the streaming loop (around line 1363 in 0.1.41) — the `BDONE` handler replaces the per-request stats instead of accumulating them:
```python
elif line.startswith("BDONE "):
...
self.last = {**self.last, "finish": f[3], "decode_ms": float(f[4]),
"generated": int(f[2]) if f[2].isdigit() else self.last.get("generated")}
```
`serve/test_request_accounting.py` is the contract here — it exercises thinking-budget continuations and asserts the totals are **summed** (`assertEqual((row["prompt_ms"], row["decode_ms"]), (47.0, 280.0))`, i.e. 40+7 / 200+80). The BDONE path overwrites, so a continuation's last segment wins over the request's totals.
### Suggested fix / workaround
A segment must never shrink the request's totals — accumulate, or keep whichever value is larger:
```python
self.last = {**self.last, "finish": f[3],
"decode_ms": max(float(f[4]), float(self.last.get("decode_ms") or 0.0)),
"generated": max(int(f[2]), int(self.last.get("generated") or 0)) if f[2].isdigit()
else self.last.get("generated")}
```
We have been running exactly this as a local patch since 0.1.41 (with `serve.test_request_accounting` + `serve.test_server` + `serve.test_prometheus` green, 284 tests) and `/v1/status` then reports `predicted_ms 714.0 / predicted_per_second 42.0` for a 30-token stop turn — consistent with the ~54 tok/s the engine is actually doing.
### Strata version, GPU, OS
0.1.41 · 2x RTX 2080Ti 22GB (layer split, `--slots 2`, spec=6) · Ubuntu 26.04, driver 595.91.07
Related on strata.com
Editorial links to help you install, pick models, or read release notes — not part of the upstream thread.