Skip to content
69 changes: 66 additions & 3 deletions docs/features/per_request_metrics.md
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,17 @@ vllm serve meta-llama/Llama-3.1-8B-Instruct --enable-per-request-metrics
When this flag is set, supported API responses include metrics for each
attributable request.

!!! warning "Security: prefix-cache state"
Prefix-cache metrics expose exact per-request cache-hit and eviction state.
In a shared deployment, this can reveal whether another tenant populated a
guessed prefix without relying on timing analysis. Use this flag only in a
trusted single-tenant deployment, or ensure that every request includes an
unpredictable secret `cache_salt` scoped to the intended tenant isolation
boundary. A shared or predictable salt does not provide cross-tenant
isolation. See the
[cache-salting guidance](../usage/security.md#prefix-cache-timing-side-channel-mitigation-cache-salting)
and [CVE-2025-46570](https://github.com/vllm-project/vllm/security/advisories/GHSA-4qjh-9fv9-r85r).

!!! note
At high concurrency, enabling per-request metrics computation may introduce
non-negligible CPU overhead. Benchmark your specific workload to evaluate the
Expand All @@ -41,7 +52,19 @@ When per-request metrics are enabled, the response includes a `metrics` object:
"generation_time_ms": 1240.5,
"queue_time_ms": 12.3,
"mean_itl_ms": 9.1,
"tokens_per_second": 103.2
"tokens_per_second": 103.2,
"prefix_cache": {
"num_computed_tokens": 26,
"num_cached_tokens": 16,
"num_local_cached_tokens": 16,
"num_external_cached_tokens": 0,
"num_cache_creation_tokens": 26,
"num_new_full_blocks": 2,
"num_block_allocations": 3,
"num_block_evictions": 1,
"num_prefill_chunks": 1,
"prefill_time_ms": 85.2
}
}
}
```
Expand All @@ -54,8 +77,48 @@ When per-request metrics are enabled, the response includes a `metrics` object:
| `mean_itl_ms` | Mean inter-token latency (average time between successive output tokens) during the decode phase. `null` for single-token responses. |
| `tokens_per_second` | Overall output token throughput: all generated tokens over the inference interval (scheduling to last output token). Unlike `generation_time_ms`, this includes the prefill phase, so it reflects end-to-end generation speed rather than pure decode speed. |

All fields are `null` if the underlying timing data is not available for that
request.
All timing fields are `null` if the underlying timestamp data is not available
for that request.

The experimental `metrics.prefix_cache` object provides request-attributed
prompt and KV-cache telemetry:

| Field | Description |
| --- | --- |
| `num_computed_tokens` | Logical prompt tokens assigned to local model computation when each input chunk is admitted. Recomputation after preemption is not double-counted. |
| `num_cached_tokens` | Prompt tokens skipped during local computation (`num_local_cached_tokens + num_external_cached_tokens`). |
| `num_local_cached_tokens` | Prompt tokens supplied by the local prefix cache. |
| `num_external_cached_tokens` | Prompt tokens supplied through an external KV transfer. This describes the scheduler source, not whether every transferred block was a cache hit in an upstream deployment. |
| `num_cache_creation_tokens` | Prompt tokens counted as local prefix-cache creation for the request. |
| `num_new_full_blocks` | Physical KV blocks newly inserted or promoted in local prefix-cache hash maps during prefill. |
| `num_block_allocations` | Physical KV blocks allocated during prefill. |
| `num_block_evictions` | Cached physical KV blocks evicted by allocations for this request. This attributes the eviction trigger; it does not claim that the request owned the evicted block. |
| `num_prefill_chunks` | Scheduler iterations that processed at least one prompt token, including recomputation after preemption. |
| `prefill_time_ms` | Time from first scheduling to the first output token, including prefill-time preemptions. It currently has the same measurement boundaries as `time_to_first_token_ms`. |

Block counts are physical counts summed across KV cache groups. Consequently,
one logical token block can contribute more than one physical block on hybrid
models. The response's top-level `id` correlates the telemetry with the request;
the same ID is present on the final streaming chunk.

For streaming-input sessions, prefix-cache telemetry is cumulative across all
admitted input chunks. Each continuation is measured independently inside the
scheduler and then added to the prior chunks. Generated tokens retained as the
next chunk's context are not counted again as prompt input or cache creation;
physical block activity and prefill-chunk counts still include work attributable
to every input chunk. Previously emitted `RequestOutput` snapshots remain
unchanged when a later chunk completes.

These engine-level fields intentionally live under `metrics`, rather than
OpenAI `usage`: block allocation and eviction are implementation details, and
external-transfer and local-cache sources are not billing-token categories.

Offline generation exposes the same engine values as
`RequestOutput.prefill_stats`, alongside `RequestOutput.request_id`. Custom stat
logger plugins receive it as `FinishedRequestStats.prefill_stats`, correlated by
`FinishedRequestStats.request_id`. As documented by the stat-logger interface,
the plugin-side stats classes are not stable APIs and can change between
versions.

!!! note
Timing metrics describe a single generation stream, so they are only
Expand Down
36 changes: 35 additions & 1 deletion tests/entrypoints/openai/chat_completion/test_serving_chat.py
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,7 @@
from vllm.tokenizers.mistral import MistralTokenizer
from vllm.tokenizers.registry import cached_tokenizer_from_config
from vllm.v1.engine.async_llm import AsyncLLM
from vllm.v1.metrics.stats import RequestStateStats
from vllm.v1.metrics.stats import PrefillStats, RequestStateStats

GPT_OSS_MODEL_NAME = "openai/gpt-oss-20b"
GPT_OSS_SPECULATOR_NAME = "RedHatAI/gpt-oss-20b-speculator.eagle3"
Expand All @@ -65,6 +65,18 @@
last_token_ts=3.0,
num_generation_tokens=2,
)
_PREFIX_CACHE_STATS = PrefillStats(
num_prompt_tokens=42,
num_computed_tokens=26,
num_cached_tokens=16,
num_local_cached_tokens=12,
num_external_cached_tokens=4,
num_cache_creation_tokens=24,
num_new_full_blocks=2,
num_block_allocations=3,
num_block_evictions=1,
num_prefill_chunks=2,
)


@pytest.fixture(scope="module")
Expand Down Expand Up @@ -662,6 +674,7 @@ def _make_metrics_request_output(
],
finished=True,
metrics=metrics,
prefill_stats=_PREFIX_CACHE_STATS,
)


Expand Down Expand Up @@ -712,6 +725,21 @@ def test_build_per_request_timing_metrics_valid_timestamps():
assert metrics.mean_itl_ms == pytest.approx(1000.0 / 9, rel=1e-4)
assert metrics.tokens_per_second == pytest.approx(10.0 / 1.5, rel=1e-4)

metrics = build_per_request_timing_metrics(
_PER_REQUEST_STATS,
num_generation_tokens=10,
prefill_stats=_PREFIX_CACHE_STATS,
)
assert metrics.prefix_cache is not None
assert metrics.prefix_cache.num_computed_tokens == 26
assert metrics.prefix_cache.num_local_cached_tokens == 12
assert metrics.prefix_cache.num_external_cached_tokens == 4
assert metrics.prefix_cache.num_new_full_blocks == 2
assert metrics.prefix_cache.num_block_allocations == 3
assert metrics.prefix_cache.num_block_evictions == 1
assert metrics.prefix_cache.num_prefill_chunks == 2
assert metrics.prefix_cache.prefill_time_ms == pytest.approx(500.0)


@pytest.mark.asyncio
async def test_chat_per_request_metrics_follow_server_flag():
Expand Down Expand Up @@ -753,6 +781,9 @@ async def test_chat_per_request_metrics_follow_server_flag():
)
assert enabled_response.metrics is not None
assert enabled_response.metrics.time_to_first_token_ms == pytest.approx(500.0)
assert enabled_response.id == "chatcmpl-test-id"
assert enabled_response.metrics.prefix_cache is not None
assert enabled_response.metrics.prefix_cache.num_cached_tokens == 16


@pytest.mark.asyncio
Expand Down Expand Up @@ -793,6 +824,9 @@ async def test_chat_streaming_metrics_ride_on_usage_chunk():
usage_chunks = [chunk for chunk in chunks if chunk.get("usage")]
assert usage_chunks
assert usage_chunks[-1]["metrics"]["time_to_first_token_ms"] == pytest.approx(500.0)
assert usage_chunks[-1]["id"] == "chatcmpl-test-id"
assert usage_chunks[-1]["metrics"]["prefix_cache"]["num_computed_tokens"] == 26
assert usage_chunks[-1]["metrics"]["prefix_cache"]["num_block_evictions"] == 1


@pytest.mark.asyncio
Expand Down
62 changes: 61 additions & 1 deletion tests/entrypoints/openai/completion/test_completion_error.py
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
# SPDX-License-Identifier: Apache-2.0
# SPDX-FileCopyrightText: Copyright contributors to the vLLM project

import json
from dataclasses import dataclass, field
from typing import Any
from unittest.mock import AsyncMock, MagicMock
Expand All @@ -20,7 +21,11 @@
from vllm.renderers.online_renderer import OnlineRenderer
from vllm.tokenizers.registry import cached_tokenizer_from_config
from vllm.v1.engine.async_llm import AsyncLLM
from vllm.v1.metrics.stats import RequestSpecDecodeMetrics, RequestStateStats
from vllm.v1.metrics.stats import (
PrefillStats,
RequestSpecDecodeMetrics,
RequestStateStats,
)

MODEL_NAME = "openai-community/gpt2"
MODEL_NAME_SHORT = "gpt2"
Expand All @@ -31,6 +36,18 @@
last_token_ts=3.0,
num_generation_tokens=2,
)
_PREFIX_CACHE_STATS = PrefillStats(
num_prompt_tokens=42,
num_computed_tokens=26,
num_cached_tokens=16,
num_local_cached_tokens=12,
num_external_cached_tokens=4,
num_cache_creation_tokens=24,
num_new_full_blocks=2,
num_block_allocations=3,
num_block_evictions=1,
num_prefill_chunks=2,
)
BASE_MODEL_PATHS = [
BaseModelPath(name=MODEL_NAME, model_path=MODEL_NAME),
BaseModelPath(name=MODEL_NAME_SHORT, model_path=MODEL_NAME_SHORT),
Expand Down Expand Up @@ -106,6 +123,8 @@ def _build_minimal_metrics_serving_completion(
) -> OpenAIServingCompletion:
serving = OpenAIServingCompletion.__new__(OpenAIServingCompletion)
serving.enable_prompt_tokens_details = False
serving.enable_force_include_usage = False
serving.return_tokens_as_token_ids = False
serving.system_fingerprint = None
serving.enable_per_request_metrics = enable_per_request_metrics
return serving
Expand All @@ -131,6 +150,7 @@ def _make_metrics_request_output(
],
finished=True,
metrics=metrics,
prefill_stats=_PREFIX_CACHE_STATS,
)


Expand Down Expand Up @@ -173,6 +193,46 @@ def test_completion_per_request_metrics_follow_server_flag():
)
assert enabled_response.metrics is not None
assert enabled_response.metrics.time_to_first_token_ms == pytest.approx(500.0)
assert enabled_response.id == "cmpl-test-id"
assert enabled_response.metrics.prefix_cache is not None
assert enabled_response.metrics.prefix_cache.num_external_cached_tokens == 4


@pytest.mark.asyncio
async def test_completion_streaming_prefix_cache_metrics_ride_on_usage_chunk():
serving = _build_minimal_metrics_serving_completion(enable_per_request_metrics=True)
request = CompletionRequest(
model=MODEL_NAME,
prompt="Test prompt",
max_tokens=10,
stream=True,
stream_options={"include_usage": True},
)

async def result_generator():
yield 0, _make_metrics_request_output()

chunks = []
async for line in serving.completion_stream_generator(
request=request,
engine_inputs=[MagicMock()],
result_generator=result_generator(),
request_id="cmpl-test-id",
created_time=0,
model_name=MODEL_NAME,
num_prompts=1,
tokenizer=None,
request_metadata=RequestResponseMetadata(request_id="cmpl-test-id"),
):
payload = line.removeprefix("data: ").strip()
if payload != "[DONE]":
chunks.append(json.loads(payload))

usage_chunks = [chunk for chunk in chunks if chunk.get("usage")]
assert usage_chunks[-1]["id"] == "cmpl-test-id"
prefix_cache = usage_chunks[-1]["metrics"]["prefix_cache"]
assert prefix_cache["num_cached_tokens"] == 16
assert prefix_cache["num_prefill_chunks"] == 2


def test_completion_per_request_metrics_suppressed_for_multiple_prompts():
Expand Down
56 changes: 56 additions & 0 deletions tests/v1/core/test_prefix_caching.py
Original file line number Diff line number Diff line change
Expand Up @@ -3105,6 +3105,62 @@ def test_prefix_cache_stats_disabled():
assert manager.prefix_cache_stats is None


def test_prefill_block_activity_is_attributed_to_allocating_request():
block_size = 4
manager = make_kv_cache_manager(
make_kv_cache_config(block_size, 4),
max_model_len=8192,
enable_caching=True,
hash_block_size=block_size,
log_stats=True,
)

first = make_request("first", list(range(8)), block_size, sha256)
assert manager.allocate_slots(first, 8) is not None
assert first.prefill_stats is not None
assert first.prefill_stats.num_block_allocations == 2
assert first.prefill_stats.num_block_evictions == 0
assert first.prefill_stats.num_new_full_blocks == 2
manager.free(first)

# Three physical blocks remain after the null block. Allocating all three
# for a different request reuses one uncached block and evicts the two
# cached blocks created by ``first``.
second = make_request("second", list(range(100, 112)), block_size, sha256)
assert manager.allocate_slots(second, 12) is not None
assert second.prefill_stats is not None
assert second.prefill_stats.num_block_allocations == 3
assert second.prefill_stats.num_block_evictions == 2
assert second.prefill_stats.num_new_full_blocks == 3

# Attribution is immutable after the first request's prefill operations.
assert first.prefill_stats.num_block_allocations == 2
assert first.prefill_stats.num_block_evictions == 0


def test_delayed_cache_creation_is_attributed_to_request_prefill():
block_size = 4
manager = make_kv_cache_manager(
make_kv_cache_config(block_size, 4),
max_model_len=8192,
enable_caching=True,
hash_block_size=block_size,
log_stats=True,
)
request = make_request("async-load", list(range(8)), block_size, sha256)

assert manager.allocate_slots(request, 8, delay_cache_blocks=True) is not None
assert request.prefill_stats is not None
assert request.prefill_stats.num_block_allocations == 2
assert request.prefill_stats.num_new_full_blocks == 0

# Async KV paths commit block hashes after the transfer completes, outside
# allocate_slots(). The later cache operation must retain request attribution.
manager.cache_blocks(request, 8)
assert request.prefill_stats.num_new_full_blocks == 2
assert request.prefill_stats.num_block_allocations == 2


def test_maybe_evict_cached_block():
pool = BlockPool(num_gpu_blocks=4, enable_caching=True, hash_block_size=16)
block_hash0 = make_block_hash_with_group_id(BlockHash(b"10"), 1000)
Expand Down
9 changes: 8 additions & 1 deletion tests/v1/core/test_scheduler.py
Original file line number Diff line number Diff line change
Expand Up @@ -1785,6 +1785,8 @@ def test_no_spec_tokens_scheduled_for_prefill_chunks():
output = scheduler.schedule()
assert len(output.scheduled_new_reqs) == 1
assert output.num_scheduled_tokens[req.request_id] == 50
assert req.prefill_stats is not None
assert req.prefill_stats.num_prefill_chunks == 1

# Update from output (no sampled token since still prefilling)
req_to_index = {req.request_id: 0}
Expand Down Expand Up @@ -1816,6 +1818,8 @@ def test_no_spec_tokens_scheduled_for_prefill_chunks():
assert req.request_id not in output.scheduled_spec_decode_tokens, (
"Spec tokens should not be scheduled with prefill chunks"
)
assert req.prefill_stats is not None
assert req.prefill_stats.num_prefill_chunks == 2

# Update from output with a sampled token (prefill complete)
model_runner_output = ModelRunnerOutput(
Expand All @@ -1826,7 +1830,10 @@ def test_no_spec_tokens_scheduled_for_prefill_chunks():
prompt_logprobs_dict={},
pooler_output=[],
)
scheduler.update_from_output(output, model_runner_output)
engine_core_outputs = scheduler.update_from_output(output, model_runner_output)
prefill_stats = engine_core_outputs[0].outputs[0].prefill_stats
assert prefill_stats is not None
assert prefill_stats.num_prefill_chunks == 2

# Now provide draft tokens - should be accepted since prefill is complete
draft_token_ids = DraftTokenIds([req.request_id], [[1, 2, 3]])
Expand Down
Loading
Loading