fix(timing): anchor response duration and overhead at proxy receive time

Co-Authored-By: Ishaan Jaffer <155045088+ishaan-berri@users.noreply.github.com>

litellm/litellm_core_utils/llm_response_utils/response_metadata.py

@@ -5,7 +5,7 @@ from typing import Any, Final
 import httpx
 
 from litellm.constants import LITELLM_DETAILED_TIMING
-from litellm.litellm_core_utils.core_helpers import process_response_headers
+from litellm.litellm_core_utils.core_helpers import get_litellm_metadata_from_kwargs, process_response_headers
 from litellm.litellm_core_utils.llm_response_utils.get_api_base import get_api_base
 from litellm.litellm_core_utils.logging_utils import LiteLLMLoggingObject
 from litellm.types.utils import (
@@ -16,19 +16,25 @@ from litellm.types.utils import (
 )
 
 
+def _timing_window_start(start_time: datetime.datetime, logging_obj: LiteLLMLoggingObject) -> datetime.datetime:
+    received_at: Final = get_litellm_metadata_from_kwargs(logging_obj.model_call_details).get("litellm_received_at")
+    return received_at if isinstance(received_at, datetime.datetime) else start_time
+
+
 def response_timing_metrics(
     start_time: datetime.datetime,
     end_time: datetime.datetime,
     logging_obj: LiteLLMLoggingObject,
     include_overhead: bool = True,
 ) -> Mapping[str, float]:
-    """``_response_ms`` for the whole call, plus ``litellm_overhead_time_ms`` when it can be derived.
+    """``_response_ms`` for the window starting at proxy receive time when stamped, else ``start_time``.
 
     On a cache hit the overhead is the total minus the cache read; otherwise it is the total minus
     the provider call (``llm_api_duration_ms``). It is omitted when neither duration was recorded,
     and when ``include_overhead`` is False because the two durations cover different windows.
     """
-    total_response_time_ms: Final = (end_time - start_time).total_seconds() * 1000
+    window_start: Final = _timing_window_start(start_time, logging_obj)
+    total_response_time_ms: Final = (end_time.timestamp() - window_start.timestamp()) * 1000
     if not include_overhead:
         return {"_response_ms": total_response_time_ms}  # mutable-ok: read-only timing result
     caching_details: Final = logging_obj.caching_details

tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py

@@ -9,6 +9,8 @@ import asyncio
 import datetime
 from unittest.mock import MagicMock
 
+import pytest
+
 import litellm.litellm_core_utils.llm_response_utils.response_metadata as response_metadata_mod
 import litellm.proxy.common_request_processing as common_request_processing_mod
 from litellm.litellm_core_utils.litellm_logging import Logging
@@ -231,11 +233,13 @@ class TestResponseTimingMetrics:
     START = datetime.datetime(2025, 1, 1, 0, 0, 0)
     END = datetime.datetime(2025, 1, 1, 0, 0, 1)
 
-    def _make_logging_obj(self, llm_api_duration_ms=None, caching_details=None):
+    def _make_logging_obj(self, llm_api_duration_ms=None, caching_details=None, received_at=None):
         logging_obj = MagicMock()
         logging_obj.model_call_details = {}
         if llm_api_duration_ms is not None:
             logging_obj.model_call_details["llm_api_duration_ms"] = llm_api_duration_ms
+        if received_at is not None:
+            logging_obj.model_call_details["litellm_params"] = {"metadata": {"litellm_received_at": received_at}}
         logging_obj.caching_details = caching_details
         return logging_obj
 
@@ -246,6 +250,35 @@ class TestResponseTimingMetrics:
             "litellm_overhead_time_ms": 100.0,
         }
 
+    def test_window_starts_at_proxy_receive_when_stamped(self):
+        received_at = self.START.astimezone(datetime.timezone.utc) - datetime.timedelta(seconds=3)
+        logging_obj = self._make_logging_obj(llm_api_duration_ms=900.0, received_at=received_at)
+
+        result = response_timing_metrics(self.START, self.END, logging_obj)
+
+        assert result["_response_ms"] == pytest.approx(4000.0)
+        assert result["litellm_overhead_time_ms"] == pytest.approx(3100.0)
+
+    def test_cache_hit_window_starts_at_proxy_receive_when_stamped(self):
+        received_at = self.START.astimezone(datetime.timezone.utc) - datetime.timedelta(seconds=3)
+        logging_obj = self._make_logging_obj(
+            caching_details={"cache_hit": True, "cache_duration_ms": 250.0},
+            received_at=received_at,
+        )
+
+        result = response_timing_metrics(self.START, self.END, logging_obj)
+
+        assert result["_response_ms"] == pytest.approx(4000.0)
+        assert result["litellm_overhead_time_ms"] == pytest.approx(3750.0)
+
+    def test_non_datetime_proxy_receive_falls_back_to_start_time(self):
+        logging_obj = self._make_logging_obj(llm_api_duration_ms=900.0, received_at="bad")
+
+        result = response_timing_metrics(self.START, self.END, logging_obj)
+
+        assert result["_response_ms"] == pytest.approx(1000.0)
+        assert result["litellm_overhead_time_ms"] == pytest.approx(100.0)
+
     def test_overhead_omitted_when_no_provider_or_cache_duration_recorded(self):
         logging_obj = self._make_logging_obj()
         assert response_timing_metrics(self.START, self.END, logging_obj) == {"_response_ms": 1000.0}