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 diff --git a/backend/src/http_utils.py b/backend/src/http_utils.py index 0d55664..2836bb5 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: @@ -60,7 +70,38 @@ 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) + + +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) 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/src/router.py b/backend/src/router.py index 885b7d8..c8540cb 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,36 @@ async def route_request(request: Any, env: Any) -> Any: except ValueError: limit = 100 + # 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, limit=limit, search=search_value, period_id=period_value, ) - return json_response( - { - "count": len(courses), - "courses": courses, - }, + payload = { + "count": len(courses), + "courses": courses, + } + # 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..e1b20d9 --- /dev/null +++ b/backend/src/services/catalog_response_cache.py @@ -0,0 +1,97 @@ +"""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 + +# 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, 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: + return _entries.get(key) + + +def put(key: str, body: bytes) -> None: + """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. A + body larger than the whole budget is simply not cached, rather than being + stored and immediately evicting everything else. + """ + 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 new file mode 100644 index 0000000..0335288 --- /dev/null +++ b/backend/tests/test_catalog_response_cache.py @@ -0,0 +1,92 @@ +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_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.assertLessEqual(catalog_response_cache.size(), catalog_response_cache._MAX_ENTRIES) + self.assertIsNone(catalog_response_cache.get("key-0")) + self.assertIsNotNone(catalog_response_cache.get(f"key-{catalog_response_cache._MAX_ENTRIES + 2}")) + + 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__": + unittest.main() diff --git a/backend/wrangler.toml b/backend/wrangler.toml index 5b005b2..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 @@ -14,6 +15,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 3dbd5af..93d29c8 100644 --- a/docs/load-test-2026-08.md +++ b/docs/load-test-2026-08.md @@ -1,5 +1,290 @@ # 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, second session) + +**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 +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 | +| --- | --- | +| 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) | +| 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 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 | +| --- | --- | --- | --- | +| 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 | + +Low-CPU workloads exceed that same cumulative figure and survive, which is what +ruled the cumulative reading out: + +| 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. + +### The rule (resolved) + +**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. + +### 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 +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. + +### 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, 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. + +| 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** | +| 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. + +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. + +### 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. 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). + +**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) + +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 + +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. **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. **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). +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 + +- `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 + +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). @@ -17,8 +302,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 +332,49 @@ 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: **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 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. --- @@ -160,28 +483,218 @@ 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. + +### 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 -_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 (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 +> 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. + +### What the 56 failures were + +`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. + +### 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. -Expected pressure points, from reading the code: +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. -- `/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. +`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 +/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 +938,436 @@ 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. + +### 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 +~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**. +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. + +**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 +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. + +| 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 +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 % +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 +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/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/features/courses/hooks/useHistoricalLecturerLookup.ts b/frontend/src/features/courses/hooks/useHistoricalLecturerLookup.ts index 7e2767d..aae3930 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,18 @@ 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. 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) + }) if (cancelled) { return } 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/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/) +}) 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. 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/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`, + } +} 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/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..525ed75 --- /dev/null +++ b/load-test/isolate-probe.mjs @@ -0,0 +1,665 @@ +/** + * 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, + // 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. + 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, + seq: Number(headers['x-probe-seq'] ?? headers['x-isolate-seq'] ?? 0), + 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() + + // 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 > 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) + 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(' ')}`, + ) + }) +} + +/** + * 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) { + // 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) => { + 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(loadPaths[round % loadPaths.length]) + 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, + '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 new file mode 100644 index 0000000..1d89232 --- /dev/null +++ b/load-test/payload-probe/src/main.py @@ -0,0 +1,266 @@ +"""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 + +# 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 +_ONE_MEGABYTE = 1024 * 1024 + +# 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] = [] + +# 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) + 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 | None) -> int | None: + 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 + + +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) + + 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" + if "mode=cachedbytes" in url: + mode = "cachedbytes" + 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)), + } + ), + ) + + # 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: + body = _build_body(kilobytes) + _cached_bodies[kilobytes] = body + else: + body = _build_body(kilobytes) + + return Response( + body, + headers=_probe_headers( + { + "content-type": "application/json", + "x-probe-mode": mode, + "x-probe-kb": str(kilobytes), + "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 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..755c781 100644 --- a/load-test/scenario.js +++ b/load-test/scenario.js @@ -43,9 +43,81 @@ 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) +// 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') +// 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 +// 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) +} + +/** + * 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 + * 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', @@ -59,13 +131,20 @@ 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'], + // 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(), }, } @@ -138,36 +217,100 @@ 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 - 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, - }) + const notFoundIsExpected = expectsNotFound(step.method, 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 }) + } - stepDuration.add(response.timings.duration, { 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 }) + 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 }) + } + + 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)}`, ) } - 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) { @@ -196,13 +339,16 @@ 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] - 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 - 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)}` } /** @@ -214,6 +360,8 @@ 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 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' @@ -225,6 +373,12 @@ 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' : ''}`, + `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',