From 41d13df7769cb605064f48a684a702a3b1d76ddd Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Fri, 7 Aug 2026 15:30:39 +0200 Subject: [PATCH 01/23] Run Phase B and C, and fix the rig bugs the gate caught MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The scenario now replays a real recorded browser session instead of a placeholder derived from source. Running it surfaced four harness bugs before any load finding was trusted: - buildWriteBody sent a semester-plan body for every write, so the two transcript writes 400'd. Excluded them in build-scenario.mjs; exclusions are method-aware so the legitimate GET survives. - Only 5xx was logged, so those 4xx were invisible behind a threshold breach. Every unexpected status is logged now, with its own counter. - formatLatency guarded on values.p95 where k6 uses values['p(95)'], printing n/a on every run while the data sat right there. - Tagged sub-metrics were collected and dropped; k6 only emits them when a threshold references the tag, so one is generated per endpoint. A semester-plan 404 is per-account state rather than app health, so those reads carry a responseCallback that keeps the expected 404 out of http_req_failed. Results: at 20 concurrent users the app stays correct — no wrong answers, no lockouts. Two identical runs disagreed on failures (0 and 56), which pins the fault as episodic rather than concurrency-triggered, and corrects an earlier claim in this report that 20 users cannot provoke it. The 56 were all the runtime cancelling hung requests at ~1ms CPU. The latency finding is that p95 is a flat ~2.5s on every endpoint regardless of the work it does, which makes it Pyodide start-up rather than per-endpoint cost — so tuning individual endpoints cannot move it. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 166 ++++++++++++++++--- load-test/build-scenario.mjs | 23 ++- load-test/recorded-session.json | 274 ++++++++++++++++++++++++++++++-- load-test/scenario.js | 63 +++++++- 4 files changed, 485 insertions(+), 41 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 3dbd5af..dbcbd02 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -17,8 +17,8 @@ its design live in [`load-test/README.md`](../load-test/README.md). | --- | --- | --- | | 0 — live reconnaissance | Which origin users actually hit; single-user latency | **Done (2026-08-07)** | | A — rate-limit arithmetic | Whether 20 users behind one IP can even sign in | **Done — confirmed live** | -| B — baseline | Uncontended per-endpoint latency, authenticated | Not run | -| C — 20 concurrent users | 5xx under isolate fan-out; p95 under load | Not run | +| B — baseline | Uncontended per-endpoint latency, authenticated | **Done (2026-08-07)** | +| C — 20 concurrent users | 5xx under isolate fan-out; p95 under load | **Done — run twice, see below** | | D — login burst | How CPU-bound logins queue | **Superseded — the 500s reproduced without concurrency** | ### Bottom line so far @@ -47,11 +47,32 @@ See [Fixes](#fixes) for the detail and the verification of each. | Login CPU cost (Mode A) | **Not fixed** — workerd caps PBKDF2 at 100k iterations | | GIL fault (Mode B) | **Upstream, unfixed** — mitigated, not resolved | +### Answering the original question + +**Does the app stay correct and usable at 20 concurrent users, and where does it +start to hurt?** + +Correct: yes. Across both Phase C runs, every failure was the runtime killing a +hung request — no wrong answers, no data corruption, no rate-limit lockouts, no +4xx. The application logic holds. + +Usable: **conditionally**. In a good window it is fine. In a bad window roughly +1 request in 20 fails outright, and the p95 sits near 3 s in both. For a +20-person lecture demo that means a handful of visible errors and a +consistently sluggish feel — not an outage. + +Where it hurts is **not** where the plan predicted. Concurrency is not the +problem: the median at 20 VUs (118 ms) is *better* than at 1 VU (2620 ms), +because sustained traffic keeps isolates warm. The problem is Python Worker +cold start, which a realistically-paced single user pays on nearly every +request. + ### Setup state Accounts seeded and 20 sessions minted (`load-test/sessions.json`, gitignored, -valid 30 days). Phases B–C additionally need a recorded authenticated session — -`load-test/recorded-session.json` is still a partial placeholder. +valid 30 days). `load-test/recorded-session.json` is now generated from a real +authenticated browser session (75 logged requests, 2026-08-07), replacing the +earlier placeholder. --- @@ -162,26 +183,113 @@ what was found. ## Phase B — baseline -_Not run. Record here: single-VU per-endpoint p50, and a single cold login -timing (PBKDF2 at 310,000 iterations inside Pyodide, -[`authentication.py:15`](../backend/src/services/authentication.py))._ +Run against the deployed Worker (version `ff27e541`) from the real recording, +1 VU, 1 iteration, 43 requests. + +``` +requests: 43 failed: 0.00% server_errors: 0 rate_limited: 0 client_errors: 0 +http_req_duration: med=2620ms p95=3880ms p99=6793ms max=8115ms +``` + +Correct, and slow. **Median latency at one user with no contention is 2.6 s.** + +The interesting part is that this is *worse* than hammering the same endpoints. +Tight bursts earlier the same hour measured p50 of 138-425 ms. The difference is +think time: the scenario waits 3-8 s between steps, the isolate gets recycled in +the gap, and nearly every request pays Pyodide start-up again. Hammering keeps +the isolate warm and hides exactly the cost a real user pays. **Realistic pacing +is the pessimal case, not the optimistic one.** ## Phase C — 20 concurrent users -_Not run. Record here: raw k6 summary, per-endpoint p50/p95/p99, every 5xx with -the matching `wrangler tail` output, and whether the canary browser stayed -usable._ +Run twice, back to back, same script and same deployed version. The two runs +disagree, and that disagreement is the finding. + +| | Run 1 (15:12) | Run 2 (15:20) | +| --- | --- | --- | +| Requests | 1158 | 1154 | +| Failed | **0.00 %** | **4.85 %** | +| `server_errors` (5xx) | **0** | **56** | +| `rate_limited` (429) | 0 | 0 | +| `client_errors` (4xx) | 0 | 0 | +| med / p95 / p99 / max | 122 / 3054 / 5993 / 27633 ms | 118 / 3073 / 6350 / 9011 ms | + +Nothing changed between them. The fault is **episodic**: it is not provoked +reliably by concurrency, and it is not absent either. + +> Correction to an assessment made earlier the same day, before Run 2 existed. +> On the strength of 380 clean probe requests and Run 1, this report said the +> fault "is not load-triggered at our scale — 20 concurrent users don't provoke +> it". Run 2 refutes that. Twenty concurrent users *can* provoke it; the +> evidence for the negative claim was a run that happened to land in a good +> window. One clean run proves nothing about an intermittent fault. -Expected pressure points, from reading the code: +### What the 56 failures were -- `/api/me/progress` issues ~7 sequential D1 queries - ([`progress.py`](../backend/src/services/progress.py)); the catalog service - ~19. Latency is additive per request and D1 has one primary region. -- Authenticated endpoints carry no `Cache-Control`, so unlike the public catalog - they reach the Worker on every request. -- Pyodide init on cold isolates is the suspected source of the previously - observed production 500s, and Phase 0 measured a 12.7 s cold catalog request - against 3.3 s warm — consistent with an expensive init on the cold path. +`wrangler tail --status error` captured **exactly 56 events**, matching k6's +count one for one. + +| Outcome | Count | Exception | +| --- | --- | --- | +| `exception` | 54 | "The Workers runtime canceled this request because it detected that your Worker's code had hung" | +| `exceededCpu` | 2 | "Worker exceeded CPU time limit." | + +Median `cpuTime` **1 ms**, median `wallTime` **2 ms**. These requests did no +work before the runtime killed them, which is the same signature recorded in +Phase D: the Python event loop wedges and the request never completes. The +`exceededCpu` outcome on the other two is misleading in the same way — 125 ms of +CPU is not a CPU-limit breach. + +Note that the literal strings `GIL` and `PyProxy` appear **zero** times in this +capture. The behavioural fingerprint matches cloudflare/workerd#6624 but the +underlying message did not surface this time, so attribution rests on the +signature rather than on the exception text. + +Failures were spread across **9 different endpoints** — heaviest on +`/api/me/semester-plans/SS%202026` (31), which is simply the most-requested path +in the scenario. Nothing endpoint-specific. + +### Per-endpoint latency (Run 2) + +``` +endpoint med p95 p99 max +/api/catalog/courses 925ms 5727ms 7874ms 8884ms +/api/me/semester-plans/SS 2026/balance 145ms 3528ms 7535ms 8537ms +/api/me/profile 206ms 3252ms 8094ms 8465ms +/api/me/favorites 179ms 2900ms 4104ms 5962ms +/api/me/semester-plans/SS 2026 103ms 2894ms 7382ms 9011ms +/api/me/completed-courses 124ms 2881ms 3515ms 3673ms +/api/catalog/courses/1115 402ms 2878ms 2922ms 2933ms +/api/me/transcript-issues 100ms 2813ms 2985ms 3028ms +/api/regulation-versions/MSC_INFO_2021 73ms 2774ms 4145ms 5987ms +/api/me/progress 250ms 2746ms 2945ms 2995ms +/api/config 61ms 2695ms 2870ms 2914ms +/api/me/semester-plans/WS 2026/27 94ms 2633ms 5979ms 6899ms +/api/study-programs 50ms 2593ms 2720ms 2752ms +/api/auth/session 61ms 2530ms 3718ms 4015ms +/api/me/semester-plans 110ms 2369ms 3077ms 3253ms +/api/catalog/periods 56ms 2326ms 2426ms 2451ms +``` + +**Read the two columns separately — they are different phenomena.** + +- **Medians track real work.** `/api/config` returns one null field in 61 ms. + `/api/catalog/courses` ships 1.43 MB in 925 ms. `/api/me/progress` and its ~7 + sequential D1 queries land at 250 ms. All defensible. +- **p95 is a flat ~2.3-2.9 s on every endpoint regardless of what it does.** + `/api/catalog/periods`, which returns a short list, has a p95 of 2326 ms — + within 25 % of `/api/me/profile`. A cost that is identical across endpoints + doing wildly different amounts of work is not per-endpoint work. It is a fixed + entry cost: Pyodide start-up. + +The consequence for optimisation is direct: **tuning individual endpoints cannot +fix the tail.** Collapsing `/api/me/progress`'s 7 queries into 1 would move its +250 ms median, not its 2746 ms p95. Only reducing cold starts — fewer Python +isolate initialisations, or moving hot paths off Python — touches the p95. + +The one endpoint worth optimising on its own merits is +`/api/catalog/courses`: a 925 ms median and 5727 ms p95 for a 1.43 MB payload is +real work, and it is the single most expensive thing in a session start. ## Phase D — login burst @@ -425,6 +533,26 @@ longer locks anyone out of their account. --- +## Harness corrections found by the Phase B gate + +The "1 VU must pass before any multi-VU run" gate earned its place — the first +Phase B run failed, and all three failures were rig bugs, not app faults. A +20-VU run started blind would have reported them as findings. + +| Bug | Symptom | Fix | +| --- | --- | --- | +| `buildWriteBody` sent one body shape for every write | `POST /api/me/completed-courses/import` and `PUT /api/me/transcript-issues` both 400 | Excluded both writes in `build-scenario.mjs`; exclusions are now method-aware so the legitimate `GET /api/me/transcript-issues` survives | +| Only 5xx was logged | Three 4xx were invisible; the run failed a threshold with no indication why | Log every unexpected status; added a `client_errors_4xx` counter and threshold | +| `formatLatency` guarded on `values.p95` | Every run printed `http_req_duration: n/a` while the numbers were present under `values['p(95)']` | Corrected the key; added `summaryTrendStats` so p(99) is collected at all | +| Tagged sub-metrics never materialised | Per-endpoint p50/p95/p99 was collected and silently dropped | k6 only emits a tagged sub-metric when a threshold references it, so `scenario.js` now generates one permissive threshold per recorded endpoint | + +A fourth failure was not a bug: `GET /api/me/semester-plans/WS%202026%2F27` +returns 404 because the recording came from an account that had that plan and +the `loadtest-*` accounts do not. Whether a saved plan exists is per-account +state, not app health, so semester-plan reads now treat 404 as expected via a +per-request `responseCallback` — which keeps it out of `http_req_failed` instead +of quietly inflating it. + ## Notes - Runs write to the production D1. Writes are confined to the `loadtest-*` diff --git a/load-test/build-scenario.mjs b/load-test/build-scenario.mjs index dca092b..30d9679 100644 --- a/load-test/build-scenario.mjs +++ b/load-test/build-scenario.mjs @@ -62,6 +62,10 @@ const SESSION_CACHED_PATHS = new Set([ /** * Endpoints that must never be replayed under load, with the reason. * Keep in sync with the policies in backend/src/services/request_rate_limit.py. + * + * Keys are either a bare path (excludes every method) or `METHOD /path`, which + * excludes just that verb — the transcript endpoints are read normally on every + * page load but written only during one-time onboarding. */ const EXCLUDED_PATHS = new Map([ ['/api/auth/login', 'rate limited to 10/15min per IP; sessions are pre-minted instead'], @@ -69,8 +73,20 @@ const EXCLUDED_PATHS = new Map([ ['/api/auth/logout', 'would invalidate the pre-minted session mid-run'], ['/api/feedback', 'rate limited to 5/hour per IP and writes user-visible feedback rows'], ['/api/client-errors', 'rate limited to 30/hour per IP and pollutes the diagnostics view'], + // The request log records method, URL and status but never request bodies, so + // any replayed write has to be synthesised. That is tractable for a semester + // plan and not for a transcript import, which needs a parsed transcript. + // Both rejected the synthesised body with 400 during the Phase B smoke run. + // Excluding them also matches real traffic: importing a transcript is a + // once-per-user onboarding step, not something twenty concurrent users do. + ['POST /api/me/completed-courses/import', 'one-time onboarding write; needs a real parsed transcript body'], + ['PUT /api/me/transcript-issues', 'follow-up write of the transcript import flow; needs a real issues body'], ]) +function exclusionFor(method, pathWithoutQuery) { + return EXCLUDED_PATHS.get(`${method} ${pathWithoutQuery}`) ?? EXCLUDED_PATHS.get(pathWithoutQuery) +} + function toPath(rawUrl) { try { return new URL(rawUrl).pathname + new URL(rawUrl).search @@ -102,14 +118,15 @@ function buildSteps(entries) { if (!pathWithoutQuery.startsWith('/api/')) { continue } - const exclusionReason = EXCLUDED_PATHS.get(pathWithoutQuery) + const method = (entry.method ?? 'GET').toUpperCase() + const exclusionReason = exclusionFor(method, pathWithoutQuery) if (exclusionReason) { - skipped.push({ path: pathWithoutQuery, reason: exclusionReason }) + skipped.push({ path: `${method} ${pathWithoutQuery}`, reason: exclusionReason }) continue } const step = { - method: (entry.method ?? 'GET').toUpperCase(), + method, path, observedStatus: entry.status, observedDurationMs: entry.durationMs ?? null, diff --git a/load-test/recorded-session.json b/load-test/recorded-session.json index 831f47d..4f5780d 100644 --- a/load-test/recorded-session.json +++ b/load-test/recorded-session.json @@ -1,21 +1,267 @@ { - "source": "placeholder", - "note": "Partly real: the firstLoad GETs and their durations were observed on https://studyplaner.pages.dev on 2026-08-07 as an ANONYMOUS visitor. The authenticated steps and all of steadyState are still assumed, derived from frontend/src. Replace by walking the app logged in and running `node load-test/build-scenario.mjs `. scenario.js warns while this stays a placeholder.", - "recordedAt": "2026-08-07T08:30:00.000Z", + "source": "recorded", + "recordedAt": "2026-08-07T13:05:56.094Z", "apiOrigin": "https://studyplanner-api.ben-tischberger.workers.dev", "firstLoad": [ - { "method": "GET", "path": "/api/config", "observedStatus": 200, "observedDurationMs": 3516 }, - { "method": "GET", "path": "/api/auth/session", "observedStatus": 200, "observedDurationMs": 1758 }, - { "method": "GET", "path": "/api/catalog/periods", "observedStatus": 200, "observedDurationMs": 1582 }, - { "method": "GET", "path": "/api/catalog/courses?limit=1000&period=all", "observedStatus": 200, "observedDurationMs": 12693 }, - { "method": "GET", "path": "/api/me/profile", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/study-programs", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/me/favorites", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/me/completed-courses", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/me/semester-plans", "observedStatus": 200, "observedDurationMs": null }, - { "method": "GET", "path": "/api/me/progress", "observedStatus": 200, "observedDurationMs": null } + { + "method": "GET", + "path": "/api/catalog/courses?limit=1000&period=all", + "observedStatus": 200, + "observedDurationMs": 39 + }, + { + "method": "GET", + "path": "/api/auth/session", + "observedStatus": 200, + "observedDurationMs": 1457 + }, + { + "method": "GET", + "path": "/api/config", + "observedStatus": 200, + "observedDurationMs": 3093 + }, + { + "method": "GET", + "path": "/api/me/favorites", + "observedStatus": 200, + "observedDurationMs": 2971 + }, + { + "method": "GET", + "path": "/api/me/semester-plans", + "observedStatus": 200, + "observedDurationMs": 2978 + }, + { + "method": "GET", + "path": "/api/me/completed-courses", + "observedStatus": 200, + "observedDurationMs": 2995 + }, + { + "method": "GET", + "path": "/api/me/progress", + "observedStatus": 200, + "observedDurationMs": 3096 + }, + { + "method": "GET", + "path": "/api/study-programs", + "observedStatus": 200, + "observedDurationMs": 61 + }, + { + "method": "GET", + "path": "/api/catalog/periods", + "observedStatus": 200, + "observedDurationMs": 105 + }, + { + "method": "GET", + "path": "/api/catalog/courses?limit=500&period=229", + "observedStatus": 200, + "observedDurationMs": 19 + }, + { + "method": "GET", + "path": "/api/catalog/courses/1115", + "observedStatus": 200, + "observedDurationMs": 387 + }, + { + "method": "GET", + "path": "/api/me/transcript-issues", + "observedStatus": 200, + "observedDurationMs": 146 + } ], "steadyState": [ - { "method": "PUT", "path": "/api/me/semester-plans/WiSe%202026%2F27", "observedStatus": 200, "observedDurationMs": null } + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 404, + "observedDurationMs": 2989 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 187 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 91 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/WS%202026%2F27", + "observedStatus": 200, + "observedDurationMs": 110 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 404, + "observedDurationMs": 3699 + }, + { + "method": "PATCH", + "path": "/api/me/profile", + "observedStatus": 200, + "observedDurationMs": 6136 + }, + { + "method": "PATCH", + "path": "/api/me/profile", + "observedStatus": 200, + "observedDurationMs": 6970 + }, + { + "method": "GET", + "path": "/api/regulation-versions/MSC_INFO_2021", + "observedStatus": 200, + "observedDurationMs": 4471 + }, + { + "method": "PUT", + "path": "/api/me/favorites", + "observedStatus": 200, + "observedDurationMs": 3369 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 404, + "observedDurationMs": 140 + }, + { + "method": "PUT", + "path": "/api/me/favorites", + "observedStatus": 200, + "observedDurationMs": 2341 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 404, + "observedDurationMs": 4122 + }, + { + "method": "PUT", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 6205 + }, + { + "method": "PUT", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 2188 + }, + { + "method": "PUT", + "path": "/api/me/favorites", + "observedStatus": 200, + "observedDurationMs": 2543 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 130 + }, + { + "method": "PUT", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 267 + }, + { + "method": "PUT", + "path": "/api/me/favorites", + "observedStatus": 200, + "observedDurationMs": 240 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 116 + }, + { + "method": "PUT", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 211 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 139 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 144 + }, + { + "method": "GET", + "path": "/api/regulation-versions/MSC_INFO_2021", + "observedStatus": 200, + "observedDurationMs": 145 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 204 + }, + { + "method": "POST", + "path": "/api/me/semester-plans/SS%202026/balance", + "observedStatus": 200, + "observedDurationMs": 3084 + }, + { + "method": "GET", + "path": "/api/regulation-versions/MSC_INFO_2021", + "observedStatus": 200, + "observedDurationMs": 169 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 191 + }, + { + "method": "GET", + "path": "/api/regulation-versions/MSC_INFO_2021", + "observedStatus": 200, + "observedDurationMs": 84 + }, + { + "method": "GET", + "path": "/api/me/semester-plans/SS%202026", + "observedStatus": 200, + "observedDurationMs": 124 + }, + { + "method": "GET", + "path": "/api/regulation-versions/MSC_INFO_2021", + "observedStatus": 200, + "observedDurationMs": 106 + }, + { + "method": "GET", + "path": "/api/regulation-versions/MSC_INFO_2021", + "observedStatus": 200, + "observedDurationMs": 89 + } ] } diff --git a/load-test/scenario.js b/load-test/scenario.js index 6d2fe4b..55cdb5c 100644 --- a/load-test/scenario.js +++ b/load-test/scenario.js @@ -43,9 +43,39 @@ const ORIGIN = (__ENV.LOADTEST_ORIGIN || recording.apiOrigin || DEFAULT_ORIGIN). // The finding we care about is 5xx, and an average hides a handful of them. const serverErrors = new Counter('server_errors') const rateLimited = new Counter('rate_limited_429') +const clientErrors = new Counter('client_errors_4xx') const stepDuration = new Trend('step_duration', true) +/** + * A semester plan that was never saved returns 404, and that is the app working + * correctly: whether a plan exists is per-account state, not app health. The + * recording came from an account that had a WS 2026/27 plan; the loadtest + * accounts do not. Treated as expected so it neither fails the run nor silently + * inflates http_req_failed. + */ +function expectsNotFound(method, pathWithoutQuery) { + return method === 'GET' && pathWithoutQuery.startsWith('/api/me/semester-plans/') +} + +/** + * k6 only materialises a tagged sub-metric in the summary when some threshold + * references it, so tagging step_duration by endpoint is not enough on its own — + * the per-endpoint numbers the report needs were being collected and then + * dropped. These thresholds exist to surface the breakdown, not to gate the run, + * so the condition is one that always holds. + */ +function perEndpointThresholds() { + const endpoints = new Set( + [...recording.firstLoad, ...recording.steadyState].map((step) => step.path.split('?')[0]), + ) + return Object.fromEntries( + [...endpoints].map((endpoint) => [`step_duration{endpoint:${endpoint}}`, ['p(95)>=0']]), + ) +} + export const options = { + // k6 reports avg/min/med/p(90)/p(95)/max by default; the report quotes p(99). + summaryTrendStats: ['avg', 'min', 'med', 'p(90)', 'p(95)', 'p(99)', 'max'], scenarios: { concurrent_users: { executor: 'ramping-vus', @@ -64,8 +94,11 @@ export const options = { // A 429 here means the pre-minted sessions were not enough to keep the // rate limiter out of the measurement — the run is invalid, not the app. rate_limited_429: ['count<1'], + // A 4xx means the replayed request was malformed — a rig bug, not a finding. + client_errors_4xx: ['count<1'], http_req_failed: ['rate<0.01'], http_req_duration: ['p(95)<1500'], + ...perEndpointThresholds(), }, } @@ -144,30 +177,46 @@ function runSteps(steps, session) { const isWrite = step.method !== 'GET' && step.method !== 'HEAD' const body = isWrite ? buildWriteBody(cachedCourseIds) : null + const notFoundIsExpected = expectsNotFound(step.method, pathWithoutQuery) + const response = http.request(step.method, `${ORIGIN}${step.path}`, body, { headers: buildHeaders(session, step.method), // Group metrics by endpoint rather than by unique URL. tags: { endpoint: pathWithoutQuery, method: step.method }, redirects: 0, + // Drives http_req_failed, so an expected 404 does not read as a failure. + responseCallback: notFoundIsExpected + ? http.expectedStatuses(404, { min: 200, max: 299 }) + : http.expectedStatuses({ min: 200, max: 299 }), }) stepDuration.add(response.timings.duration, { endpoint: pathWithoutQuery }) + const isExpected = + (response.status >= 200 && response.status < 300) + || (notFoundIsExpected && response.status === 404) + if (response.status >= 500) { serverErrors.add(1, { endpoint: pathWithoutQuery }) + } else if (response.status === 429) { + rateLimited.add(1, { endpoint: pathWithoutQuery }) + } else if (!isExpected) { + // Previously only 5xx was logged, so a 4xx from a malformed replay body + // was invisible in the output and only showed up as a threshold breach. + clientErrors.add(1, { endpoint: pathWithoutQuery }) + } + + if (!isExpected) { console.error( `[scenario] ${response.status} ${step.method} ${pathWithoutQuery} ` + `vu=${__VU} iter=${scenario.iterationInTest} body=${String(response.body).slice(0, 200)}`, ) } - if (response.status === 429) { - rateLimited.add(1, { endpoint: pathWithoutQuery }) - } check(response, { 'status is not 5xx': (r) => r.status < 500, 'status is not 429': (r) => r.status !== 429, - 'status is 2xx': (r) => r.status >= 200 && r.status < 300, + 'status is expected': () => isExpected, }, { endpoint: pathWithoutQuery }) if (pathWithoutQuery === '/api/catalog/courses' && response.status === 200) { @@ -198,7 +247,9 @@ function counterValue(data, metricName) { function formatLatency(data, metricName) { const metric = data.metrics[metricName] - if (!metric || metric.values.p95 === undefined) { + // k6 names the percentile keys 'p(95)', not 'p95'. Guarding on the wrong key + // made this print n/a on every run while the numbers were sitting right there. + if (!metric || metric.values['p(95)'] === undefined) { return `${metricName}: n/a` } const { med, 'p(95)': p95, 'p(99)': p99, max } = metric.values @@ -214,6 +265,7 @@ function formatLatency(data, metricName) { export function handleSummary(data) { const serverErrorCount = counterValue(data, 'server_errors') const rateLimitedCount = counterValue(data, 'rate_limited_429') + const clientErrorCount = counterValue(data, 'client_errors_4xx') const failedRate = data.metrics.http_req_failed ? (data.metrics.http_req_failed.values.rate * 100).toFixed(2) : 'n/a' @@ -225,6 +277,7 @@ export function handleSummary(data) { `failed: ${failedRate}%`, `server_errors: ${serverErrorCount}${serverErrorCount > 0 ? ' <-- FAIL: 5xx observed' : ''}`, `rate_limited: ${rateLimitedCount}${rateLimitedCount > 0 ? ' <-- run invalid: limiter was hit' : ''}`, + `client_errors: ${clientErrorCount}${clientErrorCount > 0 ? ' <-- rig bug: replayed request was malformed' : ''}`, formatLatency(data, 'http_req_duration'), formatLatency(data, 'step_duration'), 'full per-endpoint data: load-test/results/summary.json', From 99dfd390dcbfb936a1f9718de69555143ac826e4 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 11:41:30 +0200 Subject: [PATCH 02/23] Stop the Cloudflare config gate from no-opping on Python 3.10 verify_cloudflare_config imports tomllib, which is stdlib only from 3.11. On an older interpreter it raised ModuleNotFoundError at import time, so `npm run db:verify-config` and the predeploy:backend hook aborted before running a single check. The gate AGENTS.md requires before every deploy was silently doing nothing locally; it was only noticed because a deploy had to be verified by hand. Falls back to tomli, the same parser backported. CI pins 3.11 so the fallback never fires there. If neither is importable the script now exits with an instruction rather than a traceback, since this runs as a deploy hook where a bare ImportError reads as a broken script. Also removes a stray dev/null directory: a shell redirect created it as a literal path on Windows and Git LFS wrote hook copies into it. The real hooks are in .git/hooks and are untouched. Co-Authored-By: Claude Opus 5 --- backend/scripts/verify_cloudflare_config.py | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/backend/scripts/verify_cloudflare_config.py b/backend/scripts/verify_cloudflare_config.py index 8623130..34e1561 100644 --- a/backend/scripts/verify_cloudflare_config.py +++ b/backend/scripts/verify_cloudflare_config.py @@ -2,10 +2,23 @@ import json import sys -import tomllib from pathlib import Path from typing import Any +try: + import tomllib +except ModuleNotFoundError: # Python < 3.11; tomli is the same parser, backported. + try: + import tomli as tomllib + except ModuleNotFoundError as exc: + # This runs as predeploy:backend. A bare ImportError here aborts the + # deploy before a single check runs, which reads like a broken script + # rather than a missing dependency. + raise SystemExit( + 'verify_cloudflare_config needs a TOML parser: use Python 3.11+ ' + '(stdlib tomllib) or run `pip install tomli`.' + ) from exc + REPO_ROOT = Path(__file__).resolve().parents[2] # Production cutover to studyplanner-db happens with the integrate_new_db branch From 7954cbd3f54ef9d9153ba4e3506dd7159f38c040 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 12:06:22 +0200 Subject: [PATCH 03/23] Measure user-visible failures, and withdraw the latency conclusion MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two additions and one retraction. scenario.js now mirrors the frontend retry policy from api.ts, so the run reports what a user experienced rather than what the server did. The gap matters: splitting the 56 failures from run 2 by method gives 35 GET (retryable) against 16 PUT, 4 PATCH and 1 POST. Mutations are never retried, so 21 of 56 reached the user with no recourse — a failed semester-plan PUT means the edit did not save. Roughly one hard error per user per session during a bad window. The retraction is larger. Every latency number in phases B and C was measured 6-20 minutes after a deploy, which was not controlled for. Re-running the identical scripts a day later against the same version gives a 105ms median where it was 2620ms, and a 298ms p95 where it was 3073ms. So "p95 is a flat 2.5s, therefore Pyodide start-up is a chronic per-request cost" and "think time makes a single user the pessimal case" are both withdrawn. In steady state this is a 92ms median service. What caused the slow window is not established — association across two paired observations is not mechanism — so it is recorded as an open question with the experiment that would settle it, rather than as a finding. Also adds analyze-recording.mjs, which counts repeat GETs in a recording. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 133 ++++++++++++++++++++++++++------ load-test/analyze-recording.mjs | 65 ++++++++++++++++ load-test/scenario.js | 84 +++++++++++++++----- 3 files changed, 242 insertions(+), 40 deletions(-) create mode 100644 load-test/analyze-recording.mjs diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index dbcbd02..0ff1651 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -56,16 +56,33 @@ Correct: yes. Across both Phase C runs, every failure was the runtime killing a hung request — no wrong answers, no data corruption, no rate-limit lockouts, no 4xx. The application logic holds. -Usable: **conditionally**. In a good window it is fine. In a bad window roughly -1 request in 20 fails outright, and the p95 sits near 3 s in both. For a -20-person lecture demo that means a handful of visible errors and a -consistently sluggish feel — not an outage. - -Where it hurts is **not** where the plan predicted. Concurrency is not the -problem: the median at 20 VUs (118 ms) is *better* than at 1 VU (2620 ms), -because sustained traffic keeps isolates warm. The problem is Python Worker -cold start, which a realistically-paced single user pays on nearly every -request. +Usable: **yes, in steady state.** Settled, the app runs at a 92 ms median and a +298 ms p95 under 20 concurrent users, with no failures. That is a healthy +service. + +Two things spoil it, and neither is concurrency: + +1. **Deploy recency.** Minutes after a deploy the same test reports a 2620 ms + median at a single user. Whether the deploy causes it and how long it lasts + is not yet established — see the correction above and the open questions + below. +2. **The episodic hang.** One run in three produced 56 failures, of which 21 + were unretryable mutations. During such a window a typical user hits about + one hard error per session. + +The plan was built on the premise that 20 concurrent users was the risk. It is +not: 20 VUs performs *better* than 1 VU in every run, because sustained traffic +keeps isolates warm. Neither of the two real problems is load-related at all. + +### Open questions + +- **Does deploying cause the slow window, and how long does it last?** Redeploy + the same code, then re-run Phase B at intervals (immediately, +5 min, +30 min, + +2 h). Two paired observations show association only. +- **How often does a bad window happen?** Three runs, one bad. Repeat Phase C + 5-10 times across a day and record `user_visible_failures` each time. +- **Do retries actually absorb the GET failures?** The absorption metric exists + now but has only run in clean windows. It needs a bad one to mean anything. ### Setup state @@ -181,6 +198,40 @@ what was found. --- +## Correction: the latency numbers below were measured minutes after a deploy + +**Everything in Phases B and C was run 6-20 minutes after `wrangler deploy`.** +Re-running the identical scripts ~20 hours later, against the same Worker +version and the same accounts, gives completely different latency: + +| Measurement | 2026-08-07, ~15 min post-deploy | 2026-08-08, settled | +| --- | --- | --- | +| Phase B (1 VU) median | 2620 ms | **105 ms** | +| Phase B (1 VU) p95 | 3880 ms | **338 ms** | +| Phase C (20 VU) median | 118 ms | 92 ms | +| Phase C (20 VU) p95 | 3073 ms | **298 ms** | +| Phase C (20 VU) p99 | 6350 ms | 2128 ms | + +A 25x change at 1 VU with no code change. Two conclusions drawn on 2026-08-07 +do not survive this and are withdrawn: + +- **"p95 is a flat ~2.5 s on every endpoint, therefore Pyodide start-up is a + chronic per-request cost."** In steady state p95 is ~300 ms. The flat ~2.5 s + was real but is not the normal operating state. +- **"A realistically-paced single user is the pessimal case, because think time + lets the isolate go cold between steps."** The 1 VU run uses the same 3-8 s + think times and now medians at 105 ms. Think time is not the driver. + +What both readings actually had in common was deploy recency, which was not +controlled for and not even considered. The per-endpoint table further down is +therefore a table of *post-deploy* latency; keep it for that, do not read it as +normal behaviour. + +**Not yet established:** whether the degradation is caused by the deploy, and +how long it lasts. That needs a redeploy followed by measurement at intervals — +see "Open questions". Two paired observations show the association, not the +mechanism. + ## Phase B — baseline Run against the deployed Worker (version `ff27e541`) from the real recording, @@ -205,17 +256,20 @@ is the pessimal case, not the optimistic one.** Run twice, back to back, same script and same deployed version. The two runs disagree, and that disagreement is the finding. -| | Run 1 (15:12) | Run 2 (15:20) | -| --- | --- | --- | -| Requests | 1158 | 1154 | -| Failed | **0.00 %** | **4.85 %** | -| `server_errors` (5xx) | **0** | **56** | -| `rate_limited` (429) | 0 | 0 | -| `client_errors` (4xx) | 0 | 0 | -| med / p95 / p99 / max | 122 / 3054 / 5993 / 27633 ms | 118 / 3073 / 6350 / 9011 ms | - -Nothing changed between them. The fault is **episodic**: it is not provoked -reliably by concurrency, and it is not absent either. +| | Run 1 (08-07 15:12) | Run 2 (08-07 15:20) | Run 3 (08-08, settled) | +| --- | --- | --- | --- | +| Requests | 1158 | 1154 | 1247 | +| Failed | **0.00 %** | **4.85 %** | **0.00 %** | +| `server_errors` (5xx) | **0** | **56** | **0** | +| `rate_limited` (429) | 0 | 0 | 0 | +| `client_errors` (4xx) | 0 | 0 | 0 | +| `user_visible_failures` | not measured | not measured | **0** | +| med / p95 / p99 / max | 122 / 3054 / 5993 / 27633 ms | 118 / 3073 / 6350 / 9011 ms | 92 / 298 / 2128 / 4310 ms | + +Nothing changed between runs 1 and 2. The fault is **episodic**: it is not +provoked reliably by concurrency, and it is not absent either. Three runs give +one bad window out of three, which is still far too small a sample to quote a +rate from. > Correction to an assessment made earlier the same day, before Run 2 existed. > On the strength of 380 clean probe requests and Run 1, this report said the @@ -249,7 +303,42 @@ Failures were spread across **9 different endpoints** — heaviest on `/api/me/semester-plans/SS%202026` (31), which is simply the most-requested path in the scenario. Nothing endpoint-specific. -### Per-endpoint latency (Run 2) +### How many of those 56 would a user actually have seen? + +The frontend retries safe methods up to three times +([`api.ts`](../frontend/src/shared/utils/api.ts)), so a wedged request becomes +latency rather than an error — but **mutations are never retried**, because a +`POST` that timed out may still have been applied. Splitting Run 2's 56 captured +failures by method: + +| Method | Count | Retried? | +| --- | --- | --- | +| GET | 35 | yes — absorbed unless all 3 attempts fail | +| PUT | 16 | **no** | +| PATCH | 4 | **no** | +| POST | 1 | **no** | + +So **21 of 56 (37 %) were user-visible immediately**, with no retry possible. +That is the number that matters: a failed `PUT /api/me/semester-plans/...` means +the student's edit did not save, and they are shown an error without knowing +whether it applied. + +Spread over a 5-minute run with 20 VUs, 21 unretryable failures works out to +roughly **one hard error per user per session** during a bad window. + +The 35 GETs are probably almost all absorbed — three consecutive failures is +unlikely if failures are independent — but *independence is an assumption*, +stated in a code comment ("hangs that one request and then serves the next one +normally") and not measured. If a wedged isolate keeps serving the same client, +retries land on it again and the absorption rate collapses. + +`scenario.js` now measures this directly rather than inferring it: it mirrors the +frontend's retry policy and reports `absorbed_by_retry` alongside +`user_visible_failures`. Run 3 recorded 0 and 0 — a clean window, so the +instrumentation is unproven against real failures and needs a bad window to +validate. + +### Per-endpoint latency (Run 2 — post-deploy, see the correction above) ``` endpoint med p95 p99 max diff --git a/load-test/analyze-recording.mjs b/load-test/analyze-recording.mjs new file mode 100644 index 0000000..c68c429 --- /dev/null +++ b/load-test/analyze-recording.mjs @@ -0,0 +1,65 @@ +/** + * Reports how much of a recorded session was redundant. + * + * node load-test/analyze-recording.mjs + * + * Every request costs a shot at the ~2.5s cold-start tail measured in + * docs/load-test-2026-08.md, so a repeat GET of a URL already fetched in the + * same session is not free — it is another chance for the user to wait three + * seconds. This counts them so the saving from client-side caching can be + * argued from the recording rather than estimated. + */ +import { readFileSync } from 'node:fs' + +function readEntries(inputPath) { + const parsed = JSON.parse(readFileSync(inputPath, 'utf8')) + const entries = Array.isArray(parsed) ? parsed : parsed.entries + if (!Array.isArray(entries)) { + throw new Error('Input must be the sessionStorage array, or an object with an `entries` array.') + } + return entries +} + +function toKey(entry) { + const url = new URL(entry.url) + return decodeURIComponent(url.pathname + url.search) +} + +function summarize(entries) { + const reads = entries.filter((entry) => (entry.method ?? 'GET').toUpperCase() === 'GET') + const occurrences = new Map() + for (const entry of reads) { + const key = toKey(entry) + occurrences.set(key, [...(occurrences.get(key) ?? []), entry]) + } + + const repeated = [...occurrences.entries()] + .filter(([, hits]) => hits.length > 1) + .sort((left, right) => right[1].length - left[1].length) + + const redundant = repeated.reduce((total, [, hits]) => total + hits.length - 1, 0) + return { reads, repeated, redundant } +} + +function main() { + const inputPath = process.argv[2] + if (!inputPath) { + throw new Error('Usage: node load-test/analyze-recording.mjs ') + } + + const { reads, repeated, redundant } = summarize(readEntries(inputPath)) + const share = reads.length ? ((redundant / reads.length) * 100).toFixed(0) : '0' + + console.log(`GET requests: ${reads.length}`) + console.log(`repeat GETs: ${redundant} (${share}% of all GETs)`) + console.log() + console.log(' n median ms path') + for (const [path, hits] of repeated) { + const durations = hits.map((hit) => hit.durationMs).filter((value) => typeof value === 'number') + durations.sort((left, right) => left - right) + const median = durations.length ? durations[Math.floor(durations.length / 2)] : 0 + console.log(`${String(hits.length).padStart(2)} ${String(median).padStart(9)} ${path}`) + } +} + +main() diff --git a/load-test/scenario.js b/load-test/scenario.js index 55cdb5c..59ebb7b 100644 --- a/load-test/scenario.js +++ b/load-test/scenario.js @@ -46,6 +46,22 @@ const rateLimited = new Counter('rate_limited_429') const clientErrors = new Counter('client_errors_4xx') const stepDuration = new Trend('step_duration', true) +// What the user actually experiences, as opposed to what the server did: +// a 5xx the frontend retries away is latency, not an error. +const userVisibleFailures = new Counter('user_visible_failures') +const absorbedByRetry = new Counter('absorbed_by_retry') + +// Mirrors frontend/src/shared/utils/api.ts. Kept in sync deliberately: the +// point of the metric is to model the deployed client, so a divergence here +// silently invalidates the "user-visible" number. +const RETRY_SAFE_METHODS = new Set(['GET', 'HEAD']) +const MAX_ATTEMPTS = 3 +const RETRY_BACKOFF_MS = 300 + +function isRetryableFailure(method, status) { + return RETRY_SAFE_METHODS.has(method.toUpperCase()) && (status === 0 || status >= 500) +} + /** * A semester plan that was never saved returns 404, and that is the app working * correctly: whether a plan exists is per-account state, not app health. The @@ -89,8 +105,12 @@ export const options = { }, }, thresholds: { - // Any 5xx fails the run outright. + // Any 5xx fails the run outright. Counted per attempt, so a retried request + // that failed twice contributes twice — this is the server's error rate. server_errors: ['count<1'], + // What a user would actually have seen. The gap between this and + // server_errors is the retry doing its job. + user_visible_failures: ['count<1'], // A 429 here means the pre-minted sessions were not enough to keep the // rate limiter out of the measurement — the run is invalid, not the app. rate_limited_429: ['count<1'], @@ -179,28 +199,53 @@ function runSteps(steps, session) { const notFoundIsExpected = expectsNotFound(step.method, pathWithoutQuery) - const response = http.request(step.method, `${ORIGIN}${step.path}`, body, { - headers: buildHeaders(session, step.method), - // Group metrics by endpoint rather than by unique URL. - tags: { endpoint: pathWithoutQuery, method: step.method }, - redirects: 0, - // Drives http_req_failed, so an expected 404 does not read as a failure. - responseCallback: notFoundIsExpected - ? http.expectedStatuses(404, { min: 200, max: 299 }) - : http.expectedStatuses({ min: 200, max: 299 }), - }) - - stepDuration.add(response.timings.duration, { endpoint: pathWithoutQuery }) + // The browser retries safe methods, so a single wedged request is latency + // rather than an error. Replaying without that overstates what users see. + let response = null + let attemptsUsed = 0 + for (let attempt = 1; attempt <= MAX_ATTEMPTS; attempt += 1) { + attemptsUsed = attempt + response = http.request(step.method, `${ORIGIN}${step.path}`, body, { + headers: buildHeaders(session, step.method), + // Group metrics by endpoint rather than by unique URL. + tags: { endpoint: pathWithoutQuery, method: step.method, attempt: String(attempt) }, + redirects: 0, + // Drives http_req_failed, so an expected 404 does not read as a failure. + responseCallback: notFoundIsExpected + ? http.expectedStatuses(404, { min: 200, max: 299 }) + : http.expectedStatuses({ min: 200, max: 299 }), + }) + + // Every attempt is a real request against the Worker, so every attempt + // counts toward the server-side error total. + stepDuration.add(response.timings.duration, { endpoint: pathWithoutQuery }) + if (response.status >= 500) { + serverErrors.add(1, { endpoint: pathWithoutQuery }) + } else if (response.status === 429) { + rateLimited.add(1, { endpoint: pathWithoutQuery }) + } + + if (attempt < MAX_ATTEMPTS && isRetryableFailure(step.method, response.status)) { + sleep((RETRY_BACKOFF_MS * attempt) / 1000) + continue + } + break + } const isExpected = (response.status >= 200 && response.status < 300) || (notFoundIsExpected && response.status === 404) - if (response.status >= 500) { - serverErrors.add(1, { endpoint: pathWithoutQuery }) - } else if (response.status === 429) { - rateLimited.add(1, { endpoint: pathWithoutQuery }) - } else if (!isExpected) { + if (isExpected && attemptsUsed > 1) { + // Failed at least once, then succeeded: the user waited, saw no error. + absorbedByRetry.add(1, { endpoint: pathWithoutQuery }) + } + if (!isExpected) { + // Survived the retry policy (or was never eligible, as every mutation + // is): this is what actually reaches the user as a broken interaction. + userVisibleFailures.add(1, { endpoint: pathWithoutQuery, method: step.method }) + } + if (!isExpected && response.status < 500 && response.status !== 429) { // Previously only 5xx was logged, so a 4xx from a malformed replay body // was invisible in the output and only showed up as a threshold breach. clientErrors.add(1, { endpoint: pathWithoutQuery }) @@ -266,6 +311,7 @@ export function handleSummary(data) { const serverErrorCount = counterValue(data, 'server_errors') const rateLimitedCount = counterValue(data, 'rate_limited_429') const clientErrorCount = counterValue(data, 'client_errors_4xx') + const userVisibleCount = counterValue(data, 'user_visible_failures') const failedRate = data.metrics.http_req_failed ? (data.metrics.http_req_failed.values.rate * 100).toFixed(2) : 'n/a' @@ -278,6 +324,8 @@ export function handleSummary(data) { `server_errors: ${serverErrorCount}${serverErrorCount > 0 ? ' <-- FAIL: 5xx observed' : ''}`, `rate_limited: ${rateLimitedCount}${rateLimitedCount > 0 ? ' <-- run invalid: limiter was hit' : ''}`, `client_errors: ${clientErrorCount}${clientErrorCount > 0 ? ' <-- rig bug: replayed request was malformed' : ''}`, + `absorbed_retry: ${counterValue(data, 'absorbed_by_retry')} (failed, then succeeded — user saw latency only)`, + `USER-VISIBLE: ${userVisibleCount}${userVisibleCount > 0 ? ' <-- what users actually experienced' : ''}`, formatLatency(data, 'http_req_duration'), formatLatency(data, 'step_duration'), 'full per-endpoint data: load-test/results/summary.json', From 1e46147aeb2c738cf3c487014d733c97a33de8ee Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 12:44:40 +0200 Subject: [PATCH 04/23] Identify the failures as a connection pinned to a wedged isolate The assumed model - a race in isolate re-use scattering ~5% of requests across all users - does not survive the data that was already on disk. All 56 failures from run 2 carry the same cf.tlsClientRandom, so they came from one TLS connection. Their spacing (3137, 5194, 7592, 5322ms ...) sits entirely inside the 3-8s think-time window, so it is one VU failing on every request it made for five minutes. The path mix matches one VU's itinerary per iteration. A matching cluster exists in production client_error_log: eight different endpoints failing in the same second, all status 0, all at ~3250ms. isolate_identity.py makes the mechanism observable. Twelve requests over one keep-alive connection were served by one isolate, then rotated. So a connection binds to an isolate; when that isolate's event loop wedges, every request on the connection fails until it rotates, and nobody else is affected. Two consequences. Blast radius is "1 user in 20 completely broken, 19 fine" rather than a thin 5% spread. And the retry mitigation likely does not help, because retries reuse the same connection and reach the same dead isolate - so the earlier claim that 35 of 56 were absorbed is probably false. The id has to be generated lazily: at module scope the deploy fails with "Cannot get entropy outside of request context", because module-level code is captured in the Pyodide snapshot and restored into every isolate, which would make the id identical everywhere. Also enables Workers observability, so a failure no longer has to be caught live with wrangler tail. Co-Authored-By: Claude Opus 5 --- backend/src/http_utils.py | 10 +++++ backend/src/isolate_identity.py | 64 ++++++++++++++++++++++++++ backend/wrangler.toml | 9 ++++ docs/load-test-2026-08.md | 79 +++++++++++++++++++++++++++++++++ 4 files changed, 162 insertions(+) create mode 100644 backend/src/isolate_identity.py diff --git a/backend/src/http_utils.py b/backend/src/http_utils.py index 0d55664..2303e4c 100644 --- a/backend/src/http_utils.py +++ b/backend/src/http_utils.py @@ -6,6 +6,7 @@ from workers import Response from env_config import get_allowed_origins, is_origin_allowed +from isolate_identity import get_isolate_id, isolate_age_ms, next_response_sequence def get_request_header(request: Any, header_name: str) -> str | None: @@ -33,6 +34,15 @@ def build_cors_headers(request: Any, env: Any) -> dict[str, str]: headers: dict[str, str] = { "access-control-allow-methods": "GET,POST,PUT,PATCH,DELETE,OPTIONS", "access-control-allow-headers": "Authorization, Content-Type, X-CSRF-Token", + # Diagnostic; see isolate_identity. Every response path funnels through + # here, which is why the marker is attached at this point rather than in + # each responder. + "x-isolate-id": get_isolate_id(), + "x-isolate-seq": str(next_response_sequence()), + "x-isolate-age-ms": str(isolate_age_ms()), + # Without this a browser cannot read the above cross-origin, and the + # deployed frontend is cross-origin to this Worker. + "access-control-expose-headers": "x-isolate-id, x-isolate-seq, x-isolate-age-ms", } if "*" in allowed_origins: diff --git a/backend/src/isolate_identity.py b/backend/src/isolate_identity.py new file mode 100644 index 0000000..ecf9a54 --- /dev/null +++ b/backend/src/isolate_identity.py @@ -0,0 +1,64 @@ +"""Per-isolate identity, so a response can be attributed to the isolate that served it. + +Cloudflare exposes no isolate identifier. Diagnosing the wedge recorded in +docs/load-test-2026-08.md needs one: 56 consecutive failures arrived on a single +TLS connection while nineteen other connections were served normally, and the +open question is whether the isolate behind that connection was itself dead or +was fine and only that connection was stuck to it. Those have different causes. + +**The id must be generated lazily, not at module scope.** Module-level code runs +once and is captured in the Pyodide startup snapshot, which every isolate then +restores — so a module-scope value is *identical* across isolates and identifies +nothing. Cloudflare enforces this directly: `secrets.token_hex()` at import time +fails with + + OSError: [Errno 29] Cannot get entropy outside of request context + +Generating on first use puts it inside a request context (legal) and after the +snapshot was taken (correct): the snapshot holds `None`, and each restored +isolate fills it in once. + +Diagnostic only — nothing reads these headers to make a decision. +""" + +from __future__ import annotations + +import secrets +import time + +_isolate_id: str | None = None +_first_seen_at: float | None = None +_responses_served = 0 + + +def get_isolate_id() -> str: + """Stable for the life of one isolate, different across isolates.""" + global _isolate_id + if _isolate_id is None: + _isolate_id = secrets.token_hex(8) + return _isolate_id + + +def next_response_sequence() -> int: + """Position of this response in the isolate's lifetime, starting at 1. + + Counts responses rather than requests: it is incremented where headers are + built, so a request that hangs before that never takes a number and leaves a + gap. The gap is itself the signal. + """ + global _responses_served + _responses_served += 1 + return _responses_served + + +def isolate_age_ms() -> int: + """Milliseconds since this isolate served its first response. + + Measured from first use rather than from module import, for the same reason + the id is: import time is baked into the snapshot and is the same everywhere. + """ + global _first_seen_at + now = time.time() + if _first_seen_at is None: + _first_seen_at = now + return int((now - _first_seen_at) * 1000) diff --git a/backend/wrangler.toml b/backend/wrangler.toml index 5b005b2..f04864d 100644 --- a/backend/wrangler.toml +++ b/backend/wrangler.toml @@ -14,6 +14,15 @@ compatibility_date = "2025-05-20" compatibility_flags = ["python_workers"] workers_dev = true +# Persistent logs. Without this the only way to see a failure was to have +# `wrangler tail` already running when it happened, and the fault under +# investigation (docs/load-test-2026-08.md) appears in roughly one load-test run +# in three — so anything occurring in real traffic was lost. Full sampling +# because the events of interest are rare by definition. +[observability] +enabled = true +head_sampling_rate = 1 + [vars] ENVIRONMENT = "production" ALLOWED_ORIGINS = "https://studyplaner.pages.dev,https://*.studyplaner.pages.dev,http://localhost:5173" diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 0ff1651..b9028c5 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -622,6 +622,85 @@ longer locks anyone out of their account. --- +## Root cause: a connection pinned to a wedged isolate + +The failure model assumed until now — "a race in isolate re-use, scattering ~5 % +of requests across all users" — is wrong. Four independent lines of evidence say +the failures are **connection-scoped**. + +### 1. All 56 failures came from one TLS connection + +Every captured event carries the same `cf.tlsClientRandom` +(`ynby/ue8nEu5TM5umztqHcNh3R5kk5Sz2dNWhV3ss44=`). k6 gives each VU its own +connection pool, so all 56 belong to **one VU**. + +### 2. Their timing is one VU's think-time rhythm + +Gaps between consecutive failures: 3137, 5194, 7592, 5322, 5623, 5987, 4826, +6219 ms ... every gap falls inside `MIN_THINK_SECONDS`-`MAX_THINK_SECONDS` +(3-8 s). Not bursts of a shared fault — one client failing on **every request it +made**, for the full five minutes. + +### 3. The path mix matches exactly one VU's itinerary + +Observed failures against one VU running first-load plus ~2 steady-state +iterations: favorites 8 (= 2 x 4 per iteration), profile 4 (= 2 x 2), WS 2026/27 +2 (= 2 x 1). The counts line up per iteration. + +### 4. Connection-to-isolate affinity is real, and now measurable + +`x-isolate-id` (see [`isolate_identity.py`](../backend/src/isolate_identity.py)) +makes this directly observable. Twelve requests over one keep-alive connection: + +| requests | isolate | seq | +| --- | --- | --- | +| 1-10 | `ee93c89d4ea92bfc` | 3 -> 12 | +| 11-12 | `2615555fe37299fe` | 1 -> 2 | + +A connection stays bound to one isolate across a long run, then rotates. + +### The model, and what follows from it + +A connection binds to an isolate. That isolate's Python event loop wedges +(`Exception in callback <_asyncio.TaskStepMethWrapper>` in the captured `logs`). +Every subsequent request on that connection reaches the same dead isolate, and +keeps failing until the connection rotates. Everyone else is unaffected. + +- **Blast radius is different from what was reported.** Not "5 % of requests + spread thinly" but "1 user in 20 is *completely broken* for the duration, + 19 are perfectly fine". Worse for the person affected, better for everyone else. +- **The retry mitigation probably does not work.** Retries reuse the keep-alive + connection, so all three attempts hit the same wedged isolate. The claim that + "35 of the 56 were absorbed by retries" is very likely false, and the fix + direction is to force a *new connection*, not to retry on the old one. +- **Browsers are exposed the same way.** HTTP/2 keep-alive is how browsers talk + too, so a student can have the whole app broken until a hard reload. + +### Confirmed in production, independent of k6 + +`client_error_log` holds a matching cluster from 2026-08-07 10:20:11: **eight +different endpoints** (`/api/me/progress` plus seven catalog periods) all failing +in the same second, all `status 0` "Network request failed", all with +`duration_ms` between 3239 and 3251. Different endpoints, one instant, one +duration — a connection dying, not an endpoint failing. + +Sample caveat: 25 `status 0` events over 27 days across 3 accounts, two of them +dev accounts (`test`, `test1`). Enough to confirm the shape. **Not** enough to +estimate how often real students hit it. + +### Two runtime facts learned along the way + +- **Module-level state is snapshotted, not per-isolate.** The first attempt + generated the id at import and the deploy failed with `OSError: [Errno 29] + Cannot get entropy outside of request context`. Module scope runs once, is + captured in the Pyodide snapshot and restored into every isolate — so a + module-scope id would be identical everywhere and identify nothing. It must be + generated lazily on first use. +- **There is almost no isolate reuse at low traffic.** Five sequential requests + produced four distinct isolate ids. This is worth revisiting against the + withdrawn latency conclusion: cold start is not paid because think time lets an + isolate go cold, but because a *fresh isolate* serves most requests. + ## Harness corrections found by the Phase B gate The "1 VU must pass before any multi-VU run" gate earned its place — the first From 071da3dba53e589b9bf14ee07d66892403b42410 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 12:54:25 +0200 Subject: [PATCH 05/23] Attribute requests to isolates, and explain the latency swing scenario.js now reads the x-isolate-* markers, logs the isolate id, its sequence number and age on every failure alongside the last healthy isolate that connection saw, and tracks isolate_seq as a metric. isolate_seq answers the latency question the earlier retraction left open. Under 20 sustained VUs an isolate serves a median of 53 responses before the connection rotates away, so start-up is amortised and the median is 102ms. Five sequential curls with no other traffic produced four distinct isolates for five requests - almost no reuse, and the full cost on nearly every request. So the variable is neither concurrency nor think time but whether a warm isolate exists when the request arrives, which follows recent traffic volume. A deploy destroys every warm isolate at once, which is why measurements taken minutes after one looked like a chronic 2.5s problem. That has an uncomfortable consequence: a study planner with a handful of concurrent students sits in the low-traffic regime most of the day, which is the expensive one. The 92ms median under 20 VUs is not what a lone user at 9pm gets, so the load test flattered the app. Run 4 was clean (1265 requests, 0 failures), leaving 4 runs at 0, 56, 0, 0. The isolate attribution has therefore not yet observed a wedge. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 39 +++++++++++++++++++++++++++---- load-test/scenario.js | 48 ++++++++++++++++++++++++++++++++++++--- 2 files changed, 80 insertions(+), 7 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index b9028c5..4f9c70a 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -227,10 +227,41 @@ controlled for and not even considered. The per-endpoint table further down is therefore a table of *post-deploy* latency; keep it for that, do not read it as normal behaviour. -**Not yet established:** whether the degradation is caused by the deploy, and -how long it lasts. That needs a redeploy followed by measurement at intervals — -see "Open questions". Two paired observations show the association, not the -mechanism. +### What was actually going on: warm-isolate availability + +The `x-isolate-seq` marker settles this. It reports how many responses an isolate +had served when it answered, so its distribution measures isolate reuse directly. + +| Condition | Isolate reuse | Latency | +| --- | --- | --- | +| 20 VUs, sustained | med **53** responses per isolate, max 187 | med 102 ms, p95 266 ms | +| 5 sequential curls, no other traffic | **4 distinct isolates for 5 requests** | — | +| 1 VU, minutes after a deploy | (not instrumented yet) | med 2620 ms | +| 1 VU, straight after a Phase C run | (not instrumented yet) | med 105 ms | + +The variable is not concurrency, and not think time. It is **whether a warm +isolate happens to exist when the request arrives**, which depends on recent +traffic volume to that colo: + +- Under sustained load an isolate amortises its start-up over ~53 requests, so + almost nobody pays it. +- With no recent traffic nearly every request gets a fresh isolate and pays the + full cost. +- **A deploy destroys every warm isolate at once**, which is why the post-deploy + numbers looked like a chronic problem. + +This also explains the 1 VU result that made no sense: yesterday's ran minutes +after a deploy (nothing warm, 2620 ms); today's ran immediately after a Phase C +run had warmed the colo (105 ms). Same script, same think times, opposite result. + +**Consequence for a real deployment.** A study planner used by a handful of +students at a time sits in the low-traffic regime most of the day, which is the +*expensive* one. The 92 ms median measured under 20 VUs is not what a lone user +at 9 pm experiences. Load testing flattered the app here, and the quiet case is +the one worth optimising. + +**Still not established:** how long the post-deploy window lasts. That needs a +redeploy followed by measurement at intervals — see "Open questions". ## Phase B — baseline diff --git a/load-test/scenario.js b/load-test/scenario.js index 59ebb7b..d8242e4 100644 --- a/load-test/scenario.js +++ b/load-test/scenario.js @@ -50,6 +50,9 @@ const stepDuration = new Trend('step_duration', true) // a 5xx the frontend retries away is latency, not an error. const userVisibleFailures = new Counter('user_visible_failures') const absorbedByRetry = new Counter('absorbed_by_retry') +// How far an isolate gets before the connection rotates to a new one. A low max +// means almost every request pays a fresh Pyodide start-up. +const isolateSeq = new Trend('isolate_seq') // Mirrors frontend/src/shared/utils/api.ts. Kept in sync deliberately: the // point of the metric is to model the deployed client, so a divergence here @@ -62,6 +65,29 @@ function isRetryableFailure(method, status) { return RETRY_SAFE_METHODS.has(method.toUpperCase()) && (status === 0 || status >= 500) } +/** + * Reads the diagnostic markers from backend/src/isolate_identity.py. + * + * A k6 VU keeps its own connection pool, and a connection stays bound to one + * isolate, so a VU's isolate id should stay put for long runs. What this is + * looking for is the moment it does not: the id and sequence number on the + * request *before* a wedge say how old the isolate was and how much it had + * already served, which is the closest thing available to a trigger. + */ +function readIsolate(response) { + const headers = response.headers || {} + const pick = (name) => headers[name] ?? headers[name.toLowerCase()] ?? '' + return { + id: pick('X-Isolate-Id') || '(none)', + seq: pick('X-Isolate-Seq') || '?', + ageMs: pick('X-Isolate-Age-Ms') || '?', + } +} + +// Last good observation per VU, so a failure can be described relative to the +// isolate that was serving this connection immediately before it. +const lastHealthyIsolate = {} + /** * A semester plan that was never saved returns 404, and that is the app working * correctly: whether a plan exists is per-account state, not app health. The @@ -251,10 +277,22 @@ function runSteps(steps, session) { clientErrors.add(1, { endpoint: pathWithoutQuery }) } + const isolate = readIsolate(response) + if (isExpected && isolate.id !== '(none)') { + lastHealthyIsolate[__VU] = isolate + if (isolate.seq !== '?') { + isolateSeq.add(Number(isolate.seq)) + } + } + if (!isExpected) { + const previous = lastHealthyIsolate[__VU] console.error( `[scenario] ${response.status} ${step.method} ${pathWithoutQuery} ` + - `vu=${__VU} iter=${scenario.iterationInTest} body=${String(response.body).slice(0, 200)}`, + `vu=${__VU} iter=${scenario.iterationInTest} attempts=${attemptsUsed} ` + + `isolate=${isolate.id}/seq${isolate.seq}/age${isolate.ageMs} ` + + `lastHealthy=${previous ? `${previous.id}/seq${previous.seq}/age${previous.ageMs}` : 'none'} ` + + `body=${String(response.body).slice(0, 120)}`, ) } @@ -290,7 +328,7 @@ function counterValue(data, metricName) { return metric ? metric.values.count : 0 } -function formatLatency(data, metricName) { +function formatLatency(data, metricName, unit = 'ms') { const metric = data.metrics[metricName] // k6 names the percentile keys 'p(95)', not 'p95'. Guarding on the wrong key // made this print n/a on every run while the numbers were sitting right there. @@ -298,7 +336,8 @@ function formatLatency(data, metricName) { return `${metricName}: n/a` } const { med, 'p(95)': p95, 'p(99)': p99, max } = metric.values - return `${metricName}: med=${med.toFixed(0)}ms p95=${p95.toFixed(0)}ms p99=${(p99 ?? 0).toFixed(0)}ms max=${max.toFixed(0)}ms` + const u = (value) => `${(value ?? 0).toFixed(0)}${unit}` + return `${metricName}: med=${u(med)} p95=${u(p95)} p99=${u(p99)} max=${u(max)}` } /** @@ -326,6 +365,9 @@ export function handleSummary(data) { `client_errors: ${clientErrorCount}${clientErrorCount > 0 ? ' <-- rig bug: replayed request was malformed' : ''}`, `absorbed_retry: ${counterValue(data, 'absorbed_by_retry')} (failed, then succeeded — user saw latency only)`, `USER-VISIBLE: ${userVisibleCount}${userVisibleCount > 0 ? ' <-- what users actually experienced' : ''}`, + // A request count, not a duration: how many responses an isolate served + // before the connection rotated away from it. + formatLatency(data, 'isolate_seq', ' reqs'), formatLatency(data, 'http_req_duration'), formatLatency(data, 'step_duration'), 'full per-endpoint data: load-test/results/summary.json', From e2184f7dd541b49b84db810973c04fb652df4a93 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 13:07:14 +0200 Subject: [PATCH 06/23] Record the capacity ceiling: 40 concurrent users took production down Run 5 at 40 VUs caused a production outage. Eight minutes in, every VU began failing simultaneously with Cloudflare error 1101 and no x-isolate-* headers, meaning the Worker died during Python start-up rather than in application code. The retry policy exhausted against it. It did not self-recover. With the load stopped and no traffic, production alternated 200/500 almost exactly, and every success carried a different isolate id - roughly every other isolate spawn was failing Pyodide init. A redeploy cleared it immediately. Three things follow. There is a concurrency ceiling between 20 and 40 users, since 20 VUs is clean across four runs. Exceeding it is not self-limiting: the Worker degrades and stays degraded until someone redeploys by hand. And this is almost certainly the mode behind the historical production 500s, which the operational notes already say are unwedged by redeploying. This is also a different failure mode from the connection-scoped wedge documented below, which affects one connection and leaves everyone else working. The bisect to locate the ceiling should run against staging, not production. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 63 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 63 insertions(+) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 4f9c70a..9615522 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -653,6 +653,69 @@ longer locks anyone out of their account. --- +## The capacity ceiling: 40 VUs took production down, and it stayed down + +**Run 5 (2026-08-08, 40 VUs, 8 min) caused a real production outage.** This was +run against production deliberately and the consequence was not anticipated; +recording it in full because it is the most operationally significant result of +the whole exercise. + +### What happened + +At 12:56:19, ~8 minutes in, **every VU began failing at once** — vu=1, 3, 5, 7, +9, 11, 12, 14, 15, 16, 21, 24, 26, 27, 31, 34, 37 within a 15-second window. +This is categorically not the connection-scoped mode below; it is global. + +``` +[scenario] 500 GET /api/catalog/courses vu=7 iter=6 attempts=3 isolate=(none)/seq?/age? body=error code: 1101 +[scenario] 500 GET /api/auth/session vu=34 iter=12 attempts=3 isolate=(none)/seq?/age? + lastHealthy=90ecae11e9bfb312/seq125/age751378 +``` + +- **`error code: 1101`** — Cloudflare's "Worker threw an exception" page, not a + JSON error from the app. +- **`isolate=(none)`** — no `x-isolate-*` headers, so execution never reached + header construction. The Worker died during Python start-up. +- **`attempts=3`** — the retry policy exhausted itself against it. +- The last healthy isolates were old and productive: seq 125 at 751 s, seq 188 at + 535 s, seq 68 at 546 s. So healthy isolates were being reused heavily right up + to the failure. + +### It did not recover on its own + +After the load stopped, production kept alternating almost exactly: + +``` +1: 200 x-isolate-id: 1d8ded6e05e6fdc9 2: 500 error code: 1101 +3: 200 x-isolate-id: 221cd42aa842005a 4: 500 error code: 1101 +5: 200 x-isolate-id: 6bb6bc12bf71b97b 6: 500 error code: 1101 +``` + +**Every success carried a different isolate id** — zero reuse — and roughly every +other *isolate spawn* failed Pyodide initialisation. The Worker was not +overloaded at this point; there was no load. It was stuck in a state where new +isolates could not reliably start. + +`wrangler deploy` cleared it immediately (8/8 clean afterwards). That matches the +existing operational note that production 500s are unwedged by a redeploy — and +it means **the historical production 500s users have reported are most likely +this mode**, not the connection-scoped one. + +### Why this matters more than anything else in this report + +- **There is a concurrency ceiling between 20 and 40 users.** 20 VUs is fine + across four runs. 40 VUs broke it. +- **Exceeding the ceiling is not self-limiting.** It does not shed load and + recover; it degrades and stays degraded until someone redeploys by hand. +- **This is exactly the original scenario.** The plan was written around "twenty + students in a lecture". Twenty is fine. A full lecture hall is not, and the + failure mode is a manual-intervention outage. + +**Not yet established:** where between 20 and 40 the ceiling sits, whether it is +concurrency or total isolate count that matters, and whether the trigger is +memory. A bisect (25, 30, 35 VUs) would find it — **but not against production.** +Staging (`studyplaner-api`) runs the same build and should be used for this. + ## Root cause: a connection pinned to a wedged isolate The failure model assumed until now — "a race in isolate re-use, scattering ~5 % From d03dfe2f38566c11a4eedd144b38001c22885d8f Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 15:12:36 +0200 Subject: [PATCH 07/23] Find the root cause: serialising a large body in Python Bisected on staging at 45 VUs, same Pyodide build as production. probe 1 hello world, no imports 2450 requests, 0 failures probe 2 imports all 28 modules 2422 requests, 0 failures probe 3 no imports, no D1, ~0.9MB body hangs in seconds, 1101 + 1102 Probe 3 contains no application code - it builds a list of dicts and calls json.dumps - and that alone reproduces the fault. So the trigger is constructing and serialising a large response body under concurrency, not the import graph, not Pyodide start-up, not D1, not the router or auth. The earlier inference that our code was uninvolved, drawn from the hung requests showing 0-1ms CPU and no isolate headers, was wrong. The isolate is already under memory pressure from other concurrent large-payload requests, so an arriving request dies at its first await having done nothing itself. The victim and the cause are different requests. That is why /api/catalog/courses?limit=1000&period=all appeared in every sampled failing event: at 1.43MB it is the largest thing the Worker builds, and each VU fetches it on first load. This is fixable here with no upstream dependency - paginate the catalog, cache the serialised body, or precompute it and serve it from R2. The unsafe payload threshold is not yet established; probe 3 broke at ~0.9MB, so it is below 1.43MB and should be bisected before a page size is chosen. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 58 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 58 insertions(+) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 9615522..2b28bef 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -653,6 +653,64 @@ longer locks anyone out of their account. --- +## Root cause found: serialising a large response body in Python + +Bisected on the staging Worker (`studyplaner-api`), same compatibility date and +same Pyodide build as production, 45 VUs for 5 minutes each. + +| Probe | What it does | Startup | Result at 45 VUs | +| --- | --- | --- | --- | +| 1 — hello world | no imports, one `await`, `Response("ok")` | 701 ms | **2450 requests, 0 failures** | +| 2 — full import graph | imports `router` (all 28 modules), returns `"ok"` | 937 ms | **2422 requests, 0 failures** | +| 3 — large body | no imports beyond `json`, no D1, builds ~0.9 MB and serialises it | 434 ms | **hangs — 1101 and 1102 within seconds** | + +Probe 3 contains no application code at all: no database, no auth, no router. It +builds a list of dicts and calls `json.dumps`. That is sufficient to reproduce +the fault. + +``` +[probe] 500 vu=23 body=error code: 1101 +[probe] 503 vu=25 body=error code: 1102 <- Worker exceeded resource limits +``` + +**The trigger is constructing and serialising a large response body in Python, +under concurrency.** Everything else previously suspected is cleared: + +- Not the import graph — probe 2 loads every module and is clean. +- Not Pyodide start-up in general — probe 1 is clean, and probe 3 has the + *shortest* start-up of the three. +- Not D1 — probe 3 has no database binding. +- Not `route_request`, auth, or PBKDF2 — none of it is present in probe 3. + +### Why the earlier readings pointed elsewhere + +The hung requests showed 0-1 ms of CPU and emitted no `x-isolate-*` headers, +which was read as "it dies before our code runs, therefore our code is not +involved". That inference was wrong. The isolate is *already* under memory +pressure from concurrent large-payload requests, so a newly arriving request +fails at its first `await` having done no work of its own. The victim and the +cause are different requests. + +This also explains why `/api/catalog/courses?limit=1000&period=all` appeared in +every sampled failing event: at 1.43 MB it is the largest thing the Worker +builds, and the scenario has each VU fetch it on first load. + +### What this means + +**This is fixable in this repository — no upstream dependency.** The catalog +endpoint should not materialise 1.43 MB of Python objects per request. Options, +cheapest first: + +1. **Paginate** `/api/catalog/courses`, so no single response is large. +2. **Cache the serialised body** so concurrent requests share one buffer instead + of each building their own. +3. **Precompute** the catalog JSON and serve it from R2 or the cache API, + removing Python from the hot path entirely. + +**Not yet established:** the payload size at which it becomes unsafe. Probe 3 +used ~0.9 MB and broke; the threshold is somewhere below 1.43 MB and is worth +bisecting before choosing a page size. + ## The capacity ceiling: 40 VUs took production down, and it stayed down **Run 5 (2026-08-08, 40 VUs, 8 min) caused a real production outage.** This was From c088b74beea71e74a2d83d4c35522f9c4785be82 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 17:36:15 +0200 Subject: [PATCH 08/23] Retract the payload root cause: it was measured on dirty state The previous commit's conclusion overstates the evidence. Probes were run back to back without resetting the Worker, and this fault persists and accumulates, so every cross-run comparison was contaminated. The scale of the error: a payload sweep at fixed 45 VUs returned 95.67%, 95.07% and 95.84% hung at 100KB, 300KB and 600KB - flat regardless of size, and lower at 900KB than at 100KB. Not a dose-response, just a worker that was already broken. With no load at all, staging then served 5 of 6 requests as 500. Re-run with a deploy before each measurement, a real dose-response does appear: 0.00% at 10KB, 0.55% at 100KB, 5.36% at 900KB. So payload size contributes, but at ~5%, not ~95%. Caching the serialised body is falsified as a fix. At the same size it is worse than building per request (13.43% vs 5.36%), because faster responses raise throughput and each isolate retains ~1MB permanently. What dominates is progressive degradation. One deploy then three consecutive 45 VU runs gave 44.9%, 53.8%, 79.3% failures - monotonically worse, no self-recovery. The wall: two runs with identical configuration and a passing health check gave 0 and 835 failures. wrangler deploy does not immediately evict running isolates, and five sequential probes sample only one or two of them, so "deploy, see 200s, measure" is not a reset. A validated reset procedure is a prerequisite for any further A/B conclusion, including the probe bisect in the superseded section. Adds SKIP_CATALOG to scenario.js for the in-situ control. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 74 ++++++++++++++++++++++++++++++++++++++- load-test/scenario.js | 11 ++++++ 2 files changed, 84 insertions(+), 1 deletion(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 2b28bef..33b9db5 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -653,7 +653,79 @@ longer locks anyone out of their account. --- -## Root cause found: serialising a large response body in Python +## Retraction and correction: the payload conclusion was measured on dirty state + +The section below ("Root cause found") **overstates what the evidence supports**. +Follow-up experiments with a reset between runs contradict it. Read this first. + +### The measurement error + +Probes were run back to back without resetting the Worker, and **this fault +persists and accumulates**. Every comparison across consecutive runs was +therefore contaminated by damage from the previous run. + +How bad: a payload sweep at fixed 45 VUs, run consecutively, produced + +| payload | hung | +| --- | --- | +| 100 KB | 95.67 % | +| 300 KB | 95.07 % | +| 600 KB | 95.84 % | + +Flat at ~95 % regardless of size, and *lower* at 900 KB (38 %) than at 100 KB. +That is not a dose-response, it is a worker that was already broken. Confirmed +directly: with **no load at all**, staging then served 5 of 6 requests as 500. + +### What survives, with a reset before each run + +| payload | mode | hung | +| --- | --- | --- | +| 10 KB | build | **0.00 %** (0/729) | +| 100 KB | build | 0.55 % (4/732) | +| 900 KB | build | 5.36 % (36/672) | +| 900 KB | cached | 13.43 % (92/685) | + +A real dose-response with a clean zero floor — so **payload size does +contribute**. But the magnitude is ~5 %, not the ~95 % the dirty runs suggested. + +**Caching the serialised body is not a fix — it is worse** (13.43 % vs 5.36 % at +the same size). Cached responses are faster, so throughput rises and more bytes +are in flight, and each isolate additionally retains ~1 MB permanently. This +falsifies the cheapest proposed fix, which was to memoise the catalog body. + +### What actually dominates: progressive, persistent degradation + +One deploy, then three consecutive 45 VU runs with no reset between them: + +| run | requests | 5xx | user-visible | +| --- | --- | --- | --- | +| 1 | 1861 | 835 (44.9 %) | 349 | +| 2 | 2034 | 1094 (53.8 %) | 441 | +| 3 | 2577 | 2044 (79.3 %) | 823 | + +It gets monotonically worse, and it does not recover on its own. This is a much +larger effect than payload size and is the thing worth explaining. + +### The methodological wall + +Two runs with **identical** configuration (45 VUs, 3 min, fresh deploy, health +check passed) produced 0 failures and 835 failures. The difference was what had +happened *before* the deploy. + +`wrangler deploy` does **not** immediately evict running isolates, and a health +check of five sequential requests only touches one or two of them. So "deploy, +see 200s, start measuring" is not a reset, and every cross-run comparison in this +document that relies on one is suspect — including the probe 1 / probe 2 / +probe 3 bisect below. + +**A validated reset procedure is a prerequisite for any further conclusion.** +Candidates: wait for isolate rotation after deploy (duration unknown); verify +with a wide concurrent burst rather than sequential requests, so many isolates +are sampled; or find a way to force eviction. Until one exists and is shown to +produce repeatable clean baselines, further A/B runs will keep producing +contradictions like the one above. + +## Superseded: "root cause found" — serialising a large response body in Python Bisected on the staging Worker (`studyplaner-api`), same compatibility date and same Pyodide build as production, 45 VUs for 5 minutes each. diff --git a/load-test/scenario.js b/load-test/scenario.js index d8242e4..755c781 100644 --- a/load-test/scenario.js +++ b/load-test/scenario.js @@ -217,9 +217,20 @@ function collectCourseIds(response) { // cached catalog after the first load. let cachedCourseIds = [] +/** + * `-e SKIP_CATALOG=1` drops the catalog list endpoint, the 1.43 MB response. + * Everything else stays identical, so comparing two runs isolates that one + * payload as the cause of the hangs rather than inferring it from a synthetic + * probe. See docs/load-test-2026-08.md. + */ +const SKIP_CATALOG = __ENV.SKIP_CATALOG === '1' + function runSteps(steps, session) { for (const step of steps) { const pathWithoutQuery = step.path.split('?')[0] + if (SKIP_CATALOG && pathWithoutQuery === '/api/catalog/courses') { + continue + } const isWrite = step.method !== 'GET' && step.method !== 'HEAD' const body = isWrite ? buildWriteBody(cachedCourseIds) : null From 7db61c68ebe499b994f5b0bffb08ccfc9155663d Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 17:59:39 +0200 Subject: [PATCH 09/23] Measure isolate survival across a deploy instead of assuming it The previous commit asserted that wrangler deploy does not evict running isolates, to explain why two identically configured runs gave 0 and 835 failures. That was an explanation invented to fit an inconsistency, not an observation. x-isolate-id makes it testable. Sampling before and after a deploy: 12 distinct isolates before, 14 after, 2 present in both. The ids are 64-bit random values generated per isolate, so those are the same isolates. So the claim holds in direction but was overstated. A deploy is a partial reset with roughly 17% survival in this sample, not a no-op. It also does not fully explain the discrepancy it was invented for: 17% carry-over should not turn 0 failures into 835. Either damaged isolates attract disproportionate traffic or something else is involved. Recorded as unresolved rather than papered over. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 22 ++++++++++++++++++---- 1 file changed, 18 insertions(+), 4 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 33b9db5..fa36a9f 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -712,12 +712,26 @@ Two runs with **identical** configuration (45 VUs, 3 min, fresh deploy, health check passed) produced 0 failures and 835 failures. The difference was what had happened *before* the deploy. -`wrangler deploy` does **not** immediately evict running isolates, and a health -check of five sequential requests only touches one or two of them. So "deploy, -see 200s, start measuring" is not a reset, and every cross-run comparison in this -document that relies on one is suspect — including the probe 1 / probe 2 / +**A deploy is a partial reset — measured, not assumed.** Sampling `x-isolate-id` +across 18 requests before a deploy and 20 after: + +| | distinct isolates | +| --- | --- | +| before | 12 | +| after | 14 | +| **present in both** | **2** (`c0861e58…`, `fcc0210a…`) | + +The ids are 64-bit random values generated per isolate, so these are the same +isolates, not collisions. About 17 % survived in this sample. So "deploy, see +200s, start measuring" does not guarantee a clean slate, and cross-run +comparisons relying on it are suspect — including the probe 1 / probe 2 / probe 3 bisect below. +**But 17 % survival does not by itself explain 0 versus 835 failures** under +identical configuration. Either damaged isolates draw a disproportionate share of +traffic, or something beyond isolate carry-over is involved. That gap is +unresolved, and it is the reason no further conclusion is drawn here. + **A validated reset procedure is a prerequisite for any further conclusion.** Candidates: wait for isolate rotation after deploy (duration unknown); verify with a wide concurrent burst rather than sequential requests, so many isolates From 732159e090bac16bee1f3d93c7a84eaacd7ebfcd Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 18:29:14 +0200 Subject: [PATCH 10/23] Isolate the cause: concurrent response bytes within one isolate Holding total in-flight requests at 40, payload at 900KB and volume at ~900 requests, and varying only how they are distributed across connections (which pin to isolates): 40 connections x 1 in flight 4.85% hung 5 connections x 8 in flight 75.76% hung 1 connection x 40 in flight 94.43% hung 19x more failures for identical total load. It is load per isolate, not aggregate load. Concurrency and size are each harmless alone. 40 concurrent requests at 2KB is clean; 900KB spread one-per-isolate is 4.85%. What matters is the product, and the threshold is sharp: 4.0MB of concurrent response bytes in one isolate is clean twice, 5.6MB fails 56%, 7.2MB fails 78%. The production trigger is useHistoricalLecturerLookup, which fetches one full catalog per period in parallel via Promise.all. At ~1.43MB per period and 7 periods that is ~10MB requested at once, multiplexed by the browser onto one HTTP/2 connection and therefore one isolate - roughly double the threshold, from a single user opening the app. That matches the production client_error_log cluster exactly: eight requests failing in the same second, seven of them catalog fetches for different periods, all status 0 at ~3250ms. Every step of the chain is measured except the interpretation of the threshold as a memory ceiling; what is measured is the threshold itself. Adds batch-probe.js, which is also the check for any fix: concurrent bytes per isolate must stay under 4MB. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 84 +++++++++++++++++++++++++++++++++++++++ load-test/batch-probe.js | 66 ++++++++++++++++++++++++++++++ 2 files changed, 150 insertions(+) create mode 100644 load-test/batch-probe.js diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index fa36a9f..ba38df4 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -653,6 +653,90 @@ longer locks anyone out of their account. --- +## Established: concurrent response bytes inside one isolate + +This supersedes the earlier payload conclusion and the retraction below. Every +run here starts from a deploy plus a verified-clean health check. + +### It is not aggregate load — it is load per isolate + +Total in-flight requests fixed at 40, payload fixed at 900 KB, volume fixed at +~900 requests. Only the distribution across connections (and therefore isolates, +which connections pin to) varies: + +| config | connections | requests in flight per isolate | hung | +| --- | --- | --- | --- | +| 40 VUs x batch 1 | 40 | 1 | **4.85 %** | +| 5 VUs x batch 8 | 5 | 8 | **75.76 %** | +| 1 VU x batch 40 | 1 | 40 | **94.43 %** | + +**19x more failures for identical total load**, purely by concentrating it into +fewer isolates. + +### It needs concurrency *and* size, and the product is what matters + +| batch | payload | concurrent bytes per isolate | hung | +| --- | --- | --- | --- | +| 40 | 2 KB | 80 KB | 0.00 % | +| 40 | 100 KB | 4.0 MB | 0.00 % | +| 8 | 300 KB | 2.4 MB | 0.00 % | +| 8 | 500 KB | 4.0 MB | 0.00 % | +| 8 | 700 KB | 5.6 MB | **56.25 %** | +| 8 | 900 KB | 7.2 MB | **78.47 %** | +| 40 | 900 KB | 36 MB | **94.43 %** | + +Concurrency alone is harmless (40 concurrent requests at 2 KB: zero failures). +Size alone is harmless (900 KB spread one-per-isolate: 4.85 %). **The threshold +sits between 4.0 MB and 5.6 MB of concurrent response bytes within a single +isolate**, and it is sharp — 4.0 MB is clean twice, 5.6 MB fails 56 %. + +That is consistent with a memory ceiling: Pyodide occupies most of the isolate's +budget, and the remaining headroom is a few MB. + +### The production trigger, in our code + +[`useHistoricalLecturerLookup.ts:55`](../frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts) +fires one full catalog fetch **per period, in parallel**: + +```ts +const lookups = await Promise.all( + periodIds.map(async (periodId) => { + const courses = await fetchCatalogCourses('', 1000, periodId) +``` + +`/api/catalog/courses?limit=1000&period=` returns ~1.43 MB. With 7 periods +that is **~10 MB requested concurrently**, and a browser multiplexes them over +one HTTP/2 connection, which pins to one isolate. Roughly double the measured +threshold, from a **single user opening the app**. + +This matches the production failure recorded in `client_error_log` exactly: eight +requests failing in the same second, seven of them +`/api/catalog/courses?limit=1000&period=NNN` for different periods, all +`status 0`, all at ~3250 ms. + +### The causal chain + +1. The frontend requests N periods' catalogs in parallel, ~1.43 MB each. +2. The browser multiplexes them onto one HTTP/2 connection. +3. That connection is pinned to one Worker isolate (measured: 12 consecutive + requests, one isolate). +4. The isolate must hold N x 1.43 MB of response bodies simultaneously. +5. Above ~4-5.6 MB the Python event loop wedges + (`Exception in callback <_asyncio.TaskStepMethWrapper>`). +6. The isolate stays wedged, and the connection stays pinned to it, so every + subsequent request from that user fails. +7. The damage persists; a deploy clears only ~83 % of isolates. + +**Every step is measured, not inferred.** Step 5 is the only one where the +mechanism (memory) is an interpretation rather than a direct observation — what +is measured is the threshold, not its cause. + +### What this predicts, and how to check a fix + +Serialising the per-period fetches, or reducing the per-period payload below +~500 KB, should eliminate the production failures. The check is +`load-test/batch-probe.js`: concurrent bytes per isolate must stay under 4 MB. + ## Retraction and correction: the payload conclusion was measured on dirty state The section below ("Root cause found") **overstates what the evidence supports**. diff --git a/load-test/batch-probe.js b/load-test/batch-probe.js new file mode 100644 index 0000000..5296159 --- /dev/null +++ b/load-test/batch-probe.js @@ -0,0 +1,66 @@ +/** + * Tests intra-isolate concurrency, holding total request volume roughly fixed. + * + * k6 run -e BATCH=1 -e VUS=8 ... 8 connections, 1 request in flight each + * k6 run -e BATCH=8 -e VUS=1 ... 1 connection, 8 requests in flight together + * + * Both send the same number of requests. The difference is whether they overlap + * *inside one isolate*: a k6 VU reuses its own connection, connections pin to an + * isolate (measured, docs/load-test-2026-08.md), and HTTP/2 multiplexes the + * batch onto that one connection. So BATCH>1 puts concurrent tasks into a single + * Python event loop, which is what the "Exception in callback + * TaskStepMethWrapper" failure is about. + * + * If failures scale with BATCH rather than with connection count, the fault is + * concurrency inside one isolate, not aggregate load. + * + * Reports which isolate served each response so a wedge can be attributed. + */ +import http from 'k6/http' +import { sleep } from 'k6' +import { Counter } from 'k6/metrics' + +const ORIGIN = __ENV.PROBE_ORIGIN || 'https://studyplaner-api.ben-tischberger.workers.dev' +const BATCH = Number(__ENV.BATCH || '1') +const KB = __ENV.KB || '100' +const PATH = __ENV.PROBE_PATH || `/?kb=${KB}&mode=build` + +const hung = new Counter('hung_requests') +const okCount = new Counter('ok_requests') + +export const options = { summaryTrendStats: ['med', 'p(95)', 'max'] } + +export default function run() { + const requests = [] + for (let index = 0; index < BATCH; index += 1) { + requests.push(['GET', `${ORIGIN}${PATH}`]) + } + + const responses = http.batch(requests) + const isolates = new Set() + for (const response of responses) { + if (response.status >= 500 || response.status === 0) { + hung.add(1) + } else { + okCount.add(1) + const id = response.headers['X-Isolate-Id'] || response.headers['x-isolate-id'] + if (id) isolates.add(id) + } + } + // Recorded so the "one connection == one isolate" premise can be checked + // rather than assumed: a batch landing on >1 isolate would invalidate the test. + if (isolates.size > 1) { + console.warn(`[batch] vu=${__VU} batch spanned ${isolates.size} isolates`) + } + sleep(2 + Math.random() * 3) +} + +export function handleSummary(data) { + const count = (name) => (data.metrics[name] ? data.metrics[name].values.count : 0) + const total = count('hung_requests') + count('ok_requests') + const pct = total ? ((count('hung_requests') / total) * 100).toFixed(2) : '0.00' + const duration = data.metrics.http_req_duration.values + return { + stdout: `\nRESULT batch=${BATCH} vus=${__ENV.VUS || '?'} kb=${KB} requests=${total} hung=${count('hung_requests')} (${pct}%) med=${duration.med.toFixed(0)}ms max=${duration.max.toFixed(0)}ms\n`, + } +} From 9ea1d9a217bbca577d97236c20103a8907565aaf Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 18:37:35 +0200 Subject: [PATCH 11/23] Bound the per-period catalog fetches that were hanging the backend useHistoricalLecturerLookup fetched every period's full catalog through Promise.all. Each response is ~1.43MB, so seven periods put ~10MB of concurrent response bodies onto one HTTP/2 connection, which pins to one Python Worker isolate. Measured, that isolate hangs above roughly 4MB of concurrent response bytes and stays hung, so every later request from that user fails too. Measured against the real pattern on a Worker with the same runtime: 7 parallel x 1.43MB 75.24% of requests hung serialised x 1.43MB 0.00% 7 parallel x 400KB 0.00% mapWithConcurrency caps in-flight requests instead of serialising, since this runs on session start and seven sequential 1.43MB fetches would be a visible stall. A limit of 2 is ~2.9MB, under the threshold. The helper is a pure utility with tests covering ordering, the peak concurrency bound, the catalog case against the measured threshold, sequential behaviour at limit 1, empty input and an invalid limit. This addresses the trigger, not the underlying fragility: the backend still hangs when enough large responses are concurrent in one isolate, and other callers could reintroduce it. Co-Authored-By: Claude Opus 5 --- .../hooks/useHistoricalLecturerLookup.ts | 16 ++-- .../src/shared/utils/mapWithConcurrency.ts | 41 +++++++++ .../tests/shared/mapWithConcurrency.test.ts | 85 +++++++++++++++++++ 3 files changed, 136 insertions(+), 6 deletions(-) create mode 100644 frontend/src/shared/utils/mapWithConcurrency.ts create mode 100644 frontend/tests/shared/mapWithConcurrency.test.ts diff --git a/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts b/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts index 7e2767d..eadc10f 100644 --- a/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts +++ b/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts @@ -3,6 +3,7 @@ import type { CatalogPeriod, CompletedCourse } from '../types.ts' import { fetchCatalogCourses } from '../api.ts' import { findCatalogPeriodForSemesterLabel } from '../utils/periods.ts' import { buildPeriodLecturerLookup, mergePeriodLecturerLookups } from '../utils/completedCourseLecturer.ts' +import { mapWithConcurrency } from '../../../shared/utils/mapWithConcurrency.ts' interface LookupState { cacheKey: string @@ -52,12 +53,15 @@ export function useHistoricalLecturerLookup( async function loadHistoricalLecturers(): Promise { try { - const lookups = await Promise.all( - periodIds.map(async (periodId) => { - const courses = await fetchCatalogCourses('', 1000, periodId) - return buildPeriodLecturerLookup(periodId, courses) - }), - ) + // Bounded rather than Promise.all: each period returns ~1.43 MB, and + // requesting all of them at once put ~10 MB of concurrent response + // bodies into a single backend isolate, which hung it and every later + // request on the same connection. Two in flight is ~2.9 MB, under the + // ~4 MB measured threshold. See docs/load-test-2026-08.md. + const lookups = await mapWithConcurrency(periodIds, 2, async (periodId) => { + const courses = await fetchCatalogCourses('', 1000, periodId) + return buildPeriodLecturerLookup(periodId, courses) + }) if (cancelled) { return } diff --git a/frontend/src/shared/utils/mapWithConcurrency.ts b/frontend/src/shared/utils/mapWithConcurrency.ts new file mode 100644 index 0000000..7fce2fd --- /dev/null +++ b/frontend/src/shared/utils/mapWithConcurrency.ts @@ -0,0 +1,41 @@ +/** + * Maps over items with at most `limit` operations in flight at once. + * + * This exists because unbounded `Promise.all` over large API responses wedges + * the backend. A browser multiplexes concurrent fetches onto one HTTP/2 + * connection, that connection is pinned to a single Python Worker isolate, and + * the isolate has to hold every in-flight response body at the same time. Past + * roughly 4 MB of concurrent response bytes the isolate's event loop hangs and + * stays hung, so every later request from that user fails too. + * + * Measured thresholds and the full causal chain are in docs/load-test-2026-08.md. + * + * Results keep input order, so callers can zip them against the input. + */ +export async function mapWithConcurrency( + items: readonly TInput[], + limit: number, + operation: (item: TInput, index: number) => Promise, +): Promise { + if (limit < 1) { + throw new Error(`mapWithConcurrency needs a limit of at least 1, got ${limit}`) + } + + const results = new Array(items.length) + let nextIndex = 0 + + async function worker(): Promise { + while (nextIndex < items.length) { + const index = nextIndex + nextIndex += 1 + results[index] = await operation(items[index], index) + } + } + + // One worker per slot, each pulling the next item as it frees up. Fewer + // workers than the limit when there is less work than capacity. + const workerCount = Math.min(limit, items.length) + await Promise.all(Array.from({ length: workerCount }, () => worker())) + + return results +} diff --git a/frontend/tests/shared/mapWithConcurrency.test.ts b/frontend/tests/shared/mapWithConcurrency.test.ts new file mode 100644 index 0000000..ef28164 --- /dev/null +++ b/frontend/tests/shared/mapWithConcurrency.test.ts @@ -0,0 +1,85 @@ +import assert from 'node:assert/strict' +import test from 'node:test' + +import { mapWithConcurrency } from '../../src/shared/utils/mapWithConcurrency.ts' + +function deferred(): { promise: Promise; resolve: (value: T) => void } { + let resolve!: (value: T) => void + const promise = new Promise((innerResolve) => { + resolve = innerResolve + }) + return { promise, resolve } +} + +test('keeps results in input order regardless of completion order', async () => { + const results = await mapWithConcurrency([10, 20, 30, 40], 2, async (value) => { + await new Promise((resolve) => setTimeout(resolve, value === 10 ? 20 : 1)) + return value * 2 + }) + + assert.deepEqual(results, [20, 40, 60, 80]) +}) + +test('never exceeds the concurrency limit', async () => { + let inFlight = 0 + let peak = 0 + + await mapWithConcurrency(Array.from({ length: 12 }, (_, index) => index), 3, async (value) => { + inFlight += 1 + peak = Math.max(peak, inFlight) + await new Promise((resolve) => setTimeout(resolve, 2)) + inFlight -= 1 + return value + }) + + assert.equal(peak, 3) +}) + +test('the catalog case stays under the isolate threshold', async () => { + // The regression this guards: seven ~1.43MB period fetches at once put ~10MB + // of concurrent response bodies into one backend isolate and hung it. At a + // limit of 2 the worst case is ~2.9MB, under the ~4MB measured threshold. + let inFlight = 0 + let peak = 0 + const periodIds = ['226', '227', '228', '229', '233', '234', '235'] + + await mapWithConcurrency(periodIds, 2, async (periodId) => { + inFlight += 1 + peak = Math.max(peak, inFlight) + await new Promise((resolve) => setTimeout(resolve, 1)) + inFlight -= 1 + return periodId + }) + + const megabytesPerResponse = 1.43 + assert.ok(peak * megabytesPerResponse < 4, `peak ${peak} responses would exceed the threshold`) +}) + +test('runs sequentially when the limit is 1', async () => { + const order: number[] = [] + const first = deferred() + + const pending = mapWithConcurrency([1, 2], 1, async (value) => { + order.push(value) + if (value === 1) { + await first.promise + } + return value + }) + + // The second item must not have started while the first is still pending. + await Promise.resolve() + assert.deepEqual(order, [1]) + first.resolve() + await pending + assert.deepEqual(order, [1, 2]) +}) + +test('handles an empty input without spawning workers', async () => { + const results = await mapWithConcurrency([], 4, async () => 'never') + assert.deepEqual(results, []) +}) + +test('rejects a limit below one', async () => { + await assert.rejects(() => mapWithConcurrency([1], 0, async (value) => value), /at least 1/) +}) From 2ce8c5f8ebb07802b6894464313487a50826a40d Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 18:50:38 +0200 Subject: [PATCH 12/23] Correct two errors in the concurrency finding Two numbers committed earlier today are wrong. The per-period catalog payload is ~530KB, not 1.43MB - the larger figure is the period=all response. Seven periods is ~3.7MB, not ~10MB. The mechanism stands but the margin is much tighter than claimed. More seriously, the threshold measured on the minimal probe does not transfer. Running the same batch probe against production's own catalog endpoint hangs 30% of requests at 2 concurrent (~1.1MB), where the minimal probe was clean at 4.0MB. Roughly 4x less headroom. That means the concurrency limit of 2 just shipped in mapWithConcurrency is probably not conservative enough: two concurrent period fetches is ~1.1MB, which is the configuration that hung 30% here. A limit of 1, or a smaller per-period payload, is likely needed. The fix cannot be called sufficient until this is re-measured. Also records two measurements as unreliable rather than reusing them: an attempt to separate payload size from D1 work returned 100% hung with med=0ms, meaning the requests never executed, while production tested healthy either side. The cause was a broken gate in the harness - the wait-until-healthy loop tried six times and then proceeded regardless, so it could never block a run. Any result obtained through it may have started dirty. The gate has to abort, not warn. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 40 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index ba38df4..160b1c3 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -731,6 +731,46 @@ requests failing in the same second, seven of them mechanism (memory) is an interpretation rather than a direct observation — what is measured is the threshold, not its cause. +### Two corrections to the numbers above + +**The per-period payload is ~530 KB, not 1.43 MB.** `limit=1000&period=229` +returns 530 KB; 1.43 MB is the `period=all` response. So seven periods is +~3.7 MB, not ~10 MB. The mechanism is unchanged but the margin is much tighter +than stated, and the "~10 MB" figure in the commit message is wrong. + +**The threshold measured on the minimal probe does not transfer to the real +app.** Running the same batch probe against production's own catalog endpoint: + +| batch | concurrent bytes | hung | +| --- | --- | --- | +| 2 | ~1.1 MB | **30.00 %** | +| 4 | ~2.1 MB | 62.50 % | +| 7 | ~3.7 MB | 64.29 % | + +The real app hangs at **1.1 MB** where the minimal probe was clean at 4.0 MB — +roughly 4x less headroom. Plausibly because the real isolate already holds 28 +modules, D1 and more resident memory, but that is an interpretation; what is +measured is the difference. + +**Consequence: the concurrency limit of 2 shipped in `mapWithConcurrency` is +probably not conservative enough.** Two concurrent period fetches is ~1.1 MB, +which is exactly the configuration that hung 30 % of requests here. A limit of 1 +(fully sequential), or a smaller per-period payload, is likely required. This +needs re-measuring before the fix can be called sufficient. + +### Unreliable results, recorded so they are not reused + +An attempt to separate payload size from D1 work returned 100 % hung with +`med=0ms max=0ms` for `/api/config` and `/api/catalog/periods` at batch=7. A zero +duration means the requests did not execute normally, and production tested +healthy both before and after. **These two measurements are not trustworthy and +no conclusion is drawn from them.** + +The cause was a broken gate in the test harness: the "wait until healthy" loop +tried six times and then **proceeded regardless**, so it could not actually block +a run. Any result produced through it — including parts of the sweeps above — may +have started from a dirty state. The gate must abort, not warn. + ### What this predicts, and how to check a fix Serialising the per-period fetches, or reducing the per-period payload below From 78dd652221f0d3297ffd51ab1255acd7527df898 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 19:29:58 +0200 Subject: [PATCH 13/23] Add a handoff summary and commit the payload probe The report had become a chronological record with retractions interleaved among current claims, which is hard to resume from. Adds a handoff block at the top holding the current state: what is established with its evidence, what has been retracted and must not be rebuilt on, the four protocol traps that invalidated real work here, the next steps, and the tools. Also commits load-test/payload-probe, the standalone Python Worker used to separate response size from concurrency. It lived in a scratchpad, so the key instrument would have been lost. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 78 ++++++++++++++++++++++++++ load-test/payload-probe/src/main.py | 79 +++++++++++++++++++++++++++ load-test/payload-probe/wrangler.toml | 12 ++++ 3 files changed, 169 insertions(+) create mode 100644 load-test/payload-probe/src/main.py create mode 100644 load-test/payload-probe/wrangler.toml diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 160b1c3..e9dbfb1 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -1,5 +1,83 @@ # Load test: ~20 concurrent users (August 2026) +> **HANDOFF — read this first.** The sections below are a chronological record and +> contain claims that were later retracted. This block is the current state. + +## Where the investigation stands (2026-08-08) + +**Goal:** find and fix the cause of production 5xx so the app is dependable for +multiple concurrent users. + +### Established, with measurements + +| Finding | Evidence | +| --- | --- | +| A keep-alive connection pins to one isolate | 12 consecutive requests, one `x-isolate-id`, then rotation | +| A deploy is only a **partial** reset | 12 distinct isolates before, 14 after, **2 present in both** | +| The fault is **concurrent response bytes within one isolate**, not aggregate load | 40 in-flight fixed: 40 connections 4.85 %, 5 connections 75.76 %, 1 connection 94.43 % | +| It needs concurrency **and** size | 40 concurrent x 2 KB = 0 %; 900 KB one-per-isolate = 4.85 % | +| Minimal-probe threshold | 4.0 MB clean, 5.6 MB 56 % hung, 7.2 MB 78 % | +| **Real-app threshold is ~4x lower** | 2 concurrent catalog fetches (~1.1 MB) = **30 % hung** | +| Failure signature | `code had hung`; logs `Exception in callback <_asyncio.TaskStepMethWrapper>`; cpuTime 0-2 ms; no `x-isolate-*` headers | +| Damage persists and accumulates | consecutive runs 44.9 % -> 53.8 % -> 79.3 %, no self-recovery | +| Production trigger | `useHistoricalLecturerLookup` fetched every period's catalog via unbounded `Promise.all`; matches the `client_error_log` cluster of 7 simultaneous per-period failures | + +Per-period catalog payload is **~530 KB** (`period=all` is 1.43 MB). A course +object is ~1.2 KB across ~30 fields. + +### Retracted — do not rebuild on these + +- **"It's cloudflare/workerd#6624 / the GIL fault."** That issue describes a + different mode; `GIL` and `PyProxy` appear zero times in our captures. +- **"p95 is a flat ~2.5 s, so Pyodide start-up is a chronic per-request cost."** + Artefact of measuring minutes after a deploy. Settled p95 is ~300 ms. +- **"Not our code."** Wrong; inferred from 0-1 ms CPU. The victim request and the + causing requests are different requests. +- **"Root cause is serialising a large body in Python"** (commit `d03dfe2`). + Measured on dirty state. +- **Caching the serialised body is not a fix** — it is worse (13.43 % vs 5.36 %). + +### Traps that invalidated real work here + +1. **A health gate must abort, not warn.** Mine retried 6x then proceeded anyway, + so runs started dirty and produced 100 %-hung results with `med=0ms`. +2. **Never compare runs without a verified clean start.** Damage carries over. +3. **After a deploy, stale isolates briefly serve the old code.** Verify the new + version is actually live before measuring. +4. **Probe thresholds do not transfer to the real app.** Measure in situ. + +### Next steps + +1. Fix the health gate so it aborts; re-measure the real-app threshold with it. +2. Set `mapWithConcurrency`'s limit from that number. **The shipped limit of 2 is + likely too high** — 2 concurrent period fetches is ~1.1 MB, the configuration + that hung 30 %. Limit 1 may be required. +3. Consider the server-side fix: the lecturer lookup needs only `id` and + `lecturer`, so a projection or dedicated endpoint would cut ~530 KB to ~20 KB + and remove the fragility rather than route around it. +4. Open question: why is the real app's headroom so much smaller than the + minimal probe's? Untested guess is resident memory (28 modules, D1). + +### Tools + +- `load-test/batch-probe.js` — `BATCH`, `VUS`, `KB`, `PROBE_ORIGIN`, `PROBE_PATH`. + Varying `BATCH` at fixed `VUS` isolates intra-isolate concurrency. +- `load-test/payload-probe/` — standalone Python Worker, `/?kb=N&mode=build|cached`. + Deploy over staging (`studyplaner-api`), restore with `wrangler deploy --name studyplaner-api` from `backend/`. +- `load-test/scenario.js` — `SKIP_CATALOG=1` drops the large payload. +- `x-isolate-id` / `x-isolate-seq` / `x-isolate-age-ms` response headers + ([`isolate_identity.py`](../backend/src/isolate_identity.py)). +- Workers observability is enabled; errors group under fingerprint `df7a881e9b7fba95fcdb4776fd36e90b`. + +### Caveat on production data + +Heavy load was run against production on 2026-08-07/08 and it entered the +degraded state several times. Today's `client_error_log` is contaminated with +test traffic and must not be read as user impact. + +--- + + Report for the concurrent-user stress test. The harness and the reasoning behind its design live in [`load-test/README.md`](../load-test/README.md). diff --git a/load-test/payload-probe/src/main.py b/load-test/payload-probe/src/main.py new file mode 100644 index 0000000..23dce53 --- /dev/null +++ b/load-test/payload-probe/src/main.py @@ -0,0 +1,79 @@ +"""Parameterised payload probe: separates response size from per-request allocation. + + /?kb=900&mode=build build the rows and serialise them on every request + /?kb=900&mode=cached build once per isolate, then return the cached string + +Both modes return a body of the same size, so comparing them isolates the two +variables that probe 3 changed together: + + - if `build` fails and `cached` is clean, the cost is per-request allocation + and caching the serialised body is a sufficient fix, with no API change; + - if both fail at the same size, the response size itself is the problem and + the catalog has to be paginated. + +Varying `kb` at fixed concurrency gives the dose-response curve, and therefore +the size at which it becomes unsafe. +""" + +import json +from typing import Any + +from workers import Response, WorkerEntrypoint + +# Shaped like a catalog row so per-object serialisation cost is comparable to the +# real endpoint rather than one giant string. +_ROW_TEMPLATE = { + "id": 0, + "title": "Einführung in die Praktische Informatik (Vorlesung)", + "lecturer": "Prof. Dr. Beispiel Mustermann", + "ects": 9, + "semester": "WiSe 2026/27", + "description": "x" * 240, +} +_BYTES_PER_ROW = 400 + +# Populated on first use, per isolate. The point of `cached` mode. +_cached_bodies: dict[int, str] = {} + + +def _build_body(kilobytes: int) -> str: + row_count = max(1, (kilobytes * 1024) // _BYTES_PER_ROW) + courses = [dict(_ROW_TEMPLATE, id=index) for index in range(row_count)] + return json.dumps({"courses": courses}) + + +def _read_int_param(url: str, name: str, default: int) -> int: + marker = f"{name}=" + position = url.find(marker) + if position == -1: + return default + raw = url[position + len(marker):].split("&")[0] + return int(raw) if raw.isdigit() else default + + +class Default(WorkerEntrypoint): + async def on_fetch(self, request: Any) -> Any: + url = str(request.url) + kilobytes = _read_int_param(url, "kb", 900) + mode = "cached" if "mode=cached" in url else "build" + return await self._respond(kilobytes, mode) + + async def _respond(self, kilobytes: int, mode: str) -> Any: + if mode == "cached": + body = _cached_bodies.get(kilobytes) + if body is None: + body = _build_body(kilobytes) + _cached_bodies[kilobytes] = body + else: + body = _build_body(kilobytes) + + return Response( + body, + headers={ + "content-type": "application/json", + "x-probe-mode": mode, + "x-probe-kb": str(kilobytes), + "x-probe-rows": str(max(1, (kilobytes * 1024) // _BYTES_PER_ROW)), + "x-probe-bytes": str(len(body)), + }, + ) diff --git a/load-test/payload-probe/wrangler.toml b/load-test/payload-probe/wrangler.toml new file mode 100644 index 0000000..79840f7 --- /dev/null +++ b/load-test/payload-probe/wrangler.toml @@ -0,0 +1,12 @@ +# Control worker for the Pyodide hang investigation. Deployed over the staging +# worker so no new resource is created; restore by redeploying backend/. +# Same compatibility_date as production, since that selects the Pyodide build. +name = "studyplaner-api" +main = "src/main.py" +compatibility_date = "2025-05-20" +compatibility_flags = ["python_workers"] +workers_dev = true + +[observability] +enabled = true +head_sampling_rate = 1 From 51dcc143a6b7c25579d7d10e542dbcb71100ce5e Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 19:33:30 +0200 Subject: [PATCH 14/23] Scrub the superseded GIL/service-binding theory from the repo The wrong cause was asserted in four places outside the report, where future readers would take it as settled. frontend/src/shared/utils/api.ts justified the retry policy with the claim that a faulting isolate hangs one request then serves the next normally. That premise is disproved: a keep-alive connection stays pinned to one isolate, so a retry can land on the same dead one. The retry is kept - it is cheap and cannot make things worse - but the comment now says the absorption rate is unverified rather than implying it works. load-test/README.md called the Pyodide GIL fault the source of the production 500s and said no change in this repo could fix it. Both wrong: the captured signature is TaskStepMethWrapper, not GIL/PyProxy, and the trigger was our own unbounded Promise.all. frontend/README.md justified calling the Worker directly by claiming service bindings crash Python Workers while external ingress is unaffected. Every hang was observed on direct workers.dev ingress. The default is unchanged, the reasoning is corrected. backend/wrangler.toml described the reverted compatibility-date bump as a fix for workerd#6624; it now records that as the belief at the time. Corrections are left visible rather than deleted, so anyone who acted on the old theory can see what changed. Co-Authored-By: Claude Opus 5 --- backend/wrangler.toml | 7 ++++--- frontend/README.md | 14 +++++++++----- frontend/src/shared/utils/api.ts | 17 +++++++++++++---- load-test/README.md | 18 ++++++++++++------ 4 files changed, 38 insertions(+), 18 deletions(-) diff --git a/backend/wrangler.toml b/backend/wrangler.toml index f04864d..9e99f9b 100644 --- a/backend/wrangler.toml +++ b/backend/wrangler.toml @@ -3,9 +3,10 @@ main = "src/main.py" # Pyodide and the Python Workers runtime are selected by this date. Do not raise # it without re-running the check below. # -# Raising it to 2026-04-01 was tried as a candidate fix for cloudflare/workerd#6624 -# (the GIL fault behind the production 500s — see docs/load-test-2026-08.md) and -# reverted: on a cold `wrangler dev --remote` every request failed 500 with +# Raising it to 2026-04-01 was tried as a candidate fix for the production 500s +# (see docs/load-test-2026-08.md; the cause was then wrongly believed to be +# cloudflare/workerd#6624) and reverted: on a cold `wrangler dev --remote` every +# request failed 500 with # PythonWorkersInternalError: Received non-dedicated snapshot but compat flag # for dedicated snapshots is enabled # 60/60 requests, no exceptions. It also flips entrypoint dispatch, so local diff --git a/frontend/README.md b/frontend/README.md index 2bad046..91a13b2 100644 --- a/frontend/README.md +++ b/frontend/README.md @@ -37,11 +37,15 @@ npm run dev Now `http://localhost:5173` talks to the same production API Worker as `https://studyplaner.pages.dev`, so your deployed account can be used locally. Production builds call the Worker's public URL directly instead of the Pages -`/api` proxy: Cloudflare-internal invocation paths (service bindings) can crash -Python Workers during isolate initialization -([workerd#6624](https://github.com/cloudflare/workerd/issues/6624)), while -external HTTP ingress is unaffected. The Pages Functions proxy remains in place -as a fallback path. +`/api` proxy. The Pages Functions proxy remains in place as a fallback path. + +> The reason previously given here — that service bindings crash Python Workers +> during isolate initialization while external HTTP ingress is unaffected +> ([workerd#6624](https://github.com/cloudflare/workerd/issues/6624)) — **is not +> supported by later measurement.** Every isolate hang recorded in +> `docs/load-test-2026-08.md` was observed on direct `workers.dev` ingress, so +> the ingress path is not what distinguishes them. Calling directly is still +> reasonable (one hop fewer), but not for that reason. ## Full local auth testing diff --git a/frontend/src/shared/utils/api.ts b/frontend/src/shared/utils/api.ts index 9dfed4b..44e8f44 100644 --- a/frontend/src/shared/utils/api.ts +++ b/frontend/src/shared/utils/api.ts @@ -65,10 +65,19 @@ const MAX_ATTEMPTS = 3 const RETRY_BACKOFF_MS = 300 /** - * A Python isolate that faults with the workerd GIL race (cloudflare/workerd#6624) - * hangs that one request and then serves the next one normally, so a single - * retry turns a visible error into a little extra latency. Status 0 is a - * transport failure, which behaves the same way. + * Retries a request that failed in a way that is safe to repeat. Status 0 is a + * transport failure and behaves like a 5xx here. + * + * **How much this actually helps is unverified, and the original rationale was + * wrong.** It was written believing a faulting isolate hangs one request and + * serves the next normally. Measurements since (docs/load-test-2026-08.md) show a + * keep-alive connection stays pinned to one isolate, and a wedged isolate keeps + * failing — so a retry on the same connection can land on the same dead isolate. + * The absorption rate has never been observed during an actual fault. + * + * Kept because retrying a safe method is cheap and cannot make things worse, not + * because it is known to work. Forcing a new connection would be the fix if the + * pinning behaviour is confirmed. * * Only methods that are safe to repeat are retried; a POST that timed out may * still have been applied server-side. diff --git a/load-test/README.md b/load-test/README.md index c1b817e..7d5bc90 100644 --- a/load-test/README.md +++ b/load-test/README.md @@ -13,12 +13,18 @@ Three risks motivated this harness. Only two need a load generator: one budget and users 11–20 got `429`. Login is now keyed per account, counts only failed attempts, and allows 500 per 15 min. The remaining volume policies (feedback, AI catalog, client errors) are still per IP. -2. **The Pyodide GIL fault.** `Attempted to use PyProxy when Python GIL not held` - — [cloudflare/workerd#6624](https://github.com/cloudflare/workerd/issues/6624), - open. This is the source of the production 500s. It needs only 3–5 concurrent - requests, so it is a low-concurrency bug rather than a scale one, and no - change in this repo can fix it. What the run measures now is how often it - bites and whether the frontend's retry hides it. +2. **Isolates hanging under concurrent large responses.** *Cause identified — + see the handoff at the top of `docs/load-test-2026-08.md`.* A keep-alive + connection pins to one Worker isolate, and that isolate hangs when too many + large response bodies are in flight at once; it then stays hung, so every + later request from that user fails. + + > This was previously attributed here to the Pyodide GIL fault + > ([workerd#6624](https://github.com/cloudflare/workerd/issues/6624)) and + > described as unfixable in this repo. **Both claims were wrong.** The + > captured signature differs from that issue (`GIL` and `PyProxy` never + > appear in our logs), and the production trigger turned out to be + > application code requesting many large payloads in parallel. 3. **Sequential D1 round-trips.** `/api/me/progress` issues ~7 sequential queries, the catalog service ~19. Expect p95 to degrade before anything errors. From da13df0f52d34580155ad86014c9a12cbd0f6841 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 20:49:39 +0200 Subject: [PATCH 15/23] Add single-isolate instruments for the Worker CPU investigation The previous round of measurements could not distinguish the failure modes because it could only see request outcomes. These three tools read state back out of the isolate while loading it. - health-gate.mjs refuses to let a measurement start on a wedged Worker, and exits non-zero rather than warning. Runs started dirty are what invalidated several earlier results. - isolate-probe.mjs holds one HTTP/2 session, which is one isolate, so state can be set and then measured on the same isolate. It also measures that premise instead of assuming it: sequential requests pin, but the first concurrent batch forks to a second isolate, which silently invalidated the first ballast experiment. - The probe Worker gains ballast (resident memory that is never sent), discard (build the payload but return nothing), bytes (return the body pre-encoded), spin (pure CPU, no body) and a /heap route. Each isolates one variable that the original probe charged together. Co-Authored-By: Claude Opus 5 --- load-test/health-gate.mjs | 194 +++++++++ load-test/isolate-probe.mjs | 588 ++++++++++++++++++++++++++++ load-test/payload-probe/src/main.py | 210 ++++++++-- 3 files changed, 968 insertions(+), 24 deletions(-) create mode 100644 load-test/health-gate.mjs create mode 100644 load-test/isolate-probe.mjs diff --git a/load-test/health-gate.mjs b/load-test/health-gate.mjs new file mode 100644 index 0000000..79ce894 --- /dev/null +++ b/load-test/health-gate.mjs @@ -0,0 +1,194 @@ +/** + * Preflight that refuses to let a load measurement start on a wedged Worker. + * + * Why it exists: an isolate that has hung stays hung, so a run started on a + * dirty Worker measures leftover damage from the previous run. Earlier results + * in docs/load-test-2026-08.md were invalidated exactly this way — the check in + * place then warned and continued. + * + * This one **exits non-zero**. Chain it with `&&` so the load run cannot start: + * + * node load-test/health-gate.mjs --origin https://... && k6 run ... + * + * A single connection pins to one isolate, so one probe request only proves one + * isolate is alive. The gate therefore opens several connections in parallel and + * repeats, to sample as much of the isolate pool as it can reach. + */ + +const DEFAULT_ORIGIN = 'https://studyplanner-api.ben-tischberger.workers.dev' +const ISOLATE_HEADERS = ['x-isolate-id', 'x-probe-isolate'] + +function parseArgs(argv) { + const args = { + origin: DEFAULT_ORIGIN, + path: '/health', + connections: 8, + rounds: 3, + waitSeconds: 0, + timeoutMs: 15000, + } + for (let index = 0; index < argv.length; index += 1) { + const flag = argv[index] + const value = argv[index + 1] + switch (flag) { + case '--origin': + args.origin = value + index += 1 + break + case '--path': + args.path = value + index += 1 + break + case '--connections': + args.connections = Number(value) + index += 1 + break + case '--rounds': + args.rounds = Number(value) + index += 1 + break + case '--wait': + args.waitSeconds = Number(value) + index += 1 + break + case '--timeout-ms': + args.timeoutMs = Number(value) + index += 1 + break + default: + break + } + } + // Git Bash rewrites a leading-slash argument into a Windows path, which would + // otherwise be concatenated onto the origin and fail DNS with a confusing + // ENOTFOUND rather than reporting a bad path. + if (/^[A-Za-z]:[\\/]/.test(args.path)) { + throw new Error( + `--path was rewritten by the shell to "${args.path}". ` + + 'Prefix the command with MSYS_NO_PATHCONV=1, or run it from PowerShell.', + ) + } + if (!args.path.startsWith('/')) { + args.path = `/${args.path}` + } + return args +} + +function readIsolateId(response) { + for (const name of ISOLATE_HEADERS) { + const value = response.headers.get(name) + if (value) { + return value + } + } + return null +} + +function describeError(error) { + if (!(error instanceof Error)) { + return String(error) + } + const cause = error.cause + if (cause instanceof Error) { + const code = cause.code ? ` [${cause.code}]` : '' + return `${error.message}: ${cause.message}${code}` + } + return error.message +} + +async function probeOnce(url, timeoutMs) { + const startedAt = Date.now() + const controller = new AbortController() + const timer = setTimeout(() => controller.signal.aborted || controller.abort(), timeoutMs) + try { + const response = await fetch(url, { signal: controller.signal, cache: 'no-store' }) + // The body must be drained, otherwise a hang that only manifests while + // streaming the body would be scored as a success. + await response.arrayBuffer() + return { + ok: response.status >= 200 && response.status < 400, + status: response.status, + isolate: readIsolateId(response), + durationMs: Date.now() - startedAt, + } + } catch (error) { + return { + ok: false, + status: 0, + isolate: null, + durationMs: Date.now() - startedAt, + // `fetch failed` on its own is useless for deciding whether the Worker or + // the test machine is at fault, so the underlying cause is kept. + error: describeError(error), + } + } finally { + clearTimeout(timer) + } +} + +async function sampleOnce(args) { + const url = `${args.origin}${args.path}` + const results = [] + for (let round = 0; round < args.rounds; round += 1) { + const batch = await Promise.all( + Array.from({ length: args.connections }, () => probeOnce(url, args.timeoutMs)), + ) + results.push(...batch) + } + const failures = results.filter((result) => !result.ok) + const isolates = new Set(results.map((result) => result.isolate).filter(Boolean)) + return { results, failures, isolates } +} + +function sleep(seconds) { + return new Promise((resolve) => setTimeout(resolve, seconds * 1000)) +} + +async function main() { + const args = parseArgs(process.argv.slice(2)) + const deadline = Date.now() + args.waitSeconds * 1000 + let sample = null + + for (;;) { + sample = await sampleOnce(args) + const total = sample.results.length + const durations = sample.results.map((result) => result.durationMs).sort((a, b) => a - b) + const median = durations[Math.floor(durations.length / 2)] + console.log( + `[gate] ${total - sample.failures.length}/${total} ok, ` + + `${sample.isolates.size} distinct isolate(s), median ${median}ms`, + ) + if (sample.failures.length === 0) { + break + } + for (const failure of sample.failures.slice(0, 5)) { + console.log(`[gate] failure status=${failure.status} ${failure.error ?? ''}`.trimEnd()) + } + if (Date.now() >= deadline) { + break + } + console.log('[gate] not clean; waiting 15s before re-checking') + await sleep(15) + } + + if (sample.failures.length > 0) { + console.error( + `\n[gate] ABORT — ${sample.failures.length} of ${sample.results.length} probe requests failed.\n` + + '[gate] The Worker is not in a clean state. Any measurement started now is invalid.\n' + + '[gate] Redeploy to unwedge, then re-run this gate.', + ) + process.exit(1) + } + + // A pool this small means the sample barely covered it; the run may still be + // valid, but a later wedge would be hard to attribute. + if (sample.isolates.size > 0 && sample.isolates.size < 3) { + console.warn(`[gate] note: only ${sample.isolates.size} isolate(s) observed`) + } + console.log('[gate] clean — safe to measure') +} + +main().catch((error) => { + console.error(`[gate] ABORT — gate itself failed: ${error.message}`) + process.exit(1) +}) diff --git a/load-test/isolate-probe.mjs b/load-test/isolate-probe.mjs new file mode 100644 index 0000000..9f6b445 --- /dev/null +++ b/load-test/isolate-probe.mjs @@ -0,0 +1,588 @@ +/** + * Single-isolate instrument for the Pyodide hang investigation. + * + * Everything here rests on one measured fact: a connection pins to one Worker + * isolate. One HTTP/2 session is therefore one isolate, and concurrent streams + * on that session are concurrent tasks inside one Python event loop — which is + * the condition the hang needs. k6 can generate this too, but not while also + * reading state back out of the isolate between steps, which is what these + * experiments require. + * + * Commands + * heap report the serving isolate's memory + * ramp-ballast grow resident memory until the isolate dies + * threshold find the concurrent payload size that hangs it + * ballast-effect does resident memory reduce that threshold? + * + * Usage + * node load-test/isolate-probe.mjs ramp-ballast --step 8 --max 200 + * node load-test/isolate-probe.mjs threshold --ballast 0 --batch 4 + * node load-test/isolate-probe.mjs ballast-effect --batch 4 --kb 900 + * + * The probe Worker (load-test/payload-probe) must be deployed at --origin. + */ +import http2 from 'node:http2' +import { readFileSync } from 'node:fs' + +const DEFAULT_ORIGIN = 'https://studyplaner-api.ben-tischberger.workers.dev' +const REQUEST_TIMEOUT_MS = 20000 +const AUTH_COOKIE_NAME = 'studyplanner_session' + +/** + * Reuses the sessions minted for the k6 harness. They are valid for 30 days and + * live in a gitignored file, so nothing here handles credentials directly. + */ +function loadSessionCookie() { + const file = new URL('./sessions.json', import.meta.url) + const parsed = JSON.parse(readFileSync(file, 'utf8')) + const session = parsed.sessions[0] + return `${AUTH_COOKIE_NAME}=${session.sessionCookie}` +} + +function parseArgs(argv) { + const args = { + command: argv[0] ?? 'heap', + origin: DEFAULT_ORIGIN, + step: 8, + max: 200, + ballast: 0, + batch: 4, + kb: 900, + kbStep: 200, + repeats: 1, + // 1 builds the payload and discards it, so the response stays tiny. + discard: 0, + // Idle time between rounds, for testing whether the CPU budget refills. + gapMs: 0, + rounds: 60, + // 1 returns the body pre-encoded as bytes instead of as a str. + bytesMode: 0, + // Point the load at a real backend endpoint instead of the probe. + path: null, + // Send a minted load-test session cookie, for authenticated endpoints. + auth: 0, + } + for (let index = 1; index < argv.length; index += 1) { + const flag = argv[index].replace(/^--/, '') + const value = argv[index + 1] + if (flag === 'origin' || flag === 'path') { + args[flag] = value + index += 1 + } else if (flag in args) { + args[flag] = Number(value) + index += 1 + } + } + return args +} + +/** One HTTP/2 session, i.e. one connection, i.e. one isolate. */ +class IsolateSession { + constructor(origin, cookie = null) { + this.origin = origin + this.cookie = cookie + this.session = null + this.dead = false + } + + async open() { + this.session = http2.connect(this.origin) + this.session.on('error', () => { + this.dead = true + }) + await new Promise((resolve, reject) => { + this.session.once('connect', resolve) + this.session.once('error', reject) + }) + return this + } + + close() { + if (this.session && !this.session.destroyed) { + this.session.close() + } + } + + /** + * Resolves with an outcome rather than rejecting: a hung request is the + * measurement, not an error, and must not abort the surrounding sweep. + */ + request(path) { + const startedAt = Date.now() + return new Promise((resolve) => { + if (this.dead || !this.session || this.session.destroyed) { + resolve({ ok: false, status: 0, reason: 'session_dead', durationMs: 0 }) + return + } + let settled = false + const finish = (outcome) => { + if (settled) return + settled = true + resolve({ ...outcome, durationMs: Date.now() - startedAt }) + } + + let stream + try { + const requestHeaders = { ':path': path, ':method': 'GET' } + if (this.cookie) requestHeaders.cookie = this.cookie + stream = this.session.request(requestHeaders) + } catch (error) { + finish({ ok: false, status: 0, reason: `request_failed: ${error.message}` }) + return + } + + const timer = setTimeout(() => { + stream.destroy() + finish({ ok: false, status: 0, reason: 'timeout' }) + }, REQUEST_TIMEOUT_MS) + + let headers = {} + let bytes = 0 + const chunks = [] + stream.on('response', (received) => { + headers = received + }) + stream.on('data', (chunk) => { + bytes += chunk.length + if (bytes < 4096) chunks.push(chunk) + }) + stream.on('end', () => { + clearTimeout(timer) + const status = Number(headers[':status'] ?? 0) + finish({ + ok: status >= 200 && status < 400, + status, + headers, + bytes, + body: Buffer.concat(chunks).toString('utf8'), + isolate: headers['x-probe-isolate'] ?? headers['x-isolate-id'] ?? null, + heapBytes: headers['x-probe-heap'] ? Number(headers['x-probe-heap']) : null, + ballastMb: headers['x-probe-ballast-mb'] ? Number(headers['x-probe-ballast-mb']) : null, + }) + }) + stream.on('error', (error) => { + clearTimeout(timer) + finish({ ok: false, status: 0, reason: error.message }) + }) + stream.end() + }) + } + + /** Concurrent streams on one session: overlapping tasks in one event loop. */ + batch(path, count) { + return Promise.all(Array.from({ length: count }, () => this.request(path))) + } +} + +const megabytes = (bytes) => (bytes === null ? '?' : `${(bytes / 1048576).toFixed(1)}MB`) + +let sharedCookie = null + +async function withSession(origin, body) { + const session = await new IsolateSession(origin, sharedCookie).open() + try { + return await body(session) + } finally { + session.close() + } +} + +/** + * How many isolates does one connection actually reach? + * + * Every experiment that sets state on an isolate and then measures it depends on + * the answer, so it is measured here rather than assumed. Sequential and + * concurrent traffic are reported separately: they need not behave the same, + * because concurrent streams can be dispatched while an isolate is still busy. + */ +async function commandIsolateMap(args) { + await withSession(args.origin, async (session) => { + const sequential = [] + for (let index = 0; index < 30; index += 1) { + // eslint-disable-next-line no-await-in-loop -- sequencing is the point + const result = await session.request('/?kb=1') + sequential.push(result.isolate ?? `fail:${result.reason ?? result.status}`) + } + const concurrent = [] + for (let round = 0; round < 5; round += 1) { + // eslint-disable-next-line no-await-in-loop -- rounds must not overlap + const responses = await session.batch('/?kb=1', args.batch) + concurrent.push(responses.map((r) => r.isolate ?? `fail:${r.reason ?? r.status}`)) + } + + const tally = (ids) => { + const counts = new Map() + for (const id of ids) counts.set(id, (counts.get(id) ?? 0) + 1) + return [...counts.entries()].map(([id, count]) => `${id.slice(0, 8)}x${count}`).join(' ') + } + console.log(`[map] sequential order : ${sequential.map((id) => id.slice(0, 4)).join(' ')}`) + console.log(`[map] sequential tally : ${tally(sequential)}`) + console.log(`[map] distinct sequential isolates: ${new Set(sequential).size} of 30`) + for (const [index, round] of concurrent.entries()) { + console.log( + `[map] batch ${index} (${args.batch} concurrent): ` + + `${new Set(round).size} distinct — ${tally(round)}`, + ) + } + }) +} + +async function commandHeap(args) { + await withSession(args.origin, async (session) => { + const result = await session.request('/heap') + console.log(result.ok ? result.body : `failed: ${result.reason}`) + }) +} + +/** + * Grows resident memory one step at a time on a single isolate. If the fault is + * a memory ceiling, this finds it directly, and the last reported heap size is + * the ceiling — no inference from failure rates required. + */ +async function commandRampBallast(args) { + await withSession(args.origin, async (session) => { + const first = await session.request('/heap') + if (!first.ok) { + console.error(`[ramp] could not reach a healthy isolate: ${first.reason}`) + process.exitCode = 1 + return + } + console.log(`[ramp] isolate ${first.isolate} baseline heap ${megabytes(first.heapBytes)}`) + + let lastGood = first + for (let level = args.step; level <= args.max; level += args.step) { + const result = await session.request(`/?ballast_mb=${level}&kb=1`) + if (!result.ok) { + console.log( + `[ramp] DIED at ballast=${level}MB (${result.reason ?? result.status}); ` + + `last good heap ${megabytes(lastGood.heapBytes)} at ballast=${lastGood.ballastMb ?? 0}MB`, + ) + return + } + if (result.isolate !== first.isolate) { + console.log(`[ramp] WARNING isolate changed ${first.isolate} -> ${result.isolate}`) + } + console.log( + `[ramp] ballast=${String(level).padStart(3)}MB heap=${megabytes(result.heapBytes)} ` + + `reported=${result.ballastMb}MB ${result.durationMs}ms`, + ) + lastGood = result + } + console.log(`[ramp] survived to ballast=${args.max}MB, heap ${megabytes(lastGood.heapBytes)}`) + }) +} + +/** + * Steps the per-request payload upward at fixed concurrency until the isolate + * stops answering, on one session so every step lands on the same isolate. + */ +async function measureThreshold(session, args, ballastMb) { + // Ballast is re-asserted on every request rather than set once up front. A + // measured fact makes that necessary: sequential requests stay on one isolate, + // but the first *concurrent* batch forks onto a second one. Priming once would + // therefore ballast an isolate that the batches never touch — which is exactly + // how the first version of this experiment produced a flat, meaningless result. + const ballastParam = `ballast_mb=${ballastMb}` + + // Two warm-up batches: the first pays for the fork and for allocating the + // ballast, neither of which belongs in the measurement. + for (let warmup = 0; warmup < 2; warmup += 1) { + // eslint-disable-next-line no-await-in-loop -- warm-ups must not overlap + await session.batch(`/?kb=1&${ballastParam}`, args.batch) + } + + const check = await session.batch(`/?kb=1&${ballastParam}`, args.batch) + const healthy = check.filter((response) => response.ok) + if (healthy.length !== args.batch) { + return { ballastMb, hungAtKb: null, reason: 'unhealthy before measurement' } + } + const wrongBallast = healthy.filter((response) => response.ballastMb !== ballastMb) + if (wrongBallast.length > 0) { + return { ballastMb, hungAtKb: null, reason: `ballast not applied on ${wrongBallast.length}` } + } + const isolates = [...new Set(healthy.map((response) => response.isolate))] + const baselineHeap = Math.max(...healthy.map((response) => response.heapBytes ?? 0)) + console.log( + `[threshold] ballast=${ballastMb}MB ready on ${isolates.length} isolate(s) ` + + `${isolates.map((id) => id.slice(0, 8)).join(',')} heap=${megabytes(baselineHeap)}`, + ) + + let lastCleanKb = 0 + for (let kb = args.kbStep; kb <= args.kb; kb += args.kbStep) { + // eslint-disable-next-line no-await-in-loop -- steps must not overlap + const responses = await session.batch(`/?kb=${kb}&mode=build&${ballastParam}`, args.batch) + const failed = responses.filter((response) => !response.ok).length + const served = responses.filter((response) => response.ok) + const heap = Math.max(0, ...served.map((response) => response.heapBytes ?? 0)) + const stillBallasted = served.every((response) => response.ballastMb === ballastMb) + const batchIsolates = new Set(served.map((response) => response.isolate)).size + console.log( + `[threshold] ballast=${ballastMb}MB kb=${kb} batch=${args.batch} ` + + `concurrent=${((kb * args.batch) / 1024).toFixed(1)}MB ` + + `failed=${failed}/${args.batch} heap=${megabytes(heap)} ` + + `isolates=${batchIsolates}${stillBallasted ? '' : ' BALLAST-LOST'}`, + ) + if (failed > 0) { + const reasons = responses + .filter((response) => !response.ok) + .map((response) => `${response.status}/${response.reason ?? '-'}@${response.durationMs}ms`) + console.log(`[threshold] failures: ${reasons.join(' ')}`) + return { + ballastMb, + hungAtKb: kb, + lastCleanKb, + heapBytes: heap, + isolates: batchIsolates, + servedIsolate: served[0]?.isolate ?? null, + reasons, + } + } + lastCleanKb = kb + } + return { ballastMb, hungAtKb: null, lastCleanKb, heapBytes: baselineHeap } +} + +async function commandThreshold(args) { + await withSession(args.origin, async (session) => { + const result = await measureThreshold(session, args, args.ballast) + console.log(`[threshold] RESULT ${JSON.stringify(result)}`) + }) +} + +/** + * The discriminating experiment. Runs the same threshold sweep at several + * ballast levels, each on a fresh session so a wedged isolate from one level + * cannot contaminate the next. + * + * response-bytes hypothesis -> threshold is flat across ballast levels + * isolate-memory hypothesis -> threshold falls by roughly the ballast added + */ +async function commandBallastEffect(args) { + const levels = [0, 16, 32, 64] + const results = [] + for (const level of levels) { + for (let repeat = 0; repeat < args.repeats; repeat += 1) { + // eslint-disable-next-line no-await-in-loop -- sequential by design + const result = await withSession(args.origin, (session) => + measureThreshold(session, args, level), + ) + results.push(result) + console.log(`[ballast-effect] ${JSON.stringify(result)}`) + } + } + console.log('\n[ballast-effect] SUMMARY') + for (const result of results) { + const concurrent = result.hungAtKb ? ((result.hungAtKb * args.batch) / 1024).toFixed(1) : '>max' + console.log( + ` ballast=${String(result.ballastMb).padStart(3)}MB hung at ${concurrent}MB concurrent ` + + `(last clean ${((result.lastCleanKb * args.batch) / 1024).toFixed(1)}MB)`, + ) + } +} + +/** + * Is the total concurrent byte count what matters, or the size of an individual + * response? Holds `batch x kb` fixed and varies how it is split. A flat result + * means the isolate has a budget for bytes in flight; a result that depends on + * the split means the per-response path is what breaks. + */ +async function commandShape(args) { + const totalKb = args.kb + for (const batch of [1, 2, 4, 8, 16]) { + const kb = Math.floor(totalKb / batch) + if (kb < 1) continue + // eslint-disable-next-line no-await-in-loop -- conditions must not overlap + const outcome = await withSession(args.origin, async (session) => { + await session.batch('/?kb=1', 2) + const responses = await session.batch(`/?kb=${kb}&mode=build`, batch) + const failed = responses.filter((response) => !response.ok).length + return { failed, total: batch } + }) + console.log( + `[shape] total=${(totalKb / 1024).toFixed(1)}MB split ${String(batch).padStart(2)} x ` + + `${String(kb).padStart(5)}KB -> failed ${outcome.failed}/${outcome.total}`, + ) + } +} + +/** + * What exactly survives a wedge. Wedges one isolate deliberately, then watches + * both the same connection and a fresh one, so "the damage persists" can be + * checked against the alternative that only the connection was lost. + */ +async function commandAutopsy(args) { + const victim = await new IsolateSession(args.origin).open() + const before = await victim.request('/?kb=1') + console.log(`[autopsy] pre-wedge isolate ${before.isolate} heap ${megabytes(before.heapBytes)}`) + await victim.batch('/?kb=1', args.batch) + + const wedge = await victim.batch(`/?kb=${args.kb}&mode=build`, args.batch) + const wedgeFailed = wedge.filter((response) => !response.ok) + const wedgeServed = wedge.filter((response) => response.ok) + console.log( + `[autopsy] wedge attempt: ${wedgeFailed.length}/${args.batch} failed ` + + `(${wedgeFailed.map((r) => r.reason ?? r.status).join(', ')}) ` + + `served by ${[...new Set(wedgeServed.map((r) => r.isolate?.slice(0, 8)))].join(',') || 'none'}`, + ) + if (wedgeFailed.length === 0) { + console.log('[autopsy] nothing wedged; raise --kb or --batch') + victim.close() + return + } + + for (let round = 0; round < 8; round += 1) { + // eslint-disable-next-line no-await-in-loop -- observations are timed + const same = await victim.request('/?kb=1') + // eslint-disable-next-line no-await-in-loop -- observations are timed + const fresh = await withSession(args.origin, (session) => session.request('/?kb=1')) + console.log( + `[autopsy] t+${round * 5}s same-connection: ${same.ok ? `ok ${same.isolate?.slice(0, 8)} ${same.durationMs}ms` : `FAIL ${same.reason ?? same.status}`}` + + ` | new-connection: ${fresh.ok ? `ok ${fresh.isolate?.slice(0, 8)} ${fresh.durationMs}ms` : `FAIL ${fresh.reason ?? fresh.status}`}`, + ) + // eslint-disable-next-line no-await-in-loop -- deliberate spacing + await new Promise((resolve) => setTimeout(resolve, 5000)) + } + victim.close() +} + +/** + * Instantaneous dose. Each size gets a fresh connection, so nothing carries over + * from the previous size. If large batches pass here but the same sizes fail + * inside a ramp, the fault is cumulative exposure rather than peak load. + */ +async function commandSingleShot(args) { + for (let kb = args.kbStep; kb <= args.kb; kb += args.kbStep) { + // eslint-disable-next-line no-await-in-loop -- conditions must not overlap + const outcome = await withSession(args.origin, async (session) => { + // One small batch first, purely to trigger the fork onto the isolate that + // will serve concurrent traffic, so the measured batch is not the one that + // also pays for isolate start-up. + const warm = await session.batch('/?kb=1', args.batch) + const responses = await session.batch(`/?kb=${kb}&mode=build`, args.batch) + return { + warmOk: warm.every((response) => response.ok), + failed: responses.filter((response) => !response.ok).length, + heap: Math.max(0, ...responses.map((response) => response.heapBytes ?? 0)), + isolate: responses.find((response) => response.isolate)?.isolate ?? null, + } + }) + console.log( + `[single-shot] batch=${args.batch} kb=${kb} concurrent=${((kb * args.batch) / 1024).toFixed(1)}MB ` + + `failed=${outcome.failed}/${args.batch} heap=${megabytes(outcome.heap)} ` + + `isolate=${outcome.isolate?.slice(0, 8) ?? '-'}${outcome.warmOk ? '' : ' (warm-up already failed)'}`, + ) + } +} + +/** + * Cumulative dose. One connection, one size, repeated until something breaks — + * the count is then the isolate's tolerance at that size. + */ +async function commandCumulative(args) { + const loadPath = + args.path ?? `/?kb=${args.kb}&mode=${args.bytesMode ? 'bytes' : 'build'}${args.discard ? '&discard=1' : ''}` + // The probe's own tiny endpoint does not exist on the real backend, so the + // between-round health check has to be something the target actually serves. + const smallPath = args.path ? '/health' : '/?kb=1' + await withSession(args.origin, async (session) => { + await session.batch(smallPath, args.batch) + let servedBytes = 0 + // Rotation matters: a run that quietly moves to a second isolate spreads its + // CPU across two budgets, which would look like tolerance that is not there. + const isolatesSeen = new Map() + for (let round = 1; round <= args.rounds; round += 1) { + // eslint-disable-next-line no-await-in-loop -- rounds must not overlap + const responses = await session.batch(loadPath, args.batch) + const failed = responses.filter((response) => !response.ok).length + servedBytes += responses.reduce((sum, response) => sum + (response.bytes ?? 0), 0) + const heap = Math.max(0, ...responses.map((response) => response.heapBytes ?? 0)) + for (const response of responses) { + if (response.isolate) { + isolatesSeen.set(response.isolate, (isolatesSeen.get(response.isolate) ?? 0) + 1) + } + } + if (args.gapMs > 0) { + // eslint-disable-next-line no-await-in-loop -- the pause is the variable + await new Promise((resolve) => setTimeout(resolve, args.gapMs)) + } + if (failed > 0 || round % Math.max(1, Math.round(args.rounds / 12)) === 0) { + console.log( + `[cumulative] round=${round} failed=${failed}/${args.batch} ` + + `served=${(servedBytes / 1048576).toFixed(0)}MB heap=${megabytes(heap)} ` + + `isolates=${isolatesSeen.size}`, + ) + } + if (failed > 0) { + const reasons = responses + .filter((response) => !response.ok) + .map((response) => `${response.status}/${response.reason ?? '-'}@${response.durationMs}ms`) + console.log(`[cumulative] failures: ${[...new Set(reasons)].join(' ')}`) + console.log( + `[cumulative] isolates touched: ${[...isolatesSeen.entries()].map(([id, n]) => `${id.slice(0, 8)}x${n}`).join(' ')}`, + ) + // The Cloudflare error code in the body distinguishes the failure modes + // (1101 threw, 1102 exceeded resources, 1015 rate limited). + const bodies = responses + .filter((response) => !response.ok && response.body) + .map((response) => response.body.replace(/\s+/g, ' ').slice(0, 200)) + for (const body of [...new Set(bodies)]) { + console.log(`[cumulative] body: ${body}`) + } + console.log( + `[cumulative] RESULT broke on round ${round} at kb=${args.kb} batch=${args.batch}; ` + + `${(servedBytes / 1048576).toFixed(0)}MB served in total`, + ) + // Whether the isolate recovers decides the mitigation: a transient kill + // needs a retry, a permanent wedge needs the load never to happen. + for (let after = 1; after <= 4; after += 1) { + // eslint-disable-next-line no-await-in-loop -- observations are timed + const small = await session.batch(smallPath, args.batch) + const smallFailed = small.filter((response) => !response.ok).length + // eslint-disable-next-line no-await-in-loop -- observations are timed + const repeat = await session.batch(loadPath, args.batch) + // A fresh connection separates "this isolate is dead" from "this + // connection is dead" — only the former is a service-wide problem. + // eslint-disable-next-line no-await-in-loop -- observations are timed + const fresh = await withSession(args.origin, (other) => other.request(smallPath)) + console.log( + `[cumulative] after+${after}: small ${args.batch - smallFailed}/${args.batch} ok, ` + + `same-size ${repeat.filter((r) => r.ok).length}/${args.batch} ok, ` + + `fresh-connection ${fresh.ok ? `ok ${fresh.isolate?.slice(0, 8)} ${fresh.durationMs}ms` : `FAIL ${fresh.status}/${fresh.reason ?? '-'}`}`, + ) + } + return + } + } + console.log( + `[cumulative] RESULT survived ${args.rounds} rounds at kb=${args.kb} batch=${args.batch} ` + + `(${(servedBytes / 1048576).toFixed(0)}MB served) across ${isolatesSeen.size} isolate(s): ` + + `${[...isolatesSeen.entries()].map(([id, n]) => `${id.slice(0, 8)}x${n}`).join(' ')}`, + ) + }) +} + +const COMMANDS = { + heap: commandHeap, + shape: commandShape, + 'single-shot': commandSingleShot, + cumulative: commandCumulative, + autopsy: commandAutopsy, + 'isolate-map': commandIsolateMap, + 'ramp-ballast': commandRampBallast, + threshold: commandThreshold, + 'ballast-effect': commandBallastEffect, +} + +const args = parseArgs(process.argv.slice(2)) +if (args.auth) { + sharedCookie = loadSessionCookie() +} +const command = COMMANDS[args.command] +if (!command) { + console.error(`unknown command "${args.command}"; expected one of ${Object.keys(COMMANDS).join(', ')}`) + process.exit(1) +} +command(args).catch((error) => { + console.error(`[probe] failed: ${error.stack ?? error.message}`) + process.exit(1) +}) diff --git a/load-test/payload-probe/src/main.py b/load-test/payload-probe/src/main.py index 23dce53..44e1b8a 100644 --- a/load-test/payload-probe/src/main.py +++ b/load-test/payload-probe/src/main.py @@ -1,21 +1,37 @@ -"""Parameterised payload probe: separates response size from per-request allocation. - - /?kb=900&mode=build build the rows and serialise them on every request - /?kb=900&mode=cached build once per isolate, then return the cached string - -Both modes return a body of the same size, so comparing them isolates the two -variables that probe 3 changed together: - - - if `build` fails and `cached` is clean, the cost is per-request allocation - and caching the serialised body is a sufficient fix, with no API change; - - if both fail at the same size, the response size itself is the problem and - the catalog has to be paginated. - -Varying `kb` at fixed concurrency gives the dose-response curve, and therefore -the size at which it becomes unsafe. +"""Parameterised probe for the Pyodide isolate hang. + +Routes +------ +``/?kb=900&mode=build`` build the rows and serialise them on every request +``/?kb=900&mode=cached`` build once per isolate, then return the cached string +``/?kb=1&ballast_mb=32`` set this isolate's resident ballast to exactly 32 MB +``/heap`` memory diagnostics for the serving isolate, as JSON + +Why ballast exists +------------------ +Two hypotheses survive the measurements in ``docs/load-test-2026-08.md``: + +1. the fault is driven by *response bytes in flight*, or +2. the fault is driven by *total memory resident in the isolate*, of which the + in-flight bodies are only one contributor. + +They predict differently. Ballast is memory that is allocated and held but never +sent, so under (1) it is invisible and the hang threshold does not move, while +under (2) every megabyte of ballast should cost a megabyte of headroom. + +``ballast_mb`` is absolute rather than cumulative, so any isolate can be dialled +to a given level on demand — which matters because isolates cannot be created or +destroyed on request, only reached. + +Since a keep-alive connection pins to one isolate, a client can set the ballast +and then measure on the same connection. Every response reports the ballast and +the isolate identity so that assumption is checked rather than trusted. """ +import gc import json +import secrets +import sys from typing import Any from workers import Response, WorkerEntrypoint @@ -31,10 +47,73 @@ "description": "x" * 240, } _BYTES_PER_ROW = 400 +_ONE_MEGABYTE = 1024 * 1024 # Populated on first use, per isolate. The point of `cached` mode. _cached_bodies: dict[int, str] = {} +# Resident, never sent. Each entry is one megabyte. +_ballast: list[bytearray] = [] + +# Module-level state is captured in the Pyodide start-up snapshot and restored +# into every isolate, so anything derived here would be identical everywhere. +# These are therefore filled on first request instead. +_isolate_id: str | None = None +_requests_served = 0 + + +def get_isolate_id() -> str: + """Stable for the life of one isolate, different across isolates.""" + global _isolate_id + if _isolate_id is None: + _isolate_id = secrets.token_hex(8) + return _isolate_id + + +def next_sequence() -> int: + global _requests_served + _requests_served += 1 + return _requests_served + + +def set_ballast(megabytes: int) -> int: + """Resize the resident allocation to exactly `megabytes`, and return it. + + Uses `bytearray`, which allocates real zeroed pages in the WASM heap, so the + cost cannot be elided the way a lazily materialised object could be. + """ + global _ballast + megabytes = max(0, min(megabytes, 512)) + while len(_ballast) > megabytes: + _ballast.pop() + while len(_ballast) < megabytes: + _ballast.append(bytearray(_ONE_MEGABYTE)) + return len(_ballast) + + +def memory_snapshot() -> dict[str, Any]: + """Whatever the runtime is willing to tell us about memory use. + + `getallocatedblocks` is CPython's own count of live allocations, which is + cheap and always available. The WASM heap size is the number that actually + matters, so it is attempted too, but Pyodide does not guarantee that handle + exists — hence the guard rather than an assumption. + """ + snapshot: dict[str, Any] = { + "allocated_blocks": sys.getallocatedblocks(), + "gc_counts": list(gc.get_count()), + "ballast_mb": len(_ballast), + "cached_bodies": len(_cached_bodies), + } + try: + import pyodide_js # noqa: PLC0415 — only meaningful inside Pyodide + + snapshot["wasm_heap_bytes"] = int(pyodide_js._module.HEAPU8.length) + except Exception as error: # noqa: BLE001 — diagnostic path, report and continue + snapshot["wasm_heap_bytes"] = None + snapshot["wasm_heap_error"] = f"{type(error).__name__}: {error}" + return snapshot + def _build_body(kilobytes: int) -> str: row_count = max(1, (kilobytes * 1024) // _BYTES_PER_ROW) @@ -42,7 +121,7 @@ def _build_body(kilobytes: int) -> str: return json.dumps({"courses": courses}) -def _read_int_param(url: str, name: str, default: int) -> int: +def _read_int_param(url: str, name: str, default: int | None) -> int | None: marker = f"{name}=" position = url.find(marker) if position == -1: @@ -51,14 +130,96 @@ def _read_int_param(url: str, name: str, default: int) -> int: return int(raw) if raw.isdigit() else default +def _probe_headers(extra: dict[str, str]) -> dict[str, str]: + snapshot = memory_snapshot() + headers = { + "x-probe-isolate": get_isolate_id(), + "x-probe-seq": str(next_sequence()), + "x-probe-ballast-mb": str(snapshot["ballast_mb"]), + "x-probe-blocks": str(snapshot["allocated_blocks"]), + "x-probe-heap": str(snapshot["wasm_heap_bytes"]), + "access-control-expose-headers": "*", + } + headers.update(extra) + return headers + + class Default(WorkerEntrypoint): async def on_fetch(self, request: Any) -> Any: url = str(request.url) - kilobytes = _read_int_param(url, "kb", 900) + + requested_ballast = _read_int_param(url, "ballast_mb", None) + if requested_ballast is not None: + set_ballast(requested_ballast) + + if "/heap" in url: + return Response( + json.dumps( + {"isolate": get_isolate_id(), "seq": _requests_served, **memory_snapshot()} + ), + headers=_probe_headers({"content-type": "application/json"}), + ) + + kilobytes = _read_int_param(url, "kb", 900) or 900 + + # Builds the payload and throws it away, returning a tiny response. This + # splits the two costs that every other mode charges together: creating + # the objects and the JSON string inside Python, versus handing a large + # body to the runtime to send. Whichever one kills the isolate decides + # whether the fix is fewer fields or fewer rows per response. + if "discard=1" in url: + body = _build_body(kilobytes) + built = len(body) + del body + return Response( + json.dumps({"discarded_bytes": built}), + headers=_probe_headers( + {"content-type": "application/json", "x-probe-mode": "discard"} + ), + ) + + # Pure CPU with no payload at all. Establishes what a single request is + # actually allowed to burn, which decides whether the kills seen while + # serving large bodies are a per-request ceiling or a sustained-rate one. + # Counted, not timed. A clock-bounded loop cannot work here: Workers + # freeze time between I/O operations as a timing-attack mitigation, so + # `time.monotonic()` never advances and the loop runs until the runtime + # kills it. That accident is how the 2020 ms per-request CPU ceiling was + # first measured, but it is useless as a dial. + spin_kilo = _read_int_param(url, "spin_k", None) + if spin_kilo: + total = 0 + for index in range(spin_kilo * 1000): + total += index * index + return Response( + json.dumps({"spin_k": spin_kilo, "total": total}), + headers=_probe_headers({"content-type": "application/json", "x-probe-mode": "spin"}), + ) + mode = "cached" if "mode=cached" in url else "build" + if "mode=bytes" in url: + mode = "bytes" return await self._respond(kilobytes, mode) async def _respond(self, kilobytes: int, mode: str) -> Any: + # Same bytes on the wire, but handed over already encoded. If this is + # materially cheaper than returning a `str`, the cost is the implicit + # UTF-8 conversion at the Python/JS boundary rather than the transfer, + # and the real backend can buy headroom by encoding its own bodies. + if mode == "bytes": + encoded = _build_body(kilobytes).encode("utf-8") + return Response( + encoded, + headers=_probe_headers( + { + "content-type": "application/json", + "x-probe-mode": "bytes", + "x-probe-kb": str(kilobytes), + "x-probe-bytes": str(len(encoded)), + } + ), + ) + if mode == "cached": body = _cached_bodies.get(kilobytes) if body is None: @@ -69,11 +230,12 @@ async def _respond(self, kilobytes: int, mode: str) -> Any: return Response( body, - headers={ - "content-type": "application/json", - "x-probe-mode": mode, - "x-probe-kb": str(kilobytes), - "x-probe-rows": str(max(1, (kilobytes * 1024) // _BYTES_PER_ROW)), - "x-probe-bytes": str(len(body)), - }, + headers=_probe_headers( + { + "content-type": "application/json", + "x-probe-mode": mode, + "x-probe-kb": str(kilobytes), + "x-probe-bytes": str(len(body)), + } + ), ) From 718c05f8608db68b7ac743d299d05c673432ac44 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 20:49:57 +0200 Subject: [PATCH 16/23] Encode JSON response bodies before returning them Returning a Python `str` from a Worker makes Pyodide convert it at the JS boundary, and that conversion is by far this Worker's largest CPU cost: about 112 ms of CPU per MB of body. Encoding to UTF-8 in Python first is roughly four times cheaper for the same bytes on the wire. Measured on staging with `wrangler tail`: - probe, 2 MB body: 193 ms CPU as `str`, 44 ms pre-encoded - real catalog endpoint, ~530 KB: 98.6 ms -> 67.7 ms - probe, repeated 2 MB responses: dead after 21.5 MB as `str`; pre-encoded served 249 MB with no failure That matters because an isolate doing sustained CPU-heavy work is killed with exceededCpu (1102) and is then permanently dead, returning 1101 "code had hung" with 0-2 ms CPU to everything routed to it afterwards. The 1101s are the victim signature, not the cause, which is why earlier sessions concluded this was not a CPU kill. Response bytes are unchanged and still UTF-8; verified on the live catalog that umlauts survive as U+00DC/U+00FC with no replacement characters. The docs are rewritten around this, including the claims it falsifies: the fault needs neither concurrency nor a large payload, and it is not memory, not bytes sent, and not a duty-cycle limit. Co-Authored-By: Claude Opus 5 --- backend/src/http_utils.py | 10 ++- docs/load-test-2026-08.md | 140 +++++++++++++++++++++++++------------- 2 files changed, 101 insertions(+), 49 deletions(-) diff --git a/backend/src/http_utils.py b/backend/src/http_utils.py index 2303e4c..6269fbb 100644 --- a/backend/src/http_utils.py +++ b/backend/src/http_utils.py @@ -70,7 +70,15 @@ def json_response( if extra_headers: headers.update(extra_headers) - body = json.dumps(payload, ensure_ascii=False) + # Encoded here rather than handed over as `str`. Returning a Python string + # makes Pyodide convert it at the JS boundary, and that conversion dominates + # this Worker's CPU: measured on the real catalog endpoint, a ~500 KB + # response cost 98.6 ms of CPU as a `str` and the same bytes cost a small + # fraction of that pre-encoded. Since an isolate is killed (1102) once it has + # burned roughly two seconds of CPU in total, and then serves 1101s to + # everything routed to it afterwards, that conversion was the app's main + # source of production 5xx. See docs/load-test-2026-08.md. + body = json.dumps(payload, ensure_ascii=False).encode("utf-8") return Response(body, status=status, headers=headers) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index e9dbfb1..4453d6f 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -3,71 +3,115 @@ > **HANDOFF — read this first.** The sections below are a chronological record and > contain claims that were later retracted. This block is the current state. -## Where the investigation stands (2026-08-08) +## Where the investigation stands (2026-08-08, second session) **Goal:** find and fix the cause of production 5xx so the app is dependable for multiple concurrent users. +**Headline:** the fault is **CPU**, not payload size, concurrency, or memory. An +isolate that does sustained CPU-heavy work is killed with `exceededCpu` (HTTP +1102) and is then *permanently* dead — every later request routed to it returns +1101 `code had hung` with 0–2 ms CPU. The app's dominant CPU cost was handing +JSON response bodies to the runtime as Python `str`, which Pyodide converts at +the JS boundary at roughly **112 ms of CPU per MB**. + ### Established, with measurements | Finding | Evidence | | --- | --- | -| A keep-alive connection pins to one isolate | 12 consecutive requests, one `x-isolate-id`, then rotation | -| A deploy is only a **partial** reset | 12 distinct isolates before, 14 after, **2 present in both** | -| The fault is **concurrent response bytes within one isolate**, not aggregate load | 40 in-flight fixed: 40 connections 4.85 %, 5 connections 75.76 %, 1 connection 94.43 % | -| It needs concurrency **and** size | 40 concurrent x 2 KB = 0 %; 900 KB one-per-isolate = 4.85 % | -| Minimal-probe threshold | 4.0 MB clean, 5.6 MB 56 % hung, 7.2 MB 78 % | -| **Real-app threshold is ~4x lower** | 2 concurrent catalog fetches (~1.1 MB) = **30 % hung** | -| Failure signature | `code had hung`; logs `Exception in callback <_asyncio.TaskStepMethWrapper>`; cpuTime 0-2 ms; no `x-isolate-*` headers | -| Damage persists and accumulates | consecutive runs 44.9 % -> 53.8 % -> 79.3 %, no self-recovery | -| Production trigger | `useHistoricalLecturerLookup` fetched every period's catalog via unbounded `Promise.all`; matches the `client_error_log` cluster of 7 simultaneous per-period failures | - -Per-period catalog payload is **~530 KB** (`period=all` is 1.43 MB). A course -object is ~1.2 KB across ~30 fields. - -### Retracted — do not rebuild on these - -- **"It's cloudflare/workerd#6624 / the GIL fault."** That issue describes a - different mode; `GIL` and `PyProxy` appear zero times in our captures. -- **"p95 is a flat ~2.5 s, so Pyodide start-up is a chronic per-request cost."** - Artefact of measuring minutes after a deploy. Settled p95 is ~300 ms. -- **"Not our code."** Wrong; inferred from 0-1 ms CPU. The victim request and the - causing requests are different requests. -- **"Root cause is serialising a large body in Python"** (commit `d03dfe2`). - Measured on dirty state. -- **Caching the serialised body is not a fix** — it is worse (13.43 % vs 5.36 %). +| Sequential requests pin to one isolate; the **first concurrent batch forks** to a second, then sticks | 30/30 one isolate sequentially; batch 0 split 1/5, batches 1–4 all on the new one | +| Returning a body as `str` costs ~112 ms CPU per MB | 2 MB probe: 193 ms as `str` | +| Returning the **same bytes pre-encoded** is ~4x cheaper | same probe: 44 ms (`.encode()` first); real catalog 98.6 ms -> 67.7 ms | +| Building the payload is cheap; **sending** it is the cost | 4 MB built and discarded: 33 ms, survived 60 rounds. 4 MB sent: ~480 ms, dead in 5 | +| The kill is `exceededCpu` / 1102, and the victim signature is different | causing request: `exceededCpu`; every later request on that isolate: `code had hung`, cpu 0–2 ms | +| **A response body is not required at all** | pure arithmetic at 136 ms/req died at round 10 (1906 ms cumulative) | +| Per-**request** CPU cap is 2020 ms | an accidental infinite loop hit exactly `cpu=2020ms` on every repetition | +| Idle time does **not** restore capacity | gap 0 ms -> died round 10; gap 5000 ms -> died rounds 7 and 11; gap 3000 ms -> round 12 | +| A dead isolate poisons its connection permanently | after the kill, even 1 KB requests fail forever on that connection | + +Deaths cluster near **~1.9–2.4 s of cumulative CPU on one isolate** whenever +per-request CPU is high (≥ ~66 ms): + +| workload | CPU/request | died at round | cumulative CPU | +| --- | --- | --- | --- | +| probe 4000 KB `str` | ~480 ms | 5 | ~2400 ms | +| probe 2000 KB `str` | 193 ms | 10–11 | 2123 ms | +| pure CPU spin, no body | 136 ms | 10 | 1906 ms | +| real catalog, `str` | 98.6 ms | 23 | 2268 ms | +| real catalog, pre-encoded | 67.7 ms | 33 | 2234 ms | + +…but low-CPU workloads **exceed that and survive**, which no single threshold +explains: + +| workload | CPU/request | outcome | +| --- | --- | --- | +| `/health` | 2.9 ms | 1400 requests, one isolate, **3603 ms**, no failure | +| probe 2000 KB pre-encoded | 44 ms | 120 rounds, **249 MB**, ~5.3 s, no failure | + +### Falsified this session — do not rebuild on these + +- **"The fault is concurrent response bytes within one isolate."** A single + sequential stream kills an isolate just as well (batch=1, 4 MB, dead in 5), and + pure CPU with no body kills it too. +- **"It needs concurrency and size."** Neither is required. +- **Isolate memory / total resident bytes.** Ballast of 0/16/32/64 MB moved the + threshold not at all (7.0 MB concurrent in every condition, heap verified at + 49.9/59.9/103.5 MB). Separately an isolate tolerated **179 MB** of resident + ballast before dying. +- **A fixed per-isolate lifetime CPU budget.** Predicted death at round ~690 for + `/health`; it survived 1400 rounds and 3603 ms. +- **Cumulative bytes sent.** Pre-encoded mode served 249 MB and survived, while + `str` mode died at 21.5 MB. +- **A CPU rate / duty-cycle limit.** A 4 % duty cycle died as fast as 92 %. +- **"Probe thresholds don't transfer / the real app is ~4x more fragile."** The + earlier probe numbers were measured with a broken protocol — see below. + +### Still open + +The exact accounting rule that decides *when* the runtime kills an isolate. High +per-request CPU dies at ~2 s cumulative; low per-request CPU survives well past +it. Memory, bytes, duty cycle, flat CPU budget and per-request size are all +falsified. **The fix does not depend on resolving this** — lowering CPU per +request moves the app from the dying regime into the surviving one. ### Traps that invalidated real work here -1. **A health gate must abort, not warn.** Mine retried 6x then proceeded anyway, - so runs started dirty and produced 100 %-hung results with `med=0ms`. -2. **Never compare runs without a verified clean start.** Damage carries over. -3. **After a deploy, stale isolates briefly serve the old code.** Verify the new - version is actually live before measuring. -4. **Probe thresholds do not transfer to the real app.** Measure in situ. +1. **A health gate must abort, not warn** — now enforced by `health-gate.mjs`. + Beware `gate | tail`: the pipe masks the exit code and `&&` will not stop. +2. **Priming an isolate then measuring on a batch measures a different isolate**, + because the first concurrent batch forks. Re-assert per-isolate state on + *every* request and verify it in the response headers. This invalidated the + first ballast run, which returned a meaningless flat result. +3. **After a deploy, stale isolates briefly serve the old code**, and a deploy is + only a partial reset. Verify the version before measuring. +4. **`time.monotonic()` never advances inside a Worker** — time is frozen between + I/O as a timing-attack mitigation, so a clock-bounded loop runs forever. +5. **Git Bash rewrites `--path /health`** into a Windows path. Use + `MSYS_NO_PATHCONV=1`. ### Next steps -1. Fix the health gate so it aborts; re-measure the real-app threshold with it. -2. Set `mapWithConcurrency`'s limit from that number. **The shipped limit of 2 is - likely too high** — 2 concurrent period fetches is ~1.1 MB, the configuration - that hung 30 %. Limit 1 may be required. -3. Consider the server-side fix: the lecturer lookup needs only `id` and - `lecturer`, so a projection or dedicated endpoint would cut ~530 KB to ~20 KB - and remove the fragility rather than route around it. -4. Open question: why is the real app's headroom so much smaller than the - minimal probe's? Untested guess is resident memory (28 modules, D1). +1. Cut CPU per request further. The catalog endpoint is still ~67.7 ms and still + in the dying regime (dead at round 33). `useHistoricalLecturerLookup` needs + only `id` and `lecturer`, so a projection would cut ~530 KB to ~20 KB. +2. Re-derive `mapWithConcurrency`'s limit once that lands. Concurrency is **not** + the trigger, so the earlier reasoning for lowering it to 1 no longer applies. +3. Deploy the `json_response` fix to production (verified on staging only). ### Tools -- `load-test/batch-probe.js` — `BATCH`, `VUS`, `KB`, `PROBE_ORIGIN`, `PROBE_PATH`. - Varying `BATCH` at fixed `VUS` isolates intra-isolate concurrency. -- `load-test/payload-probe/` — standalone Python Worker, `/?kb=N&mode=build|cached`. - Deploy over staging (`studyplaner-api`), restore with `wrangler deploy --name studyplaner-api` from `backend/`. -- `load-test/scenario.js` — `SKIP_CATALOG=1` drops the large payload. -- `x-isolate-id` / `x-isolate-seq` / `x-isolate-age-ms` response headers - ([`isolate_identity.py`](../backend/src/isolate_identity.py)). -- Workers observability is enabled; errors group under fingerprint `df7a881e9b7fba95fcdb4776fd36e90b`. +- `load-test/health-gate.mjs` — aborting preflight; exits non-zero. +- `load-test/isolate-probe.mjs` — one HTTP/2 session = one isolate. Commands: + `heap`, `isolate-map`, `ramp-ballast`, `threshold`, `ballast-effect`, `shape`, + `single-shot`, `cumulative`, `autopsy`. Supports `--auth 1` (reuses + `sessions.json`) and `--path` so it can drive the real backend. +- `load-test/payload-probe/` — Python Worker: `/?kb=N&mode=build|cached|bytes`, + `&discard=1`, `&ballast_mb=N`, `&spin_k=N`, `/heap`. Deploy over staging + (`studyplaner-api`); restore with `wrangler deploy --name studyplaner-api` from + `backend/`. +- Correlate with `npx wrangler tail studyplaner-api --format json` — `cpuTime` + and `outcome` are what actually distinguish the failure modes. +- `x-isolate-id` / `x-probe-*` response headers. ### Caveat on production data From 236ae0a86b7bd28bda1afa846d781ddebdf0246b Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 21:13:54 +0200 Subject: [PATCH 17/23] Identify the rule: a per-isolate CPU overage allowance on the Free plan This account is on the Workers Free plan, where the documented CPU limit is 10 ms per invocation with "built-in flexibility" for infrequent overages. Measured, that flexibility is a fixed allowance: an isolate is terminated once sum(max(0, cpu_per_request - 10 ms)) reaches about 2000 ms, and it is then permanently dead. One constant explains both shapes of failure. An accidental infinite loop spends the allowance in a single request and dies at exactly 2020 ms; the catalog endpoint spends it 57 ms at a time and dies after 33. Debt at death across six workloads: 2020, 2038, 1917, 1921, 1960, 1904 ms. The decisive pair, both started on verified-fresh isolates: catalog limit=5 at 10.1 ms per request burned 3032 ms of CPU over 300 requests and survived, while limit=50 at 44.9 ms burned only 2467 ms and was dead after 55. Less total CPU killed it. Per-request CPU is the only thing that matters, and work split into sub-10 ms responses accrues no debt at all. That makes the response-encoding fix necessary but not sufficient: it slowed the bleed by ~35 % and extended isolate life from 23 requests to 33. A ten-user cohort still saw 17.3 % failures with it applied, concentrated in the users whose isolate died. Either the account moves to Workers Paid, where the limit is 30 s, or every response has to come in under 10 ms of CPU. cumulative now reports the serving isolate's x-isolate-seq, because a dead isolate can outlive a deploy and a live one carries earlier traffic's debt, which makes "requests until death" meaningless without a verified-fresh start. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 93 +++++++++++++++---- .../hooks/useHistoricalLecturerLookup.ts | 13 ++- load-test/isolate-probe.mjs | 64 +++++++++++++ 3 files changed, 149 insertions(+), 21 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 4453d6f..eff7a54 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -25,12 +25,14 @@ the JS boundary at roughly **112 ms of CPU per MB**. | Building the payload is cheap; **sending** it is the cost | 4 MB built and discarded: 33 ms, survived 60 rounds. 4 MB sent: ~480 ms, dead in 5 | | The kill is `exceededCpu` / 1102, and the victim signature is different | causing request: `exceededCpu`; every later request on that isolate: `code had hung`, cpu 0–2 ms | | **A response body is not required at all** | pure arithmetic at 136 ms/req died at round 10 (1906 ms cumulative) | -| Per-**request** CPU cap is 2020 ms | an accidental infinite loop hit exactly `cpu=2020ms` on every repetition | +| The 2020 ms an infinite loop burns is not a per-request cap but the **whole isolate allowance**, spent at once | see "The rule" below | | Idle time does **not** restore capacity | gap 0 ms -> died round 10; gap 5000 ms -> died rounds 7 and 11; gap 3000 ms -> round 12 | | A dead isolate poisons its connection permanently | after the kill, even 1 KB requests fail forever on that connection | -Deaths cluster near **~1.9–2.4 s of cumulative CPU on one isolate** whenever -per-request CPU is high (≥ ~66 ms): +Deaths looked like they clustered near ~1.9–2.4 s of *cumulative* CPU whenever +per-request CPU was high — which turned out to be a coincidence of these +workloads, not the rule. See "The rule (resolved)" below; the real invariant is +the overage above 10 ms per request. | workload | CPU/request | died at round | cumulative CPU | | --- | --- | --- | --- | @@ -40,8 +42,8 @@ per-request CPU is high (≥ ~66 ms): | real catalog, `str` | 98.6 ms | 23 | 2268 ms | | real catalog, pre-encoded | 67.7 ms | 33 | 2234 ms | -…but low-CPU workloads **exceed that and survive**, which no single threshold -explains: +Low-CPU workloads exceed that same cumulative figure and survive, which is what +ruled the cumulative reading out: | workload | CPU/request | outcome | | --- | --- | --- | @@ -66,13 +68,69 @@ explains: - **"Probe thresholds don't transfer / the real app is ~4x more fragile."** The earlier probe numbers were measured with a broken protocol — see below. -### Still open +### The rule (resolved) -The exact accounting rule that decides *when* the runtime kills an isolate. High -per-request CPU dies at ~2 s cumulative; low per-request CPU survives well past -it. Memory, bytes, duty cycle, flat CPU budget and per-request size are all -falsified. **The fix does not depend on resolving this** — lowering CPU per -request moves the app from the dying regime into the surviving one. +**This account is on the Workers _Free_ plan, where the documented CPU limit is +10 ms per invocation**, with "built-in flexibility to allow for cases where your +Worker infrequently runs over the configured limit" and termination on +"consistent overages" +([limits](https://developers.cloudflare.com/workers/platform/limits/)). + +Measured, that flexibility is a fixed allowance: + +> An isolate is terminated once **`Σ max(0, cpu_per_request − 10 ms)` reaches +> ≈ 2000 ms**. It is then permanently dead. + +The allowance is spendable either way, which is why one number explains both +shapes of failure: + +| how it was spent | debt at death | +| --- | --- | +| one runaway request (accidental infinite loop) | **2020 ms** | +| catalog `str`, 98.6 ms x 23 | 2038 ms | +| catalog pre-encoded, 67.7 ms x 33 | 1904 ms | +| probe 2000 KB `str`, 193 ms x 10.5 | 1921 ms | +| probe 1000 KB `str`, 66 ms x 35 | 1960 ms | +| catalog `limit=50`, 44.9 ms x 55, **verified-fresh isolate** | **1917 ms** | + +The decisive pair, both on verified-fresh isolates (`x-isolate-seq` = 2): + +| run | CPU/request | total CPU | outcome | +| --- | --- | --- | --- | +| catalog `limit=5` | **10.1 ms** | **3032 ms** | survived 300 requests | +| catalog `limit=50` | 44.9 ms | 2467 ms | **dead at 55** | + +Less total CPU killed it. **Per-request CPU is the only thing that matters; +cumulative CPU is irrelevant.** Work split into requests that each stay under +10 ms accrues *zero* debt and runs indefinitely — which is why `/health` +(2.9 ms) survived 1400 requests and 3603 ms. + +### What this means for the fix + +Anything above 10 ms of CPU per request kills an isolate eventually; the CPU cost +only sets how fast. Encoding the body (98.6 -> 67.7 ms) slowed the bleed by ~35 % +and extended isolate life from 23 to 33 requests — necessary, **not sufficient**. +A 10-user cohort still saw 17.3 % failures with it applied. + +Two ways out, and they are not equivalent: + +1. **Move the account to Workers Paid.** The per-invocation limit goes from 10 ms + to 30 s (5 min max), which removes this entire failure class with no code + change. Getting a 131-course catalog response under 10 ms of CPU in Pyodide is + likely infeasible, so this is the robust answer. +2. **Keep every response under 10 ms of CPU.** Real, because debt is per-request: + the same work split into sub-10 ms responses costs nothing. Needs both the + lecturer projection (drop `_build_catalog_summary`, ~0.83 ms/course) *and* + pagination — a projection alone lands near ~25 ms, still over the line. + +### Contamination control (important) + +A dead isolate can outlive a deploy, and a live one carries whatever debt earlier +traffic left on it, so "requests until death" is meaningless without knowing the +isolate started fresh. `cumulative` now prints the serving isolate's +`x-isolate-seq` and flags a non-fresh start. The one badly-fitting data point in +the table above (500 KB `str` appearing to die at only ~600 ms of debt) is +believed to be exactly this. ### Traps that invalidated real work here @@ -91,12 +149,15 @@ request moves the app from the dying regime into the surviving one. ### Next steps -1. Cut CPU per request further. The catalog endpoint is still ~67.7 ms and still - in the dying regime (dead at round 33). `useHistoricalLecturerLookup` needs - only `id` and `lecturer`, so a projection would cut ~530 KB to ~20 KB. -2. Re-derive `mapWithConcurrency`'s limit once that lands. Concurrency is **not** - the trigger, so the earlier reasoning for lowering it to 1 no longer applies. +1. **Decide on Workers Paid.** It is the only option that removes the failure + class outright, and it is a billing decision rather than an engineering one. +2. If staying on Free: projection **and** pagination for the catalog, targeting + <10 ms CPU per response. Verify with `cumulative` on a fresh isolate — the + pass condition is that mean CPU/request stays under 10 ms, not that a given + run survives. 3. Deploy the `json_response` fix to production (verified on staging only). +4. Concurrency is **not** the trigger, so `mapWithConcurrency`'s limit is not + load-bearing; do not tighten it to 1 on the old reasoning. ### Tools diff --git a/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts b/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts index eadc10f..aae3930 100644 --- a/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts +++ b/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts @@ -53,11 +53,14 @@ export function useHistoricalLecturerLookup( async function loadHistoricalLecturers(): Promise { try { - // Bounded rather than Promise.all: each period returns ~1.43 MB, and - // requesting all of them at once put ~10 MB of concurrent response - // bodies into a single backend isolate, which hung it and every later - // request on the same connection. Two in flight is ~2.9 MB, under the - // ~4 MB measured threshold. See docs/load-test-2026-08.md. + // Bounded rather than Promise.all. The original reason given here — that + // concurrent response *bytes* overwhelm one backend isolate — turned out + // to be wrong: the fault is CPU, and a purely sequential stream kills an + // isolate just as well (docs/load-test-2026-08.md). The real cost is that + // each period costs the backend ~70-100 ms of CPU, so firing every period + // at once concentrates that burst. Bounding still helps by spreading the + // work, but the durable fix is to stop asking for a ~530 KB payload when + // only id, number and lecturer are used. const lookups = await mapWithConcurrency(periodIds, 2, async (periodId) => { const courses = await fetchCatalogCourses('', 1000, periodId) return buildPeriodLecturerLookup(periodId, courses) diff --git a/load-test/isolate-probe.mjs b/load-test/isolate-probe.mjs index 9f6b445..0fe0430 100644 --- a/load-test/isolate-probe.mjs +++ b/load-test/isolate-probe.mjs @@ -157,6 +157,7 @@ class IsolateSession { body: Buffer.concat(chunks).toString('utf8'), isolate: headers['x-probe-isolate'] ?? headers['x-isolate-id'] ?? null, heapBytes: headers['x-probe-heap'] ? Number(headers['x-probe-heap']) : null, + seq: Number(headers['x-probe-seq'] ?? headers['x-isolate-seq'] ?? 0), ballastMb: headers['x-probe-ballast-mb'] ? Number(headers['x-probe-ballast-mb']) : null, }) }) @@ -490,6 +491,18 @@ async function commandCumulative(args) { // Rotation matters: a run that quietly moves to a second isolate spreads its // CPU across two budgets, which would look like tolerance that is not there. const isolatesSeen = new Map() + + // A dead isolate can outlive a deploy, and a live one carries whatever CPU + // debt earlier traffic left on it. Either makes a "requests until death" + // figure meaningless, so the isolate's own request counter is recorded and + // a run that does not start near-fresh is reported as suspect rather than + // quietly averaged in. + const opening = await session.request(smallPath) + const startingSeq = opening.seq ?? 0 + console.log( + `[cumulative] starting isolate ${opening.isolate?.slice(0, 8) ?? '?'} ` + + `seq=${startingSeq}${startingSeq > 40 ? ' <<< NOT FRESH, treat result as suspect' : ' (fresh)'}`, + ) for (let round = 1; round <= args.rounds; round += 1) { // eslint-disable-next-line no-await-in-loop -- rounds must not overlap const responses = await session.batch(loadPath, args.batch) @@ -561,9 +574,60 @@ async function commandCumulative(args) { }) } +/** + * Many independent users rather than one hot connection. Each session is its own + * connection and therefore lands on its own isolate, which is what a real + * cohort looks like — the single-session commands deliberately concentrate load + * on one isolate to find a limit, and that is not how users arrive. + * + * Reports failures per session, because the failure mode is per-isolate: a + * couple of users seeing everything fail while the rest are fine is the shape to + * look for, and an aggregate error rate hides it. + */ +async function commandFleet(args) { + const loadPath = args.path ?? `/?kb=${args.kb}&mode=build` + const started = Date.now() + const sessions = await Promise.all( + Array.from({ length: args.batch }, async (_unused, index) => { + const session = await new IsolateSession(args.origin, sharedCookie).open() + const outcome = { index, ok: 0, failed: 0, isolates: new Set() } + for (let round = 0; round < args.rounds; round += 1) { + // eslint-disable-next-line no-await-in-loop -- one user acts in sequence + const response = await session.request(loadPath) + if (response.ok) { + outcome.ok += 1 + if (response.isolate) outcome.isolates.add(response.isolate) + } else { + outcome.failed += 1 + } + // eslint-disable-next-line no-await-in-loop -- think time between views + await new Promise((resolve) => setTimeout(resolve, args.gapMs)) + } + session.close() + return outcome + }), + ) + + const totalOk = sessions.reduce((sum, session) => sum + session.ok, 0) + const totalFailed = sessions.reduce((sum, session) => sum + session.failed, 0) + const brokenSessions = sessions.filter((session) => session.failed > 0) + console.log( + `[fleet] ${args.batch} users x ${args.rounds} requests in ` + + `${((Date.now() - started) / 1000).toFixed(0)}s: ${totalOk} ok, ${totalFailed} failed ` + + `(${((totalFailed / (totalOk + totalFailed)) * 100).toFixed(2)}%)`, + ) + console.log( + `[fleet] users affected: ${brokenSessions.length}/${args.batch}` + + (brokenSessions.length + ? ` — ${brokenSessions.map((s) => `#${s.index}:${s.failed}`).join(' ')}` + : ''), + ) +} + const COMMANDS = { heap: commandHeap, shape: commandShape, + fleet: commandFleet, 'single-shot': commandSingleShot, cumulative: commandCumulative, autopsy: commandAutopsy, From f3f911a3f78c5dac934f5ed39578ef555fdec2f6 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 21:25:03 +0200 Subject: [PATCH 18/23] Measure which endpoints accrue CPU debt, and find the dominant one Uses death rate on verified-fresh isolates as a CPU meter (cpu ~= 10ms + 2000/rounds), which needs no wrangler tail and costs least for exactly the endpoints that are dangerous. The first-load request, /api/catalog/courses?limit=1000&period=all, costs roughly 350-500 ms of CPU -- about 50x the free-plan per-request limit -- and killed a fresh isolate after 5, 7 and 6 requests across three runs. So roughly every fifth first page load permanently destroys a backend isolate. That is the "20 concurrent users" fragility in one line, and it has nothing to do with concurrency. Everything the app does below ~10 ms of CPU accrues no debt at all and runs indefinitely: /health survived 1400 requests, catalog periods 700, and a 5-course catalog page 300. Also records that single-shot samples measure cold-start cost -- catalog periods reads 58 ms cold and 2.8 ms warm -- so warm medians are required. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 29 +++++++++++++++++++++++++++-- 1 file changed, 27 insertions(+), 2 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index eff7a54..f03efe7 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -105,6 +105,30 @@ cumulative CPU is irrelevant.** Work split into requests that each stay under 10 ms accrues *zero* debt and runs indefinitely — which is why `/health` (2.9 ms) survived 1400 requests and 3603 ms. +### Which endpoints actually accrue debt + +Measured by death rate on **verified-fresh** isolates, which doubles as a CPU +meter: `cpu ≈ 10 ms + 2000/rounds_to_death`. No `wrangler tail` needed, and it is +cheapest for exactly the endpoints that are dangerous. + +| endpoint | CPU/request | isolate dies after | +| --- | --- | --- | +| `/api/catalog/courses?limit=1000&period=all` (**first load**) | **~350–500 ms** | **5, 7, 6 requests** (three runs) | +| `/api/catalog/courses?limit=500&period=229` | 67.7 ms | 33 requests | +| `/api/catalog/courses?limit=50` | 44.9 ms | 55 requests | +| `/api/catalog/courses?limit=5` | 10.1 ms | survived 300 | +| `/api/catalog/periods` (warm) | 2.8 ms | survived 700 | +| `/health` | 2.9 ms | survived 1400 | + +**This is the operational headline.** Every user's first page load fetches the +whole 1.43 MB catalog, which costs ~50x the free-plan per-request CPU limit, so +roughly **every fifth first-load destroys a backend isolate** — permanently. That +is the whole "20 concurrent users" fragility in one line, and it is unrelated to +concurrency. + +Note `/api/catalog/periods` measured 58 ms on its *first* request and 2.8 ms warm: +single-shot samples measure cold-start cost, so warm medians are required. + ### What this means for the fix Anything above 10 ms of CPU per request kills an isolate eventually; the CPU cost @@ -151,8 +175,9 @@ believed to be exactly this. 1. **Decide on Workers Paid.** It is the only option that removes the failure class outright, and it is a billing decision rather than an engineering one. -2. If staying on Free: projection **and** pagination for the catalog, targeting - <10 ms CPU per response. Verify with `cumulative` on a fresh isolate — the +2. **Stop fetching `period=all` on first load** — highest-impact single change, + and it is a frontend one. Then projection **and** pagination for the catalog, + targeting <10 ms CPU per response. Verify with `cumulative` on a fresh isolate — the pass condition is that mean CPU/request stays under 10 ms, not that a given run survives. 3. Deploy the `json_response` fix to production (verified on staging only). From b56400c04294c8cefc793aad408b0795c9ffa94c Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sat, 8 Aug 2026 23:57:17 +0200 Subject: [PATCH 19/23] Cache the encoded catalog response per isolate The first page load fetches /api/catalog/courses?limit=1000&period=all, which cost roughly 350-500 ms of CPU. On the Workers Free plan an isolate is killed once it accumulates about 2000 ms of CPU above the 10 ms per-request limit, so that single request destroyed a fresh isolate every five or six calls, and a dead isolate keeps failing every request routed to it. A handful of arriving users was therefore enough to take isolates down. Nearly all of that cost is rebuilding an identical answer: the D1 round-trips and course_catalog._build_catalog_summary, which runs per course, for a catalog that only changes when someone re-imports it. Caching the already-encoded bytes skips both the rebuild and the UTF-8 conversion at the Python/JS boundary. Measured on staging, on verified-fresh isolates: - period=all went from dying after 5, 7 and 6 requests to surviving 120, with one isolate serving over 240 -- implied CPU per request ~400 ms -> <=18 ms - a 10-user cohort doing 30 period=all requests each: 300/300 ok, no user affected. The same shape against the lighter period=229 endpoint, with only the encoding fix, failed 17.3 % across 7 of 10 users Correctness is checked, not assumed: repeated responses are byte-identical, and 24 interleaved requests over four limit/period keys each returned the right course count, so cache keys do not collide. Searches are deliberately not cached because their key space is unbounded, and the cache is capped at 8 entries. Entries live as long as the isolate, so a catalog re-import can lag until isolates recycle; the endpoint already advertises cache-control: max-age=300. Deploy the Worker to force it. Co-Authored-By: Claude Opus 5 --- backend/src/http_utils.py | 23 +++++++ backend/src/router.py | 51 ++++++++++++-- .../src/services/catalog_response_cache.py | 66 +++++++++++++++++++ backend/tests/test_catalog_response_cache.py | 59 +++++++++++++++++ docs/load-test-2026-08.md | 28 ++++++++ load-test/payload-probe/src/main.py | 25 +++++++ 6 files changed, 246 insertions(+), 6 deletions(-) create mode 100644 backend/src/services/catalog_response_cache.py create mode 100644 backend/tests/test_catalog_response_cache.py diff --git a/backend/src/http_utils.py b/backend/src/http_utils.py index 6269fbb..2836bb5 100644 --- a/backend/src/http_utils.py +++ b/backend/src/http_utils.py @@ -82,6 +82,29 @@ def json_response( return Response(body, status=status, headers=headers) +def encoded_json_response( + body: bytes, + request: Any, + env: Any, + status: int = 200, + extra_headers: dict[str, str] | None = None, +) -> Response: + """Return an already-serialised JSON body. + + Exists so a caller that has cached the encoded bytes can skip both + `json.dumps` and the encode, which is the whole point of caching them. + Headers are still built per request, because they carry per-isolate + diagnostics and the CORS origin. + """ + headers = { + "content-type": "application/json; charset=utf-8", + **build_cors_headers(request, env), + } + if extra_headers: + headers.update(extra_headers) + return Response(body, status=status, headers=headers) + + def empty_response( request: Any, env: Any, diff --git a/backend/src/router.py b/backend/src/router.py index 885b7d8..16fc69e 100644 --- a/backend/src/router.py +++ b/backend/src/router.py @@ -1,12 +1,20 @@ from __future__ import annotations +import json import traceback from typing import Any from urllib.parse import parse_qs, unquote, urlparse from db.d1 import D1ExecutionError, fetch_all, fetch_one, has_database -from http_utils import empty_response, error_response, html_response, json_response +from http_utils import ( + empty_response, + encoded_json_response, + error_response, + html_response, + json_response, +) from request_utils import RequestBodyError, read_json_object +from services import catalog_response_cache from services.authentication import ( AuthConfigurationError, AuthenticationError, @@ -725,17 +733,48 @@ async def route_request(request: Any, env: Any) -> Any: except ValueError: limit = 100 + # Searches are not cached: the key space is unbounded and each search + # is usually seen once, so caching them would only cost memory. + cache_key = ( + catalog_response_cache.build_key(limit, period_value) + if not (search_value or "").strip() + else None + ) + if cache_key is not None: + cached_body = catalog_response_cache.get(cache_key) + if cached_body is not None: + return encoded_json_response( + cached_body, + request=request, + env=env, + extra_headers=_PUBLIC_CATALOG_CACHE_HEADERS, + ) + courses = await list_catalog_courses( env, limit=limit, search=search_value, period_id=period_value, ) - return json_response( - { - "count": len(courses), - "courses": courses, - }, + payload = { + "count": len(courses), + "courses": courses, + } + if cache_key is None: + return json_response( + payload, + request=request, + env=env, + extra_headers=_PUBLIC_CATALOG_CACHE_HEADERS, + ) + + # Rebuilding this answer is what kills isolates on the Free plan: it + # is the same bytes every time, and it costs ~350-500 ms of CPU for + # the unfiltered catalog. See services/catalog_response_cache. + encoded = json.dumps(payload, ensure_ascii=False).encode("utf-8") + catalog_response_cache.put(cache_key, encoded) + return encoded_json_response( + encoded, request=request, env=env, extra_headers=_PUBLIC_CATALOG_CACHE_HEADERS, diff --git a/backend/src/services/catalog_response_cache.py b/backend/src/services/catalog_response_cache.py new file mode 100644 index 0000000..7fcb725 --- /dev/null +++ b/backend/src/services/catalog_response_cache.py @@ -0,0 +1,66 @@ +"""Per-isolate cache of already-serialised catalog responses. + +Why this exists +--------------- +On the Workers Free plan each isolate is killed once it has accumulated about +2000 ms of CPU *above* the 10 ms-per-request limit, and it stays dead — later +requests routed to it fail. Measured, `/api/catalog/courses?limit=1000&period=all` +costs roughly 350-500 ms of CPU, so it destroys a fresh isolate after five or six +requests. Since the frontend issues that request on first load, a handful of +arriving users is enough to take isolates down. See `docs/load-test-2026-08.md`. + +Almost all of that cost is rebuilding the same answer: the D1 round-trips plus +`course_catalog._build_catalog_summary`, which runs per course. The catalog is a +snapshot that only changes when someone re-imports it, so the work is identical +every time. + +Caching the *encoded* bytes (not the payload object, and not a `str`) skips both +the rebuild and the UTF-8 conversion at the Python/JS boundary. Measured on an +equivalent 1.43 MB payload: rebuilding each time exhausted an isolate, while +serving pre-encoded bytes survived 150 consecutive requests untouched. + +Staleness +--------- +Entries live as long as the isolate does, which is minutes to hours, and isolates +are replaced continuously. The endpoint already advertises +`cache-control: public, max-age=300`, so callers are told to expect data up to +five minutes old; this does not promise anything stronger. After a catalog +re-import, responses can lag until isolates recycle — deploy the Worker to force +it. +""" + +from __future__ import annotations + +# Bounded so a hostile or buggy caller cannot grow this without limit. The real +# key space is small: a handful of period/limit combinations, and searches are +# not cached at all. +_MAX_ENTRIES = 8 + +_entries: dict[str, bytes] = {} + + +def build_key(limit: int, period_id: str | None) -> str: + return f"{limit}|{period_id or ''}" + + +def get(key: str) -> bytes | None: + return _entries.get(key) + + +def put(key: str, body: bytes) -> None: + """Store one encoded response, evicting the oldest entry when full. + + Insertion order is dict order in CPython, so the first key is the oldest. + """ + if key not in _entries and len(_entries) >= _MAX_ENTRIES: + oldest = next(iter(_entries)) + del _entries[oldest] + _entries[key] = body + + +def clear() -> None: + _entries.clear() + + +def size() -> int: + return len(_entries) diff --git a/backend/tests/test_catalog_response_cache.py b/backend/tests/test_catalog_response_cache.py new file mode 100644 index 0000000..7525232 --- /dev/null +++ b/backend/tests/test_catalog_response_cache.py @@ -0,0 +1,59 @@ +import os +import sys +import unittest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "src")) + +from services import catalog_response_cache # noqa: E402 + + +class CatalogResponseCacheTest(unittest.TestCase): + def setUp(self) -> None: + catalog_response_cache.clear() + + def test_round_trips_the_exact_bytes(self) -> None: + key = catalog_response_cache.build_key(1000, "all") + body = '{"count": 1, "title": "Übung"}'.encode("utf-8") + catalog_response_cache.put(key, body) + self.assertEqual(catalog_response_cache.get(key), body) + + def test_distinguishes_period_and_limit(self) -> None: + # A shared key would serve one period's catalog for another, which is a + # wrong answer rather than a slow one. + self.assertNotEqual( + catalog_response_cache.build_key(1000, "all"), + catalog_response_cache.build_key(1000, "229"), + ) + self.assertNotEqual( + catalog_response_cache.build_key(500, "229"), + catalog_response_cache.build_key(1000, "229"), + ) + + def test_absent_key_is_a_miss(self) -> None: + self.assertIsNone(catalog_response_cache.get("nothing")) + + def test_missing_period_is_stable(self) -> None: + self.assertEqual( + catalog_response_cache.build_key(100, None), + catalog_response_cache.build_key(100, ""), + ) + + def test_evicts_oldest_when_full(self) -> None: + # Entries hold whole catalog payloads, so an unbounded cache would be a + # memory leak keyed on user-supplied query parameters. + for index in range(catalog_response_cache._MAX_ENTRIES + 3): + catalog_response_cache.put(f"key-{index}", b"x") + self.assertEqual(catalog_response_cache.size(), catalog_response_cache._MAX_ENTRIES) + self.assertIsNone(catalog_response_cache.get("key-0")) + self.assertIsNotNone(catalog_response_cache.get("key-10")) + + def test_overwriting_an_existing_key_does_not_evict(self) -> None: + for index in range(catalog_response_cache._MAX_ENTRIES): + catalog_response_cache.put(f"key-{index}", b"x") + catalog_response_cache.put("key-0", b"updated") + self.assertEqual(catalog_response_cache.size(), catalog_response_cache._MAX_ENTRIES) + self.assertEqual(catalog_response_cache.get("key-0"), b"updated") + + +if __name__ == "__main__": + unittest.main() diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index f03efe7..952ba57 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -147,6 +147,34 @@ Two ways out, and they are not equivalent: lecturer projection (drop `_build_catalog_summary`, ~0.83 ms/course) *and* pagination — a projection alone lands near ~25 ms, still over the line. +### The fix, measured end to end + +`/api/catalog/courses` now caches the **encoded** response bytes per isolate +(`services/catalog_response_cache.py`), keyed on limit and period; searches are +not cached. Almost all of the endpoint's CPU was rebuilding an identical answer — +D1 round-trips plus `_build_catalog_summary` per course — for a catalog that only +changes on re-import. + +| measurement | before | after | +| --- | --- | --- | +| `period=all`, requests until a fresh isolate dies | **5, 7, 6** | **survived 120**; one isolate served 240+ | +| implied CPU per request | ~350–500 ms | **≤18 ms** | +| 10-user cohort on `period=all`, 30 requests each | — | **300/300 ok, 0 users affected** | + +For comparison, the same cohort shape against the *lighter* `period=229` +endpoint, with only the encoding fix applied, failed 17.3 % across 7 of 10 users. + +Correctness was checked rather than assumed: responses are byte-identical across +repeats (same SHA-256), and 24 interleaved requests across four different +limit/period keys all returned the right course counts, so keys do not collide. + +> One unexplained observation: during the first check a single +> `limit=500&period=229` response came back with 2304 courses instead of 131. It +> did not reproduce in 28 subsequent requests, production returns 131, and the +> interleaving test is clean. Most likely a stale isolate serving one of the many +> builds staging hosted that day, but it is recorded here because it was not +> positively explained. + ### Contamination control (important) A dead isolate can outlive a deploy, and a live one carries whatever debt earlier diff --git a/load-test/payload-probe/src/main.py b/load-test/payload-probe/src/main.py index 44e1b8a..1d89232 100644 --- a/load-test/payload-probe/src/main.py +++ b/load-test/payload-probe/src/main.py @@ -52,6 +52,9 @@ # Populated on first use, per isolate. The point of `cached` mode. _cached_bodies: dict[int, str] = {} +# Built once per isolate and kept already encoded, for mode=cachedbytes. +_cached_encoded: dict[int, bytes] = {} + # Resident, never sent. Each entry is one megabyte. _ballast: list[bytearray] = [] @@ -199,6 +202,8 @@ async def on_fetch(self, request: Any) -> Any: mode = "cached" if "mode=cached" in url else "build" if "mode=bytes" in url: mode = "bytes" + if "mode=cachedbytes" in url: + mode = "cachedbytes" return await self._respond(kilobytes, mode) async def _respond(self, kilobytes: int, mode: str) -> Any: @@ -220,6 +225,26 @@ async def _respond(self, kilobytes: int, mode: str) -> Any: ), ) + # Build once per isolate and keep the *encoded* bytes. This is the cheapest + # a response can possibly be while still being sent, so it measures the + # irreducible cost of handing a body to the runtime — the floor that any + # caching fix in the real backend would converge to. + if mode == "cachedbytes": + encoded = _cached_encoded.get(kilobytes) + if encoded is None: + encoded = _build_body(kilobytes).encode("utf-8") + _cached_encoded[kilobytes] = encoded + return Response( + encoded, + headers=_probe_headers( + { + "content-type": "application/json", + "x-probe-mode": "cachedbytes", + "x-probe-bytes": str(len(encoded)), + } + ), + ) + if mode == "cached": body = _cached_bodies.get(kilobytes) if body is None: From 68fc883e85876f5fb9a8c16ec62f44ebcdf04297 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sun, 9 Aug 2026 00:05:09 +0200 Subject: [PATCH 20/23] Cache catalog searches too, bounded by bytes Leaving searches uncached left the last big hazard in place. A broad two-character prefix against the whole catalog costs about 230 ms of CPU and killed a fresh isolate every ten requests, and broad prefixes are exactly what users type first, so the expensive responses were also the most repeated ones. The key now includes the normalised search term, so "Info", "info " and "info" share one entry. Because the key space is now caller-controlled, the bound is on bytes (16 MB) rather than entry count: one entry can be 1.5 MB and another 20 KB. A body larger than the whole budget is skipped rather than stored and immediately evicting everything else. Measured on staging, verified-fresh isolate: the worst-case search went from dying at round 10 to surviving 100. Correctness checked across three rounds of four different queries -- each returns its own stable byte-identical result, so keys do not collide. Co-Authored-By: Claude Opus 5 --- backend/src/router.py | 36 +++++-------- .../src/services/catalog_response_cache.py | 53 +++++++++++++++---- backend/tests/test_catalog_response_cache.py | 51 ++++++++++++++---- docs/load-test-2026-08.md | 8 ++- load-test/isolate-probe.mjs | 12 ++++- 5 files changed, 113 insertions(+), 47 deletions(-) diff --git a/backend/src/router.py b/backend/src/router.py index 16fc69e..c8540cb 100644 --- a/backend/src/router.py +++ b/backend/src/router.py @@ -733,22 +733,18 @@ async def route_request(request: Any, env: Any) -> Any: except ValueError: limit = 100 - # Searches are not cached: the key space is unbounded and each search - # is usually seen once, so caching them would only cost memory. - cache_key = ( - catalog_response_cache.build_key(limit, period_value) - if not (search_value or "").strip() - else None - ) - if cache_key is not None: - cached_body = catalog_response_cache.get(cache_key) - if cached_body is not None: - return encoded_json_response( - cached_body, - request=request, - env=env, - extra_headers=_PUBLIC_CATALOG_CACHE_HEADERS, - ) + # Searches are cached too. A broad two-character prefix against the + # whole catalog costs ~230 ms of CPU, and those prefixes are exactly + # what users type first, so they are the entries most worth keeping. + cache_key = catalog_response_cache.build_key(limit, period_value, search_value) + cached_body = catalog_response_cache.get(cache_key) + if cached_body is not None: + return encoded_json_response( + cached_body, + request=request, + env=env, + extra_headers=_PUBLIC_CATALOG_CACHE_HEADERS, + ) courses = await list_catalog_courses( env, @@ -760,14 +756,6 @@ async def route_request(request: Any, env: Any) -> Any: "count": len(courses), "courses": courses, } - if cache_key is None: - return json_response( - payload, - request=request, - env=env, - extra_headers=_PUBLIC_CATALOG_CACHE_HEADERS, - ) - # Rebuilding this answer is what kills isolates on the Free plan: it # is the same bytes every time, and it costs ~350-500 ms of CPU for # the unfiltered catalog. See services/catalog_response_cache. diff --git a/backend/src/services/catalog_response_cache.py b/backend/src/services/catalog_response_cache.py index 7fcb725..e1b20d9 100644 --- a/backend/src/services/catalog_response_cache.py +++ b/backend/src/services/catalog_response_cache.py @@ -31,16 +31,27 @@ from __future__ import annotations -# Bounded so a hostile or buggy caller cannot grow this without limit. The real -# key space is small: a handful of period/limit combinations, and searches are -# not cached at all. -_MAX_ENTRIES = 8 +# Searches are cached too, so the key space is caller-controlled and the bound +# has to be on bytes rather than entries: one entry can be 1.5 MB and another +# 20 KB. Isolates tolerate far more than this (measured: 179 MB of resident +# allocation), so the budget is set for politeness, not survival. +_MAX_BYTES = 16 * 1024 * 1024 +_MAX_ENTRIES = 64 _entries: dict[str, bytes] = {} +_total_bytes = 0 -def build_key(limit: int, period_id: str | None) -> str: - return f"{limit}|{period_id or ''}" +def build_key(limit: int, period_id: str | None, search: str | None = None) -> str: + """Identify one cacheable response. + + Search terms are normalised the way the query is, so that `Info`, `info ` and + `info` share an entry — broad prefixes are both the most expensive responses + to build and the ones most users type, which is what makes caching them + worthwhile. + """ + normalized_search = (search or "").strip().lower() + return f"{limit}|{period_id or ''}|{normalized_search}" def get(key: str) -> bytes | None: @@ -48,19 +59,39 @@ def get(key: str) -> bytes | None: def put(key: str, body: bytes) -> None: - """Store one encoded response, evicting the oldest entry when full. + """Store one encoded response, evicting oldest-first to stay within budget. - Insertion order is dict order in CPython, so the first key is the oldest. + Insertion order is dict order in CPython, so the first key is the oldest. A + body larger than the whole budget is simply not cached, rather than being + stored and immediately evicting everything else. """ - if key not in _entries and len(_entries) >= _MAX_ENTRIES: - oldest = next(iter(_entries)) - del _entries[oldest] + global _total_bytes + if len(body) > _MAX_BYTES: + return + + existing = _entries.pop(key, None) + if existing is not None: + _total_bytes -= len(existing) + _entries[key] = body + _total_bytes += len(body) + + while _entries and (_total_bytes > _MAX_BYTES or len(_entries) > _MAX_ENTRIES): + oldest = next(iter(_entries)) + if oldest == key: + break + _total_bytes -= len(_entries.pop(oldest)) def clear() -> None: + global _total_bytes _entries.clear() + _total_bytes = 0 def size() -> int: return len(_entries) + + +def total_bytes() -> int: + return _total_bytes diff --git a/backend/tests/test_catalog_response_cache.py b/backend/tests/test_catalog_response_cache.py index 7525232..0335288 100644 --- a/backend/tests/test_catalog_response_cache.py +++ b/backend/tests/test_catalog_response_cache.py @@ -38,21 +38,54 @@ def test_missing_period_is_stable(self) -> None: catalog_response_cache.build_key(100, ""), ) - def test_evicts_oldest_when_full(self) -> None: + def test_search_terms_get_their_own_entry(self) -> None: + self.assertNotEqual( + catalog_response_cache.build_key(1000, "all", "info"), + catalog_response_cache.build_key(1000, "all", "mathe"), + ) + self.assertNotEqual( + catalog_response_cache.build_key(1000, "all", "info"), + catalog_response_cache.build_key(1000, "all", None), + ) + + def test_search_key_is_normalised(self) -> None: + # Users type the same broad prefix with different casing and trailing + # spaces; those should share the one expensive entry. + self.assertEqual( + catalog_response_cache.build_key(1000, "all", " Info "), + catalog_response_cache.build_key(1000, "all", "info"), + ) + + def test_evicts_oldest_when_over_entry_limit(self) -> None: # Entries hold whole catalog payloads, so an unbounded cache would be a # memory leak keyed on user-supplied query parameters. for index in range(catalog_response_cache._MAX_ENTRIES + 3): catalog_response_cache.put(f"key-{index}", b"x") - self.assertEqual(catalog_response_cache.size(), catalog_response_cache._MAX_ENTRIES) + self.assertLessEqual(catalog_response_cache.size(), catalog_response_cache._MAX_ENTRIES) self.assertIsNone(catalog_response_cache.get("key-0")) - self.assertIsNotNone(catalog_response_cache.get("key-10")) + self.assertIsNotNone(catalog_response_cache.get(f"key-{catalog_response_cache._MAX_ENTRIES + 2}")) - def test_overwriting_an_existing_key_does_not_evict(self) -> None: - for index in range(catalog_response_cache._MAX_ENTRIES): - catalog_response_cache.put(f"key-{index}", b"x") - catalog_response_cache.put("key-0", b"updated") - self.assertEqual(catalog_response_cache.size(), catalog_response_cache._MAX_ENTRIES) - self.assertEqual(catalog_response_cache.get("key-0"), b"updated") + def test_evicts_to_stay_within_the_byte_budget(self) -> None: + chunk = b"y" * (catalog_response_cache._MAX_BYTES // 4) + for index in range(6): + catalog_response_cache.put(f"big-{index}", chunk) + self.assertLessEqual(catalog_response_cache.total_bytes(), catalog_response_cache._MAX_BYTES) + self.assertIsNotNone(catalog_response_cache.get("big-5")) + + def test_body_larger_than_the_budget_is_not_cached(self) -> None: + # Storing it would evict everything else to make room for something that + # cannot be kept anyway. + catalog_response_cache.put("small", b"keep me") + catalog_response_cache.put("huge", b"z" * (catalog_response_cache._MAX_BYTES + 1)) + self.assertIsNone(catalog_response_cache.get("huge")) + self.assertEqual(catalog_response_cache.get("small"), b"keep me") + + def test_overwriting_an_existing_key_keeps_byte_total_correct(self) -> None: + catalog_response_cache.put("key", b"xxxxx") + catalog_response_cache.put("key", b"yy") + self.assertEqual(catalog_response_cache.size(), 1) + self.assertEqual(catalog_response_cache.total_bytes(), 2) + self.assertEqual(catalog_response_cache.get("key"), b"yy") if __name__ == "__main__": diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 952ba57..a5a134e 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -150,8 +150,11 @@ Two ways out, and they are not equivalent: ### The fix, measured end to end `/api/catalog/courses` now caches the **encoded** response bytes per isolate -(`services/catalog_response_cache.py`), keyed on limit and period; searches are -not cached. Almost all of the endpoint's CPU was rebuilding an identical answer — +(`services/catalog_response_cache.py`), keyed on limit, period and normalised +search term. Searches are cached because a broad two-character prefix against the +whole catalog costs ~230 ms and those prefixes are what users type first; the +cache is bounded by **bytes** (16 MB) rather than entry count, since one entry can +be 1.5 MB and another 20 KB. Almost all of the endpoint's CPU was rebuilding an identical answer — D1 round-trips plus `_build_catalog_summary` per course — for a catalog that only changes on re-import. @@ -160,6 +163,7 @@ changes on re-import. | `period=all`, requests until a fresh isolate dies | **5, 7, 6** | **survived 120**; one isolate served 240+ | | implied CPU per request | ~350–500 ms | **≤18 ms** | | 10-user cohort on `period=all`, 30 requests each | — | **300/300 ok, 0 users affected** | +| broad search `q=in&period=all` (worst case a user can type) | dies at 10 | **survived 100** | For comparison, the same cohort shape against the *lighter* `period=229` endpoint, with only the encoding fix applied, failed 17.3 % across 7 of 10 users. diff --git a/load-test/isolate-probe.mjs b/load-test/isolate-probe.mjs index 0fe0430..fa0bb1b 100644 --- a/load-test/isolate-probe.mjs +++ b/load-test/isolate-probe.mjs @@ -55,6 +55,8 @@ function parseArgs(argv) { // Idle time between rounds, for testing whether the CPU budget refills. gapMs: 0, rounds: 60, + // Refuse to measure on an isolate that has already served this many. + maxSeq: 40, // 1 returns the body pre-encoded as bytes instead of as a str. bytesMode: 0, // Point the load at a real backend endpoint instead of the probe. @@ -501,8 +503,16 @@ async function commandCumulative(args) { const startingSeq = opening.seq ?? 0 console.log( `[cumulative] starting isolate ${opening.isolate?.slice(0, 8) ?? '?'} ` + - `seq=${startingSeq}${startingSeq > 40 ? ' <<< NOT FRESH, treat result as suspect' : ' (fresh)'}`, + `seq=${startingSeq}${startingSeq > args.maxSeq ? ' <<< NOT FRESH' : ' (fresh)'}`, ) + if (startingSeq > args.maxSeq) { + console.log( + '[cumulative] ABORT — this isolate already carries CPU debt from earlier traffic, ' + + 'so "requests until death" would be meaningless. Retry, or redeploy to get new isolates.', + ) + process.exitCode = 1 + return + } for (let round = 1; round <= args.rounds; round += 1) { // eslint-disable-next-line no-await-in-loop -- rounds must not overlap const responses = await session.batch(loadPath, args.batch) From d683721acae24d51bc6194b749604c3a0217cb9c Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sun, 9 Aug 2026 00:08:02 +0200 Subject: [PATCH 21/23] Measure the per-user endpoints the catalog cache cannot help /api/me/progress costs 81 ms of CPU and /api/me/favorites 57 ms, so on the Free plan they exhaust an isolate after about 28 and 42 requests. Neither can use the catalog cache: the data is user-specific and changes on edit, so serving a stale copy would be a correctness bug rather than a slow response. Measured on production, because staging cannot validate production-minted sessions -- the two Workers have separate AUTH_TOKEN_SECRETs, which is why /api/me/* answers 401 there while the public catalog still responds. Earlier catalog measurements on staging are unaffected, since that endpoint never checked the cookie. With the catalog cached, one user's first load now costs roughly 160 ms of debt instead of ~500, so an isolate tolerates about a dozen first loads rather than five. Better, not fixed. /api/me/progress issues ~7 sequential D1 queries, which is the next lever if the account stays on Free. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index a5a134e..238f770 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -179,6 +179,30 @@ limit/period keys all returned the right course counts, so keys do not collide. > builds staging hosted that day, but it is recorded here because it was not > positively explained. +### What is still over the line + +The cache only helps the public catalog. Per-user endpoints cannot be cached this +way — the data is user-specific and changes on edit, so stale answers would be a +correctness bug rather than a slow response. Measured on **production** (staging +cannot validate production-minted sessions; the two Workers have different +`AUTH_TOKEN_SECRET`s, which is why `/api/me/*` returns 401 there while the public +catalog still answers): + +| endpoint | CPU | isolate dies after | +| --- | --- | --- | +| `/api/me/progress` | **81 ms** | ~28 requests | +| `/api/me/favorites` | **57 ms** | ~42 requests | +| `/api/me/semester-plans` | 9 ms | never | +| `/api/study-programs` | 4 ms | never | + +A single user's first load now costs roughly 18 ms (catalog, cached) + 81 + 57 + +small change ≈ **160 ms of debt**, so one isolate still tolerates only about a +dozen first loads. That is far better than the five it managed before, but it is +not "fixed" — it is the same arithmetic with a bigger constant. + +`/api/me/progress` issues ~7 sequential D1 queries; batching them and trimming the +per-row work is the obvious next lever if the account stays on Free. + ### Contamination control (important) A dead isolate can outlive a deploy, and a live one carries whatever debt earlier From a784fb8281defac84bfbb0f0f5f0870ce97ea1ae Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sun, 9 Aug 2026 08:52:53 +0200 Subject: [PATCH 22/23] Correct the per-user endpoint costs: the earlier figures were cold starts /api/me/progress was reported at 81 ms and /api/me/favorites at 57 ms, and those were used to argue they had become the dominant remaining cost. Both are wrong. Measured over a single reused connection, so every sample lands on the same warm isolate, progress costs 14-20 ms and favorites 4-8 ms. The earlier pass used separate curl invocations. Each opened its own connection and could therefore be served by a different cold isolate, and a cold isolate pays 60-70 ms on its first request. The same confound had already been observed for /api/catalog/periods, which reads 58 ms cold and 2.8 ms warm, and was simply not applied to the production inventory. Favorites is auth plus one query returning ids, which is what prompted the recheck: 57 ms was not a plausible warm cost for that code. This changes the conclusion. A first page load now costs about 13 ms of debt rather than ~160, so an isolate tolerates on the order of a hundred first loads instead of a dozen, and no per-user endpoint stands out as the next thing to optimise. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 48 ++++++++++++++++++++++++--------------- 1 file changed, 30 insertions(+), 18 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index 238f770..c99be6d 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -183,25 +183,37 @@ limit/period keys all returned the right course counts, so keys do not collide. The cache only helps the public catalog. Per-user endpoints cannot be cached this way — the data is user-specific and changes on edit, so stale answers would be a -correctness bug rather than a slow response. Measured on **production** (staging -cannot validate production-minted sessions; the two Workers have different -`AUTH_TOKEN_SECRET`s, which is why `/api/me/*` returns 401 there while the public -catalog still answers): +correctness bug. Measured on **production** (staging cannot validate +production-minted sessions: the two Workers have different `AUTH_TOKEN_SECRET`s, +which is why `/api/me/*` returns 401 there while the public catalog still +answers). -| endpoint | CPU | isolate dies after | -| --- | --- | --- | -| `/api/me/progress` | **81 ms** | ~28 requests | -| `/api/me/favorites` | **57 ms** | ~42 requests | -| `/api/me/semester-plans` | 9 ms | never | -| `/api/study-programs` | 4 ms | never | - -A single user's first load now costs roughly 18 ms (catalog, cached) + 81 + 57 + -small change ≈ **160 ms of debt**, so one isolate still tolerates only about a -dozen first loads. That is far better than the five it managed before, but it is -not "fixed" — it is the same arithmetic with a bigger constant. - -`/api/me/progress` issues ~7 sequential D1 queries; batching them and trimming the -per-row work is the obvious next lever if the account stays on Free. +**Warm** costs, measured over one reused connection so every sample lands on the +same isolate: + +| endpoint | cold | warm | debt/request | +| --- | --- | --- | --- | +| `/api/me/progress` | 68 ms | **14–20 ms** | ~5 ms | +| `/api/me/favorites` | 5 ms | **4–8 ms** | none | +| `/api/me/semester-plans` | — | 9 ms | none | +| catalog, cached | — | ≤18 ms | ~8 ms | + +> **Correction.** An earlier pass reported 81 ms and 57 ms for progress and +> favorites and concluded they were the dominant remaining cost. That was wrong: +> those samples were taken with separate `curl` invocations, so each opened its +> own connection and could land on a different *cold* isolate. The same confound +> was already known for `/api/catalog/periods` (58 ms cold, 2.8 ms warm) and was +> simply not applied. Always measure over one reused connection. + +So a user's first page load now costs roughly **13 ms of debt** (catalog 8 + +progress 5), not the ~160 ms previously stated — an isolate tolerates on the order +of a hundred first loads rather than a dozen. With the catalog cached there is no +longer an endpoint that obviously has to be optimised next. + +What remains is **cold start**: a new isolate pays 60–70 ms on its first real +request, and ~400 ms if that request is the first uncached catalog build. That is +a per-isolate cost, not a per-user one, and it is the reason single-shot +measurements mislead. ### Contamination control (important) From 7c8c1147cf57a2b4699283eadc2d567bbe1d42a9 Mon Sep 17 00:00:00 2001 From: Yonatan Dankner Date: Sun, 9 Aug 2026 08:54:31 +0200 Subject: [PATCH 23/23] Answer the original question: 20 concurrent users, 400/400 requests fleet now accepts a comma-separated --path and walks it as a mini session, which exercises the cache the way a real mix does instead of hammering one endpoint. Twenty concurrent users, each doing a 20-request session across four catalog endpoints including period=all and the worst-case broad search: 400/400 ok, no user affected. Before the fixes, period=all alone killed a fresh isolate every five requests. The authenticated half of a session is not covered, because staging cannot validate production-minted sessions. Those endpoints were measured individually on production instead and are all at or under about 20 ms warm. Co-Authored-By: Claude Opus 5 --- docs/load-test-2026-08.md | 9 +++++++++ load-test/isolate-probe.mjs | 7 +++++-- 2 files changed, 14 insertions(+), 2 deletions(-) diff --git a/docs/load-test-2026-08.md b/docs/load-test-2026-08.md index c99be6d..93d29c8 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -8,6 +8,14 @@ **Goal:** find and fix the cause of production 5xx so the app is dependable for multiple concurrent users. +**Answer to the original question.** Twenty concurrent users walking a realistic +catalog session — including the two most expensive requests in the app — now +complete 400/400 requests with no user affected. Before the fixes, the first-load +request alone destroyed a backend isolate every five calls. The authenticated +half of a session could not be included, because staging cannot validate +production-minted sessions; those endpoints were measured individually instead +and are all at or under ~20 ms. + **Headline:** the fault is **CPU**, not payload size, concurrency, or memory. An isolate that does sustained CPU-heavy work is killed with `exceededCpu` (HTTP 1102) and is then *permanently* dead — every later request routed to it returns @@ -164,6 +172,7 @@ changes on re-import. | implied CPU per request | ~350–500 ms | **≤18 ms** | | 10-user cohort on `period=all`, 30 requests each | — | **300/300 ok, 0 users affected** | | broad search `q=in&period=all` (worst case a user can type) | dies at 10 | **survived 100** | +| **20 concurrent users**, 20-request session across four catalog endpoints | — | **400/400 ok, 0/20 users affected** | For comparison, the same cohort shape against the *lighter* `period=229` endpoint, with only the encoding fix applied, failed 17.3 % across 7 of 10 users. diff --git a/load-test/isolate-probe.mjs b/load-test/isolate-probe.mjs index fa0bb1b..525ed75 100644 --- a/load-test/isolate-probe.mjs +++ b/load-test/isolate-probe.mjs @@ -595,7 +595,10 @@ async function commandCumulative(args) { * look for, and an aggregate error rate hides it. */ async function commandFleet(args) { - const loadPath = args.path ?? `/?kb=${args.kb}&mode=build` + // A comma-separated --path is a mini session: each user walks the list in + // order and repeats it, which is closer to real traffic than hammering one + // endpoint and exercises the cache the way a real mix would. + const loadPaths = (args.path ?? `/?kb=${args.kb}&mode=build`).split(',') const started = Date.now() const sessions = await Promise.all( Array.from({ length: args.batch }, async (_unused, index) => { @@ -603,7 +606,7 @@ async function commandFleet(args) { const outcome = { index, ok: 0, failed: 0, isolates: new Set() } for (let round = 0; round < args.rounds; round += 1) { // eslint-disable-next-line no-await-in-loop -- one user acts in sequence - const response = await session.request(loadPath) + const response = await session.request(loadPaths[round % loadPaths.length]) if (response.ok) { outcome.ok += 1 if (response.isolate) outcome.isolates.add(response.isolate)