[V1][Metrics] Add prefill/decode/inference time histograms

Prefill time: first token time - first scheduled time
Decode time: finish time - first token time
Inference time: finish time - first scheduled time

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

Author: markmc

vllm/v1/metrics/loggers.py

@@ -179,6 +179,27 @@ def __init__(self, model_config: ModelConfig):
                 "Histogram of time spent in WAITING phase for request.",
                 buckets=request_latency_buckets,
                 labelnames=labelnames).labels(*labelvalues)
+        self.histogram_inference_time_request = \
+            prometheus_client.Histogram(
+                name="vllm:request_inference_time_seconds",
+                documentation=
+                "Histogram of time spent in RUNNING phase for request.",
+                buckets=request_latency_buckets,
+                labelnames=labelnames).labels(*labelvalues)
+        self.histogram_prefill_time_request = \
+            prometheus_client.Histogram(
+                name="vllm:request_prefill_time_seconds",
+                documentation=
+                "Histogram of time spent in PREFILL phase for request.",
+                buckets=request_latency_buckets,
+                labelnames=labelnames).labels(*labelvalues)
+        self.histogram_decode_time_request = \
+            prometheus_client.Histogram(
+                name="vllm:request_decode_time_seconds",
+                documentation=
+                "Histogram of time spent in DECODE phase for request.",
+                buckets=request_latency_buckets,
+                labelnames=labelnames).labels(*labelvalues)
 
     def log(self, scheduler_stats: SchedulerStats,
             iteration_stats: IterationStats):
@@ -196,6 +217,10 @@ def log(self, scheduler_stats: SchedulerStats,
             self.counter_request_success[finished_request.finish_reason].inc()
             self.histogram_e2e_time_request.observe(
                 finished_request.e2e_latency)
+            self.histogram_inference_time_request.observe(
+                finished_request.inference_time)
+            self.histogram_decode_time_request.observe(
+                finished_request.decode_time)
             self.histogram_num_prompt_tokens_request.observe(
                 finished_request.num_prompt_tokens)
             self.histogram_num_generation_tokens_request.observe(
@@ -207,6 +232,8 @@ def log(self, scheduler_stats: SchedulerStats,
             self.histogram_time_per_output_token.observe(tpot)
         for queue_time in iteration_stats.queue_times_iter:
             self.histogram_queue_time_request.observe(queue_time)
+        for prefill_time in iteration_stats.prefill_times_iter:
+            self.histogram_prefill_time_request.observe(prefill_time)
 
     @staticmethod
     def _unregister_vllm_metrics():

vllm/v1/metrics/stats.py

@@ -29,6 +29,7 @@ class RequestStateStats:
     num_generation_tokens: int = 0
     arrival_time: float = 0.0
     first_scheduled_time: float = 0.0
+    first_token_time: float = 0.0
     last_token_time: float = 0.0
 
 
@@ -40,6 +41,8 @@ class FinishedRequestStats:
     e2e_latency: float = 0.0
     num_prompt_tokens: int = 0
     num_generation_tokens: int = 0
+    inference_time: float = 0.0
+    decode_time: float = 0.0
 
 
 class IterationStats:
@@ -53,6 +56,7 @@ def __init__(self, log_stats: bool):
         self.time_to_first_tokens_iter: List[float] = []
         self.time_per_output_tokens_iter: List[float] = []
         self.queue_times_iter: List[float] = []
+        self.prefill_times_iter: List[float] = []
 
     def update_from_output(self, output: "EngineCoreOutput",
                            is_prefilling: bool, prompt_len: int,
@@ -72,8 +76,12 @@ def update_from_output(self, output: "EngineCoreOutput",
             # iff num_computed_tokens == num_tokens).
             assert (num_new_generation_tokens > 0)
             self.num_prompt_tokens += prompt_len
+            self.first_token_time = now
 
             self.time_to_first_tokens_iter.append(last_token_latency)
+
+            prefill_time = now - request_state_stats.first_scheduled_time
+            self.prefill_times_iter.append(prefill_time)
         else:
             self.time_per_output_tokens_iter.append(last_token_latency)
 
@@ -92,8 +100,14 @@ def update_from_finished_request(self, finish_reason: "FinishReason",
                                      request_state_stats: RequestStateStats):
         now = time.time()
         e2e_latency = now - request_state_stats.arrival_time
-
-        self.finished_requests.append(
-            FinishedRequestStats(finish_reason, e2e_latency,
-                                 len(request_output.prompt_token_ids),
-                                 request_state_stats.num_generation_tokens))
+        inference_time = now - request_state_stats.first_scheduled_time
+        decode_time = now - request_state_stats.first_token_time
+
+        finished_req = \
+            FinishedRequestStats(finish_reason=finish_reason,
+                                 e2e_latency=e2e_latency,
+                                 num_prompt_tokens=len(request_output.prompt_token_ids),
+                                 num_generation_tokens=request_state_stats.num_generation_tokens,
+                                 inference_time=inference_time,
+                                 decode_time=decode_time)
+        self.finished_requests.append(finished_req)