fix(prometheus): fold auth/pre-call time into litellm_request_total_latency_metric - #37958
Conversation
|
|
Greptile SummaryThis PR stamps request arrival before authentication and carries that timestamp through queue-time and total-latency Prometheus metrics
Confidence Score: 5/5The PR appears safe to merge No blocking failure remains
|
| Filename | Overview |
|---|---|
| litellm/integrations/prometheus.py | Adds non-overlapping queue time to total request latency and updates metric descriptions |
| litellm/proxy/auth/user_api_key_auth.py | Stamps an idempotent request-arrival timestamp before authentication and fully fixes the prior local-variable rebinding |
| litellm/proxy/common_request_processing.py | Aligns the queue interval endpoint with the logging start timestamp, resolving the previously reported overlap |
| litellm/proxy/litellm_pre_call_utils.py | Prefers the authentication-entry timestamp while preserving a fallback for callers outside the normal auth flow |
| tests/test_litellm/integrations/test_prometheus_queue_guardrail_metrics.py | Adds coverage for queue-time inclusion, fallback behavior, and invalid negative values |
| tests/test_litellm/proxy/auth/test_user_api_key_auth.py | Verifies unconditional and idempotent request-arrival stamping |
| tests/test_litellm/proxy/test_common_request_processing.py | Verifies queue and processing intervals share an exact boundary |
| tests/test_litellm/proxy/test_litellm_pre_call_utils.py | Verifies stamped arrival-time preference and fallback timestamp behavior |
Reviews (2): Last reviewed commit: "fix(prometheus): fold auth/pre-call time..." | Re-trigger Greptile
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
…atency_metric 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.
fbbfc95 to
bcfd107
Compare
|
@greptileai both findings were right: fixed the overlapping-interval double-count (queue_time_seconds now ends exactly at start_time) and the Final-annotation rebinding in the timestamp helper. Please review the current head bcfd107. |
TLDR
Problem this solves:
litellm_request_total_latency_metricsilently excludes authentication and pre-call setup timelitellm_request_queue_time_secondshas the same problem despite its own doc comment claiming otherwiseHow it solves it:
User Flow
Before: an operator's dashboard says request latency is fine while their users experience multi-second delays from a slow auth backend
litellm_request_total_latency_metricGrafana panel stays flat and low, because the metric's clock only starts after auth already finishedtrace.fastapi.request) reports several seconds higher for the same window, with no explanation from LiteLLM's own metricslitellm_request_queue_time_seconds, despite its name and docs, also reads near-zero during the same slow-auth windowAfter: the total-latency metric reflects what the customer's users actually experienced
litellm_request_total_latency_metricrises to match real end-to-end latency, including the auth delaylitellm_request_queue_time_secondsrises by (approximately) the auth delay itself, correctly isolating that phaseRelevant issues
Linear ticket
Resolves LIT-6012
Pre-Submission checklist
uv run pytest tests/test_litellm/<your_test_file>.py -v. Leave the suites (make test-unit-*,make test-unit) to CI: it finishes in ~15 minutes where a laptop takes an hour or more@greptileaito re-request a review after pushing changes)Delays in PR merge?
If you're seeing a delay in your PR being merged, ping the LiteLLM Team on Slack (#pr-review).
Screenshots / Proof of Fix
Live proxy, real OpenAI call (
gpt-4o-mini), no mocks.general_settings.custom_authpoints at a small local function thatawait asyncio.sleep(3.0)s before returning a valid key -- a controllable stand-in for a slow Redis/DB-backed auth backend, run inside the realuser_api_key_authflow (the sleep happens after the point this PR's timestamp is stamped, so it lands in the "auth" window either way).Setup (shared by both runs):
litellm_settings.callbacks: ["prometheus"], one realopenai/gpt-4o-minideployment,custom_authsleeping 3.0s, proxy on port 24012.Before (490c9f9)
curl -H "Authorization: Bearer sk-test-key" http://localhost:24012/v1/chat/completions -d '{"model": "gpt-4o-mini", "messages": [{"role": "user", "content": "Say the word OK and nothing else."}]}'->HTTP 200, real completion ("content":"OK"), wall-clock7.454s totalcurl -sL http://localhost:24012/metrics | grep '_sum':litellm_request_total_latency_metric_sum{...} 4.430722-- misses ~3s of the 7.454s real requestlitellm_request_queue_time_seconds_sum{...} 0.0001049...-- reads as essentially zero despite the real 3s auth delayAfter (bcfd107)
HTTP 200, real completion, wall-clock4.572s totalcurl -sL http://localhost:24012/metrics | grep '_sum':litellm_request_total_latency_metric_sum{...} 4.552430082550049-- now matches the real wall-clock timelitellm_request_queue_time_seconds_sum{...} 3.009190082550049-- now matches the 3.0s simulated auth delay almost exactlyType
🐛 Bug Fix
Caveats (if any)
end_timefor these metrics is captured when the LLM response is received, not when the response finishes being sent to the client (post-call hooks, guardrails, serialization). Not addressed here; filed as a follow-up consideration in LIT-6012 if it turns out to matter in practiceFinal Attestation