[V1][Metrics] Add e2e_latency histogram

Signed-off-by: Mark McLoughlin <markmc@redhat.com>

Author: markmc

tests/entrypoints/openai/test_metrics.py

@@ -218,6 +218,9 @@ async def test_metrics_counts(server: RemoteOpenAIServer,
     "vllm:time_per_output_token_seconds_sum",
     "vllm:time_per_output_token_seconds_bucket",
     "vllm:time_per_output_token_seconds_count",
+    "vllm:e2e_request_latency_seconds_sum",
+    "vllm:e2e_request_latency_seconds_bucket",
+    "vllm:e2e_request_latency_seconds_count",
 ]
 
 

vllm/v1/engine/output_processor.py

@@ -40,7 +40,8 @@ def __init__(
         self.is_prefilling = True
         self.queue = queue
 
-        self.stats = RequestStateStats(last_token_time=arrival_time)
+        self.stats = RequestStateStats(arrival_time=arrival_time,
+                                       last_token_time=arrival_time)
 
     @classmethod
     def from_new_request(

vllm/v1/metrics/loggers.py

@@ -162,6 +162,17 @@ def __init__(self, model_config: ModelConfig):
                 ],
                 labelnames=labelnames).labels(*labelvalues)
 
+        request_latency_buckets = [
+            0.3, 0.5, 0.8, 1.0, 1.5, 2.0, 2.5, 5.0, 10.0, 15.0, 20.0, 30.0,
+            40.0, 50.0, 60.0
+        ]
+        self.histogram_e2e_time_request = \
+            prometheus_client.Histogram(
+                name="vllm:e2e_request_latency_seconds",
+                documentation="Histogram of e2e request latency in seconds.",
+                buckets=request_latency_buckets,
+                labelnames=labelnames).labels(*labelvalues)
+
     def log(self, scheduler_stats: SchedulerStats,
             iteration_stats: IterationStats):
         """Log to prometheus."""
@@ -176,6 +187,8 @@ def log(self, scheduler_stats: SchedulerStats,
 
         for finished_request in iteration_stats.finished_requests:
             self.counter_request_success[finished_request.finish_reason].inc()
+            self.histogram_e2e_time_request.observe(
+                finished_request.e2e_latency)
             self.histogram_num_prompt_tokens_request.observe(
                 finished_request.num_prompt_tokens)
             self.histogram_num_generation_tokens_request.observe(

vllm/v1/metrics/stats.py

@@ -25,6 +25,7 @@ class RequestStateStats:
     """Stats that need to be tracked across delta updates."""
 
     num_generation_tokens: int = 0
+    arrival_time: float = 0.0
     last_token_time: float = 0.0
 
 
@@ -33,6 +34,7 @@ class FinishedRequestStats:
     """Stats associated with a finished request."""
 
     finish_reason: "FinishReason"
+    e2e_latency: float = 0.0
     num_prompt_tokens: int = 0
     num_generation_tokens: int = 0
 
@@ -77,7 +79,10 @@ def update_from_output(self, output: "EngineCoreOutput",
     def update_from_finished_request(self, finish_reason: "FinishReason",
                                      request_output: "RequestOutput",
                                      request_state_stats: RequestStateStats):
+        now = time.time()
+        e2e_latency = now - request_state_stats.arrival_time
+
         self.finished_requests.append(
-            FinishedRequestStats(finish_reason,
+            FinishedRequestStats(finish_reason, e2e_latency,
                                  len(request_output.prompt_token_ids),
                                  request_state_stats.num_generation_tokens))