scriptoriumadmin/litellm
1
0
Fork 0
mirror of https://github.com/BerriAI/litellm.git synced 2026-09-21 00:21:49 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 74

docs: update problem_tracker for perf testing notes

Browse source
This commit is contained in:
Alexsander Hamir 2026-02-09 17:47:27 -08:00
parent 66815c9f4f
commit c8eb55ac7b
1 changed files with 113 additions and 87 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

200
problem_tracker.md
View file

@ -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`
- [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.