Warmup server histogram observations can leak into profiling metrics

[janbernloehr]

Summary

A late server-side histogram observation from a completed warmup request can be attributed to the profiling phase. As a result, the top-level metrics section of server_metrics_export.json can contain warmup data even though it is documented as containing profiling-period metrics only.

This is easiest to observe with vllm:request_prefill_time_seconds because a server may return a response before the corresponding prefill histogram observation becomes visible at /metrics. If that observation is published after AIPerf's final warmup scrape but before profiling ends, AIPerf subtracts the last warmup snapshot from a profiling snapshot and assigns the late warmup delta to profiling.

The issue is silent. In a benchmark configured for one warmup request and five profiling requests, the export can report:

Metric	Warmup count	Profiling count	Expected split
vllm:request_prefill_time_seconds	0	6	1 / 5
vllm:time_to_first_token_seconds	1	5	1 / 5

The correctly split TTFT histogram shows that AIPerf sent the expected number of requests and that the problem is specific to a metric observation crossing the scrape boundary.

Version

• AIPerf: 0.12.0 (end-to-end reproduction confirmed)
• Current main: source inspected at commit 2f853c4e; the immediate final warmup scrape remains, so the same boundary race appears possible there
• Endpoint type: OpenAI-compatible chat endpoint
• Server metrics format: Prometheus histogram exported as JSON
• Reproduction requirements: Python 3.13, uv, and jq
• GPU: not required

Steps to reproduce

The following standard-library-only mock server exposes an OpenAI-compatible endpoint and two cumulative Prometheus histograms:

• TTFT is published synchronously for every request.
• The first request is AIPerf's warmup request. Its response completes immediately, but its prefill observation is published 1.5 seconds later.
• Each of the five profiling requests takes 0.5 seconds, keeping the profiling phase open when the delayed warmup observation arrives.

This models an inference server that completes a response before an asynchronously updated server histogram becomes visible to a scraper.

Save as /tmp/aiperf_phase_repro_server.py:

#!/usr/bin/env python3
"""OpenAI-compatible test server with deliberately late warmup metrics."""

import json
import threading
import time
from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer


LOCK = threading.Lock()
REQUESTS = 0
TTFT_COUNT = 0
TTFT_SUM = 0.0
PREFILL_COUNT = 0
PREFILL_SUM = 0.0


def add_prefill(value: float) -> None:
    global PREFILL_COUNT, PREFILL_SUM
    with LOCK:
        PREFILL_COUNT += 1
        PREFILL_SUM += value


def histogram(name: str, help_text: str, count: int, total: float) -> str:
    return "\n".join(
        [
            f"# HELP {name} {help_text}",
            f"# TYPE {name} histogram",
            f'{name}_bucket{{le="0.1"}} {count}',
            f'{name}_bucket{{le="+Inf"}} {count}',
            f"{name}_sum {total}",
            f"{name}_count {count}",
        ]
    )


class Handler(BaseHTTPRequestHandler):
    def do_GET(self) -> None:
        if self.path != "/metrics":
            self.send_error(404)
            return

        with LOCK:
            body = "\n".join(
                [
                    histogram(
                        "vllm:time_to_first_token_seconds",
                        "Synthetic TTFT histogram",
                        TTFT_COUNT,
                        TTFT_SUM,
                    ),
                    histogram(
                        "vllm:request_prefill_time_seconds",
                        "Synthetic prefill histogram",
                        PREFILL_COUNT,
                        PREFILL_SUM,
                    ),
                    "",
                ]
            ).encode()

        self.send_response(200)
        self.send_header("Content-Type", "text/plain; version=0.0.4")
        self.send_header("Content-Length", str(len(body)))
        self.end_headers()
        self.wfile.write(body)

    def do_POST(self) -> None:
        global REQUESTS, TTFT_COUNT, TTFT_SUM
        if self.path != "/v1/chat/completions":
            self.send_error(404)
            return

        length = int(self.headers.get("Content-Length", "0"))
        request = json.loads(self.rfile.read(length) or b"{}")

        with LOCK:
            REQUESTS += 1
            ordinal = REQUESTS
            TTFT_COUNT += 1
            TTFT_SUM += 0.01

        if ordinal == 1:
            # The first request is AIPerf's warmup. The response completes now,
            # but the prefill observation is published during profiling.
            timer = threading.Timer(1.5, add_prefill, args=(0.05,))
            timer.daemon = True
            timer.start()
        else:
            # Keep profiling active when the delayed warmup update arrives.
            time.sleep(0.5)
            add_prefill(0.02)

        response = {
            "id": f"chatcmpl-{ordinal}",
            "object": "chat.completion",
            "created": int(time.time()),
            "model": request.get("model", "mock-model"),
            "choices": [
                {
                    "index": 0,
                    "message": {"role": "assistant", "content": "ok"},
                    "finish_reason": "stop",
                }
            ],
            "usage": {
                "prompt_tokens": 8,
                "completion_tokens": 1,
                "total_tokens": 9,
            },
        }
        body = json.dumps(response).encode()
        self.send_response(200)
        self.send_header("Content-Type", "application/json")
        self.send_header("Content-Length", str(len(body)))
        self.end_headers()
        self.wfile.write(body)

    def log_message(self, format: str, *args: object) -> None:
        return


if __name__ == "__main__":
    ThreadingHTTPServer(("127.0.0.1", 8000), Handler).serve_forever()

Start the mock server in one terminal:

python3 /tmp/aiperf_phase_repro_server.py

Run AIPerf in a second terminal:

ARTIFACT_DIR="$(mktemp -d /tmp/aiperf-phase-repro.XXXXXX)"

uvx --python 3.13 --from 'aiperf==0.12.0' aiperf profile \
  --url http://127.0.0.1:8000 \
  --model mock-model \
  --tokenizer builtin \
  --endpoint-type chat \
  --ui none \
  --no-gpu-telemetry \
  --concurrency 1 \
  --synthetic-input-tokens-mean 8 \
  --synthetic-input-tokens-stddev 0 \
  --output-tokens-mean 1 \
  --output-tokens-stddev 0 \
  --request-count 5 \
  --warmup-request-count 1 \
  --artifact-dir "$ARTIFACT_DIR" \
  --server-metrics-formats json

Inspect the phase counts and prefill statistics:

jq '{
  warmup_prefill: .warmup_metrics["vllm:request_prefill_time_seconds"].series[0].stats,
  profiling_prefill: .metrics["vllm:request_prefill_time_seconds"].series[0].stats,
  warmup_ttft: .warmup_metrics["vllm:time_to_first_token_seconds"].series[0].stats,
  profiling_ttft: .metrics["vllm:time_to_first_token_seconds"].series[0].stats
}' "$ARTIFACT_DIR/server_metrics_export.json"

Actual behavior

I ran the reproducer above with aiperf==0.12.0. The relevant output was:

{
  "warmup_prefill": {
    "count": 0
  },
  "profiling_prefill": {
    "count": 6,
    "sum": 0.15,
    "avg": 0.024999999999999998
  },
  "warmup_ttft": {
    "count": 1,
    "sum": 0.01,
    "avg": 0.01
  },
  "profiling_ttft": {
    "count": 5,
    "sum": 0.05,
    "avg": 0.01
  }
}

There are only five profiling requests. Their synthetic prefill values are all 0.02 seconds, so profiling alone should have count=5, sum=0.10, and avg=0.02. The exported profiling values instead include the warmup observation of 0.05 seconds: count=6, sum=0.15, and avg=0.025.

In this small example, one of six exported profiling samples (16.7%) belongs to warmup. The profiling sample count is inflated by 20%, and the average is inflated by 25%.

Expected behavior

The top-level metrics object should contain only observations attributable to profiling requests, consistent with the server metrics documentation.

For this reproducer, the expected split is:

{
  "warmup_prefill_count": 1,
  "profiling_prefill_count": 5,
  "warmup_ttft_count": 1,
  "profiling_ttft_count": 5
}

At minimum, a server observation known to have crossed the warmup/profiling boundary should not silently be included in profiling statistics. Ideally, the warmup phase should remain open long enough to collect the delayed warmup observation so that both phase exports remain complete.

Root cause

In the tested v0.12.0 source, ServerMetricsManager._on_credit_phase_complete captures the final warmup scrape immediately and then retires the warmup phase. There is no server-metrics flush barrier before profiling begins.

Current main still captures the final warmup scrape immediately. Its phase-completion behavior is now additionally asymmetric:

• The warmup completion path has no flush wait or transition barrier.
• The profiling completion path waits for AIPERF_SERVER_METRICS_COLLECTION_FLUSH_PERIOD before its final scrape.

Prometheus histograms are cumulative and do not identify the request that produced an increment. AIPerf therefore determines phase-local values by subtracting cumulative snapshots associated with phase boundaries. The following sequence misattributes the late observation:

1. Baseline prefill count is 0.
2. The warmup response completes, but the server has not published its prefill observation yet.
3. AIPerf immediately captures the final warmup scrape at count 0.
4. Profiling starts.
5. The delayed warmup prefill observation increments the cumulative count to 1.
6. Five profiling requests increment the cumulative count to 6.
7. A profiling scrape observes 6 and subtracts the warmup boundary value of 0.
8. The export reports all six observations as profiling data.

This is a phase-boundary race, not a malformed Prometheus histogram and not a mismatch in the number of client requests.

Impact

Any cumulative server metric that is published after request completion can cross the boundary. For affected histogram series, all statistics derived from the phase delta may be wrong:

• count
• sum and avg
• bucket deltas
• percentile estimates
• count_rate and sum_rate

The magnitude depends on the number and distribution of late observations. A single late warmup sample is especially significant in short profiling runs, but multiple warmup requests or delayed metric publication can produce larger contamination.

AIPerf's client-side latency, throughput, and request-count metrics are not affected by this reproducer. Server histograms that are visible before the final warmup scrape are also split correctly, as shown by the TTFT control. The issue is specifically that the exported profiling server metrics are not guaranteed to be phase-pure.

Downstream consumers cannot generally repair the percentile distribution after export. They may detect a count mismatch for metrics that emit exactly one observation per request, but they cannot reliably identify or subtract the warmup observation from aggregated buckets and sums.

Suggested direction

Introduce a server-metrics phase-transition barrier so that profiling cannot begin until the warmup metrics boundary has been flushed and acknowledged. One possible implementation is:

1. When warmup credits complete, wait for a configurable flush period before the final warmup scrape. Reusing AIPERF_SERVER_METRICS_COLLECTION_FLUSH_PERIOD would make the warmup and profiling completion paths consistent, although separate warmup/profile settings may provide more control.
2. Capture the final warmup scrape while the scrape is still tagged as warmup.
3. Establish the profiling baseline from that flushed boundary.
4. Only then allow profiling requests to start.

The ordering is important. Sleeping in the server-metrics component without coordinating the request phase transition would still allow profiling observations to enter the delayed boundary scrape.

It may also be useful to record explicit boundary metadata in the export, such as the last cumulative snapshot for each phase and whether a flush/barrier completed, so consumers can diagnose uncertain boundaries.

Proposed regression test

A deterministic test does not need a real inference server or GPU. It can use a controlled Prometheus endpoint or injected scrape snapshots with this timeline:

Event	Cumulative prefill count	Active phase
Initial baseline	0	none
Warmup response completes	0	warmup
Final warmup scrape	0	warmup
Delayed warmup metric update	1	transition/profiling
Five profiling updates	6	profiling
Final profiling scrape	6	profiling

The assertion should be that the exported profiling delta is 5, never 6. If the intended fix flushes warmup observations, the warmup delta should additionally be 1.

The mock server in the reproduction section can also serve as an end-to-end regression test. A useful negative control is to make profiling finish before the 1.5-second delayed update; in that case AIPerf 0.12.0 exports the correct profiling count of 5. Lengthening profiling so the update lands inside the phase reproduces the incorrect count of 6.

Workaround

Until the phase transition is coordinated, the safest workaround is to run warmup separately, wait for server metrics to settle, and then run the measured AIPerf profile without --warmup-request-count. This lets the measured invocation establish its baseline after warmup metrics have been published.

For existing results, compare request-scoped server histogram counts with the configured profiling request count. Treat a mismatch as phase contamination rather than silently using the derived averages or percentiles. This validation is only a detector; it cannot recover the correct distribution from already aggregated data.

Related work

• #1096 added warmup-phase server-metrics export and the final warmup scrape.
• #1325 added a flush period before the final profiling scrape.
• #956 explored phase-baseline coordination but was closed without merge.

I did not find an existing issue or pull request that reports this specific late-warmup-observation leak into profiling metrics.

[dundysm]

taking this; will add a warmup flush barrier so late histogram observations cannot land in the profiling scrape window, plus a regression test. will open a pr shortly.

[dundysm]

follow-up shipped on #1436 (b0b9351): drain in-flight warmup scrapes + boundary ready ack before profiling. @janbernloehr's delayed-scrape reproducer now reports 1/5 with combined count 6.

[ajcasagrande]

Audit result: STILL PRESENT on main @ 62510dc2b (2026-09-28)
Fix in flight: ✅ PR #1436 — closes this when merged

The warmup completion path captures the final warmup scrape immediately with no flush wait (src/aiperf/server_metrics/manager.py:605-612), while only the profiling path waits COLLECTION_FLUSH_PERIOD before its final scrape (manager.py:691-699). Since phase-local histogram stats are cumulative-snapshot deltas and the phase-complete publish is fire-and-forget (no metrics ack), a late warmup observation still lands in the profiling delta. No fix is merged — note that the fix commit referenced in the thread does not exist in the repository (git cat-file -t b0b9351 → not a valid object). Open PR #1436 ("flush barrier at warmup/profiling boundary") addresses this boundary directly and would resolve the issue when merged.

— automated source audit on behalf of @ajcasagrande