[Rust Frontend] Add per-request timing metrics to chat and completions (#59314)

Signed-off-by: wxin <wxin@nvidia.com>
Signed-off-by: Bugen Zhao <i@bugenzhao.com>
Co-authored-by: Bugen Zhao <i@bugenzhao.com>
Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
xinnywinne
2026-10-12 15:39:10 -07:00
committed by GitHub
co-authored by Bugen Zhao Claude Opus 5.5
parent 802feb6770
commit 1bc6e072b0
28 changed files with 517 additions and 25 deletions
+7
View File
@@ -56,6 +56,8 @@ pub struct ApiServerOptions {
pub enable_log_requests: bool,
/// When `true`, include prompt token cache details in response usage.
pub enable_prompt_tokens_details: bool,
/// Include request timing metrics in OpenAI chat and completion responses.
pub enable_per_request_metrics: bool,
/// When `true`, set `X-Request-Id` on every HTTP response.
pub enable_request_id_headers: bool,
/// When `true`, register the scale-out `/inference/v1/generate` route.
@@ -296,6 +298,11 @@ impl Config {
/// Validate frontend configuration that can be checked before engine
/// startup.
pub fn validate(&self) -> Result<()> {
if self.api_server_options.enable_per_request_metrics && self.disable_log_stats {
bail!(
"--enable-per-request-metrics requires engine statistics logging; remove --disable-log-stats"
);
}
vllm_chat::validate_parser_overrides(&self.tool_call_parser, &self.reasoning_parser)?;
self.cors.validate()?;
if let Some(tls) = &self.tls {
+1
View File
@@ -947,6 +947,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}
}
+1
View File
@@ -259,6 +259,7 @@ impl pb::inference_server::Inference for InferenceServiceImpl {
kv_transfer_params: collected.kv_transfer_params.map(Box::new),
ec_transfer_params: collected.ec_transfer_params.map(Box::new),
sampling_mask: collected.sampling_mask,
timestamps: collected.timestamps,
};
let outputs = convert::to_sequence_output(
@@ -637,6 +637,7 @@ mod tests {
sampling_mask: None,
spec_decode_metrics: None,
weight_versions: None,
timestamps: Default::default(),
}),
Ok(GenerateOutput {
request_id: String::new(),
@@ -654,6 +655,7 @@ mod tests {
sampling_mask: None,
spec_decode_metrics: None,
weight_versions: None,
timestamps: Default::default(),
}),
]);
@@ -741,6 +743,7 @@ mod tests {
sampling_mask: None,
spec_decode_metrics: None,
weight_versions: None,
timestamps: Default::default(),
}
}
@@ -38,6 +38,7 @@ use crate::routes::openai::chat_completions::types::{
use crate::routes::openai::utils::logprobs::{
decoded_logprobs_to_openai_chat, prompt_logprobs_to_maps,
};
use crate::routes::openai::utils::metrics::PerRequestMetrics;
use crate::routes::openai::utils::types::{
ChatLogProbs, FunctionCallDelta, FunctionCallResponse, StreamResponseEnvelope, ToolCall,
ToolCallDelta, Usage,
@@ -128,6 +129,7 @@ async fn collect_chat_completion(
ApiServerOptions {
enable_log_requests,
enable_prompt_tokens_details,
enable_per_request_metrics,
..
}: ApiServerOptions,
ResponseOptions {
@@ -158,6 +160,7 @@ async fn collect_chat_completion(
logprobs,
token_ids,
usage,
timestamps,
finish_reason,
kv_transfer_params,
ec_transfer_params,
@@ -202,6 +205,8 @@ async fn collect_chat_completion(
} else {
None
};
let metrics = enable_per_request_metrics
.then(|| PerRequestMetrics::from_timestamps(timestamps, usage.output_token_count));
let usage = Usage::from_token_usage(usage, enable_prompt_tokens_details);
if enable_log_requests {
@@ -236,6 +241,7 @@ async fn collect_chat_completion(
token_ids: (return_token_ids && include_output_metadata).then_some(token_ids),
}],
usage: Some(usage),
metrics,
system_fingerprint: None,
prompt_logprobs,
prompt_token_ids: return_token_ids.then(|| prompt_token_ids.to_vec()),
@@ -254,6 +260,7 @@ async fn chat_completion_chunk_stream(
ApiServerOptions {
enable_log_requests,
enable_prompt_tokens_details,
enable_per_request_metrics,
..
}: ApiServerOptions,
ResponseOptions {
@@ -428,6 +435,7 @@ async fn chat_completion_chunk_stream(
}
Ok(ChatEvent::Done {
usage: final_usage,
timestamps,
finish_reason,
..
}) => {
@@ -472,9 +480,16 @@ async fn chat_completion_chunk_stream(
}
if include_usage {
let metrics = enable_per_request_metrics.then(|| {
PerRequestMetrics::from_timestamps(
timestamps,
final_usage.output_token_count,
)
});
y.yield_ok(usage_chunk(
&envelope,
Usage::from_token_usage(final_usage, enable_prompt_tokens_details),
metrics,
))
.await;
}
@@ -496,9 +511,11 @@ async fn chat_completion_chunk_stream(
fn usage_chunk(
envelope: &Arc<StreamResponseEnvelope>,
usage: Usage,
metrics: Option<PerRequestMetrics>,
) -> ChatCompletionStreamResponse {
let mut chunk = ChatCompletionStreamResponse::new(envelope);
chunk.usage = Some(usage);
chunk.metrics = metrics.map(Into::into);
chunk
}
@@ -962,6 +979,12 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 1, 1),
timestamps: vllm_llm::RequestTimestamps {
queued_ts: 10.0,
scheduled_ts: 10.2,
first_token_ts: 10.5,
last_token_ts: 11.0,
},
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -975,6 +998,7 @@ mod tests {
1,
ApiServerOptions {
enable_prompt_tokens_details: true,
enable_per_request_metrics: true,
..Default::default()
},
ResponseOptions {
@@ -1006,6 +1030,10 @@ mod tests {
.map(|details| details.cached_tokens),
Some(1)
);
assert!(chunks[..3].iter().all(|chunk| chunk.metrics.is_none()));
let metrics = chunks[3].metrics.as_ref().expect("per-request metrics");
assert!((metrics.time_to_first_token_ms.unwrap() - 300.0).abs() < 1e-9);
assert!((metrics.tokens_per_second.unwrap() - 1.25).abs() < 1e-9);
}
#[tokio::test]
@@ -1041,6 +1069,7 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 1, 0),
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1095,6 +1124,7 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 2, 0),
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1175,6 +1205,7 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 2, 0),
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1307,6 +1338,7 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 4, 0),
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1385,6 +1417,7 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 1, 0),
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1468,6 +1501,7 @@ mod tests {
},
reasoning_tokens: 2,
},
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1539,6 +1573,7 @@ mod tests {
},
reasoning_tokens: 2,
},
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -1593,6 +1628,7 @@ mod tests {
Ok(ChatEvent::Done {
message: Default::default(),
usage: done_usage(1, 1, 0),
timestamps: Default::default(),
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
@@ -13,6 +13,7 @@ use validator::Validate;
use vllm_engine_core_client::protocol::sampling::RepetitionDetectionParams;
use vllm_text::TruncationSide;
use crate::routes::openai::utils::metrics::{PerRequestMetrics, StreamPerRequestMetrics};
use crate::routes::openai::utils::structured_outputs::ResponseFormat;
use crate::routes::openai::utils::types::{
ChatLogProbs, ChatMessage, Normalizable, PromptLogprobs, ReasoningEffort, StreamOptions,
@@ -365,6 +366,7 @@ pub(super) struct ChatCompletionResponse {
pub model: String,
pub choices: Vec<ChatCompletionChoice>,
pub usage: Option<Usage>,
pub metrics: Option<PerRequestMetrics>,
pub system_fingerprint: Option<String>,
pub prompt_logprobs: Option<PromptLogprobs>,
pub prompt_token_ids: Option<Vec<u32>>,
@@ -412,6 +414,7 @@ pub(super) struct ChatCompletionStreamResponse {
pub envelope: Arc<StreamResponseEnvelope>,
pub choices: Vec<ChatCompletionStreamChoice>,
pub usage: Option<Usage>,
pub metrics: Option<StreamPerRequestMetrics>,
pub prompt_token_ids: Option<Vec<u32>>,
}
@@ -422,6 +425,7 @@ impl ChatCompletionStreamResponse {
envelope: Arc::clone(envelope),
choices: Vec::new(),
usage: None,
metrics: None,
prompt_token_ids: None,
}
}
@@ -33,6 +33,7 @@ use super::utils::logprobs::{
collected_logprobs_to_openai, decoded_logprobs_to_openai, decoded_prompt_logprobs_to_openai,
prompt_logprobs_to_maps, text_len,
};
use super::utils::metrics::PerRequestMetrics;
use super::utils::types::{StreamResponseEnvelope, Usage};
use crate::config::ApiServerOptions;
use crate::error::{ApiError, bail_server_error, server_error, text_submit_error};
@@ -140,6 +141,7 @@ async fn collect_completion(
ApiServerOptions {
enable_log_requests,
enable_prompt_tokens_details,
enable_per_request_metrics,
..
}: ApiServerOptions,
ResponseOptions {
@@ -197,6 +199,9 @@ async fn collect_completion(
Some(prompt) => format!("{prompt}{}", collected.text),
};
let finish_reason = completion_finish_reason_to_openai(&finish_reason)?.to_string();
let metrics = enable_per_request_metrics.then(|| {
PerRequestMetrics::from_timestamps(collected.timestamps, collected.usage.output_token_count)
});
let usage = Usage::from_token_usage(collected.usage, enable_prompt_tokens_details);
if enable_log_requests {
@@ -225,6 +230,7 @@ async fn collect_completion(
prompt_token_ids: return_token_ids.then(|| collected.prompt_token_ids.to_vec()),
}],
usage: Some(usage),
metrics,
system_fingerprint: None,
kv_transfer_params: collected.kv_transfer_params,
ec_transfer_params: collected.ec_transfer_params,
@@ -241,6 +247,7 @@ async fn completion_chunk_stream(
ApiServerOptions {
enable_log_requests,
enable_prompt_tokens_details,
enable_per_request_metrics,
..
}: ApiServerOptions,
ResponseOptions {
@@ -356,12 +363,19 @@ async fn completion_chunk_stream(
yield_chunk!(final_chunk);
if include_usage {
let metrics = enable_per_request_metrics.then(|| {
PerRequestMetrics::from_timestamps(
finished.timestamps,
finished.usage.output_token_count,
)
});
y.yield_ok(CompletionSseChunk::Usage(usage_chunk(
&envelope,
Usage::from_token_usage(
finished.usage,
enable_prompt_tokens_details,
),
metrics,
)))
.await;
}
@@ -411,9 +425,16 @@ async fn completion_chunk_stream(
yield_chunk!(final_chunk);
if include_usage {
let metrics = enable_per_request_metrics.then(|| {
PerRequestMetrics::from_timestamps(
finished.timestamps,
finished.usage.output_token_count,
)
});
y.yield_ok(CompletionSseChunk::Usage(usage_chunk(
&envelope,
Usage::from_token_usage(finished.usage, enable_prompt_tokens_details),
metrics,
)))
.await;
}
@@ -509,9 +530,14 @@ fn prompt_only_logprobs_to_openai(
))
}
fn usage_chunk(envelope: &Arc<StreamResponseEnvelope>, usage: Usage) -> CompletionStreamResponse {
fn usage_chunk(
envelope: &Arc<StreamResponseEnvelope>,
usage: Usage,
metrics: Option<PerRequestMetrics>,
) -> CompletionStreamResponse {
let mut chunk = CompletionStreamResponse::new(envelope);
chunk.usage = Some(usage);
chunk.metrics = metrics.map(Into::into);
chunk
}
@@ -578,7 +604,7 @@ mod tests {
use super::{
ApiServerOptions, CompletionSseChunk, CompletionStreamResponse, ResponseOptions,
StreamResponseEnvelope, completion_chunk_stream, final_chunk,
StreamResponseEnvelope, collect_completion, completion_chunk_stream, final_chunk,
};
fn decoded_delta(
@@ -639,6 +665,66 @@ mod tests {
assert!(final_chunk(&stream_envelope(), FinishReason::Error).is_err());
}
#[tokio::test]
async fn collected_completion_includes_metrics_only_when_enabled() {
let make_stream = || {
stream::iter(vec![
Ok(DecodedTextEvent::Start {
prompt_token_ids: vec![1].into(),
prompt_logprobs: None,
}),
Ok(decoded_delta(
"hi",
vec![2],
None,
Some(Finished {
usage: vllm_llm::TokenUsage {
prompt_token_count: 1,
output_token_count: 1,
cached_token_count: 0,
},
finish_reason: FinishReason::stop_eos(),
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: vllm_llm::RequestTimestamps {
queued_ts: 10.0,
scheduled_ts: 10.2,
first_token_ts: 10.5,
last_token_ts: 10.5,
},
}),
)),
])
};
for enabled in [false, true] {
let response = collect_completion(
make_stream(),
"cmpl-1".into(),
"model".into(),
1,
ApiServerOptions {
enable_per_request_metrics: enabled,
..Default::default()
},
ResponseOptions::default(),
)
.await
.expect("completion response");
let json = serde_json::to_value(response).expect("serializable response");
if enabled {
assert!(
(json["metrics"]["time_to_first_token_ms"].as_f64().unwrap() - 300.0).abs()
< 1e-9
);
assert_eq!(json["metrics"]["mean_itl_ms"], serde_json::Value::Null);
} else {
assert_eq!(json["metrics"], serde_json::Value::Null);
}
}
}
#[tokio::test]
async fn completion_chunk_stream_maps_streaming_logprobs() {
let stream = stream::iter(vec![
@@ -702,6 +788,12 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: vllm_llm::RequestTimestamps {
queued_ts: 10.0,
scheduled_ts: 10.2,
first_token_ts: 10.5,
last_token_ts: 11.0,
},
}),
)),
]);
@@ -713,6 +805,7 @@ mod tests {
1,
ApiServerOptions {
enable_prompt_tokens_details: true,
enable_per_request_metrics: true,
..Default::default()
},
ResponseOptions {
@@ -779,6 +872,10 @@ mod tests {
match &chunks[3] {
CompletionSseChunk::Usage(chunk) => {
assert!(chunks[..3].iter().all(|chunk| chunk_response(chunk).metrics.is_none()));
let metrics = chunk.metrics.as_ref().expect("per-request metrics");
assert!((metrics.queue_time_ms.unwrap() - 200.0).abs() < 1e-9);
assert!((metrics.tokens_per_second.unwrap() - 2.5).abs() < 1e-9);
assert_eq!(
chunk
.usage
@@ -815,6 +912,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}),
)),
]);
@@ -879,6 +977,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}),
)),
]);
@@ -932,6 +1031,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}),
)),
]);
@@ -988,6 +1088,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}),
)),
]);
@@ -1061,6 +1162,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}),
)),
]);
@@ -1136,6 +1238,7 @@ mod tests {
kv_transfer_params: None,
ec_transfer_params: None,
sampling_mask: None,
timestamps: Default::default(),
}),
)),
]);
@@ -11,6 +11,7 @@ use validator::Validate;
use vllm_engine_core_client::protocol::sampling::RepetitionDetectionParams;
use vllm_text::{Prompt, TruncationSide};
use crate::routes::openai::utils::metrics::{PerRequestMetrics, StreamPerRequestMetrics};
use crate::routes::openai::utils::types::{
LogProbs, Normalizable, PromptLogprobs, StreamOptions, StreamResponseEnvelope, StringOrArray,
Usage, default_true, deserialize_request_top_k, validate_stop,
@@ -239,6 +240,7 @@ pub(super) struct CompletionResponse {
pub model: String,
pub choices: Vec<CompletionChoice>,
pub usage: Option<Usage>,
pub metrics: Option<PerRequestMetrics>,
pub system_fingerprint: Option<String>,
pub kv_transfer_params: Option<Value>,
pub ec_transfer_params: Option<Value>,
@@ -265,6 +267,7 @@ pub(super) struct CompletionStreamResponse {
pub envelope: Arc<StreamResponseEnvelope>,
pub choices: Vec<CompletionStreamChoice>,
pub usage: Option<Usage>,
pub metrics: Option<StreamPerRequestMetrics>,
}
impl CompletionStreamResponse {
@@ -274,6 +277,7 @@ impl CompletionStreamResponse {
envelope: Arc::clone(envelope),
choices: Vec::new(),
usage: None,
metrics: None,
}
}
}
@@ -0,0 +1,122 @@
// SPDX-License-Identifier: Apache-2.0
// SPDX-FileCopyrightText: Copyright contributors to the vLLM project
use serde::Serialize;
use vllm_llm::RequestTimestamps;
/// Per-request response timing fields matching Python's `PerRequestMetrics`.
#[derive(Debug, Clone, PartialEq, Serialize)]
pub struct PerRequestMetrics {
pub time_to_first_token_ms: Option<f64>,
pub generation_time_ms: Option<f64>,
pub queue_time_ms: Option<f64>,
pub mean_itl_ms: Option<f64>,
pub tokens_per_second: Option<f64>,
}
impl PerRequestMetrics {
pub fn from_timestamps(times: RequestTimestamps, num_generation_tokens: usize) -> Self {
let duration = |end: f64, start: f64| (end > 0.0 && start > 0.0).then_some(end - start);
let decode = duration(times.last_token_ts, times.first_token_ts);
let inference = duration(times.last_token_ts, times.scheduled_ts);
Self {
time_to_first_token_ms: duration(times.first_token_ts, times.scheduled_ts)
.map(|seconds| seconds * 1000.0),
generation_time_ms: decode.map(|seconds| seconds * 1000.0),
queue_time_ms: duration(times.scheduled_ts, times.queued_ts)
.map(|seconds| seconds * 1000.0),
mean_itl_ms: decode
.filter(|_| num_generation_tokens > 1)
.map(|seconds| seconds * 1000.0 / (num_generation_tokens - 1) as f64),
tokens_per_second: inference
.filter(|seconds| *seconds > 0.0)
.map(|seconds| num_generation_tokens as f64 / seconds),
}
}
}
/// Streaming form of [`PerRequestMetrics`].
///
/// Python serializes the final usage chunk with recursive `exclude_none=True`,
/// so unset fields are omitted instead of serialized as `null`.
#[serde_with::skip_serializing_none]
#[derive(Debug, Clone, PartialEq, Serialize)]
pub struct StreamPerRequestMetrics {
pub time_to_first_token_ms: Option<f64>,
pub generation_time_ms: Option<f64>,
pub queue_time_ms: Option<f64>,
pub mean_itl_ms: Option<f64>,
pub tokens_per_second: Option<f64>,
}
impl From<PerRequestMetrics> for StreamPerRequestMetrics {
fn from(metrics: PerRequestMetrics) -> Self {
let PerRequestMetrics {
time_to_first_token_ms,
generation_time_ms,
queue_time_ms,
mean_itl_ms,
tokens_per_second,
} = metrics;
Self {
time_to_first_token_ms,
generation_time_ms,
queue_time_ms,
mean_itl_ms,
tokens_per_second,
}
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn matches_python_timing_formulas_and_missing_fields() {
let times = RequestTimestamps {
queued_ts: 10.0,
scheduled_ts: 10.2,
first_token_ts: 10.5,
last_token_ts: 11.0,
};
let metrics = PerRequestMetrics::from_timestamps(times, 6);
assert!((metrics.time_to_first_token_ms.unwrap() - 300.0).abs() < 1e-9);
assert_eq!(metrics.generation_time_ms, Some(500.0));
assert!((metrics.queue_time_ms.unwrap() - 200.0).abs() < 1e-9);
assert_eq!(metrics.mean_itl_ms, Some(100.0));
assert!((metrics.tokens_per_second.unwrap() - 7.5).abs() < 1e-9);
let single_token = PerRequestMetrics::from_timestamps(times, 1);
assert_eq!(single_token.mean_itl_ms, None);
let missing = PerRequestMetrics::from_timestamps(RequestTimestamps::default(), 0);
assert_eq!(missing.time_to_first_token_ms, None);
assert_eq!(missing.generation_time_ms, None);
assert_eq!(missing.queue_time_ms, None);
assert_eq!(missing.mean_itl_ms, None);
assert_eq!(missing.tokens_per_second, None);
}
#[test]
fn stream_serialization_omits_unset_fields() {
let metrics = PerRequestMetrics::from_timestamps(
RequestTimestamps {
queued_ts: 10.0,
scheduled_ts: 10.2,
first_token_ts: 10.5,
last_token_ts: 10.5,
},
1,
);
let value = serde_json::to_value(StreamPerRequestMetrics::from(metrics)).unwrap();
let metrics = value.as_object().unwrap();
assert_eq!(metrics.len(), 4);
assert!(metrics.contains_key("time_to_first_token_ms"));
assert!(metrics.contains_key("generation_time_ms"));
assert!(metrics.contains_key("queue_time_ms"));
assert!(metrics.contains_key("tokens_per_second"));
assert!(!metrics.contains_key("mean_itl_ms"));
}
}
@@ -2,6 +2,7 @@
// SPDX-FileCopyrightText: Copyright contributors to the vLLM project
pub mod logprobs;
pub mod metrics;
pub mod structured_outputs;
pub mod types;
pub mod usage;