measure_latency: add created user mode, require user-mode and key-mode

- Add --user-mode created to pre-create end users via /customer/new (requires --key-mode per_user)
- Remove defaults for --user-mode and --key-mode; both are now required
- Update problem_tracker.md Next Steps and Findings

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))

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.
+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.