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!")