diff --git a/measure_latency.py b/measure_latency.py index 0e6eb80c81a..032eea1b813 100644 --- a/measure_latency.py +++ b/measure_latency.py @@ -19,6 +19,12 @@ USER_MODES: - random: each user gets a random 10-digit ID (default, most reproducible for Prometheus) - sequential: each user gets sequential ID (1, 2, 3, ...) - fewer cache misses - none: no user field in payload - skips end_user lookup entirely +- created: create end users via POST /customer/new before the test, then use those IDs (requires --key-mode per_user) + +KEY_MODES (add-on; can be combined with any user mode): +- shared: all users share the same API key (default) +- per_user: create one key per user via /key/generate before the test; each user uses their own key + (required when --user-mode created) """ # ----------------------------------------------------------------------------- @@ -27,8 +33,8 @@ USER_MODES: BASE_URL = "http://localhost:4000" API_KEY = "sk-1234" MODEL = "gpt-o1" # must match a model_name in your proxy config (e.g. test_config_123.yaml) -NUM_REQUESTS = 1000 -NUM_CONCURRENT = 100 # Concurrent users; each has one connection, reuses it for their requests +NUM_REQUESTS = 10 +NUM_CONCURRENT = 1 # Concurrent users; each has one connection, reuses it for their requests MESSAGES = [{"role": "user", "content": "Say hello in one word."}] TIMEOUT = 30000.0 # ----------------------------------------------------------------------------- @@ -36,6 +42,52 @@ TIMEOUT = 30000.0 _results: list[tuple[float, bool]] = [] # shared; asyncio is single-threaded so no lock needed +async def create_keys_for_users( + base_url: str, master_key: str, num_keys: int +) -> list[str]: + """Create num_keys via POST /key/generate; return list of keys.""" + path = f"{base_url.rstrip('/')}/key/generate" + headers = { + "Authorization": f"Bearer {master_key}", + "Content-Type": "application/json", + } + async with httpx.AsyncClient(timeout=TIMEOUT) as client: + + async def create_one(_: int) -> str: + resp = await client.post(path, json={}, headers=headers) + resp.raise_for_status() + data = resp.json() + key = data.get("key") + if not key: + raise ValueError(f"Key generation response missing 'key': {data}") + return key + + tasks = [create_one(i) for i in range(num_keys)] + return list(await asyncio.gather(*tasks)) + + +async def create_end_users_for_test( + base_url: str, master_key: str, user_ids: list[str] +) -> list[str]: + """Create end users via POST /customer/new; return list of user_ids (as created).""" + path = f"{base_url.rstrip('/')}/customer/new" + headers = { + "Authorization": f"Bearer {master_key}", + "Content-Type": "application/json", + } + async with httpx.AsyncClient(timeout=TIMEOUT) as client: + + async def create_one(uid: str) -> str: + resp = await client.post( + path, json={"user_id": uid}, headers=headers + ) + resp.raise_for_status() + return uid + + tasks = [create_one(uid) for uid in user_ids] + return list(await asyncio.gather(*tasks)) + + async def run_user( user_id: int, num_requests: int, @@ -66,37 +118,87 @@ def parse_args() -> argparse.Namespace: ) parser.add_argument( "--user-mode", - choices=["random", "sequential", "none"], - default="random", - help="random: random user IDs (default, most reproducible for Prometheus); " - "sequential: 1,2,3,... (fewer cache misses); none: no user in payload", + choices=["random", "sequential", "none", "created"], + required=True, + help="random: random user IDs; sequential: 1,2,3,...; " + "none: no user in payload; created: create end users via API (requires --key-mode per_user)", ) - return parser.parse_args() + parser.add_argument( + "--key-mode", + choices=["shared", "per_user"], + required=True, + help="shared: all users use same API key; per_user: create one key per user", + ) + args = parser.parse_args() + if args.user_mode == "created" and args.key_mode != "per_user": + parser.error("--user-mode created requires --key-mode per_user") + return args -async def main(user_mode: str = "random") -> None: +async def main( + user_mode: str = "random", key_mode: str = "shared" +) -> None: base_url = BASE_URL.rstrip("/") path = "/chat/completions" - headers = { - "Authorization": f"Bearer {API_KEY}", - "Content-Type": "application/json", - } - base_per_user = NUM_REQUESTS // NUM_CONCURRENT remainder = NUM_REQUESTS - base_per_user * NUM_CONCURRENT + # Count users that will send at least one request + active_user_indices = [ + i for i in range(1, NUM_CONCURRENT + 1) + if base_per_user + (1 if i <= remainder else 0) > 0 + ] + num_active = len(active_user_indices) + + api_keys: list[str] | None = None + end_user_ids: list[str] | None = None + + if key_mode == "per_user": + print(f"Creating {num_active} keys via /key/generate...", flush=True) + api_keys = await create_keys_for_users(base_url, API_KEY, num_active) + print(f"Created {len(api_keys)} keys.", flush=True) + + if user_mode == "created": + run_prefix = f"latency-test-{int(time.time())}-" + end_user_ids = [ + f"{run_prefix}{i}" for i in active_user_indices + ] + print(f"Creating {len(end_user_ids)} end users via /customer/new...", flush=True) + await create_end_users_for_test(base_url, API_KEY, end_user_ids) + print(f"Created {len(end_user_ids)} end users.", flush=True) + print(f"=== {NUM_REQUESTS} requests, {NUM_CONCURRENT} users, fire-as-fast-as-possible ===", flush=True) - print(f"User mode: {user_mode}", flush=True) + print(f"User mode: {user_mode}, Key mode: {key_mode}", flush=True) print("Latency = time from request start until last byte of response received", flush=True) _results.clear() tasks = [] + key_idx = 0 + end_user_idx = 0 for user_idx in range(1, NUM_CONCURRENT + 1): count = base_per_user + (1 if user_idx <= remainder else 0) if count > 0: + if key_mode == "per_user" and api_keys is not None: + headers = { + "Authorization": f"Bearer {api_keys[key_idx]}", + "Content-Type": "application/json", + } + key_idx += 1 + else: + headers = { + "Authorization": f"Bearer {API_KEY}", + "Content-Type": "application/json", + } if user_mode == "none": payload = {"model": MODEL, "messages": MESSAGES} + elif user_mode == "created" and end_user_ids is not None: + payload = { + "model": MODEL, + "messages": MESSAGES, + "user": end_user_ids[end_user_idx], + } + end_user_idx += 1 elif user_mode == "sequential": payload = {"model": MODEL, "messages": MESSAGES, "user": str(user_idx)} else: # random (default) @@ -133,4 +235,4 @@ async def main(user_mode: str = "random") -> None: if __name__ == "__main__": args = parse_args() - asyncio.run(main(user_mode=args.user_mode)) + asyncio.run(main(user_mode=args.user_mode, key_mode=args.key_mode)) diff --git a/problem_tracker.md b/problem_tracker.md index ee4a9452654..ad4be460d5d 100644 --- a/problem_tracker.md +++ b/problem_tracker.md @@ -243,6 +243,8 @@ The issue was caused by hitting the database on every request when Prometheus wa > 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. + + ## 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. @@ -281,24 +283,64 @@ The issue was caused by hitting the database on every request when Prometheus wa - [x] `--user-mode sequential` → `callbacks_off_user_sequential.txt` - [x] `--user-mode random` → `callbacks_off_user_random.txt` -**Compare:** If `none` shows much lower latency than `random`/`sequential`, end_user DB lookups are a contributor. If all three are similar, the bottleneck is elsewhere. +**Callbacks off + per_user keys** (one key per user via `/key/generate`; isolates key lookup vs shared-key cache): + +- [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 | avg | p95 | Above 1s | -|---------------|-------------|--------|--------|----------| -| Callbacks on | none | 1.099s | 7.767s | 10.0% | -| Callbacks on | sequential | 1.702s | 8.524s | 37.7% | -| Callbacks on | random | 1.773s | 8.598s | 42.5% | -| Callbacks off | none | 0.998s | 7.966s | 10.0% | -| Callbacks off | sequential | 1.532s | 8.626s | 31.8% | -| Callbacks off | random | 1.556s | 8.036s | 34.3% | +| 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** -1. **Passing `user` adds significant latency.** `none` has ~10% of requests above 1s vs ~32–43% when `user` is passed. Avg latency with `none` (~1.0–1.1s) is ~35–55% lower than with `sequential`/`random` (~1.5–1.8s). -2. **End_user lookups are a contributor.** The large gap between `none` and the other modes points to end_user DB/cache lookups adding measurable overhead. -3. **Random vs sequential:** Random is slightly worse (avg +0.2s, Above 1s +3–8%), consistent with more cache misses for unique IDs. -4. **Callbacks on vs off:** Small difference (~5–10%). Callbacks-on is marginally slower; callbacks-off is not the main driver of the baseline spikes. \ No newline at end of file +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` + +#### 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. + +### Next Steps + +- [x] Run proxy + `measure_latency.py --user-mode random --key-mode shared`, capture proxy stdout → `end_user_profile_proxy_logs.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. Before optimizing this negative path, we should exercise the **happy path**: use `--user-mode created --key-mode per_user` to pre-create end users and verify latency with cache hits on subsequent requests. \ No newline at end of file