From 8b9946c9aa10a90ea2b0d96bf6a8800c81de5c66 Mon Sep 17 00:00:00 2001 From: harish-berri Date: Sat, 9 May 2026 23:10:14 +0000 Subject: [PATCH] feat(prometheus): add new latency metrics for upstream, gateway, and streaming chunks This update introduces several new Prometheus metrics to track latency: - `litellm_upstream_latency_seconds`: Measures total latency for upstream LLM provider calls. - `litellm_gateway_latency_seconds`: Captures total latency for requests through the LiteLLM gateway. - `litellm_gateway_overhead_seconds`: Computes overhead latency as the difference between gateway and upstream latencies. - `litellm_stream_first_chunk_overhead_latency_metric`: Records processing latency for the first streamed chunk. - `litellm_stream_chunk_overhead_latency_metric`: Measures processing latency for subsequent streamed chunks. Additionally, the logging structure has been updated to include the new metrics, ensuring they are recorded accurately during API calls. This enhancement aims to improve observability and performance analysis of the LiteLLM system. --- litellm/integrations/prometheus.py | 219 ++++++++++++++++-- litellm/litellm_core_utils/litellm_logging.py | 2 + .../llm_response_utils/response_metadata.py | 1 + litellm/proxy/proxy_server.py | 76 +++++- litellm/types/integrations/prometheus.py | 42 +++- litellm/types/utils.py | 1 + ...test_prometheus_metric_name_consistency.py | 58 ++++- 7 files changed, 371 insertions(+), 28 deletions(-) diff --git a/litellm/integrations/prometheus.py b/litellm/integrations/prometheus.py index f9b1c666439..ea1d97acd4a 100644 --- a/litellm/integrations/prometheus.py +++ b/litellm/integrations/prometheus.py @@ -124,6 +124,33 @@ class PrometheusLogger(CustomLogger): buckets=self.latency_buckets, ) + self.litellm_upstream_latency_seconds = self._histogram_factory( + "litellm_upstream_latency_seconds", + "Total latency (seconds) spent in upstream LLM provider calls", + labelnames=self.get_labels_for_metric( + "litellm_upstream_latency_seconds" + ), + buckets=self.latency_buckets, + ) + + self.litellm_gateway_latency_seconds = self._histogram_factory( + "litellm_gateway_latency_seconds", + "Total latency (seconds) for a request through the LiteLLM gateway", + labelnames=self.get_labels_for_metric( + "litellm_gateway_latency_seconds" + ), + buckets=self.latency_buckets, + ) + + self.litellm_gateway_overhead_seconds = self._histogram_factory( + "litellm_gateway_overhead_seconds", + "LiteLLM gateway overhead latency (seconds), computed as gateway latency minus upstream LLM latency", + labelnames=self.get_labels_for_metric( + "litellm_gateway_overhead_seconds" + ), + buckets=self.latency_buckets, + ) + self.litellm_llm_api_time_to_first_token_metric = self._histogram_factory( "litellm_llm_api_time_to_first_token_metric", "Time to first token for a models LLM API call", @@ -140,6 +167,24 @@ class PrometheusLogger(CustomLogger): buckets=self.latency_buckets, ) + self.litellm_stream_first_chunk_overhead_latency_metric = self._histogram_factory( + "litellm_stream_first_chunk_overhead_latency_metric", + "LiteLLM proxy processing latency (seconds) for the first streamed chunk before yielding to the client", + labelnames=self.get_labels_for_metric( + "litellm_stream_first_chunk_overhead_latency_metric" + ), + buckets=self.latency_buckets, + ) + + self.litellm_stream_chunk_overhead_latency_metric = self._histogram_factory( + "litellm_stream_chunk_overhead_latency_metric", + "LiteLLM proxy processing latency (seconds) for streamed chunks after the first chunk before yielding to the client", + labelnames=self.get_labels_for_metric( + "litellm_stream_chunk_overhead_latency_metric" + ), + buckets=self.latency_buckets, + ) + # Counter for spend self.litellm_spend_metric = self._counter_factory( "litellm_spend_metric", @@ -1499,7 +1544,27 @@ class PrometheusLogger(CustomLogger): end_time: datetime = kwargs.get("end_time") or datetime.now() start_time: Optional[datetime] = kwargs.get("start_time") api_call_start_time = kwargs.get("api_call_start_time", None) + api_call_end_time = kwargs.get("api_call_end_time", None) completion_start_time = kwargs.get("completion_start_time", None) + standard_logging_payload = kwargs.get("standard_logging_object") or {} + standard_logging_hidden_params = ( + standard_logging_payload.get("hidden_params", {}) + if isinstance(standard_logging_payload, dict) + else {} + ) + llm_api_duration_ms = kwargs.get( + "llm_api_duration_ms", + standard_logging_hidden_params.get("llm_api_duration_ms"), + ) + upstream_duration_seconds = self._safe_duration_seconds( + start_time=api_call_start_time, + end_time=api_call_end_time, + ) + if isinstance(llm_api_duration_ms, (int, float)) and llm_api_duration_ms >= 0: + upstream_duration_seconds = upstream_duration_seconds or ( + llm_api_duration_ms / 1000 + ) + time_to_first_token_seconds = self._safe_duration_seconds( start_time=api_call_start_time, end_time=completion_start_time, @@ -1549,6 +1614,23 @@ class PrometheusLogger(CustomLogger): _labels, ) + if upstream_duration_seconds is not None: + _upstream_labels = prometheus_label_factory( + supported_enum_labels=self.get_labels_for_metric( + metric_name="litellm_upstream_latency_seconds" + ), + enum_values=enum_values, + label_context=label_context, + ) + self.litellm_upstream_latency_seconds.labels(**_upstream_labels).observe( + upstream_duration_seconds + ) + self._track_end_user_metric_series( + self.litellm_upstream_latency_seconds, + "litellm_upstream_latency_seconds", + _upstream_labels, + ) + # total request latency total_time_seconds = self._safe_duration_seconds( start_time=start_time, @@ -1571,6 +1653,58 @@ class PrometheusLogger(CustomLogger): _labels, ) + # Gateway/upstream/overhead metrics must use the same + # sample set. Cache hits and other successes without a provider call + # still belong in litellm_request_total_latency_metric above, but they + # cannot be compared against upstream latency. + if total_time_seconds is not None and upstream_duration_seconds is not None: + _gateway_labels = prometheus_label_factory( + supported_enum_labels=self.get_labels_for_metric( + metric_name="litellm_gateway_latency_seconds" + ), + enum_values=enum_values, + label_context=label_context, + ) + self.litellm_gateway_latency_seconds.labels(**_gateway_labels).observe( + total_time_seconds + ) + self._track_end_user_metric_series( + self.litellm_gateway_latency_seconds, + "litellm_gateway_latency_seconds", + _gateway_labels, + ) + overhead_seconds = max(total_time_seconds - upstream_duration_seconds, 0) + _labels = prometheus_label_factory( + supported_enum_labels=self.get_labels_for_metric( + metric_name="litellm_overhead_latency_metric" + ), + enum_values=enum_values, + label_context=label_context, + ) + self.litellm_overhead_latency_metric.labels(**_labels).observe( + overhead_seconds + ) + self._track_end_user_metric_series( + self.litellm_overhead_latency_metric, + "litellm_overhead_latency_metric", + _labels, + ) + _gateway_overhead_labels = prometheus_label_factory( + supported_enum_labels=self.get_labels_for_metric( + metric_name="litellm_gateway_overhead_seconds" + ), + enum_values=enum_values, + label_context=label_context, + ) + self.litellm_gateway_overhead_seconds.labels( + **_gateway_overhead_labels + ).observe(overhead_seconds) + self._track_end_user_metric_series( + self.litellm_gateway_overhead_seconds, + "litellm_gateway_overhead_seconds", + _gateway_overhead_labels, + ) + # request queue time (time from arrival to processing start) _litellm_params = kwargs.get("litellm_params", {}) or {} queue_time_seconds = (_litellm_params.get("metadata") or {}).get( @@ -1593,6 +1727,75 @@ class PrometheusLogger(CustomLogger): _labels, ) + def record_streaming_chunk_overhead( + self, + *, + user_api_key_dict: Any, + request_data: dict, + duration_seconds: float, + is_first_chunk: bool, + ) -> None: + metric_name: DEFINED_PROMETHEUS_METRICS = ( + "litellm_stream_first_chunk_overhead_latency_metric" + if is_first_chunk + else "litellm_stream_chunk_overhead_latency_metric" + ) + metric = ( + self.litellm_stream_first_chunk_overhead_latency_metric + if is_first_chunk + else self.litellm_stream_chunk_overhead_latency_metric + ) + metadata = request_data.get("metadata") or {} + if not isinstance(metadata, dict): + metadata = {} + litellm_metadata = request_data.get("litellm_metadata") or {} + if not isinstance(litellm_metadata, dict): + litellm_metadata = {} + model_info = ( + litellm_metadata.get("model_info") or metadata.get("model_info") or {} + ) + if not isinstance(model_info, dict): + model_info = {} + + enum_values = UserAPIKeyLabelValues( + end_user=metadata.get("user_api_key_end_user_id"), + hashed_api_key=getattr(user_api_key_dict, "api_key", None) + or metadata.get("user_api_key_hash"), + api_key_alias=getattr(user_api_key_dict, "key_alias", None) + or metadata.get("user_api_key_alias"), + requested_model=request_data.get("_litellm_client_requested_model") + or request_data.get("model"), + model=request_data.get("model"), + litellm_model_name=request_data.get("model"), + team=getattr(user_api_key_dict, "team_id", None) + or metadata.get("user_api_key_team_id"), + team_alias=getattr(user_api_key_dict, "team_alias", None) + or metadata.get("user_api_key_team_alias"), + org_id=getattr(user_api_key_dict, "organization_id", None) + or metadata.get("user_api_key_org_id"), + org_alias=getattr(user_api_key_dict, "organization_alias", None) + or metadata.get("user_api_key_org_alias"), + user=getattr(user_api_key_dict, "user_id", None) + or metadata.get("user_api_key_user_id"), + user_email=getattr(user_api_key_dict, "user_email", None) + or metadata.get("user_api_key_user_email"), + model_id=model_info.get("id") or metadata.get("model_id"), + route=getattr(user_api_key_dict, "request_route", None) + or metadata.get("user_api_key_request_route"), + client_ip=metadata.get("requester_ip_address"), + user_agent=metadata.get("user_agent"), + custom_metadata_labels=get_custom_labels_from_metadata(metadata=metadata), + stream="True" if litellm.prometheus_emit_stream_label else None, + ) + label_context = PrometheusLabelFactoryContext(enum_values) + labels = prometheus_label_factory( + supported_enum_labels=self.get_labels_for_metric(metric_name=metric_name), + enum_values=enum_values, + label_context=label_context, + ) + metric.labels(**labels).observe(duration_seconds) + self._track_end_user_metric_series(metric, metric_name, labels) + async def async_log_failure_event(self, kwargs, response_obj, start_time, end_time): verbose_logger.debug( "prometheus Logging - Enters failure logging function (kwargs keys: %s)", @@ -2256,20 +2459,6 @@ class PrometheusLogger(CustomLogger): "x_ratelimit_remaining_tokens", None ) - if litellm_overhead_time_ms := standard_logging_payload[ - "hidden_params" - ].get("litellm_overhead_time_ms"): - _labels = prometheus_label_factory( - supported_enum_labels=self.get_labels_for_metric( - metric_name="litellm_overhead_latency_metric" - ), - enum_values=enum_values, - label_context=label_context, - ) - self.litellm_overhead_latency_metric.labels(**_labels).observe( - litellm_overhead_time_ms / 1000 - ) # set as seconds - if remaining_requests: """ "model_group", @@ -3699,7 +3888,7 @@ def get_custom_labels_from_metadata(metadata: dict) -> Dict[str, str]: def _get_combined_custom_metadata_from_standard_logging_payload( - standard_logging_payload: Optional[dict], + standard_logging_payload: Optional[Union[dict, StandardLoggingPayload]], ) -> Dict[str, Any]: """ Combine the metadata sources that can supply custom Prometheus labels. diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index a815442c2f9..22bcec16100 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -1219,6 +1219,7 @@ class Logging(LiteLLMLoggingBaseClass): self.model_call_details["original_response"] = original_response self.model_call_details["additional_args"] = additional_args self.model_call_details["log_event_type"] = "post_api_call" + self.model_call_details["api_call_end_time"] = datetime.datetime.now() if self.litellm_request_debug: attr = "warning" @@ -5041,6 +5042,7 @@ class StandardLoggingPayloadSetup: response_cost=None, additional_headers=None, litellm_overhead_time_ms=None, + llm_api_duration_ms=None, batch_models=None, litellm_model_name=None, usage_object=None, diff --git a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py index 06933a6fbcb..5aa7e799ae8 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -104,6 +104,7 @@ class ResponseMetadata: overhead_ms = round(total_response_time_ms - llm_api_duration_ms, 4) self._update_hidden_params( { + "llm_api_duration_ms": round(llm_api_duration_ms, 4), "litellm_overhead_time_ms": overhead_ms, } ) diff --git a/litellm/proxy/proxy_server.py b/litellm/proxy/proxy_server.py index c96d0acb008..841f86389c4 100644 --- a/litellm/proxy/proxy_server.py +++ b/litellm/proxy/proxy_server.py @@ -15,11 +15,13 @@ import threading import time import traceback import warnings +from collections import deque from datetime import datetime, timedelta, timezone from typing import ( TYPE_CHECKING, Any, AsyncGenerator, + Deque, Dict, List, Literal, @@ -6484,6 +6486,57 @@ def _restamp_streaming_chunk_model( return chunk, model_mismatch_logged +def _get_prometheus_logger_for_streaming_metrics() -> Optional[Any]: + for callback in litellm.callbacks: + if hasattr(callback, "record_streaming_chunk_overhead"): + return callback + return None + + +def _record_streaming_chunk_overhead( + *, + prometheus_logger: Optional[Any], + user_api_key_dict: UserAPIKeyAuth, + request_data: dict, + chunk_start_time: float, + is_first_chunk: bool, +) -> None: + if prometheus_logger is None: + return + try: + prometheus_logger.record_streaming_chunk_overhead( + user_api_key_dict=user_api_key_dict, + request_data=request_data, + duration_seconds=time.perf_counter() - chunk_start_time, + is_first_chunk=is_first_chunk, + ) + except Exception as e: + verbose_proxy_logger.debug( + "Failed to record streaming chunk overhead metric: %s", e + ) + + +async def _timestamp_streaming_chunks( + *, response: Any, chunk_start_times: Deque[float] +) -> AsyncGenerator[Any, None]: + async for chunk in response: + chunk_start_times.append(time.perf_counter()) + yield chunk + + +def _get_timestamped_streaming_response( + response: Any, +) -> Tuple[AsyncGenerator[Any, None], Deque[float]]: + chunk_start_times: Deque[float] = deque() + return ( + _timestamp_streaming_chunks( + response=response, + chunk_start_times=chunk_start_times, + ), + chunk_start_times, + ) + + async def async_data_generator( response, user_api_key_dict: UserAPIKeyAuth, request_data: dict ): @@ -6498,11 +6551,21 @@ async def async_data_generator( # Previously "".join(str_so_far_parts) was called every chunk, re-joining # the entire accumulated response. String += is O(n) amortized total. _str_so_far: str = "" + prometheus_logger = _get_prometheus_logger_for_streaming_metrics() + is_first_streaming_chunk = True + timestamped_response, chunk_start_times = _get_timestamped_streaming_response( + response + ) async for chunk in proxy_logging_obj.async_post_call_streaming_iterator_hook( user_api_key_dict=user_api_key_dict, - response=response, + response=timestamped_response, request_data=request_data, ): + chunk_start_time = ( + chunk_start_times.popleft() + if chunk_start_times + else time.perf_counter() + ) ### CALL HOOKS ### - modify outgoing data chunk = await proxy_logging_obj.async_post_call_streaming_hook( user_api_key_dict=user_api_key_dict, @@ -6530,14 +6593,21 @@ async def async_data_generator( try: yield f"data: {chunk}\n\n" + _record_streaming_chunk_overhead( + prometheus_logger=prometheus_logger, + user_api_key_dict=user_api_key_dict, + request_data=request_data, + chunk_start_time=chunk_start_time, + is_first_chunk=is_first_streaming_chunk, + ) + is_first_streaming_chunk = False except Exception as e: yield f"data: {str(e)}\n\n" # Streaming is done, yield the [DONE] chunk if error_message is not None: yield error_message - done_message = "[DONE]" - yield f"data: {done_message}\n\n" + yield "data: [DONE]\n\n" except Exception as e: verbose_proxy_logger.exception( "litellm.proxy.proxy_server.async_data_generator(): Exception occured - {}".format( diff --git a/litellm/types/integrations/prometheus.py b/litellm/types/integrations/prometheus.py index 43a287f29bc..ac109ee6229 100644 --- a/litellm/types/integrations/prometheus.py +++ b/litellm/types/integrations/prometheus.py @@ -189,6 +189,11 @@ DEFINED_PROMETHEUS_METRICS = Literal[ "litellm_llm_api_latency_metric", "litellm_llm_api_time_to_first_token_metric", "litellm_request_total_latency_metric", + "litellm_upstream_latency_seconds", + "litellm_gateway_latency_seconds", + "litellm_gateway_overhead_seconds", + "litellm_stream_first_chunk_overhead_latency_metric", + "litellm_stream_chunk_overhead_latency_metric", "litellm_overhead_latency_metric", "litellm_remaining_requests_metric", "litellm_remaining_tokens_metric", @@ -289,6 +294,10 @@ class PrometheusMetricLabels: UserAPIKeyLabelNames.MODEL_ID.value, ] + litellm_upstream_latency_seconds = litellm_request_total_latency_metric + litellm_gateway_latency_seconds = litellm_request_total_latency_metric + litellm_gateway_overhead_seconds = litellm_request_total_latency_metric + litellm_request_queue_time_seconds = [ UserAPIKeyLabelNames.END_USER.value, UserAPIKeyLabelNames.API_KEY_HASH.value, @@ -301,6 +310,23 @@ class PrometheusMetricLabels: UserAPIKeyLabelNames.MODEL_ID.value, ] + _stream_chunk_overhead_labels = [ + UserAPIKeyLabelNames.v1_LITELLM_MODEL_NAME.value, + UserAPIKeyLabelNames.API_KEY_HASH.value, + UserAPIKeyLabelNames.API_KEY_ALIAS.value, + UserAPIKeyLabelNames.REQUESTED_MODEL.value, + UserAPIKeyLabelNames.TEAM.value, + UserAPIKeyLabelNames.TEAM_ALIAS.value, + UserAPIKeyLabelNames.USER.value, + UserAPIKeyLabelNames.USER_EMAIL.value, + UserAPIKeyLabelNames.ROUTE.value, + UserAPIKeyLabelNames.CLIENT_IP.value, + UserAPIKeyLabelNames.USER_AGENT.value, + UserAPIKeyLabelNames.MODEL_ID.value, + ] + litellm_stream_first_chunk_overhead_latency_metric = _stream_chunk_overhead_labels + litellm_stream_chunk_overhead_latency_metric = _stream_chunk_overhead_labels + # Guardrail metrics - these use custom labels (guardrail_name, status, error_type, hook_type) # which are not part of UserAPIKeyLabelNames litellm_guardrail_latency_seconds: List[str] = [] @@ -351,15 +377,7 @@ class PrometheusMetricLabels: UserAPIKeyLabelNames.TEAM_ALIAS.value, ] - litellm_overhead_latency_metric = [ - UserAPIKeyLabelNames.MODEL_GROUP.value, - UserAPIKeyLabelNames.API_PROVIDER.value, - UserAPIKeyLabelNames.API_BASE.value, - UserAPIKeyLabelNames.v2_LITELLM_MODEL_NAME.value, - UserAPIKeyLabelNames.API_KEY_HASH.value, - UserAPIKeyLabelNames.API_KEY_ALIAS.value, - UserAPIKeyLabelNames.MODEL_ID.value, - ] + litellm_overhead_latency_metric = litellm_request_total_latency_metric litellm_remaining_requests_metric = [ UserAPIKeyLabelNames.MODEL_GROUP.value, @@ -652,6 +670,12 @@ class PrometheusMetricLabels: "litellm_llm_api_latency_metric", "litellm_llm_api_time_to_first_token_metric", "litellm_request_total_latency_metric", + "litellm_upstream_latency_seconds", + "litellm_gateway_latency_seconds", + "litellm_gateway_overhead_seconds", + "litellm_overhead_latency_metric", + "litellm_stream_first_chunk_overhead_latency_metric", + "litellm_stream_chunk_overhead_latency_metric", "litellm_request_queue_time_seconds", "litellm_proxy_total_requests_metric", "litellm_proxy_failed_requests_metric", diff --git a/litellm/types/utils.py b/litellm/types/utils.py index 00a7748309b..562f42e117e 100644 --- a/litellm/types/utils.py +++ b/litellm/types/utils.py @@ -2662,6 +2662,7 @@ class StandardLoggingHiddenParams(TypedDict): api_base: Optional[str] response_cost: Optional[Union[str, float]] litellm_overhead_time_ms: Optional[float] + llm_api_duration_ms: Optional[float] additional_headers: Optional[StandardLoggingAdditionalHeaders] batch_models: Optional[List[str]] litellm_model_name: Optional[str] # the model name sent to the provider by litellm diff --git a/tests/test_litellm/integrations/test_prometheus_metric_name_consistency.py b/tests/test_litellm/integrations/test_prometheus_metric_name_consistency.py index 0932925d810..8041aec8fda 100644 --- a/tests/test_litellm/integrations/test_prometheus_metric_name_consistency.py +++ b/tests/test_litellm/integrations/test_prometheus_metric_name_consistency.py @@ -81,6 +81,63 @@ def test_prometheus_metric_labels_have_remaining_metrics(): ), "litellm_remaining_tokens_metric should have api_base label" +@pytest.mark.parametrize( + "metric_name", + [ + "litellm_stream_first_chunk_overhead_latency_metric", + "litellm_stream_chunk_overhead_latency_metric", + ], +) +def test_streaming_chunk_overhead_metrics_are_defined(metric_name): + from litellm.types.integrations.prometheus import ( + DEFINED_PROMETHEUS_METRICS, + PrometheusMetricLabels, + ) + + defined_metrics = get_args(DEFINED_PROMETHEUS_METRICS) + assert metric_name in defined_metrics + + labels = PrometheusMetricLabels.get_labels(metric_name) + assert "model" in labels + assert "hashed_api_key" in labels + assert "route" in labels + + +def test_overhead_latency_metric_uses_request_latency_labels(): + from litellm.types.integrations.prometheus import PrometheusMetricLabels + + overhead_labels = PrometheusMetricLabels.get_labels( + "litellm_overhead_latency_metric" + ) + total_latency_labels = PrometheusMetricLabels.get_labels( + "litellm_request_total_latency_metric" + ) + + assert overhead_labels == total_latency_labels + + +@pytest.mark.parametrize( + "metric_name", + [ + "litellm_upstream_latency_seconds", + "litellm_gateway_latency_seconds", + "litellm_gateway_overhead_seconds", + ], +) +def test_bifrost_style_latency_metrics_are_defined(metric_name): + from litellm.types.integrations.prometheus import ( + DEFINED_PROMETHEUS_METRICS, + PrometheusMetricLabels, + ) + + defined_metrics = get_args(DEFINED_PROMETHEUS_METRICS) + assert metric_name in defined_metrics + + assert PrometheusMetricLabels.get_labels( + metric_name + ) == PrometheusMetricLabels.get_labels("litellm_request_total_latency_metric") + + def test_all_defined_metrics_have_consistent_naming(): """ Test that all metrics defined in DEFINED_PROMETHEUS_METRICS follow @@ -104,4 +161,3 @@ if __name__ == "__main__": test_remaining_tokens_metric_name_in_defined_metrics() test_prometheus_metric_labels_have_remaining_metrics() test_all_defined_metrics_have_consistent_naming() - print("All prometheus metric name consistency tests passed!")