[Bug]: OpenAI-compatible benchmark stops timer before reading response body, inflating TPS

Aperta

#1,028 aperta il 12/9/2026 0 commenti 0 reazioni 0 assegnatari Vedi su GitHub

bug

Lingua principale: Rust
Stelle: 36.3k
Fork: 2.3k
Merge medio: 2g 18h
PR unite (30g): 85

Descrizione

### Bug description

Bug description

llmfit bench produces severely inflated throughput results against an
OpenAI-compatible oMLX endpoint.

On an Apple M4 Pro with 48 GB unified memory running Qwen3.8-27B-4bit via
oMLX 0.6.4, llmfit reports an average of 111.52 tok/s.

An independent request to the same endpoint and model consistently measures
approximately 14.6 tok/s.

Inspection of llmfit-core/src/bench.rs suggests that the OpenAI-compatible
benchmark stops its wall-clock timer after send_json() returns but before
the complete response body is consumed with read_json().

This appears to cause completion tokens from the finished response to be
divided by a duration that excludes most of the actual generation time.

Environment

macOS
Apple M4 Pro
48 GB unified memory
llmfit 1.1.15
oMLX 0.6.4
model: Qwen3.8-27B-4bit
provider: mlx
endpoint: http://127.0.0.1:8000

Steps to reproduce

Start an OpenAI-compatible oMLX server serving Qwen3.8-27B-4bit.

Confirm the model:

curl -fsS http://127.0.0.1:8000/v1/models | python3 -m json.tool

The endpoint returns:

{

  "object": "list",

  "data": [

    {

      "id": "Qwen3.8-27B-4bit",

      "object": "model",

      "owned_by": "omlx",

      "max_model_len": 262144

    }

  ]

}

Run the llmfit benchmark:

llmfit --json bench \

  --provider mlx \

  --url http://127.0.0.1:8000 \

  Qwen3.8-27B-4bit

Observed result:

{

  "result": {

    "model": "Qwen3.8-27B-4bit",

    "provider": "mlx",

    "runs": [

      {

        "output_tokens": 142,

        "prompt_tokens": 64,

        "total_ms": 2002.638,

        "tps": 70.90647436031874,

        "ttft_ms": null

      },

      {

        "output_tokens": 284,

        "prompt_tokens": 70,

        "total_ms": 2002.642625,

        "tps": 141.81262121093621,

        "ttft_ms": null

      },

      {

        "output_tokens": 244,

        "prompt_tokens": 75,

        "total_ms": 2002.781541,

        "tps": 121.83056164886032,

        "ttft_ms": null

      }

    ],

    "summary": {

      "avg_output_tokens": 223.33333333333334,

      "avg_total_ms": 2002.687388666667,

      "avg_tps": 111.5165524067051,

      "avg_ttft_ms": null,

      "max_tps": 141.81262121093621,

      "min_tps": 70.90647436031874,

      "num_runs": 3

    }

  }

}

All three llmfit runs report almost exactly 2.003 seconds despite very
different output-token counts.

Independent control measurement

I sent non-streaming requests directly to the same OpenAI-compatible oMLX
endpoint and measured the complete request/response wall-clock duration.

After one warm-up run, three measured runs with 256 completion tokens were:

Run | Completion tokens | Wall time | Throughput
-- | -- | -- | --
1 | 256 | 17.491 s | 14.64 tok/s
2 | 256 | 17.505 s | 14.62 tok/s
3 | 256 | 17.472 s | 14.65 tok/s

oMLX also returned usage.total_time values of approximately 17.49, 17.50,
and 17.47 seconds, matching the independently measured wall time.

This makes the actual throughput approximately 14.6 tok/s rather than
111.5 tok/s.

Suspected root cause

In the current openai_chat() implementation, the timer appears to stop
before the response body is consumed:

let start = Instant::now();

let resp = ureq::post(url)

    // ...

    .send_json(&body)

    .map_err(|e| format!("{} request failed: {}", url, e))?;

let total_wall = start.elapsed();

let completion: ChatCompletionResponse = resp

    .into_body()

    .read_json()

    .map_err(|e| format!("JSON parse error: {}", e))?;

Later, throughput is calculated using:

let tps = output_tokens as f64 / total_wall.as_secs_f64();

If send_json() returns after response headers are available but before the
full non-streaming body has been received, this would explain the result:

llmfit timing: approximately 2.0 seconds
complete request/response timing: approximately 17.5 seconds
completion token count comes from the completed response
resulting TPS is therefore heavily inflated

Moving the start.elapsed() measurement until after the body has been fully
read appears to be the minimal fix for non-streaming OpenAI-compatible
providers.

Expected behavior

For a non-streaming OpenAI-compatible benchmark, total elapsed time should
cover the entire request through complete response-body consumption.

The measured throughput should therefore be close to the independently
observed approximately 14.6 tok/s for this model/server combination.

Actual behavior

llmfit reports approximately 70-142 tok/s and an average of 111.5 tok/s,
because the recorded elapsed duration is only approximately 2.0 seconds.

Additional impact

A successful llmfit bench stores the result locally and can later be shared
as a community benchmark.

Therefore this bug can potentially:

contaminate local calibration/recommendations;
produce incorrect measured_local results;
lead users to submit invalid community benchmark data through
llmfit bench --share.

I removed this result from my local benchmark store and did not submit it.

Diagnostic report

Paste the complete output of:

llmfit doctor

here.

### Expected behavior

`llmfit bench` should measure the complete non-streaming request, including reading the full generated response body, before calculating throughput.

For this setup, the reported throughput should therefore be close to the independently measured ~14.6 tok/s rather than ~111.5 tok/s.

### Actual behavior

`llmfit bench` reports 70.91, 141.81, and 121.83 tok/s, averaging 111.52 tok/s.

Each run is recorded as taking only about 2.003 seconds, despite the same requests taking about 17.5 seconds when measured through the complete OpenAI-compatible response.

This produces severely inflated throughput values.

### Steps to reproduce

1. Start an OpenAI-compatible oMLX server with `Qwen3.8-27B-4bit` loaded on port `8000`.

2. Verify the model is available:

```bash
curl -fsS http://127.0.0.1:8000/v1/models | python3 -m json.tool
```

3. Run the llmfit benchmark against the MLX provider:

```bash
llmfit --json bench \
--provider mlx \
--url http://127.0.0.1:8000 \
Qwen3.8-27B-4bit
```

4. Observe that llmfit reports three runs of roughly 2.0 seconds each and highly inflated throughput:

```text
70.91 tok/s
141.81 tok/s
121.83 tok/s

average: 111.52 tok/s
```

5. Run a direct non-streaming request against the same endpoint/model and measure the full request/response duration. For example, request 256 completion tokens from:

```text
POST http://127.0.0.1:8000/v1/chat/completions
```

6. After one warm-up run, observe approximately:

```text
Run 1: 256 tokens / 17.491 s = 14.64 tok/s
Run 2: 256 tokens / 17.505 s = 14.62 tok/s
Run 3: 256 tokens / 17.472 s = 14.65 tok/s
```

7. Compare the results. The same model and server produce approximately `14.6 tok/s` when measuring the complete response, while llmfit reports an average of `111.5 tok/s`.

### Diagnostic report (`llmfit doctor`)

```text
# llmfit doctor report

Paste this whole report into a GitHub issue at https://github.com/AlexsJones/llmfit/issues — the raw tool output below is what lets detection bugs become regression tests. It contains hardware model names and driver info only.

- llmfit version: 1.1.15
- OS: macos (aarch64)

## Detected by llmfit

SystemSpecs {
total_ram_gb: 48.0,
available_ram_gb: 26.6988525390625,
total_cpu_cores: 14,
cpu_name: "Apple M4 Pro",
has_gpu: true,
gpu_vram_gb: Some(
48.0,
),
total_gpu_vram_gb: Some(
48.0,
),
gpu_available_gb: Some(
36.0,
),
gpu_name: Some(
"Apple M4 Pro",
),
gpu_count: 1,
unified_memory: true,
backend: Metal,
gpus: [
GpuInfo {
name: "Apple M4 Pro",
vram_gb: Some(
48.0,
),
backend: Metal,
count: 1,
unified_memory: true,
},
],
cluster_mode: false,
cluster_node_count: 0,
}

## nvidia-smi (extended query)