diff --git a/problem_tracker.md b/problem_tracker.md index 43472e017a4..0bef3e9873e 100644 --- a/problem_tracker.md +++ b/problem_tracker.md @@ -34,10 +34,10 @@ Multiple test batches comparing Prometheus enabled vs disabled: * Later batches showed smaller overhead * Hypothesis formed: provider speed + cache behavior affects reproducibility -| Batch | Callbacks | avg | p95 | >1s | -| ----------- | --------- | ----------- | ----- | ---- | -| Worst cases | on | ~0.45–0.54s | ~1.2s | 5–8% | -| Control | off | ~0.30–0.38s | ~0.4s | ~1% | +| Batch | Callbacks | avg | p95 | >1s | +| ----------- | --------- | ------------- | ------ | ----- | +| Worst cases | on | ~0.45–0.54s | ~1.2s | 5–8% | +| Control | off | ~0.30–0.38s | ~0.4s | ~1% | --- @@ -47,11 +47,11 @@ Multiple test batches comparing Prometheus enabled vs disabled: Random user IDs reliably triggered the issue: -| User IDs | Callbacks | p95 | >1s | -| ---------- | --------- | ------ | ----- | -| random | on | ~1.05s | ~5% | -| random | off | ~0.50s | ~1.5% | -| sequential | on/off | ~0.39s | ~0.8% | +| User IDs | Callbacks | p95 | >1s | +| ---------- | --------- | ------- | ------ | +| random | on | ~1.05s | ~5% | +| random | off | ~0.50s | ~1.5% | +| sequential | on/off | ~0.39s | ~0.8% | **Conclusion:** Prometheus overhead becomes reproducible when user lookups cause cache misses. @@ -79,10 +79,10 @@ Prometheus overhead becomes reproducible when user lookups cause cache misses. #### Early Return Tests -| Configuration | >1s | -| --------------- | ---- | -| Full Prometheus | 5.6% | -| Early return | 2.1% | +| Configuration | >1s | +| --------------- | ----- | +| Full Prometheus | 5.6% | +| Early return | 2.1% | ➡️ Confirms Prometheus callback is on the critical path. @@ -110,11 +110,11 @@ Prometheus overhead becomes reproducible when user lookups cause cache misses. #### Prometheus ON vs OFF -| Metric | On | Off | Δ | -| -------- | ------ | ------ | ---- | -| Mean avg | 0.408s | 0.322s | +27% | -| Mean p95 | 0.911s | 0.641s | +42% | -| >1s | 4.4% | 1.7% | 2.6× | +| Metric | On | Off | Δ | +| -------- | ------ | ------ | ----- | +| Mean avg | 0.408s | 0.322s | +27% | +| Mean p95 | 0.911s | 0.641s | +42% | +| >1s | 4.4% | 1.7% | 2.6× | **Target after fix:** Prometheus-on within ~10–15% of Prometheus-off. @@ -154,9 +154,9 @@ This behavior: ### Reference Baseline (Callbacks Off) -| avg | p95 | >1s | >5s | -| ----- | ----- | ---- | ---- | -| ~4.0s | ~6.3s | 100% | ~33% | +| avg | p95 | >1s | >5s | +| ------ | ------ | ----- | ----- | +| ~4.0s | ~6.3s | 100% | ~33% | --- @@ -174,11 +174,11 @@ Baseline spikes are driven by: #### 1000 requests / 100 users -| User mode | avg | p95 | >1s | -| ---------- | ----- | ----- | ---- | -| none | ~1.0s | ~7.9s | 10% | -| sequential | ~1.5s | ~8.6s | ~32% | -| random | ~1.6s | ~8.0s | ~34% | +| User mode | avg | p95 | >1s | +| ---------- | ------ | ------ | ------ | +| none | ~1.0s | ~7.9s | 10% | +| sequential | ~1.5s | ~8.6s | ~32% | +| random | ~1.6s | ~8.0s | ~34% | **Key insight:** Passing `user` dramatically increases latency. @@ -189,10 +189,10 @@ Passing `user` dramatically increases latency. #### Callbacks Off, Random Users -| Req/user | avg | >1s | -| -------- | ----- | ---- | -| 1 | ~8.6s | 100% | -| 10 | ~1.5s | 33% | +| Req/user | avg | >1s | +| -------- | ------ | ----- | +| 1 | ~8.6s | 100% | +| 10 | ~1.5s | 33% | ➡️ Cache hits on subsequent requests reduce latency by ~6× @@ -200,10 +200,10 @@ Passing `user` dramatically increases latency. ### Created Users vs Random Users -| Mode | avg (10/user) | >1s | -| ------- | ------------- | --- | -| random | ~1.5s | 33% | -| created | ~1.2s | 10% | +| Mode | avg (10/user) | >1s | +| ------- | ------------- | ---- | +| random | ~1.5s | 33% | +| created | ~1.2s | 10% | --- @@ -211,20 +211,20 @@ Passing `user` dramatically increases latency. **1 request per user** (100 requests, 100 users): -| User mode | File | avg | p95 | max | Above 1s | -|-----------|------|-----|-----|-----|----------| -| none | `user_none_1_requests_per_user.txt` | 11.836s | 20.736s | 22.443s | 100% | -| created | `callbacks_off_1_per_user_created.txt` | 8.923s | 14.962s | 15.774s | 100% | -| random | `callbacks_off_1_per_user.txt` | 8.647s | 14.909s | 15.668s | 100% | +| User mode | File | avg | p95 | max | Above 1s | +| --------- | ------------------------------------- | ------- | ------- | ------- | -------- | +| none | `user_none_1_requests_per_user.txt` | 11.836s | 20.736s | 22.443s | 100% | +| created | `callbacks_off_1_per_user_created.txt` | 8.923s | 14.962s | 15.774s | 100% | +| random | `callbacks_off_1_per_user.txt` | 8.647s | 14.909s | 15.668s | 100% | **10 requests per user** (1000 requests, 100 users): -| User mode | File | avg | p95 | max | Above 1s | -|-----------|------|-----|-----|-----|----------| -| none (callbacks off) | `callbacks_off_user_none.txt` | 0.998s | 7.966s | 14.698s | 10.0% | -| none (callbacks on) | `callbacks_on_user_none.txt` | 1.099s | 7.767s | 14.873s | 10.0% | -| created | `callbacks_off_10_per_user_created.txt` | 1.198s | 8.839s | 15.483s | 10.0% | -| random | `callbacks_off_10_per_user.txt` | 1.538s | 8.275s | 15.499s | 33.2% | +| User mode | File | avg | p95 | max | Above 1s | +| --------------------- | ---------------------------------------- | ------ | ------ | ------- | -------- | +| none (callbacks off) | `callbacks_off_user_none.txt` | 0.998s | 7.966s | 14.698s | 10.0% | +| none (callbacks on) | `callbacks_on_user_none.txt` | 1.099s | 7.767s | 14.873s | 10.0% | +| created | `callbacks_off_10_per_user_created.txt` | 1.198s | 8.839s | 15.483s | 10.0% | +| random | `callbacks_off_10_per_user.txt` | 1.538s | 8.275s | 15.499s | 33.2% | ### Findings @@ -237,10 +237,10 @@ The latency spike is high regardless of whether a user is passed to the payload - [x] User none + caching true → `user_none_1_request_per_user_local_llm_cache_on.txt` - [x] User none + caching false → `user_none_1_request_per_user_local_llm_cache_off.txt` -| Config | File | avg | p95 | max | Above 1s | -|--------|------|-----|-----|-----|----------| -| User none, local LLM (localhost:8090), cache ON | `user_none_1_request_per_user_local_llm_cache_on.txt` | 15.204s | 26.543s | 27.706s | 100% | -| User none, local LLM (localhost:8090), cache OFF | `user_none_1_request_per_user_local_llm_cache_off.txt` | 15.449s | 26.317s | 27.430s | 100% | +| Config | File | avg | p95 | max | Above 1s | +| -------------------------------------------------- | --------------------------------------------------- | ------- | ------- | ------- | -------- | +| User none, local LLM (localhost:8090), cache ON | `user_none_1_request_per_user_local_llm_cache_on.txt` | 15.204s | 26.543s | 27.706s | 100% | +| User none, local LLM (localhost:8090), cache OFF | `user_none_1_request_per_user_local_llm_cache_off.txt` | 15.449s | 26.317s | 27.430s | 100% | --- @@ -258,11 +258,11 @@ The latency spike is high regardless of whether a user is passed to the payload - [x] **Test completed:** `validation_123.txt` -| Config | File | avg | p95 | max | Above 1s | -|--------|------|-----|-----|-----|----------| -| **Minimal config** | `validation_123.txt` | **8.654s** | 15.065s | 15.807s | 100% | -| Full config (cache ON) | `user_none_1_request_per_user_local_llm_cache_on.txt` | 15.204s | 26.543s | 27.706s | 100% | -| Full config (cache OFF) | `user_none_1_requests_per_user_local_llm_cache_off.txt` | 15.449s | 26.317s | 27.430s | 100% | +| Config | File | avg | p95 | max | Above 1s | +| ----------------------- | ---------------------------------------------------- | --------- | ------- | ------- | -------- | +| **Minimal config** | `validation_123.txt` | **8.654s**| 15.065s | 15.807s | 100% | +| Full config (cache ON) | `user_none_1_request_per_user_local_llm_cache_on.txt` | 15.204s | 26.543s | 27.706s | 100% | +| Full config (cache OFF) | `user_none_1_requests_per_user_local_llm_cache_off.txt` | 15.449s | 26.317s | 27.430s | 100% | **Improvement: 43% faster** (15.2s → 8.6s avg) @@ -300,15 +300,15 @@ The latency spike is high regardless of whether a user is passed to the payload Profile captured with `test_config_minimal.yaml`. Ordered by cumtime, normalized per request: -| Component | Calls | Cumtime | Per-call (est.) | Notes | -| ------------------------------------ | --------- | ------- | --------------- | ---------------------------------- | -| user_api_key_auth | 200 | 12.58s | ~63ms | Auth entry point | -| _user_api_key_auth_builder | 100 | 12.55s | **~125ms** | Main auth logic | -| log_db_metrics wrapper | 100 | 12.53s | **~125ms** | Still in path despite no DB | -| FastAPI solve_dependencies | 1600/200 | 12.61s | ~63ms | Dependency injection for chat route| -| Starlette/FastAPI middleware/routing | 600 | ~12.7s | ~21ms | Middleware stack | -| annotationlib call_annotate_function | 23400 | 8.28s | ~0.4ms × many | Python 3.14 annotation processing | -| router acompletion | 586 | 0.67s | ~1ms | LLM call path (mostly I/O) | +| Component | Calls | Cumtime | Per-call (est.) | Notes | +| ------------------------------------ | --------- | ------- | --------------- | ----------------------------------- | +| user_api_key_auth | 200 | 12.58s | ~63ms | Auth entry point | +| _user_api_key_auth_builder | 100 | 12.55s | **~125ms** | Main auth logic | +| log_db_metrics wrapper | 100 | 12.53s | **~125ms** | Still in path despite no DB | +| FastAPI solve_dependencies | 1600/200 | 12.61s | ~63ms | Dependency injection for chat route | +| Starlette/FastAPI middleware/routing | 600 | ~12.7s | ~21ms | Middleware stack | +| annotationlib call_annotate_function | 23400 | 8.28s | ~0.4ms × many | Python 3.14 annotation processing | +| router acompletion | 586 | 0.67s | ~1ms | LLM call path (mostly I/O) | **Key finding:** Auth + log_db_metrics ≈ **125ms per request** even with no database. Expected for a simple master_key compare: microseconds. @@ -325,23 +325,23 @@ Profile captured with `test_config_minimal.yaml`. Ordered by cumtime, normalized ### Results -| Concurrency | File | avg | p95 | max | >1s | >5s | >10s | -|-------------|-----------------------------------|--------|--------|--------|-----|-----|------| -| 1 | `concurrency_1_requests_100.txt` | 0.012s | 0.007s | 0.716s | 0% | 0% | 0% | -| 10 | `concurrency_10_requests_100.txt` | 0.144s | 1.195s | 2.034s | 7% | 0% | 0% | -| 30 | `concurrency_30_requests_100.txt` | 0.833s | 3.861s | 4.836s | 27% | 0% | 0% | -| 50 | `concurrency_50_requests_100.txt` | 2.087s | 6.975s | 7.689s | 47% | 18% | 0% | -| 100 | `concurrency_100_requests_100.txt` | 7.721s | 14.019s | 14.657s | 97% | 69% | 33% | +| Concurrency | File | avg | p95 | max | >1s | >5s | >10s | +| ----------- | ---------------------------------- | ------ | ------- | ------- | ---- | ---- | ---- | +| 1 | `concurrency_1_requests_100.txt` | 0.012s | 0.007s | 0.716s | 0% | 0% | 0% | +| 10 | `concurrency_10_requests_100.txt` | 0.144s | 1.195s | 2.034s | 7% | 0% | 0% | +| 30 | `concurrency_30_requests_100.txt` | 0.833s | 3.861s | 4.836s | 27% | 0% | 0% | +| 50 | `concurrency_50_requests_100.txt` | 2.087s | 6.975s | 7.689s | 47% | 18% | 0% | +| 100 | `concurrency_100_requests_100.txt` | 7.721s | 14.019s | 14.657s | 97% | 69% | 33% | **Δ vs baseline (c=1):** -| Concurrency | Δ avg | Δ p95 | Δ max | -|-------------|--------------------|---------------------|----------------| -| 1 | — | — | — | -| 10 | +1,100% (12×) | +16,971% (171×) | +184% (2.8×) | -| 30 | +6,842% (69×) | +55,057% (551×) | +575% (6.8×) | -| 50 | +17,292% (174×) | +99,529% (996×) | +974% (10.7×) | -| 100 | +64,242% (643×) | +200,129% (2,002×) | +1,947% (20.5×)| +| Concurrency | Δ avg | Δ p95 | Δ max | +| ----------- | ------------------ | ------------------ | --------------- | +| 1 | — | — | — | +| 10 | +1,100% (12×) | +16,971% (171×) | +184% (2.8×) | +| 30 | +6,842% (69×) | +55,057% (551×) | +575% (6.8×) | +| 50 | +17,292% (174×) | +99,529% (996×) | +974% (10.7×) | +| 100 | +64,242% (643×) | +200,129% (2,002×) | +1,947% (20.5×) | ### Analysis @@ -361,13 +361,13 @@ cProfile was run at each concurrency level with: `$env:DATABASE_URL = $null; $env:REDIS_URL = $null; python -m cProfile -o concurrency_N_requests_100.prof -m litellm.proxy.proxy_cli --config test_config_minimal.yaml` (Proxy runs until latency test completes 100 requests, then stopped.) -| Concurrency | Profile file | -|-------------|--------------------------------------| -| 1 | `concurrency_1_requests_100.prof` | -| 10 | `concurrency_10_requests_100.prof` | -| 30 | `concurrency_30_requests_100.prof` | -| 50 | `concurrency_50_requests_100.prof` | -| 100 | `concurrency_100_requests_100.prof` | +| Concurrency | Profile file | +| ----------- | ------------------------------------- | +| 1 | `concurrency_1_requests_100.prof` | +| 10 | `concurrency_10_requests_100.prof` | +| 30 | `concurrency_30_requests_100.prof` | +| 50 | `concurrency_50_requests_100.prof` | +| 100 | `concurrency_100_requests_100.prof` | - [x] `concurrency_1_requests_100.prof` - [x] `concurrency_10_requests_100.prof` @@ -382,8 +382,6 @@ cProfile was run at each concurrency level with: - **2× more completion calls per request** *(all OS)* – `router.acompletion` chain: ~309 calls (~3/req) at c=1 vs ~599 (~6/req) at c=100; suggests retries, fallbacks, or middleware work scaling with concurrency. - **Thread pool teardown** *(all OS)* – c=100: ~14.7s in `threading.join` / ThreadPoolExecutor shutdown (29 threads); c=1: negligible. Suggests blocking work delegated to thread pool under load. - **Context switching** *(all OS)* – `Context.run` ~15s cumtime at c=100 (7,503 calls); not in top 100 at c=1. -- **I/O contention** *(Windows-specific metric)* – `GetQueuedCompletionStatus` ~21ms/call at c=100 vs ~13ms at c=1 (~60% slower per call under high concurrency). Same underlying phenomenon applies on Linux/macOS (epoll/kqueue). -- **Event loop saturation** *(all OS)* – c=100: ~16 `_run_once`/s vs c=1: ~41/s; each iteration does more work under load. ### Checklist @@ -391,4 +389,32 @@ cProfile was run at each concurrency level with: - [x] Concurrency 10 → `concurrency_10_requests_100.txt` - [x] Concurrency 30 → `concurrency_30_requests_100.txt` - [x] Concurrency 50 → `concurrency_50_requests_100.txt` -- [x] Concurrency 100 → `concurrency_100_requests_100.txt` \ No newline at end of file +- [x] Concurrency 100 → `concurrency_100_requests_100.txt` + +--- + +## Real Auth vs Mock Auth Comparison + +**Setup:** Minimal config (`test_config_minimal.yaml`), no DB/Redis. Command: `poetry run python measure_latency.py --user-mode none --key-mode shared`. Instrumented with `[proxy] user_api_key_auth called at T` and `[proxy] chat/completions request received at T` prints. + +### Log Files + +| Auth mode | File | Description | +| --------- | ------------------------------------- | --------------------------------------------------------------------------- | +| Real | `proxy_real_auth_100_requests_log.txt` | Full auth path (`_read_request_body`, `_user_api_key_auth_builder`) | +| Mock | `proxy_mock_auth_100_requests_log.txt` | Early return with mock `UserAPIKeyAuth`; skips DB/cache and body parsing | + +### Findings + +| Metric | Real auth | Mock auth | +| --------------------------------- | ------------------------------------- | ------------------------ | +| Auth calls before first chat | 93 | 1 (interleaved) | +| First auth → first chat handler | ~47 ms | ~0.3–0.6 ms | +| Auth↔chat pattern | Auth burst; chat handler delayed | Auth and chat back-to-back | +| 100 requests throughput | ~250 ms (auth dominates) | ~152 ms | + +### Interpretation + +1. **Auth path is the bottleneck** — Real auth does 93 calls before the first request reaches the chat handler; mock auth processes each request immediately. The ~47 ms gap is consistent with cProfile (~63 ms per auth call under load). +2. **Queueing in real auth** — Auth invocations are serialized and block the chat route; mock auth removes that delay, so chat handlers run as soon as requests arrive. +3. **Confirms cProfile targets** — Aligns with cProfile: `user_api_key_auth` + `_user_api_key_auth_builder` + `log_db_metrics` ≈ 125 ms/req. Mocking auth eliminates that cost. \ No newline at end of file