fix(timing): use epoch math for detailed pre-processing and drop client-supplied timing windows

Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>
This commit is contained in:
kerry 2026-09-19 01:06:53 +00:00
parent d74e1bb445
commit a1560936f7
4 changed files with 36 additions and 4 deletions

View file

@ -205,7 +205,7 @@ class ResponseMetadata:
api_call_start: Final[datetime.datetime | None] = logging_obj.model_call_details.get("api_call_start_time")
if api_call_start is not None and start_time is not None:
anchor: Final = _timing_window_start(start_time, logging_obj)[0]
pre_ms: Final = (api_call_start - anchor).total_seconds() * 1000
pre_ms: Final = (api_call_start.timestamp() - anchor.timestamp()) * 1000
detailed["timing_pre_processing_ms"] = round(pre_ms, 4)
# post-processing = total - pre - llm_api

View file

@ -2367,6 +2367,7 @@ async def add_litellm_data_to_request(
# OTel layer can compute pre-request latency, including on the failure
# path after the logging object is popped.
data[_metadata_variable_name]["litellm_received_at"] = getattr(request.state, "litellm_received_at", None)
data[_metadata_variable_name]["llm_api_timing_windows"] = ()
# OTEL Controls / Tracing
# Add the OTEL Parent Trace before sending it LiteLLM

View file

@ -474,12 +474,13 @@ class TestDetailedTiming:
monkeypatch.setattr(response_metadata_mod, "LITELLM_DETAILED_TIMING", True)
result = ModelResponse()
start = datetime.datetime(2025, 1, 1, 0, 0, 0)
received_at = start - datetime.timedelta(milliseconds=200)
received_at = datetime.datetime.now(datetime.timezone.utc)
start = received_at + datetime.timedelta(milliseconds=200)
api_call_start = start.replace(tzinfo=None)
end = start + datetime.timedelta(milliseconds=530)
logging_obj = self._make_logging_obj(
llm_api_duration_ms=500.0,
api_call_start_time=start,
api_call_start_time=api_call_start,
)
logging_obj.model_call_details["litellm_params"] = {"metadata": {"litellm_received_at": received_at}}

View file

@ -333,6 +333,36 @@ async def test_arrival_time_prefers_litellm_received_at_over_time_time():
assert updated_data["proxy_server_request"]["arrival_time"] == received_at.timestamp()
@pytest.mark.asyncio
async def test_proxy_clears_client_supplied_timing_windows():
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(litellm_received_at=datetime.now(timezone.utc))
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",
"metadata": {"llm_api_timing_windows": ((0.0, 1.0),)},
},
request=request_mock,
user_api_key_dict=user_api_key_dict,
proxy_config=MagicMock(),
general_settings={},
version="test-version",
)
assert updated_data["metadata"]["llm_api_timing_windows"] == ()
@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)