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 commentaires · Sur 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

Sur le site

Liens install, modèles, releases.