scriptoriumadmin/litellm
1
0
Fork 0
mirror of https://github.com/BerriAI/litellm.git synced 2026-10-04 02:31:27 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 71

Add local LLM cache-on test and update problem_tracker

Browse source 
- problem_tracker: add user none + cache ON run (local LLM), results table and note
- user_none_1_request_per_user_local_llm_cache_on.txt: 100 req, 100 users, cache ON
This commit is contained in:
Alexsander Hamir 2026-02-09 12:30:36 -08:00
parent f01669ccde
commit 918f25b0f5
2 changed files with 276 additions and 277 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

429
problem_tracker.md
View file

@ -1,368 +1,243 @@
### Context - Problem 1
# Zurich Performance Investigation
**Issue:** Prometheus configured as a callback causes orders-of-magnitude worse performance (reported by Zurich).
This document tracks two **independent but compounding issues** discovered during performance testing:
**Reproduction:** Intermittent—requires many runs and configuration changes. Hypothesis: provider response speed may influence reproducibility.
1. **Prometheus callback overhead** — latency added only when Prometheus is enabled
2. **Baseline latency spikes** — large spikes that occur even when callbacks are disabled
### Next Steps
---
[x] {1} **Latency comparison (2 runs):** callbacks on vs off
## Problem 1: Prometheus Callback Overhead
**Run 1**
- [x] Callbacks on → `callbacks_on_3.txt`
- [x] Callbacks off → `callbacks_off_3.txt`
### Summary
**Run 2**
- [x] Callbacks on → `callbacks_on_4.txt`
- [x] Callbacks off → `callbacks_off_4.txt`
**Issue:**
When Prometheus is configured as a callback, request latency increases significantly. In reproducible scenarios, Prometheus increases:
* mean latency by ~27%
* p95 latency by ~42%
* requests >1s by ~2.6×
#### Conclusion
This issue was intermittent at first but became fully reproducible with random user IDs.
**Data summary**
---
| Batch | Callbacks | avg | p95 | Above 1s |
|----------------|-----------|--------|--------|----------|
| 1 (yesterday) | on | 0.539s | 1.257s | 8.1% |
| 1 | off | 0.382s | 0.429s | 1.6% |
| 2 (yesterday) | on | 0.453s | 0.472s | 3.4% |
| 2 | off | 0.383s | 0.450s | 1.0% |
| 3 (today) | on | 0.410s | 0.499s | 0.8% |
| 3 | off | 0.338s | 0.425s | 0.8% |
| 4 (today) | on | 0.374s | 0.438s | 0.8% |
| 4 | off | 0.316s | 0.391s | 0.8% |
### Reproduction Strategy
**Findings:** Yesterday (batches 1–2) showed a large impact: callbacks on had ~3× higher p95 and 5–8× more requests above 1s. Today (batches 3–4) shows only a modest overhead (~15–20% on avg/p95) with similar % above 1s. This supports the hypothesis that provider response speed influences reproducibility—faster responses today may have masked the issue.
#### Baseline: Callbacks On vs Off
[x] {2} Use local provider + artificial delays to test whether slower responses make the Prometheus callback issue more reproducible
**Run 1**
- [x] Callbacks on → `callbacks_on_5.txt`
- [x] Callbacks off → `callbacks_off_5.txt`
Multiple test batches comparing Prometheus enabled vs disabled:
#### Conclusion
**Key finding**
Adding artificial delays did not make the Prometheus callback impact more reproducible. The difference between callbacks on and off remained intermittent.
* Early batches showed severe impact
* Later batches showed smaller overhead
* Hypothesis formed: provider speed + cache behavior affects reproducibility
[x] {3} Let's increase the concurrency of the test and the total number of requests **(200 concurrent users / 15000)**
**Run 1**
- [x] Callbacks on → `callbacks_on_6.txt`
- [x] Callbacks off → `callbacks_off_6.txt`
| 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% |
#### Conclusion
---
Higher concurrency and request number made performance worse for both cases.
### Making the Issue Reproducible
#### Random vs Sequential User IDs
[x] {4} Random ID generation for the user being passed onto the payload instead of sequential 1/2/3/4 ids.
**Run 1** - Introduce the random ID generation
- [x] Callbacks on → `callbacks_on_7.txt`
- [x] Callbacks off → `callbacks_off_7.txt`
**Run 2** - Remove the random ID generation
- [x] Callbacks on → `callbacks_on_8.txt`
- [x] Callbacks off → `callbacks_off_8.txt`
**Run 3** - Bring back the random ID generation
- [x] Callbacks on → `callbacks_on_9.txt`
- [x] Callbacks off → `callbacks_off_9.txt`
Random user IDs reliably triggered the issue:
#### Conclusion
| User IDs | Callbacks | p95 | >1s |
| ---------- | --------- | ------ | ----- |
| random | on | ~1.05s | ~5% |
| random | off | ~0.50s | ~1.5% |
| sequential | on/off | ~0.39s | ~0.8% |
**Data summary**
**Conclusion:**
Prometheus overhead becomes reproducible when user lookups cause cache misses.
| Run | User IDs | Callbacks | avg | p95 | Above 1s |
|-------|------------|-----------|--------|--------|----------|
| 1 | random | on | 0.415s | 1.014s | 5.1% |
| 1 | random | off | 0.303s | 0.574s | 1.4% |
| 2 | sequential | on | 0.343s | 0.389s | 0.8% |
| 2 | sequential | off | 0.217s | 0.285s | 0.8% |
| 3 | random | on | 0.484s | 1.052s | 5.4% |
| 3 | random | off | 0.286s | 0.504s | 1.6% |
---
**Findings:** With random user IDs, Prometheus callbacks clearly increase latency: ~5% of requests exceed 1s vs ~1.5% when callbacks are off. With sequential IDs, the difference disappears—both configs show ~0.8% above 1s. Random IDs make the Prometheus callback impact reproducible.
### Root Cause Analysis
### Breakpoint
#### Suspected Areas
We now have a concrete reproduction. To maximize the chance of fixing Zurich's perf issues, we should address both:
1. **`_increment_remaining_budget_metrics`**
1. **Prometheus overhead** — Extra latency when Prometheus callbacks are enabled.
2. **Baseline latency spikes** — Requests exceeding 1s even with callbacks off (~1.5% in our runs).
* Performs DB/cache lookups for key, team, and user
* Executed on every request
2. **Callback execution model**
* Callbacks run sequentially and block response completion
3. **Prometheus label cardinality**
* High-cardinality labels amplify contention
### Prometheus overhead
---
**Places to investigate (in order of suspicion):**
### Isolation & Bisection
1. **`litellm/integrations/prometheus.py`**
- `async_log_success_event` (line ~877) — main entry; runs on every completion
- `_increment_remaining_budget_metrics` (line ~1171) — async; calls `_assemble_key_object`, `_assemble_team_object`, `_assemble_user_object`, which may hit DB/cache
- `_assemble_user_object` (line ~2877) — fetches from DB when metadata is incomplete
- `_assemble_team_object` (line ~2662) — calls `get_team_object` (DB/cache)
- `_assemble_key_object` (line ~2807) — fetches key from cache/DB
#### Early Return Tests
2. **`prometheus_client` usage**
- `.labels(**kwargs).inc()` / `.observe()` / `.set()` — sync, may contend on the registry lock when many label combinations are used
- High cardinality from `end_user`, `user_api_key`, `model_id`, etc. can create many series
| Configuration | >1s |
| --------------- | ---- |
| Full Prometheus | 5.6% |
| Early return | 2.1% |
3. **Callback invocation**
- `litellm/litellm_core_utils/litellm_logging.py` (line ~2569) — callbacks run sequentially; Prometheus blocks the response until it finishes
➡️ Confirms Prometheus callback is on the critical path.
4. **`prometheus_system` callback** (if relevant)
- `litellm/integrations/prometheus_services.py` — service-level metrics (Redis, Postgres); separate from completion flow
---
**Action Plan**
#### Async vs Sync Breakdown
1. Early return from `async_log_success_event` to confirm Prometheus is the cause.
* Skipping **sync metric updates** → **no improvement**
* Skipping **budget metrics DB lookups** → **major improvement**
| Config | File | avg | p95 | Above 1s |
|---------------------|-------------------------|--------|--------|----------|
| Callbacks on + early return | `callbacks_on_10a.txt` | 0.361s | 0.631s | 2.1% |
| Callbacks on + full Prometheus | `callbacks_on_10b.txt` | 0.463s | 1.059s | 5.6% |
➡️ Root cause isolated to `_increment_remaining_budget_metrics`
**Conclusion:** Early return reduces requests above 1s from 5.6% to 2.1%. Prometheus callback is confirmed as the source of the overhead.
---
2. **Bisect: async vs sync work** — Narrow down whether the overhead comes from async DB/cache lookups or sync metric updates.
### Fix Validation
**Test A:** Early return *after* `_increment_remaining_budget_metrics` (skip sync metric updates). If latency improves → sync Prometheus updates are the culprit.
#### Confirming the Cause
**Run 1** - Introduce the random ID generation
- [x] Callbacks on + early return → `callbacks_on_11a.txt`
- [x] Callbacks on + no early return → `callbacks_on_11b.txt`
* Commenting out `_increment_remaining_budget_metrics` **eliminated the latency spike**
* Moving it off the critical path with `create_task()` showed mixed results due to variance
**Conclusion:** No effect. Skipping sync metric updates did not improve latency—sync Prometheus updates are not the culprit.
---
**Test B:** Early return *before* `_increment_remaining_budget_metrics` (skip async budget metrics only). If latency improves → DB/cache lookups in budget metrics are the culprit.
### Baseline Comparison (6 runs, 30k requests)
**Run 1** - Introduce the random ID generation
- [x] Callbacks on + early return → `callbacks_on_12a.txt`
- [x] Callbacks on + no early return → `callbacks_on_12b.txt`
#### Prometheus ON vs OFF
**Conclusion:** Early return reduced requests above 1s from 4.8% to 1.9%. Root cause: `_increment_remaining_budget_metrics` (DB/cache lookups for key, team, and user budget).
| Metric | On | Off | Δ |
| -------- | ------ | ------ | ---- |
| Mean avg | 0.408s | 0.322s | +27% |
| Mean p95 | 0.911s | 0.641s | +42% |
| >1s | 4.4% | 1.7% | 2.6× |
3. **Isolate: comment out `_increment_remaining_budget_metrics`** — Run everything else (including the sync metric updates below). Confirms whether the function is the main cause or if the code below contributes.
**Target after fix:** Prometheus-on within ~10–15% of Prometheus-off.
- [x] Comment out the function call only, run everything below → `callbacks_on_13a.txt`
- [x] Bring the function back on => `callbacks_on_13b.txt`
---
**Conclusion:** Commenting out that function stoped the latency issue caused by prometheus.
### Final Resolution
4. **Patch: run `_increment_remaining_budget_metrics` off critical path** — Use `asyncio.create_task()` instead of `await` so budget metrics run in background and no longer block request latency.
* Root cause: **DB lookups on every request inside Prometheus budget metrics**
* Cache was silently failing due to suppressed DB errors
* Fixes:
**Run 1**
- [x] Callbacks on + patch (create_task) → `callbacks_on_14a.txt`
- [x] Callbacks on + no patch (baseline) → `callbacks_on_14b.txt`
* Disable `check_db_only`
* Surface budget lookup failures in logs
* Parallelize budget lookups
| Config | File | avg | p95 | Above 1s |
|----------|-------------------------|--------|--------|----------|
| Patch | `callbacks_on_14a.txt` | 0.468s | 0.911s | 4.4% |
| Baseline | `callbacks_on_14b.txt` | 0.362s | 0.784s | 3.4% |
**Fix commits**
**Conclusion:** In this run, the patch did not improve latency—baseline (3.4% above 1s) outperformed the patch (4.4%). Run-to-run variance may be a factor; additional runs recommended to confirm.
* `30534d7e82` — cache behavior fix
* `d37796662` — error visibility
5. **Baseline: 10 runs with Prometheus on, 10 with Prometheus off** — Measure latency to establish a strong baseline before testing the parallelization patch.
---
**Prometheus on**
- [x] Run 1 → `callbacks_on_15_1.txt`
- [x] Run 2 → `callbacks_on_15_2.txt`
- [x] Run 3 → `callbacks_on_15_3.txt`
- [x] Run 4 → `callbacks_on_15_4.txt`
- [x] Run 5 → `callbacks_on_15_5.txt`
- [x] Run 6 → `callbacks_on_15_6.txt`
## Problem 2: Baseline Latency Spikes (Independent of Prometheus)
| Run | File | avg | p95 | A1s | A2s | A3s | A4s | A5s | A6s | A7s | A8s |
|-----|-------------------------|--------|--------|-------|-------|-------|-------|-------|-------|-------|-------|
| 1 | `callbacks_on_15_1.txt` | 0.405s | 0.822s | 3.1% | 1.1% | 0.9% | 0.7% | 0.5% | 0.3% | 0.2% | 0.0% |
| 2 | `callbacks_on_15_2.txt` | 0.442s | 0.887s | 4.2% | 1.7% | 1.0% | 0.8% | 0.6% | 0.4% | 0.3% | 0.1% |
| 3 | `callbacks_on_15_3.txt` | 0.511s | 1.131s | 6.3% | 1.9% | 1.2% | 0.9% | 0.6% | 0.4% | 0.3% | 0.1% |
| 4 | `callbacks_on_15_4.txt` | 0.381s | 0.952s | 4.6% | 1.5% | 0.9% | 0.7% | 0.5% | 0.3% | 0.2% | 0.0% |
| 5 | `callbacks_on_15_5.txt` | 0.318s | 0.565s | 2.2% | 1.1% | 0.8% | 0.6% | 0.4% | 0.3% | 0.2% | 0.0% |
| 6 | `callbacks_on_15_6.txt` | 0.393s | 1.106s | 5.7% | 1.9% | 1.0% | 0.7% | 0.4% | 0.3% | 0.2% | 0.0% |
### Summary
**Merged (6 runs, 30k requests):** mean avg 0.408s, mean p95 0.911s.
Above 1s: 1307 (4.4%), 2s: 455 (1.5%), 3s: 292 (1.0%), 4s: 213 (0.7%), 5s: 152 (0.5%), 6s: 101 (0.3%), 7s: 62 (0.2%), 8s: 18 (0.1%), 9s: 1 (0.0%), 10s: 0 (0.0%).
**Issue:**
Even with Prometheus fully disabled, Zurich sees extreme latency spikes (p95 >6s, 100% >1s).
**Prometheus off**
- [x] Run 1 → `callbacks_off_15_1.txt`
- [x] Run 2 → `callbacks_off_15_2.txt`
- [x] Run 3 → `callbacks_off_15_3.txt`
- [x] Run 4 → `callbacks_off_15_4.txt`
- [x] Run 5 → `callbacks_off_15_5.txt`
- [x] Run 6 → `callbacks_off_15_6.txt`
This behavior:
| Run | File | avg | p95 | A1s | A2s | A3s | A4s | A5s | A6s | A7s | A8s |
|-----|--------------------------|--------|--------|-------|-------|-------|-------|-------|-------|-------|-------|
| 1 | `callbacks_off_15_1.txt` | 0.319s | 0.693s | 2.0% | 0.9% | 0.8% | 0.6% | 0.5% | 0.4% | 0.3% | 0.1% |
| 2 | `callbacks_off_15_2.txt` | 0.328s | 0.696s | 1.8% | 0.9% | 0.8% | 0.6% | 0.4% | 0.3% | 0.2% | 0.0% |
| 3 | `callbacks_off_15_3.txt` | 0.276s | 0.540s | 1.2% | 0.9% | 0.7% | 0.6% | 0.4% | 0.3% | 0.2% | 0.0% |
| 4 | `callbacks_off_15_4.txt` | 0.376s | 0.741s | 2.1% | 0.9% | 0.8% | 0.6% | 0.5% | 0.4% | 0.2% | 0.1% |
| 5 | `callbacks_off_15_5.txt` | 0.347s | 0.580s | 1.7% | 0.9% | 0.8% | 0.6% | 0.5% | 0.3% | 0.2% | 0.0% |
| 6 | `callbacks_off_15_6.txt` | 0.288s | 0.598s | 1.5% | 0.9% | 0.7% | 0.6% | 0.4% | 0.3% | 0.1% | 0.0% |
* Affects callbacks on and off equally
* Is unrelated to the Prometheus fix
* Scales with end_user lookup patterns
**Merged (6 runs, 30k requests):** mean avg 0.322s, mean p95 0.641s.
Above 1s: 521 (1.7%), 2s: 271 (0.9%), 3s: 225 (0.8%), 4s: 180 (0.6%), 5s: 139 (0.5%), 6s: 98 (0.3%), 7s: 59 (0.2%), 8s: 15 (0.1%), 9s: 0 (0.0%), 10s: 0 (0.0%).
---
**Comparison (Prometheus on vs off)**
### Reference Baseline (Callbacks Off)
| Metric | Prometheus on | Prometheus off | Δ |
|--------------|---------------|----------------|----------|
| Mean avg | 0.408s | 0.322s | +27% |
| Mean p95 | 0.911s | 0.641s | +42% |
| Above 1s | 1307 (4.4%) | 521 (1.7%) | +2.6× |
| Above 2s | 455 (1.5%) | 271 (0.9%) | +1.7× |
| Above 3s | 292 (1.0%) | 225 (0.8%) | +1.3× |
| avg | p95 | >1s | >5s |
| ----- | ----- | ---- | ---- |
| ~4.0s | ~6.3s | 100% | ~33% |
Requests above threshold (bar length ∝ %):
---
```
Above 1s on ██████████████████████ 4.4% off ████████ 1.7%
Above 2s on ███████ 1.5% off ████ 0.9%
Above 3s on █████ 1.0% off ████ 0.8%
```
### Hypothesis
**Expectation (targets when root cause is fixed)**
Baseline spikes are driven by:
After addressing `_increment_remaining_budget_metrics` (e.g. parallelization, caching, or moving off critical path), Prometheus-on should approach Prometheus-off performance:
* `end_user` DB lookups
* cache misses (especially for non-existent users)
* provider-side queuing under concurrency
| Metric | Current (on) | Target (on) | Baseline (off) |
|------------|--------------|--------------|----------------|
| Mean avg | 0.408s | ≤ 0.35s | 0.322s |
| Mean p95 | 0.911s | ≤ 0.70s | 0.641s |
| Above 1s | 4.4% | ≤ 2.5% | 1.7% |
| Above 2s | 1.5% | ≤ 1.0% | 0.9% |
| Above 3s | 1.0% | ≤ 0.9% | 0.8% |
---
Success = Prometheus-on metrics within ~10–15% of Prometheus-off, so enabling Prometheus has minimal impact on user-facing latency.
### User Mode Experiments
**Conclusion:**
#### 1000 requests / 100 users
6. [x] **Patch: parallelize the three budget metric lookups** — Use `asyncio.gather()` instead of sequential `await` so key, team, and user lookups run in parallel.
| 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.
### Final Conclusion
---
The issue was caused by hitting the database on every request when Prometheus was used as a callback. Commit `30534d7e82` fixes this by setting `check_db_only` to `False`.
### One Request vs Many Requests per User
> It was hard to diagnose because Prometheus was catching database errors and only logging them at debug level. Fixed by commit `d37796662` (adds `_log_budget_lookup_failure` to surface errors). This error is very important—it stops the cache from working properly.
#### Callbacks Off, Random Users
| Req/user | avg | >1s |
| -------- | ----- | ---- |
| 1 | ~8.6s | 100% |
| 10 | ~1.5s | 33% |
➡️ Cache hits on subsequent requests reduce latency by ~6×
## Baseline Latency Spikes (Separate from Prometheus)
---
**Issue:** Zurich reports huge latency spikes even when callbacks are off. Unlike the Prometheus callback issue (which adds ~2.6× latency when enabled), this baseline behavior affects both configs roughly equally.
### Created Users vs Random Users
**Reference data:** 42 requests, 42 users, fire-as-fast-as-possible
| Mode | avg (10/user) | >1s |
| ------- | ------------- | --- |
| random | ~1.5s | 33% |
| created | ~1.2s | 10% |
| Config | avg | p95 | Above 1s | Above 5s |
|-----------------|--------|--------|----------|----------|
| Callbacks off | 4.034s | 6.345s | 100% | 33.3% |
| Callbacks on | 4.183s | 6.620s | 100% | 35.7% |
---
### Full Test Comparison (callbacks off)
**Reference files:** `callbacks_off_baseline.txt`, `callbacks_on_baseline.txt`
**1 request per user** (100 requests, 100 users):
### Next Steps
| 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% |
**Context - Problem 2:** Callbacks on vs off no longer affects latency (Prometheus fix). The remaining baseline spikes are likely from end_user lookups, provider latency, or other bottlenecks. Comparing user modes will isolate whether passing `user` (and cache behavior) contributes.
**10 requests per user** (1000 requests, 100 users):
**Measure baseline latency with each user mode** (run `measure_latency.py`):
| 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% |
| Mode | Command | What it isolates |
|-------------|-----------------------------|--------------------------------------------------------------------------|
| `none` | `--user-mode none` | No end_user lookup; pure proxy + provider latency |
| `sequential`| `--user-mode sequential` | End_user lookup with IDs 1,2,3,… (reused per user → cache hits) |
| `random` | `--user-mode random` | End_user lookup with unique random IDs per user → more cache misses |
### Findings
**Callbacks on** (Prometheus enabled in proxy config):
The latency spike is high regardless of whether a user is passed to the payload or not.
- [x] `--user-mode none` → `callbacks_on_user_none.txt`
- [x] `--user-mode sequential` → `callbacks_on_user_sequential.txt`
- [x] `--user-mode random` → `callbacks_on_user_random.txt`
---
**Callbacks off** (Prometheus disabled in proxy config):
### Use a local LLM mock provider
- [x] `--user-mode none` → `callbacks_off_user_none.txt`
- [x] `--user-mode sequential` → `callbacks_off_user_sequential.txt`
- [x] `--user-mode random` → `callbacks_off_user_random.txt`
- [x] User none + caching true → `user_none_1_request_per_user_local_llm_cache_on.txt`
**Callbacks off + per_user keys** (one key per user via `/key/generate`; isolates key lookup vs shared-key cache):
| 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% |
- [x] `--user-mode none --key-mode per_user` → `callbacks_off_user_none_key_per_user.txt`
- [x] `--user-mode sequential --key-mode per_user` → `callbacks_off_user_sequential_key_per_user.txt`
- [x] `--user-mode random --key-mode per_user` → `callbacks_off_user_random_key_per_user.txt`
#### Analysis (1000 requests, 100 users)
**Data summary**
| Config | User mode | Key mode | avg | p95 | Above 1s |
|---------------|-------------|-----------|--------|--------|----------|
| Callbacks on | none | shared | 1.099s | 7.767s | 10.0% |
| Callbacks on | sequential | shared | 1.702s | 8.524s | 37.7% |
| Callbacks on | random | shared | 1.773s | 8.598s | 42.5% |
| Callbacks off | none | shared | 0.998s | 7.966s | 10.0% |
| Callbacks off | sequential | shared | 1.532s | 8.626s | 31.8% |
| Callbacks off | random | shared | 1.556s | 8.036s | 34.3% |
| Callbacks off | none | per_user | 1.137s | 8.371s | 10.0% |
| Callbacks off | sequential | per_user | 1.767s | 9.057s | 40.6% |
| Callbacks off | random | per_user | 1.590s | 8.724s | 30.9% |
**Findings**
Passing `user` in the request payload spikes latency up to ~7×. Using a shared key vs per-user keys had no meaningful effect.
### Next Step: One Request vs Multiple Requests per User
**Config:** Callbacks off (Prometheus disabled in proxy config).
**Goal:** Compare latency when each simulated user sends 1 request vs many requests. With multiple requests per user, the same end_user ID is reused → cache hits on subsequent requests. One request per user → all cache misses for end_user lookups.
**How:** Edit `NUM_REQUESTS` and `NUM_CONCURRENT` in `measure_latency.py`, then run (`--user-mode random` recommended to stress end_user lookups):
| Scenario | NUM_REQUESTS | NUM_CONCURRENT | Req/user | Output file |
|-------------------|--------------|----------------|----------|---------------------------------------|
| One per user | 100 | 100 | 1 | `callbacks_off_1_per_user.txt` |
| Multiple per user | 1000 | 100 | 10 | `callbacks_off_10_per_user.txt` |
- [x] Run with `--user-mode random`, 100 requests, 100 users (1 per user) → `callbacks_off_1_per_user.txt`
- [x] Run with `--user-mode random`, 1000 requests, 100 users (10 per user) → `callbacks_off_10_per_user.txt`
**Same scenarios with `--user-mode created --key-mode per_user`** (happy path: pre-created end users):
| Scenario | NUM_REQUESTS | NUM_CONCURRENT | Req/user | Output file |
|-------------------|--------------|----------------|----------|---------------------------------------------|
| One per user | 100 | 100 | 1 | `callbacks_off_1_per_user_created.txt` |
| Multiple per user | 1000 | 100 | 10 | `callbacks_off_10_per_user_created.txt` |
- [x] Run with `--user-mode created --key-mode per_user`, 100 requests, 100 users (1 per user) → `callbacks_off_1_per_user_created.txt`
- [x] Run with `--user-mode created --key-mode per_user`, 1000 requests, 100 users (10 per user) → `callbacks_off_10_per_user_created.txt`
#### Analysis (1 vs 10 requests per user, callbacks off, `--user-mode random`)
| Scenario | Requests | Users | Req/user | avg | p95 | Above 1s |
|-------------------|----------|-------|----------|--------|---------|----------|
| One per user | 100 | 100 | 1 | 8.647s | 14.909s | 100.0% |
| Multiple per user | 1000 | 100 | 10 | 1.538s | 8.275s | 33.2% |
**Findings**
With **1 request per user**, every request triggers an end_user cache miss → DB lookup. Latency is ~5.6× higher (avg 8.6s vs 1.5s) and 100% of requests exceed 1s vs 33% with 10 per user. With **10 requests per user**, the first request per user misses cache; the next 9 hit cache. Cache hits on subsequent requests dramatically reduce latency. This confirms that end_user lookups (especially cache misses) are a major driver of baseline latency spikes.
#### Analysis (1 vs 10 requests per user, callbacks off, `--user-mode created --key-mode per_user`)
| Scenario | Requests | Users | Req/user | avg | p95 | Above 1s |
|-------------------|----------|-------|----------|--------|---------|----------|
| One per user | 100 | 100 | 1 | 8.923s | 14.962s | 100.0% |
| Multiple per user | 1000 | 100 | 10 | 1.198s | 8.839s | 10.0% |
**Findings**
Same pattern as random: 1 per user → all cache misses, ~7.5× higher avg latency and 100% above 1s; 10 per user → first request misses, next 9 hit, avg 1.2s and only 10% above 1s. **Created mode performs better than random** at 10 per user: avg 1.2s vs 1.5s, and 10% vs 33% above 1s. With pre-created end users, lookups succeed and cache; with random (non-existent) IDs, the negative path (no negative caching) keeps hitting DB. The 100 requests above 1s in created 10-per-user are the first request per user; the remaining 900 are cache hits with sub-second latency.
### Next Steps
- [x] Run proxy + `measure_latency.py --user-mode random --key-mode shared`, capture proxy stdout → `end_user_profile_proxy_logs.txt`
- [x] Run `--user-mode created --key-mode per_user --warmup --warmup-verbose` to validate whether warmup reduces latency => `cache_validation.txt`
#### Findings
Passing IDs of users that **don't exist** in the DB triggers repeated cache misses and DB lookups (no negative caching). Proxy logs show each non-existent user hits the DB on every request. With **created** mode (pre-existing users) and warmup, warm and measured runs had nearly identical profiles (~8s avg)—warmup did **not** reduce latency. The bottleneck is likely the upstream LLM call and its queue under 100 concurrent requests, not the end_user lookup.
**Note:** With cache ON and user none, all 100 requests share the same cache key (same model + messages). Most requests are served from cache; only 1–2 requests reach the local LLM mock. Latency remains high (~15s avg) due to cache lookup and the few requests that hit the LLM.

124
user_none_1_request_per_user_local_llm_cache_on.txt Normal file
View file

@ -0,0 +1,124 @@
=== 100 requests, 100 users, fire-as-fast-as-possible ===
User mode: none, Key mode: shared
Latency = time from request start until last byte of response received
[OK] User 48 request 1: 15.739s
[OK] User 9 request 1: 25.512s
[OK] User 5 request 1: 26.648s
[OK] User 15 request 1: 24.283s
[OK] User 2 request 1: 27.300s
[OK] User 26 request 1: 21.911s
[OK] User 21 request 1: 22.993s
[OK] User 8 request 1: 26.025s
[OK] User 44 request 1: 17.289s
[OK] User 42 request 1: 17.884s
[OK] User 20 request 1: 23.318s
[OK] User 10 request 1: 25.487s
[OK] User 39 request 1: 18.784s
[OK] User 23 request 1: 22.673s
[OK] User 47 request 1: 16.406s
[OK] User 14 request 1: 24.613s
[OK] User 25 request 1: 22.241s
[OK] User 11 request 1: 25.268s
[OK] User 24 request 1: 22.459s
[OK] User 33 request 1: 20.472s
[OK] User 18 request 1: 23.750s
[OK] User 31 request 1: 20.903s
[OK] User 38 request 1: 19.080s
[OK] User 4 request 1: 26.978s
[OK] User 37 request 1: 19.377s
[OK] User 6 request 1: 26.543s
[OK] User 53 request 1: 14.637s
[OK] User 50 request 1: 15.528s
[OK] User 12 request 1: 25.051s
[OK] User 49 request 1: 15.819s
[OK] User 34 request 1: 20.252s
[OK] User 27 request 1: 21.804s
[OK] User 36 request 1: 19.674s
[OK] User 29 request 1: 21.346s
[OK] User 22 request 1: 22.918s
[OK] User 17 request 1: 23.993s
[OK] User 30 request 1: 21.155s
[OK] User 52 request 1: 14.995s
[OK] User 13 request 1: 24.899s
[OK] User 16 request 1: 24.245s
[OK] User 7 request 1: 26.388s
[OK] User 41 request 1: 18.256s
[OK] User 32 request 1: 20.755s
[OK] User 45 request 1: 17.060s
[OK] User 35 request 1: 20.041s
[OK] User 46 request 1: 16.768s
[OK] User 1 request 1: 27.706s
[OK] User 43 request 1: 17.659s
[OK] User 28 request 1: 21.632s
[OK] User 19 request 1: 23.606s
[OK] User 40 request 1: 18.553s
[OK] User 54 request 1: 14.412s
[OK] User 55 request 1: 14.121s
[OK] User 61 request 1: 12.358s
[OK] User 58 request 1: 13.262s
[OK] User 57 request 1: 13.551s
[OK] User 64 request 1: 11.501s
[OK] User 63 request 1: 11.806s
[OK] User 65 request 1: 11.185s
[OK] User 56 request 1: 13.861s
[OK] User 66 request 1: 10.840s
[OK] User 67 request 1: 10.492s
[OK] User 78 request 1: 7.674s
[OK] User 72 request 1: 9.126s
[OK] User 60 request 1: 12.691s
[OK] User 77 request 1: 7.902s
[OK] User 69 request 1: 9.870s
[OK] User 76 request 1: 8.141s
[OK] User 68 request 1: 10.135s
[OK] User 73 request 1: 8.888s
[OK] User 70 request 1: 9.642s
[OK] User 74 request 1: 8.647s
[OK] User 71 request 1: 9.389s
[OK] User 75 request 1: 8.388s
[OK] User 79 request 1: 7.453s
[OK] User 92 request 1: 3.955s
[OK] User 83 request 1: 6.502s
[OK] User 81 request 1: 7.015s
[OK] User 100 request 1: 1.598s
[OK] User 91 request 1: 4.252s
[OK] User 84 request 1: 6.266s
[OK] User 3 request 1: 27.317s
[OK] User 86 request 1: 5.762s
[OK] User 82 request 1: 6.872s
[OK] User 93 request 1: 3.872s
[OK] User 98 request 1: 2.399s
[OK] User 97 request 1: 2.691s
[OK] User 95 request 1: 3.302s
[OK] User 94 request 1: 3.600s
[OK] User 99 request 1: 2.120s
[OK] User 62 request 1: 12.328s
[OK] User 85 request 1: 6.236s
[OK] User 80 request 1: 7.465s
[OK] User 89 request 1: 5.070s
[OK] User 90 request 1: 4.790s
[OK] User 88 request 1: 5.379s
[OK] User 51 request 1: 15.601s
[OK] User 59 request 1: 13.249s
[OK] User 96 request 1: 3.047s
[OK] User 87 request 1: 5.697s
[OK] 100 succeeded, [FAIL] 0 failed
Latency (successful):
min: 1.598s
avg: 15.204s
max: 27.706s
p95: 26.543s
p99: 27.317s
Requests above threshold (successful only):
Above 1s: 100/100 (100.0%)
Above 2s: 99/100 (99.0%)
Above 3s: 96/100 (96.0%)
Above 4s: 91/100 (91.0%)
Above 5s: 89/100 (89.0%)
Above 6s: 85/100 (85.0%)
Above 7s: 81/100 (81.0%)
Above 8s: 76/100 (76.0%)
Above 9s: 72/100 (72.0%)
Above 10s: 68/100 (68.0%)