Metrics: Reading a Running Server

The idea in one minute#

vLLM publishes about forty metrics at /metrics. They are not forty independent facts. Every one is produced at a specific point on the request path you have already read, and once you know which point, the numbers explain each other. Latency histograms say what users experience. Gauges and counters about the queue, the cache and preemptions say why. This lesson maps each metric to the line of code that produces it and gives a short diagnostic procedure: five questions, in order, that locate almost any performance problem.

A picture#

flowchart LR
  A[":i-clock: arrival"] -->|"queue time"| S[":i-list-checks: first scheduled"]
  S -->|"prefill time"| F[":i-zap: first token"]
  F -->|"decode time"| L[":i-check: last token"]
  A -.->|"time to first token (TTFT)"| F
  A -.->|"end-to-end latency"| L
  S -.->|"inference time"| L
  Q[":i-gauge: num_requests_waiting"] -.-> S
  K[":i-layers: kv_cache_usage_perc<br/>num_preemptions"] -.-> S
  P[":i-search: prefix_cache_hits / queries"] -.-> F
  class A,S,F,L neutral
  class Q,K,P queue

How it really works#

Where metrics are produced#

The engine core never touches Prometheus. It attaches raw facts to its outputs and the API server turns them into metrics, inside the output handler loop (AsyncLLM and the Way Back):

• Each EngineCoreOutput carries events: QUEUED, SCHEDULED and PREEMPTED, each with a timestamp from the engine core’s monotonic clock.
• Each EngineCoreOutputs carries scheduler_stats: running and waiting counts, KV cache usage, prefix-cache counters.
• IterationStats accumulates per-step token counts in the API server.

Two things follow. Timestamps taken in the engine core are only ever subtracted from each other, never compared with the API server’s clock. And with several API server processes, each one sees only its own requests; the /metrics endpoint aggregates across them.

The intervals#

From vllm/v1/metrics/stats.py:

queued_time    = req_stats.scheduled_ts   - req_stats.queued_ts
prefill_time   = req_stats.first_token_ts - req_stats.scheduled_ts
decode_time    = req_stats.last_token_ts  - req_stats.first_token_ts
inference_time = req_stats.last_token_ts  - req_stats.scheduled_ts

scheduled_ts is the first time the request was scheduled; the source ignores later SCHEDULED events caused by preemption. A preempted request’s recomputation therefore shows up inside its prefill or decode time, not as queue time.

Two of these are easily confused. Inter-token latency records one sample per streamed output, and time per output token one sample per request. They differ whenever an output carries several tokens — speculative decoding, or --stream-interval above 1 — and they are weighted differently: a long response contributes many samples to the first and one to the second. For a service-level objective on streaming smoothness use the first; for cost per token use the second.

State gauges#

num_requests_waiting_by_reason is the quickest way to tell a saturated server from a misconfigured one. Many requests waiting for capacity means buy GPUs or shed load. Many deferred means look at grammar compilation time, max_loras, or the KV transfer path.

Counters#

Watch the finished_reason label. A rising share of length means answers are being cut off by max_tokens or the context window. A rising share of abort means clients are giving up, usually because of latency.

Request-shape histograms#

vllm:request_prompt_tokens, vllm:request_generation_tokens, vllm:request_params_max_tokens, vllm:request_params_n and vllm:iteration_tokens_total describe your traffic rather than your server. They are what you feed into capacity arithmetic: the p95 of prompt plus generation tokens is the number to divide the KV capacity by (Sizing the Cache).

vllm:request_prefill_kv_computed_tokens is prompt tokens actually computed per request, after cache hits. Its ratio to request_prompt_tokens is your effective cache benefit.

Optional metrics#

• --kv-cache-metrics samples block lifetimes: vllm:kv_block_lifetime_seconds, vllm:kv_block_idle_before_evict_seconds, vllm:kv_block_reuse_gap_seconds. They answer “would a bigger cache help?”: if blocks are evicted seconds after going idle and the gap between reuses is longer than that, hits are being lost.
• Speculative decoding adds the vllm:spec_decode_* family (Speculative Decoding).
• --otlp-traces-endpoint exports an OpenTelemetry span per request with the same intervals as attributes.
• --enable-logging-iteration-details logs each engine step’s composition. Very verbose; for debugging only.

The periodic log line#

Without Prometheus you still get, every few seconds while busy:

Avg prompt throughput: 5120.4 tokens/s, Avg generation throughput: 1843.0 tokens/s,
Running: 42 reqs, Waiting: 7 reqs, Preemptions: 3, GPU KV cache usage: 91.2%,
Prefix cache hit rate: 63.5%

Deferred, KV fetch and Preemptions appear only when non-zero, and the line drops to debug level when the engine is idle. --disable-log-stats turns it off, and with it the per-request metric collection.

A diagnostic procedure#

Ask in this order. Each question either finds the problem or rules out a layer.

1. Is time to first token high because of the queue? Compare request_queue_time_seconds with time_to_first_token_seconds.

• Queue time dominates → the server is saturated or blocked. Go to 2.
• Queue time is small → the time is in prefill or the frontend. Go to 4.

2. Why are requests waiting? Look at num_requests_running against max_num_seqs, and at kv_cache_usage_perc.

• Running equals max_num_seqs, cache usage moderate → the sequence limit binds. Raise --max-num-seqs if step time allows.
• Cache usage near 1.0 → memory binds. Go to 3.
• Neither → head-of-line blocking by a large request, or deferred requests. Check num_requests_waiting_by_reason.

3. Is the cache thrashing? rate(num_preemptions).

• Sustained preemptions → over-admission. Lower --max-num-seqs, add a --watermark, lower --max-model-len, or add cache (Priorities, Preemption and Queues).
• None → the cache is simply full of useful work. You need more capacity.

4. Is prefill slow? request_prefill_time_seconds against prompt length, and the prefix hit rate.

• Hit rate lower than the workload should give → prompt structure (Prefix Caching).
• Prefill time fine but TTFT high → the frontend: tokenising, chat templates, media. Look at the API server’s CPU.

5. Is streaming uneven? The upper percentiles of inter_token_latency_seconds.

• p99 far above p50 → prefill chunks sharing steps with decoders. Lower --max-num-batched-tokens, set --long-prefill-token-threshold, or disaggregate.
• Whole distribution high → batch too large for the GPU, or CPU-bound: check that the engine core has a full core.

For the wider practice of instrumenting inference systems, see Inference Engine Metrics.

Code#

Prometheus histograms are cumulative bucket counts, and quantiles must be estimated from them. This program does what histogram_quantile does, on a sample of real metric text, and derives the three ratios that matter.

package main

import (
	"bufio"
	"fmt"
	"math"
	"sort"
	"strconv"
	"strings"
)

// A scrape of /metrics, shortened. Histogram buckets are cumulative.
const scrape = `
vllm:time_to_first_token_seconds_bucket{le="0.05"} 120
vllm:time_to_first_token_seconds_bucket{le="0.1"} 480
vllm:time_to_first_token_seconds_bucket{le="0.25"} 1630
vllm:time_to_first_token_seconds_bucket{le="0.5"} 2410
vllm:time_to_first_token_seconds_bucket{le="1.0"} 2790
vllm:time_to_first_token_seconds_bucket{le="2.5"} 2950
vllm:time_to_first_token_seconds_bucket{le="5.0"} 2990
vllm:time_to_first_token_seconds_bucket{le="+Inf"} 3000
vllm:request_queue_time_seconds_bucket{le="0.05"} 2100
vllm:request_queue_time_seconds_bucket{le="0.1"} 2350
vllm:request_queue_time_seconds_bucket{le="0.25"} 2600
vllm:request_queue_time_seconds_bucket{le="0.5"} 2780
vllm:request_queue_time_seconds_bucket{le="1.0"} 2900
vllm:request_queue_time_seconds_bucket{le="2.5"} 2970
vllm:request_queue_time_seconds_bucket{le="5.0"} 2995
vllm:request_queue_time_seconds_bucket{le="+Inf"} 3000
vllm:prefix_cache_queries 9200000
vllm:prefix_cache_hits 5840000
vllm:prompt_tokens 9200000
vllm:generation_tokens 1150000
vllm:num_preemptions 14
vllm:num_requests_running 187
vllm:num_requests_waiting 23
vllm:kv_cache_usage_perc 0.94
vllm:request_success{finished_reason="stop"} 2610
vllm:request_success{finished_reason="length"} 330
vllm:request_success{finished_reason="abort"} 60
`

type bucket struct {
	le    float64
	count float64
}

func parse(text string) (hist map[string][]bucket, scalars map[string]float64) {
	hist, scalars = map[string][]bucket{}, map[string]float64{}
	sc := bufio.NewScanner(strings.NewReader(text))
	for sc.Scan() {
		line := strings.TrimSpace(sc.Text())
		if line == "" || strings.HasPrefix(line, "#") {
			continue
		}
		sp := strings.LastIndex(line, " ")
		name, val := line[:sp], line[sp+1:]
		v, _ := strconv.ParseFloat(val, 64)
		if i := strings.Index(name, `_bucket{le="`); i >= 0 {
			leStr := strings.TrimSuffix(name[i+len(`_bucket{le="`):], `"}`)
			le := math.Inf(1)
			if leStr != "+Inf" {
				le, _ = strconv.ParseFloat(leStr, 64)
			}
			hist[name[:i]] = append(hist[name[:i]], bucket{le, v})
		} else {
			scalars[name] = v
		}
	}
	return
}

// quantile estimates q by linear interpolation inside the bucket that contains it.
func quantile(bs []bucket, q float64) float64 {
	sort.Slice(bs, func(i, j int) bool { return bs[i].le < bs[j].le })
	rank := q * bs[len(bs)-1].count
	prevLe, prevCount := 0.0, 0.0
	for _, b := range bs {
		if b.count >= rank {
			if math.IsInf(b.le, 1) {
				return prevLe // beyond the last finite bucket: only a lower bound is known
			}
			return prevLe + (b.le-prevLe)*(rank-prevCount)/(b.count-prevCount)
		}
		prevLe, prevCount = b.le, b.count
	}
	return prevLe
}

func main() {
	hist, s := parse(scrape)

	for _, name := range []string{"vllm:request_queue_time_seconds", "vllm:time_to_first_token_seconds"} {
		fmt.Printf("%-36s p50 %.3f s   p95 %.3f s   p99 %.3f s\n", name,
			quantile(hist[name], 0.50), quantile(hist[name], 0.95), quantile(hist[name], 0.99))
	}

	fmt.Printf("\nprefix cache hit rate      %.1f%% of prompt tokens\n",
		100*s["vllm:prefix_cache_hits"]/s["vllm:prefix_cache_queries"])
	fmt.Printf("prompt : generation ratio  %.1f : 1\n", s["vllm:prompt_tokens"]/s["vllm:generation_tokens"])

	total := 0.0
	for k, v := range s {
		if strings.HasPrefix(k, "vllm:request_success") {
			total += v
		}
	}
	fmt.Printf("finished by length         %.1f%%\n", 100*s[`vllm:request_success{finished_reason="length"}`]/total)
	fmt.Printf("aborted by client          %.1f%%\n", 100*s[`vllm:request_success{finished_reason="abort"}`]/total)

	fmt.Printf("\nrunning %v, waiting %v, KV usage %.0f%%, preemptions %v\n",
		s["vllm:num_requests_running"], s["vllm:num_requests_waiting"],
		100*s["vllm:kv_cache_usage_perc"], s["vllm:num_preemptions"])
	fmt.Println("reading: median queue time is small, but its p95 and p99 are a large share of TTFT's,")
	fmt.Println("KV usage is 94% and there are preemptions: the tail is caused by memory pressure.")
}

Counters in a real scrape are totals since start; in production you take rates over a window rather than dividing totals as this program does. The interpolation is exactly what a dashboard does, and it shows the main weakness of histograms: precision is limited by bucket boundaries, so a p99 that falls in a wide bucket is only an estimate.

Remember this#

• The engine core emits events and stats; the API server converts them to metrics.
• Queue time, prefill time and decode time partition a request’s life; preemption does not reset the first-scheduled timestamp.
• Inter-token latency is per streamed output; time per output token is per request.
• kv_cache_usage_perc counts live requests only; near 1.0 with preemptions means over-admission.
• Prefix-cache counters are in tokens; hit rate is hits over queries.
• num_requests_waiting_by_reason separates “no capacity” from “deferred”.
• Diagnose in order: queue, why waiting, thrashing, prefill, streaming smoothness.

Try it#

1. Change the queue-time buckets so that 95% of requests wait less than 50 ms. Rerun and rewrite the last two lines of the program’s “reading”.
2. Scrape a real server twice, 60 seconds apart, and compute the prefix-cache hit rate for that window from the two pairs of counters.
3. Build one dashboard panel that plots kv_cache_usage_perc and rate(vllm:num_preemptions[5m]) together. At what usage do preemptions begin on your workload?

Check yourself#

1. In which process are Prometheus metrics computed, and what does the engine core contribute?
2. A request is preempted once and resumes. Does its queue time increase?
3. KV cache usage is 30% but the prefix-cache hit rate is high. Is that contradictory?

Sources#

Checked on 5 October 2026 against vLLM v0.30.0 and main at commit 0c16eee.

• Metrics (design)
• Production metrics
• vllm/v1/metrics/loggers.py — every metric definition and the log line
• vllm/v1/metrics/stats.py — the interval arithmetic
• Prometheus and Grafana example