fix(prometheus): fold auth/pre-call time into litellm_request_total_latency_metric (#37958)

litellm_request_total_latency_metric's start_time is set inside
common_processing_pre_call_logic, which only runs after user_api_key_auth
has already succeeded, so the metric silently excluded authentication and
pre-call setup time despite being documented as total request latency. The
sibling litellm_request_queue_time_seconds metric had the same problem:
its arrival_time was captured after auth too, despite its own comment
claiming to track when the request arrived at the proxy.

request.state.litellm_received_at is now stamped unconditionally at the
very first line of user_api_key_auth (previously only when OTEL was
configured), giving a timestamp that precedes all auth work. Both metrics
now derive from it: queue_time_seconds genuinely spans arrival through the
start of pre-call processing, and the total-latency metric adds that
queue time on top of its existing start/end window so it becomes true
end-to-end latency.

queue_time_seconds ends exactly at start_time rather than a separately
captured timestamp, so its window and the total-latency window share a
boundary instead of overlapping and double-counting a few lines of setup
work on every request.

litellm/integrations/prometheus.py

@@ -215,7 +215,9 @@ class PrometheusLogger(CustomLogger):
             # request latency metrics
             self.litellm_request_total_latency_metric = self._histogram_factory(
                 "litellm_request_total_latency_metric",
-                "Total latency (seconds) for a request to LiteLLM",
+                "End-to-end latency (seconds) for a request to LiteLLM Proxy Server, from the moment "
+                "the request reached the proxy through the end of processing -- includes "
+                "authentication, pre-call hooks, the LLM API call, and post-call processing",
                 labelnames=self.get_labels_for_metric("litellm_request_total_latency_metric"),
                 buckets=self.latency_buckets,
             )
@@ -458,7 +460,8 @@ class PrometheusLogger(CustomLogger):
             # Request queue time metric
             self.litellm_request_queue_time_metric = self._histogram_factory(
                 "litellm_request_queue_time_seconds",
-                "Time spent in request queue before processing starts (seconds)",
+                "Time (seconds) from request arrival at the proxy to the start of pre-call "
+                "processing -- includes authentication and any ASGI-level queueing",
                 labelnames=self.get_labels_for_metric("litellm_request_queue_time_seconds"),
                 buckets=self.latency_buckets,
             )
@@ -2078,27 +2081,37 @@ class PrometheusLogger(CustomLogger):
                 _labels,
             )
 
-        # total request latency
+        # request queue time (time from arrival to processing start) -- read first so
+        # it can be folded into the total-latency metric below. start_time/end_time
+        # only span from after auth completes, so without this the "total" latency
+        # metric silently excludes auth and pre-call hook time.
+        _litellm_params: Final = kwargs.get("litellm_params", {}) or {}
+        queue_time_seconds: Final = (_litellm_params.get("metadata") or {}).get("queue_time_seconds")
+
+        # total request latency: true end-to-end, from request arrival (queue_time_seconds,
+        # when available) through the end of processing.
         total_time_seconds: Final = self._safe_duration_seconds(
             start_time=start_time,
             end_time=end_time,
         )
         if total_time_seconds is not None:
+            _observed_total_time_seconds: Final = (
+                total_time_seconds + queue_time_seconds
+                if queue_time_seconds is not None and queue_time_seconds >= 0
+                else total_time_seconds
+            )
             _labels = prometheus_label_factory(
                 supported_enum_labels=self.get_labels_for_metric(metric_name="litellm_request_total_latency_metric"),
                 enum_values=enum_values,
                 label_context=label_context,
             )
-            self.litellm_request_total_latency_metric.labels(**_labels).observe(total_time_seconds)
+            self.litellm_request_total_latency_metric.labels(**_labels).observe(_observed_total_time_seconds)
             self._track_end_user_metric_series(
                 self.litellm_request_total_latency_metric,
                 "litellm_request_total_latency_metric",
                 _labels,
             )
 
-        # request queue time (time from arrival to processing start)
-        _litellm_params: Final = kwargs.get("litellm_params", {}) or {}
-        queue_time_seconds: Final = (_litellm_params.get("metadata") or {}).get("queue_time_seconds")
         if queue_time_seconds is not None and queue_time_seconds >= 0:
             _labels = prometheus_label_factory(
                 supported_enum_labels=self.get_labels_for_metric(metric_name="litellm_request_queue_time_seconds"),

litellm/proxy/auth/user_api_key_auth.py

@@ -1069,6 +1069,26 @@ async def _resolve_jwt_to_virtual_key(
     return None
 
 
+def _ensure_litellm_received_at_on_request_state(request: Request) -> datetime:
+    """Idempotently stamp ``request.state.litellm_received_at`` with the moment
+    litellm's own code started handling this request -- the first line of
+    ``user_api_key_auth``, before any auth/pre-call work runs. This is the
+    basis for the request-latency Prometheus metrics (see
+    ``litellm/integrations/prometheus.py``), and unlike the OTEL SERVER span
+    below, it is set unconditionally so those metrics don't depend on OTEL
+    being configured.
+    """
+    existing_received_at: Final[datetime | None] = getattr(request.state, "litellm_received_at", None)
+    if existing_received_at is not None:
+        return existing_received_at
+    received_at: Final = datetime.now(timezone.utc)
+    try:
+        request.state.litellm_received_at = received_at
+    except Exception:
+        pass
+    return received_at
+
+
 def _ensure_parent_otel_span_on_request_state(request: Request) -> None:
     """Idempotently create the OTEL SERVER span and stash it on
     ``request.state.parent_otel_span``. Safe to call multiple times.
@@ -1079,15 +1099,12 @@ def _ensure_parent_otel_span_on_request_state(request: Request) -> None:
     """
     from litellm.proxy.proxy_server import open_telemetry_logger
 
+    start_time: Final = _ensure_litellm_received_at_on_request_state(request)
+
     if open_telemetry_logger is None:
         return
     if getattr(request.state, "parent_otel_span", None) is not None:
         return
-    start_time: Final = datetime.now(timezone.utc)
-    try:
-        request.state.litellm_received_at = start_time
-    except Exception:
-        pass
     parent_otel_span: Final = open_telemetry_logger.create_litellm_proxy_request_started_span(
         start_time=start_time,
         headers=_safe_get_request_headers(request),

litellm/proxy/common_request_processing.py

@@ -3,7 +3,6 @@ import contextlib
 import json
 import logging
 import math
-import time
 import traceback
 from collections.abc import AsyncGenerator, Awaitable, Callable, Mapping
 from datetime import datetime
@@ -1726,13 +1725,17 @@ class ProxyBaseLLMRequestProcessing:
             )
 
         # Calculate request queue time after add_litellm_data_to_request
-        # which sets arrival_time in proxy_server_request
+        # which sets arrival_time in proxy_server_request. Ends at start_time
+        # (not a freshly captured time.time() here) so this window is exactly
+        # [arrival_time, start_time], with zero overlap with the
+        # litellm_request_total_latency_metric window of [start_time, end_time] --
+        # otherwise the few lines of add_litellm_data_to_request's own work would
+        # be double-counted across both metrics.
         proxy_server_request: Final = self.data.get("proxy_server_request", {})
         arrival_time: Final = proxy_server_request.get("arrival_time")
         queue_time_seconds = None
         if arrival_time is not None:
-            processing_start_time: Final = time.time()
-            queue_time_seconds = processing_start_time - arrival_time
+            queue_time_seconds = start_time.timestamp() - arrival_time
 
         # Store queue time in metadata after add_litellm_data_to_request to ensure it's preserved
         if queue_time_seconds is not None:

litellm/proxy/litellm_pre_call_utils.py

@@ -1744,11 +1744,17 @@ async def add_litellm_data_to_request(
     # Init - Proxy Server Request
     # we do this as soon as entering so we track the original request
     ##########################################################
-    # Track arrival time for queue time metric. The body snapshot is filled
-    # in after the admin-injection strip below so the audit / spend-tracking
-    # consumers of proxy_server_request["body"] see the cleaned metadata
-    # rather than attacker-forged user_api_key_* fields.
-    arrival_time: Final = time.time()
+    # Track arrival time for queue time metric. Prefer the timestamp stamped at
+    # the top of user_api_key_auth (request.state.litellm_received_at): by the
+    # time this function runs, auth has already completed, so time.time() here
+    # would silently exclude the entire auth phase from the queue-time window.
+    # Falls back to time.time() for callers that never went through
+    # user_api_key_auth. The body snapshot is filled in after the
+    # admin-injection strip below so the audit / spend-tracking consumers of
+    # proxy_server_request["body"] see the cleaned metadata rather than
+    # attacker-forged user_api_key_* fields.
+    _litellm_received_at: Final = getattr(request.state, "litellm_received_at", None)
+    arrival_time: Final = _litellm_received_at.timestamp() if _litellm_received_at is not None else time.time()
     data["proxy_server_request"] = {
         "url": str(request.url),
         "method": request.method,

tests/test_litellm/integrations/test_prometheus_queue_guardrail_metrics.py

@@ -229,6 +229,137 @@ class TestPrometheusQueueTimeMetric:
         ), "Queue time metric should not be recorded for negative values"
 
 
+class TestPrometheusTotalLatencyMetric:
+    """litellm_request_total_latency_metric must be true end-to-end latency: start_time
+    (set after auth already completed, see LIT-6012) plus queue_time_seconds (the
+    auth + pre-call setup window queue_time_seconds itself covers), not start_time alone."""
+
+    @staticmethod
+    def _enum_values() -> UserAPIKeyLabelValues:
+        return UserAPIKeyLabelValues(
+            end_user=None,
+            hashed_api_key="test-key",
+            api_key_alias="test-alias",
+            requested_model="gpt-3.5-turbo",
+            model_group="gpt-3.5-turbo",
+            team=None,
+            team_alias=None,
+            user=None,
+            user_email=None,
+            status_code="200",
+            model="gpt-3.5-turbo",
+            litellm_model_name="gpt-3.5-turbo",
+            tags=[],
+            model_id="gpt-3.5-turbo",
+            api_base="https://api.openai.com",
+            api_provider="openai",
+            exception_status=None,
+            exception_class=None,
+            custom_metadata_labels={},
+            route=None,
+        )
+
+    def test_total_latency_includes_queue_time_when_present(self):
+        """The observed total-latency value must be (end_time - start_time) + queue_time_seconds,
+        so auth/pre-call time (queue_time_seconds) is not silently excluded from "total" latency."""
+        prometheus_logger = PrometheusLogger()
+
+        mock_metric = MagicMock()
+        mock_labeled_metric = MagicMock()
+        mock_metric.labels.return_value = mock_labeled_metric
+        prometheus_logger.litellm_request_total_latency_metric = mock_metric
+
+        start_time = datetime(2024, 1, 1, 0, 0, 0)
+        end_time = datetime(2024, 1, 1, 0, 0, 2)  # 2.0s of LLM-call/post-call time
+        queue_time_seconds = 0.5  # auth + pre-call setup time
+
+        kwargs = {
+            "litellm_params": {"metadata": {"queue_time_seconds": queue_time_seconds}},
+            "model": "gpt-3.5-turbo",
+            "start_time": start_time,
+            "end_time": end_time,
+        }
+
+        prometheus_logger._set_latency_metrics(
+            kwargs=kwargs,
+            model="gpt-3.5-turbo",
+            user_api_key="test-key",
+            user_api_key_alias="test-alias",
+            user_api_team=None,
+            user_api_team_alias=None,
+            enum_values=self._enum_values(),
+        )
+
+        observed_value = mock_labeled_metric.observe.call_args_list[0][0][0]
+        assert observed_value == pytest.approx(2.5)
+
+    def test_total_latency_falls_back_to_start_end_delta_without_queue_time(self):
+        """Without queue_time_seconds (e.g. a non-proxy caller), the metric must still
+        observe the plain end_time - start_time delta rather than erroring or dropping it."""
+        prometheus_logger = PrometheusLogger()
+
+        mock_metric = MagicMock()
+        mock_labeled_metric = MagicMock()
+        mock_metric.labels.return_value = mock_labeled_metric
+        prometheus_logger.litellm_request_total_latency_metric = mock_metric
+
+        start_time = datetime(2024, 1, 1, 0, 0, 0)
+        end_time = datetime(2024, 1, 1, 0, 0, 2)
+
+        kwargs = {
+            "litellm_params": {"metadata": {}},
+            "model": "gpt-3.5-turbo",
+            "start_time": start_time,
+            "end_time": end_time,
+        }
+
+        prometheus_logger._set_latency_metrics(
+            kwargs=kwargs,
+            model="gpt-3.5-turbo",
+            user_api_key="test-key",
+            user_api_key_alias="test-alias",
+            user_api_team=None,
+            user_api_team_alias=None,
+            enum_values=self._enum_values(),
+        )
+
+        observed_value = mock_labeled_metric.observe.call_args_list[0][0][0]
+        assert observed_value == pytest.approx(2.0)
+
+    def test_total_latency_ignores_negative_queue_time(self):
+        """A negative queue_time_seconds (clock skew / bad data) must not be added in --
+        matches the existing >= 0 guard on the standalone queue-time metric."""
+        prometheus_logger = PrometheusLogger()
+
+        mock_metric = MagicMock()
+        mock_labeled_metric = MagicMock()
+        mock_metric.labels.return_value = mock_labeled_metric
+        prometheus_logger.litellm_request_total_latency_metric = mock_metric
+
+        start_time = datetime(2024, 1, 1, 0, 0, 0)
+        end_time = datetime(2024, 1, 1, 0, 0, 2)
+
+        kwargs = {
+            "litellm_params": {"metadata": {"queue_time_seconds": -0.1}},
+            "model": "gpt-3.5-turbo",
+            "start_time": start_time,
+            "end_time": end_time,
+        }
+
+        prometheus_logger._set_latency_metrics(
+            kwargs=kwargs,
+            model="gpt-3.5-turbo",
+            user_api_key="test-key",
+            user_api_key_alias="test-alias",
+            user_api_team=None,
+            user_api_team_alias=None,
+            enum_values=self._enum_values(),
+        )
+
+        observed_value = mock_labeled_metric.observe.call_args_list[0][0][0]
+        assert observed_value == pytest.approx(2.0)
+
+
 class TestPrometheusGuardrailMetrics:
     """Test guardrail metrics recording"""
 

tests/test_litellm/proxy/auth/test_user_api_key_auth.py

@@ -29,6 +29,8 @@ from litellm.proxy.auth.auth_checks import get_key_object, _cache_key_object
 from litellm.proxy.auth.route_checks import RouteChecks
 from litellm.proxy.auth.user_api_key_auth import (
     _check_key_model_budget_with_fallback,
+    _ensure_litellm_received_at_on_request_state,
+    _ensure_parent_otel_span_on_request_state,
     _PendingAutoRegister,
     _matches_routing_override,
     _reserve_budget_after_common_checks,
@@ -6694,3 +6696,42 @@ async def test_unlicensed_jwt_auth_is_forbidden_not_unauthorized():
 
     assert error.code == "403"
     assert "enterprise" in error.message.lower()
+
+
+class TestLitellmReceivedAtStamping:
+    """request.state.litellm_received_at must be stamped unconditionally at the
+    top of auth (LIT-6012), so request-latency Prometheus metrics don't depend
+    on OTEL being configured to see a true request-arrival timestamp."""
+
+    def test_stamped_even_when_otel_is_not_configured(self, monkeypatch):
+        monkeypatch.setattr(
+            "litellm.proxy.proxy_server.open_telemetry_logger", None
+        )
+        request = MagicMock()
+        request.state = SimpleNamespace()
+
+        _ensure_parent_otel_span_on_request_state(request)
+
+        assert isinstance(request.state.litellm_received_at, datetime)
+
+    def test_helper_is_idempotent(self):
+        request = MagicMock()
+        request.state = SimpleNamespace()
+
+        first = _ensure_litellm_received_at_on_request_state(request)
+        second = _ensure_litellm_received_at_on_request_state(request)
+
+        assert first == second
+        assert request.state.litellm_received_at == first
+
+    def test_does_not_overwrite_an_earlier_stamp(self):
+        """Body-parse failures must not shorten the measured window: a value
+        already on request.state (stamped earlier) must win."""
+        request = MagicMock()
+        earlier = datetime(2020, 1, 1)
+        request.state = SimpleNamespace(litellm_received_at=earlier)
+
+        result = _ensure_litellm_received_at_on_request_state(request)
+
+        assert result == earlier
+        assert request.state.litellm_received_at == earlier

tests/test_litellm/proxy/test_common_request_processing.py

@@ -1392,11 +1392,25 @@ class TestProxyBaseLLMRequestProcessing:
             route_type=route_type,
         )
 
-        # Verify queue_time_seconds is set and non-negative
+        # Verify queue_time_seconds is set and non-negative. Ends at start_time
+        # (captured before this mock runs, so it can precede the mock's own
+        # time.time() by a handful of microseconds) rather than a freshly
+        # captured time.time(), so a tiny tolerance below 0.5 is expected and
+        # correct -- see LIT-6012.
         metadata = returned_data.get("metadata", {})
         assert "queue_time_seconds" in metadata, "queue_time_seconds should be set in metadata"
-        assert metadata["queue_time_seconds"] >= 0.5, (
-            f"queue_time_seconds should be at least 0.5, got {metadata['queue_time_seconds']}"
+        assert metadata["queue_time_seconds"] >= 0.49, (
+            f"queue_time_seconds should be at least ~0.5, got {metadata['queue_time_seconds']}"
+        )
+
+        # queue_time_seconds must end exactly where logging_obj.start_time begins
+        # (the same start_time litellm_request_total_latency_metric's window
+        # starts from) so the two windows share a boundary, not an overlap.
+        # A mutant that reintroduces a separately-captured processing_start_time
+        # would make this assertion fail.
+        arrival_time = returned_data["proxy_server_request"]["arrival_time"]
+        assert arrival_time + metadata["queue_time_seconds"] == pytest.approx(
+            logging_obj.start_time.timestamp(), abs=1e-6
         )
 
 

tests/test_litellm/proxy/test_litellm_pre_call_utils.py

@@ -2,6 +2,9 @@ import asyncio
 import copy
 import json
 import os
+import time
+from datetime import datetime, timezone
+from types import SimpleNamespace
 from unittest.mock import AsyncMock, MagicMock, patch
 
 import pytest
@@ -268,6 +271,75 @@ async def test_stamped_auth_object_reflects_header_derived_identity():
     assert stamped.end_user_id == "end-user-from-header"
 
 
+@pytest.mark.asyncio
+async def test_arrival_time_prefers_litellm_received_at_over_time_time():
+    """LIT-6012: by the time this function runs, auth has already completed, so
+    time.time() here would silently exclude the whole auth phase from the
+    queue-time window. request.state.litellm_received_at (stamped at the top of
+    user_api_key_auth, before auth work) must win when present."""
+    from litellm.proxy.litellm_pre_call_utils import add_litellm_data_to_request
+
+    request_mock = MagicMock(spec=Request)
+    request_mock.url = MagicMock()
+    request_mock.url.path = "/v1/chat/completions"
+    request_mock.url.__str__.return_value = "http://localhost/v1/chat/completions"
+    request_mock.method = "POST"
+    request_mock.query_params = {}
+    request_mock.headers = {"Content-Type": "application/json"}
+    request_mock.client = MagicMock()
+    request_mock.client.host = "127.0.0.1"
+    received_at = datetime(2024, 1, 1, tzinfo=timezone.utc)
+    request_mock.state = SimpleNamespace(litellm_received_at=received_at)
+
+    user_api_key_dict = UserAPIKeyAuth(api_key="hashed-key", metadata={}, team_metadata={})
+
+    updated_data = await add_litellm_data_to_request(
+        data={"model": "gpt-3.5-turbo"},
+        request=request_mock,
+        user_api_key_dict=user_api_key_dict,
+        proxy_config=MagicMock(),
+        general_settings={},
+        version="test-version",
+    )
+
+    assert updated_data["proxy_server_request"]["arrival_time"] == received_at.timestamp()
+
+
+@pytest.mark.asyncio
+async def test_arrival_time_falls_back_to_time_time_without_litellm_received_at():
+    """Callers that never went through user_api_key_auth (no stamp on request.state)
+    must still get a usable arrival_time instead of erroring."""
+    from litellm.proxy.litellm_pre_call_utils import add_litellm_data_to_request
+
+    request_mock = MagicMock(spec=Request)
+    request_mock.url = MagicMock()
+    request_mock.url.path = "/v1/chat/completions"
+    request_mock.url.__str__.return_value = "http://localhost/v1/chat/completions"
+    request_mock.method = "POST"
+    request_mock.query_params = {}
+    request_mock.headers = {"Content-Type": "application/json"}
+    request_mock.client = MagicMock()
+    request_mock.client.host = "127.0.0.1"
+    request_mock.state = SimpleNamespace()  # no litellm_received_at attribute
+
+    user_api_key_dict = UserAPIKeyAuth(api_key="hashed-key", metadata={}, team_metadata={})
+
+    before = time.time()
+    updated_data = await add_litellm_data_to_request(
+        data={"model": "gpt-3.5-turbo"},
+        request=request_mock,
+        user_api_key_dict=user_api_key_dict,
+        proxy_config=MagicMock(),
+        general_settings={},
+        version="test-version",
+    )
+    after = time.time()
+
+    arrival_time = updated_data["proxy_server_request"]["arrival_time"]
+    assert isinstance(arrival_time, float)
+    assert before <= arrival_time <= after
+
+
 @pytest.mark.asyncio
 async def test_add_litellm_data_to_request_strips_admin_injection_slots():
     """User-supplied user_api_key_metadata / user_api_key_team_metadata /
@@ -2786,7 +2858,6 @@ def test_add_headers_to_llm_call_by_model_group_existing_headers_in_data():
         litellm.model_group_settings = original_model_group_settings
 
 
-import time
 from typing import Optional
 
 from fastapi.responses import Response