From 1f54c139c3eedffb28aa465cd9fba4c47738a408 Mon Sep 17 00:00:00 2001 From: songkuan-zheng <252822057+songkuan-zheng@users.noreply.github.com> Date: Mon, 18 May 2026 09:51:59 +0000 Subject: [PATCH] fix(passthrough): record real TTFT and start_time for streaming requests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Pass-through streaming requests (/v1/messages, /vertex_ai/*, /gemini/*, /cohere/*, /assemblyai/*, /openai/*, /cursor/*) all share PassThroughStreamingHandler.chunk_processor, which had two timing bugs that interacted to collapse spend_logs.completionStartTime onto spend_logs.endTime (off by ~1ms of clock resolution, not literally identical) — making the streaming phase (endTime - completionStartTime) round to roughly zero and TTFT effectively soak up the entire request duration for every pass-through streaming row. Root cause 1. `start_time` arg too late. The caller's start_time originates in BaseAnthropicMessagesStreamingIterator.__init__, which runs AFTER the upstream HTTP response has already been received. SpendLogs. startTime therefore reflects "moment we started reading the stream", not "moment the client request entered the proxy" — the real TTFT window is silently subtracted from Duration. 2. First-chunk arrival never recorded. The chunk loop yielded bytes to the client and collected them for logging, but never noted when the first byte arrived. With litellm_logging_obj.completion_start_time left as None, the fallback at litellm_logging.py:1834-1837 sets it to end_time — completionStartTime lands within ~1ms of endTime and streaming_phase rounds to 0. Both bugs hide each other. Fixing only #2 gives TTFT close to 0 with Duration deflated by ~TTFT. Fixing only #1 leaves completionStartTime still pinned to endTime. Both must be fixed for the math to be correct. Fix In chunk_processor, at the top of the try block: - Override start_time with litellm_logging_obj.start_time when the latter is an earlier datetime — that's the true request-entry timestamp set in common_request_processing.base_process_llm_request. - On the first chunk yielded by response.aiter_bytes(), call litellm_logging_obj._update_completion_start_time(datetime.now()) to populate the field that downstream payload builders look for. Verified end-to-end (Anthropic claude-sonnet-4-6, 200-word stream): Before fix: Duration=6528ms TTFT=6527ms streaming_phase=1ms After fix: Duration=8496ms TTFT=2373ms streaming_phase=6123ms Control: /v1/chat/completions (same model+prompt) Duration=8143ms TTFT=2071ms streaming_phase=6072ms Test plan - New e2e case 13 (`13_passthrough_streaming_ttft.md` + data/13_*.sh) sends a real ~200-word streamed completion through /v1/messages, polls spend_logs for up to 30s, asserts: * streaming_phase_ms > 1000 (catches bug #2 regression) * ttft_ms > 300 (catches bug #1 regression) * ttft_ms < duration_ms / 2 (catches either regression) Plus a soft parity check vs /v1/chat/completions for the same upstream model. - Cost ~$0.005 per case run. - GREEN against the fix; was RED before (streaming_phase=1ms, ttft=6527ms) — assertions 1 and 3 fired. Blast radius: all pass-through endpoints — they all flow through this single chunk_processor. User noticed the bug via Anthropic; the same fix improves TTFT observability for Vertex AI, Gemini, Cohere, and the other pass-through providers in the same release. --- e2e/cases/13_passthrough_streaming_ttft.md | 123 +++++++++++++ e2e/cases/README.md | 1 + .../data/13_passthrough_streaming_ttft.sh | 164 ++++++++++++++++++ .../streaming_handler.py | 24 +++ 4 files changed, 312 insertions(+) create mode 100644 e2e/cases/13_passthrough_streaming_ttft.md create mode 100755 e2e/cases/data/13_passthrough_streaming_ttft.sh diff --git a/e2e/cases/13_passthrough_streaming_ttft.md b/e2e/cases/13_passthrough_streaming_ttft.md new file mode 100644 index 000000000000..33f7aa17546a --- /dev/null +++ b/e2e/cases/13_passthrough_streaming_ttft.md @@ -0,0 +1,123 @@ +# Case 13 — Pass-through streaming TTFT must reflect real time-to-first-token + +## Goal + +Regression guard for two interacting bugs in +`litellm/proxy/pass_through_endpoints/streaming_handler.py` that +together collapsed `spend_logs.completionStartTime` onto +`spend_logs.endTime` (off by ~1ms of clock resolution, not literally +identical), making the streaming phase +(`endTime - completionStartTime`) round to roughly zero and TTFT +effectively soak up the entire request duration — for every streaming +request through any pass-through endpoint (`/v1/messages`, +`/vertex_ai/*`, `/gemini/*`, `/cohere/*`, etc.). + +## Origin + +Reported by an operator looking at the dashboard: for streaming calls +through `/v1/messages` (Anthropic pass-through), `Duration (s)` and +`TTFT (s)` columns showed near-identical values (off by ≤1 ms) — +including on multi-second completions where TTFT physically can't be +the entire request time. + +## Root cause (verified end-to-end) + +Two bugs in the shared `PassThroughStreamingHandler.chunk_processor`: + +1. **`start_time` is captured too late.** The `start_time` argument + handed to `chunk_processor` originates in + `BaseAnthropicMessagesStreamingIterator.__init__`, which runs + *after* the upstream HTTP response has already been received. + So `SpendLogs.startTime` reflects "moment we started reading the + stream", not "moment the client request entered the proxy" — the + true TTFT window is silently subtracted from `Duration`. + +2. **`completion_start_time` is never recorded.** The original chunk + loop yielded bytes to the client and collected them for logging, + but never noted when the first byte arrived. With + `litellm_logging_obj.completion_start_time` left as `None`, the + fallback at `litellm_logging.py:1834-1837` sets it to `end_time` + — collapsing `completionStartTime` onto `endTime` and zeroing out + the streaming phase. + +Both bugs hide each other. Fixing only #2 leaves you with `TTFT ≈ 0` +and `Duration` deflated by ~TTFT; fixing only #1 leaves `TTFT == +Duration`. Both must be fixed for the math to come out right. + +## Numerical evidence (Anthropic claude-sonnet-4-6, 200-word stream) + +| State | Duration | TTFT | streaming_phase | curl wall-clock | +|---|---|---|---|---| +| Bug present | 6528 ms | 6527 ms | 1 ms | 8769 ms | +| Bug #2 fixed only | 7698 ms | 14 ms | 7684 ms | 9893 ms | +| Both fixed | **8496 ms** | **2373 ms** | **6123 ms** | 8551 ms | +| Control (`/v1/chat/completions` transform, same model + prompt) | 8143 ms | 2071 ms | 6072 ms | 8214 ms | + +After the fix, the pass-through path is within ~5% of the transform +path on the same upstream model — the two should report the same +streaming behavior because the underlying HTTP request is the same. + +## Preconditions + +- `e2e/tools/proxy status` reports `ready` +- `ANTHROPIC_API_KEY` set (this case uses a real ~200-word completion; + cost ≈ $0.005 per run) + +## Steps + +```bash +bash e2e/cases/data/13_passthrough_streaming_ttft.sh +echo "exit=$?" +``` + +The fixture: + +1. Sends a streaming POST to `/v1/messages` with `max_tokens=400` and a + prompt that asks for a 200-word essay, so the stream runs for + several seconds. +2. Sends an equivalent streaming POST to `/v1/chat/completions` as a + parity reference for the transform path. +3. Waits 5 s for the async spend-logger to flush, then queries the + two newest spend_logs rows. +4. Asserts on the `anthropic_messages` row: + - `streaming_phase_ms > 1000` + - `ttft_ms > 300` + - `ttft_ms < duration_ms / 2` +5. Soft-warns if `anthropic_messages.ttft` differs from `acompletion.ttft` + by more than 3× (provider cold-start variance can hit 2×, so this + is informational, not a fail). + +## Expected — GREEN (after fix lands) + +``` +A (/v1/messages): wall=8551ms, bytes=4789 +B (/v1/chat/completions): wall=8214ms, bytes=5660 + +spend_logs rows: + anthropic_messages duration= 8496ms ttft= 2373ms streaming= 6123ms + acompletion duration= 8143ms ttft= 2071ms streaming= 6072ms + +PASS: passthrough streaming TTFT is recorded correctly. + /v1/messages duration=8496ms ttft=2373ms streaming=6123ms +``` + +## Failure modes + +| Symptom | Likely cause | +|---|---| +| `FAIL [assertion 1]: streaming_phase=1ms` | Bug #2 regressed — first-chunk arrival not recorded; `completion_start_time` fell back to `end_time` | +| `FAIL [assertion 2]: ttft=14ms` | Bug #1 regressed — `start_time` is captured at iterator `__init__` again, after upstream response; need the `litellm_logging_obj.start_time` override | +| `FAIL [assertion 3]: ttft > duration/2` | One of the two bugs has partially regressed; check both `chunk_processor` entry-time and first-chunk recording | +| `WARN: TTFT parity off — ...ratio=...` | Soft signal only — usually means the Anthropic path hit a cold cache on this run; rerun once to confirm | +| `FAIL: no anthropic_messages row` | Async spend logger backed up — increase the `sleep 5` to 10 | + +## Cross-reference + +- `litellm/proxy/pass_through_endpoints/streaming_handler.py` — + fix lives at the top of `chunk_processor`'s `try:` block +- Case 12 — guards the cost-calc path for dashboard-added deployments +- Case 11 — guards observability for failure logging +- This case (13) — guards observability for streaming latency + +All four (10/11/12/13) green means the cost + observability pipeline +is trustworthy end-to-end for both transform and pass-through paths. diff --git a/e2e/cases/README.md b/e2e/cases/README.md index 06c6280f412a..6cfba1916f2d 100644 --- a/e2e/cases/README.md +++ b/e2e/cases/README.md @@ -22,6 +22,7 @@ Humans can execute them too — every step is a concrete shell command. | 10 | `10_cost_breakdown_cache_missing.md` | (none — direct calc) | `cost_breakdown.cache_read_cost` / `cache_creation_cost` not silently `None` | — | | 11 | `11_error_information_message_populated.md` | (none — invalid key) | `spend_logs.metadata.error_information.error_message` non-empty on failure | ✓ | | 12 | `12_custom_pricing_must_honor_cache_tokens.md` | (none — direct calc) | `custom_cost_per_token` short-circuit must include cache pricing (Bug #2 root cause) | — | +| 13 | `13_passthrough_streaming_ttft.md` | Anthropic | `/v1/messages` streaming `completionStartTime` must reflect first-chunk arrival, not collapse to `endTime` (streaming_phase ≈ 0) | ✓ | ## How to invoke diff --git a/e2e/cases/data/13_passthrough_streaming_ttft.sh b/e2e/cases/data/13_passthrough_streaming_ttft.sh new file mode 100755 index 000000000000..05ef6cb204ae --- /dev/null +++ b/e2e/cases/data/13_passthrough_streaming_ttft.sh @@ -0,0 +1,164 @@ +#!/usr/bin/env bash +# Regression fixture for Case 13 — passthrough streaming TTFT must be a real +# time-to-first-token, not a copy of total Duration. +# +# Makes a streaming request to /v1/messages (Anthropic passthrough), waits for +# the spend_logs row to flush, and asserts: +# +# 1. streaming_phase_ms = endTime - completionStartTime > 1000 ms +# (server actually streamed; this catches the "1ms streaming phase" +# symptom where completion_start_time gets set to end_time) +# 2. ttft_ms = completionStartTime - startTime > 300 ms +# (first chunk wasn't recorded at request entry time either) +# 3. ttft_ms < 0.5 * duration_ms +# (TTFT shouldn't dominate Duration on a long-enough stream) +# +# Side-by-side parity vs /v1/chat/completions: both paths' TTFTs should be +# within 3x of each other (cache miss + LLM warm-up varies). +# +# Cost ~ $0.005 per run. + +set -eu + +PROXY_URL="${PROXY_URL:-http://localhost:4011}" +DB_CONTAINER="${DB_CONTAINER:-litellm-e2e-db}" +DB_USER="${DB_USER:-litellm}" +DB_NAME="${DB_NAME:-litellm}" +MASTER_KEY="${MASTER_KEY:-sk-e2e-test}" + +# Unique seed so we can find exactly these requests later if needed +SENTINEL=$(date +%s%N) +PROMPT="Write a 200-word, three-paragraph essay about the history of clocks. Sentinel=$SENTINEL. Do not stop early." + +# ---------- A. /v1/messages stream (the path that had the bug) ---------- +A_RESP=$(mktemp) +A_START=$(date +%s%3N) +curl -sS -N -X POST "$PROXY_URL/v1/messages" \ + -H "x-api-key: $MASTER_KEY" \ + -H "anthropic-version: 2023-06-01" \ + -H "Content-Type: application/json" \ + -d "$(jq -n --arg p "$PROMPT" \ + '{model: "claude-sonnet-cache", messages: [{role: "user", content: $p}], max_tokens: 400, stream: true}')" \ + > "$A_RESP" +A_END=$(date +%s%3N) +A_WALL=$((A_END - A_START)) +A_BYTES=$(wc -c < "$A_RESP") +rm -f "$A_RESP" + +# ---------- B. /v1/chat/completions stream (control / parity ref) ---------- +B_RESP=$(mktemp) +B_START=$(date +%s%3N) +curl -sS -N -X POST "$PROXY_URL/v1/chat/completions" \ + -H "Authorization: Bearer $MASTER_KEY" \ + -H "Content-Type: application/json" \ + -d "$(jq -n --arg p "$PROMPT" \ + '{model: "claude-sonnet-cache", messages: [{role: "user", content: $p}], max_tokens: 400, stream: true, stream_options: {include_usage: true}}')" \ + > "$B_RESP" +B_END=$(date +%s%3N) +B_WALL=$((B_END - B_START)) +B_BYTES=$(wc -c < "$B_RESP") +rm -f "$B_RESP" + +echo "A (/v1/messages): wall=${A_WALL}ms, bytes=${A_BYTES}" +echo "B (/v1/chat/completions): wall=${B_WALL}ms, bytes=${B_BYTES}" + +if [ "$A_BYTES" -lt 500 ] || [ "$B_BYTES" -lt 500 ]; then + echo "FAIL: one of the streams returned <500 bytes — upstream rejected the request" + exit 1 +fi + +# Poll for both rows up to 30s — async spend logger flushes after the stream +# completes and the anthropic_messages row tends to lag the acompletion row +# by a few seconds. +ROW="" +for _ in $(seq 1 30); do + sleep 1 + ROW=$(docker exec "$DB_CONTAINER" psql -U "$DB_USER" -d "$DB_NAME" -tA -F'|' -c " +SELECT + call_type, + EXTRACT(EPOCH FROM (\"endTime\" - \"startTime\")) * 1000, + EXTRACT(EPOCH FROM (\"completionStartTime\" - \"startTime\")) * 1000, + EXTRACT(EPOCH FROM (\"endTime\" - \"completionStartTime\")) * 1000 +FROM \"LiteLLM_SpendLogs\" +WHERE \"startTime\" > NOW() - INTERVAL '60 seconds' + AND call_type IN ('anthropic_messages', 'acompletion') +ORDER BY \"startTime\" DESC +LIMIT 2; +") + # Need at least one anthropic_messages row to assert on + if echo "$ROW" | grep -q '^anthropic_messages'; then + break + fi +done + +if [ -z "$ROW" ]; then + echo "FAIL: no spend_logs row found in last 20s — async logger may be backed up" + exit 1 +fi + +echo +echo "spend_logs rows:" +echo "$ROW" | awk -F'|' '{ printf " %-22s duration=%6.0fms ttft=%6.0fms streaming=%6.0fms\n", $1, $2, $3, $4 }' +echo + +A_DUR=$(echo "$ROW" | awk -F'|' '$1=="anthropic_messages" {print int($2); exit}') +A_TTFT=$(echo "$ROW" | awk -F'|' '$1=="anthropic_messages" {print int($3); exit}') +A_STREAM=$(echo "$ROW" | awk -F'|' '$1=="anthropic_messages" {print int($4); exit}') + +B_TTFT=$(echo "$ROW" | awk -F'|' '$1=="acompletion" {print int($3); exit}') + +if [ -z "$A_DUR" ]; then + echo "FAIL: no anthropic_messages row found in last 20s" + exit 1 +fi + +FAIL=0 + +# Assertion 1: streaming_phase must be >1s for a 200-word stream +if [ "$A_STREAM" -lt 1000 ]; then + echo "FAIL [assertion 1]: streaming_phase=${A_STREAM}ms is too short." + echo " Expected >1000ms for a ~200-word completion." + echo " Likely cause: completion_start_time fell back to end_time" + echo " (litellm_logging.py:1834-1837 fallback fires when chunk_processor" + echo " never records first-chunk arrival). See bug fix in" + echo " litellm/proxy/pass_through_endpoints/streaming_handler.py." + FAIL=1 +fi + +# Assertion 2: TTFT must be >300ms (real provider latency floor) +if [ "$A_TTFT" -lt 300 ]; then + echo "FAIL [assertion 2]: ttft=${A_TTFT}ms is too small." + echo " Expected >300ms — real Anthropic API latency is normally 1-3 seconds." + echo " Likely cause: start_time passed into chunk_processor came from the" + echo " streaming iterator __init__ (which runs after upstream HTTP" + echo " response received), so first-chunk arrival is microseconds after." + echo " See litellm_logging_obj.start_time override in chunk_processor." + FAIL=1 +fi + +# Assertion 3: TTFT must not dominate Duration +HALF_DUR=$((A_DUR / 2)) +if [ "$A_TTFT" -gt "$HALF_DUR" ]; then + echo "FAIL [assertion 3]: ttft=${A_TTFT}ms > duration/2=${HALF_DUR}ms." + echo " For a long-enough stream, TTFT should be a small fraction of Duration." + echo " Likely cause: the same fallback as assertion 1 (TTFT collapsed to Duration)." + FAIL=1 +fi + +# Soft sanity: parity with the OpenAI transform path +if [ -n "$B_TTFT" ] && [ "$B_TTFT" -gt 0 ]; then + # Use awk for float-safe ratio (ttft can vary 1.5x easily between calls) + RATIO=$(awk "BEGIN { printf \"%.2f\", $A_TTFT / $B_TTFT }") + if awk "BEGIN { exit !($A_TTFT > $B_TTFT * 3 || $B_TTFT > $A_TTFT * 3) }"; then + echo "WARN: TTFT parity off — anthropic_messages=${A_TTFT}ms vs acompletion=${B_TTFT}ms (ratio=${RATIO})" + echo " Not a strict fail (provider cold-start variance), but worth investigating." + fi +fi + +if [ "$FAIL" -eq 0 ]; then + echo "PASS: passthrough streaming TTFT is recorded correctly." + echo " /v1/messages duration=${A_DUR}ms ttft=${A_TTFT}ms streaming=${A_STREAM}ms" + exit 0 +else + exit 1 +fi diff --git a/litellm/proxy/pass_through_endpoints/streaming_handler.py b/litellm/proxy/pass_through_endpoints/streaming_handler.py index 302d7e76edf6..172eaf756dc9 100644 --- a/litellm/proxy/pass_through_endpoints/streaming_handler.py +++ b/litellm/proxy/pass_through_endpoints/streaming_handler.py @@ -42,6 +42,20 @@ async def chunk_processor( - Inject cost into chunks if include_cost_in_streaming_usage is enabled """ try: + # Use the true request-entry timestamp held on the logging + # object when it's earlier than the start_time passed in. The + # caller's start_time is captured at the streaming-iterator + # constructor, which runs AFTER the upstream HTTP response + # has already been received — too late to represent when the + # client's request entered the proxy. Without this override, + # SpendLogs.startTime is artificially deflated by the full + # TTFT, making `endTime - startTime` shorter than reality. + true_start = getattr(litellm_logging_obj, "start_time", None) + if isinstance(true_start, datetime) and ( + not isinstance(start_time, datetime) or true_start < start_time + ): + start_time = true_start + raw_bytes: List[bytes] = [] # Extract model name for cost injection model_name = PassThroughStreamingHandler._extract_model_for_cost_injection( @@ -52,6 +66,16 @@ async def chunk_processor( ) async for chunk in response.aiter_bytes(): + # Record TTFT on the first chunk that arrives so spend_logs + # `completionStartTime` reflects real time-to-first-token. + # Without this, the fallback at + # litellm_logging.py:1834-1837 sets completion_start_time = + # end_time, making TTFT equal to total Duration for every + # passthrough streaming request. + if litellm_logging_obj.completion_start_time is None: + litellm_logging_obj._update_completion_start_time( + completion_start_time=datetime.now() + ) raw_bytes.append(chunk) if ( getattr(litellm, "include_cost_in_streaming_usage", False)