From 9e685cc6f75252fa17e718677730f3b024c7a2bb Mon Sep 17 00:00:00 2001 From: Marcus Kempe Date: Thu, 24 Sep 2026 20:40:43 +0200 Subject: [PATCH] Stop tile requests from reading the map blob and bound the render queue Every tile request pulled the whole OCAD through Cloud SQL (three times per miss) and uncached blocks queued without limit until Cloud Run's 300 s cap killed them, taking tRPC down with them. Read metadata only, resolve settings once per request, refuse with 503 + Retry-After when the queue is full, and rasterise composite and ink in parallel. Co-authored-by: Cursor --- ...fix-map-tile-cold-render-cloud-timeouts.md | 135 +++++++++++ docs/deploy-gcp-cloud-run.md | 20 +- docs/map-tile-rendering.md | 66 ++++- .../__tests__/integration/course-maps.test.ts | 27 +++ .../__tests__/integration/map-tiles.test.ts | 60 ++++- .../__tests__/integration/ppen-import.test.ts | 12 +- .../src/__tests__/map-profile-cache.test.ts | 56 +++++ .../src/__tests__/map-render-cache.test.ts | 174 +++++++++++++ .../src/__tests__/map-render-limits.test.ts | 80 ++++++ packages/api/src/map-profile-cache.ts | 50 ++++ packages/api/src/map-render-cache.ts | 229 ++++++++---------- packages/api/src/map-render-limits.ts | 69 +++++- packages/api/src/map-tiles.ts | 148 +++++------ packages/api/src/routers/course.ts | 95 +++++--- 14 files changed, 970 insertions(+), 251 deletions(-) create mode 100644 docs/bugfix-map-tile-cold-render-cloud-timeouts.md create mode 100644 packages/api/src/__tests__/map-profile-cache.test.ts create mode 100644 packages/api/src/__tests__/map-render-cache.test.ts create mode 100644 packages/api/src/map-profile-cache.ts diff --git a/docs/bugfix-map-tile-cold-render-cloud-timeouts.md b/docs/bugfix-map-tile-cold-render-cloud-timeouts.md new file mode 100644 index 0000000..02a02a8 --- /dev/null +++ b/docs/bugfix-map-tile-cold-render-cloud-timeouts.md @@ -0,0 +1,135 @@ +# Bugfix: map tiles timing out on Cloud Run after the colour-stack release + +**Date:** 2026-09-24 +**Affected:** `oxygen` Cloud Run revision `oxygen-00036-vwj` (image `:edge`, +commit `7e6f0f9`, [PR #26](https://github.com/open-orienteering/oxygen/pull/26)) +**Symptom:** `/api/map-tile/...` requests dying at 299.99 s with HTTP 504; +tRPC calls on the same instance 504-ing too; Cloud SQL connector +handshake failures. + +## What happened + +The colour-stack release changed the tile format (`TILE_FORMAT = 2`) and +folded it into the render key, so every tile already in `map_tiles` was +orphaned on deploy and the first view of each map was a fully cold +render. That part was expected. What wasn't: the first viewport on the +`Testkarta` map produced 23 tiles at 36–40 s each and 71 requests that +Cloud Run killed at its 300 s cap, and a second look 40 minutes later +did the same. For comparison the *previous* revision had cold-rendered +the same map that morning — p50 4.9 s, max 14.6 s, zero timeouts. + +``` +UTC 15:55 revision 00036 goes live +UTC 15:56 23 × 200 (36–40 s) 71 × 504 (299.99 s) +UTC 16:01 55 × 504 +UTC 16:36 23 × 200 90 × 504, 3 × 500 +UTC 16:38 "Cloud SQL connection failed", Prisma "Connection terminated + unexpectedly" on user.findUnique — connection budget gone +``` + +CPU never went above ~40 %. The instance was not busy; it was waiting. + +## Root cause 1 — the OCAD blob was read on every tile request + +`ensureEventMapRenderKey()` resolves an event's colour-stack settings and +render key. Its `select` included `fileData` unconditionally so it could +compute `file_hash` if missing — but the hash is missing only once per +upload, and the select ran every time. + +On the tile route the helper was called **three times per cache miss**: +in the handler, again inside `getMapSource`, and again inside +`maybePreCache` (whose de-duplication flag was set *after* an `await`, +so a burst of 20 tile requests all passed it). Cache hits called it once +or twice. `Testkarta` is 9.8 MB, so one uncached viewport moved roughly +2 GB through a `db-f1-micro` Cloud SQL instance over a pool capped at +eight connections. Every other query on the instance — including the +`user.findUnique` behind every authenticated request — queued behind +those blob transfers. Locally the blob comes off loopback in ~250 ms, +which is why nothing looked wrong in development. + +## Root cause 2 — two sequential rasters, parse-dominated + +Each block now rasterises a composite layer and an ink layer. They ran +one after the other, each taking its own semaphore permit. Measured +locally on the same map: composite 6.2 s (5.7 s of which is resvg +*parsing* the 16.7 MB SVG — an 8-pixel-wide render costs the same), ink +2.1 s. So ~8.5 s per block against ~6.2 s before, and on Cloud Run's +2 vCPUs with three permits, considerably more. + +## Why it queued to 300 s + +Cloud Run admits 160 concurrent requests per instance and holds each for +up to 300 s. The render semaphore allows 3. Nothing between the two said +"no": every tile request that could not get a permit simply waited, and +the blob traffic from root cause 1 made every step in front of the +permit slow as well. Requests piled up until the platform killed them, +and since they were still holding connections and admission slots while +they waited, tRPC starved too. + +## The fix + +1. **Metadata-only reads** (`map-render-cache.ts`). `ensure*RenderKey` + and `refresh*RenderKey` select the stack columns only; `file_data` is + fetched by a second query solely when `file_hash` is null. A cache + hit no longer touches the blob at all. +2. **One resolution per request** (`map-tiles.ts`). The handler resolves + `MapMeta` once and passes it to `getMapSource`, `renderBlock`, + `preCacheChunk` and `maybePreCache`. The `preCacheConsidered` + check-and-mark now happens before the first `await`. +3. **Bounded queue → fast 503** (`map-render-limits.ts`, `map-tiles.ts`). + `Semaphore.run` takes `maxQueue`; a foreground block that finds + `MAP_RENDER_MAX_QUEUE` (default 4) waiters already in line throws + `RenderBusyError`, which the route turns into + `503 Retry-After: 5, Cache-Control: no-store`. `TileLayer` already + honours `Retry-After`, so tiles fill in progressively instead of the + request sitting in Cloud Run's admission queue. Background pre-cache + work is never refused. +4. **Parallel rasters under one permit.** Composite and ink render side + by side, so a block costs roughly the slower of the two (~3.6 s + locally, was ~8.5 s). Memory per permit doubles; the doc's sizing + formula is updated. + +Adjacent hot paths found in the same sweep: + +- `course.mapFileInfo` selected `fileData` to report `.length` — every + page load downloaded the map. Now `octet_length(file_data)` in SQL. +- `course.mapMetadata` re-read and re-parsed the OCAD on every call to + work out what an `auto` profile resolved to. The answer is a function + of the render key; it is now memoised per key (`map-profile-cache.ts`). + +## Before / after (local, same 9.8 MB map, zoom 16) + +| | Before | After | +|---|---|---| +| Cache hit | ~250 ms + 9.8 MB from DB | 7–9 ms, no blob | +| Cold block | ~8.5 s (sequential rasters) | ~3.6 s | +| First block ever on an instance | ~16 s (estimated from the step timings) | ~13.5 s (OCAD parse + 2 × `ocadToSvg` dominate) | +| 20-tile burst over 5 uncached blocks | unbounded wait | 10.8 s, all 200 (queue depth ≤ 4) | +| Surplus requests when the queue is full | wait for 300 s → 504 | immediate 503, retried after 5 s | + +## Tests + +- `map-render-cache.test.ts` — the helpers never select `fileData` when + a hash is stored; exactly one blob read when it is not. +- `map-render-limits.test.ts` — `maxQueue` semantics: refuses foreground + beyond the bound, never refuses background, unbounded when unset. +- `integration/map-tiles.test.ts` — four concurrent uncached blocks with + `MAP_RENDER_MAX_QUEUE=0`: permits' worth of 200s, the rest 503 with the + right headers, and the refused tile renders on retry. +- `integration/course-maps.test.ts` — `mapFileInfo.size` equals the + fixture's byte length; `mapMetadata` resolves the same profile across + calls. + +## Operational notes + +- A render-key change is a full cache invalidation. Deploy it off-peak + or pre-warm; since tiles are content-addressed, rows rendered on any + machine for the same key are valid in production. See "Deploying a + render-key change" in [map-tile-rendering.md](map-tile-rendering.md). +- If tiles 503 continuously rather than briefly, the renderer is + genuinely under-provisioned for the load — raise + `MAP_RENDER_CONCURRENCY` (CPU permitting) or `MAP_TILE_BLOCK_TILES` + (memory permitting), not `MAP_RENDER_MAX_QUEUE`. +- The 504s on unrelated tRPC calls during the incident were starvation, + not bugs in those routes; the same pattern appears in + [bugfix-cloud-sql-handshake-eof.md](bugfix-cloud-sql-handshake-eof.md). diff --git a/docs/deploy-gcp-cloud-run.md b/docs/deploy-gcp-cloud-run.md index 074a1ef..1279c94 100644 --- a/docs/deploy-gcp-cloud-run.md +++ b/docs/deploy-gcp-cloud-run.md @@ -288,13 +288,25 @@ image ships `postgresql-client`. - **Map tile memory.** The renderer rasterises one *window* — the region covered by a block of tiles — per render, so peak memory follows the block size rather than the map size. With the defaults (4×4 tiles, -2× supersampling, 2 concurrent renders) that is a few hundred MB for any -map. The knobs are in `packages/api/src/map-render-limits.ts` and all -have env overrides (`MAP_TILE_BLOCK_TILES`, `MAP_TILE_SUPERSAMPLE`, -`MAP_RENDER_CONCURRENCY`, `MAP_SVG_CACHE_EVENTS`, +2× supersampling, 2 concurrent renders, composite + ink side by side) +that is roughly 600 MB for any map. The knobs are in +`packages/api/src/map-render-limits.ts` and all have env overrides +(`MAP_TILE_BLOCK_TILES`, `MAP_TILE_SUPERSAMPLE`, +`MAP_RENDER_CONCURRENCY`, `MAP_RENDER_MAX_QUEUE`, `MAP_SVG_CACHE_EVENTS`, `MAP_WINDOW_MAX_PIXELS`); none needs setting in normal operation. The 4 GiB allocation is headroom for parsing a large club OCAD into an SVG DOM, which still spikes, not for the tiles themselves. +- **Tile requests never wait longer than the queue bound.** Cloud Run +admits 160 requests per instance and holds each for up to 300 s, while +the renderer runs 3 blocks at a time. Left unbounded, a cold viewport +queued past the cap and every tile 504'd while the waiting requests +starved tRPC of connections (September 2026, see +[bugfix-map-tile-cold-render-cloud-timeouts.md](bugfix-map-tile-cold-render-cloud-timeouts.md)). +The route now refuses with `503 Retry-After: 5` once +`MAP_RENDER_MAX_QUEUE` (4) blocks are already waiting; the client backs +off and the viewport fills in progressively. Brief 503 bursts right +after a render-key change are expected; a steady stream means the +renderer is under-provisioned for the load. - **`--cpu=2` and `MAP_RENDER_CONCURRENCY=3`.** Tile rendering is the only genuinely CPU-bound thing the service does, and on a single throttled vCPU a fresh club map took minutes to fill — the render diff --git a/docs/map-tile-rendering.md b/docs/map-tile-rendering.md index 4701047..1784697 100644 --- a/docs/map-tile-rendering.md +++ b/docs/map-tile-rendering.md @@ -123,12 +123,43 @@ map bug: unrelated queries time out while someone pans a map. | `map_tiles` table | Shared | The real cache. Written with `ON CONFLICT DO NOTHING`, so concurrent renders of the same block across instances are harmless. | | SVG cache | Per process | Parsed map SVGs, `MAP_SVG_CACHE_EVENTS` of them. Amortises the ~70 ms parse and the OCAD read. | | In-flight block map | Per process | A viewport fetches ~20 tiles at once; they collapse onto one render per block. | -| Render semaphore | Per process | Bounds concurrent rasterisations (`MAP_RENDER_CONCURRENCY`). Foreground requests are served before pre-cache work, so background rendering never queues a user behind a whole sweep. | +| Render semaphore | Per process | Bounds concurrent block renders (`MAP_RENDER_CONCURRENCY`). One permit covers a block's composite **and** ink rasters, run side by side. Foreground requests are served before pre-cache work, so background rendering never queues a user behind a whole sweep. | +| Queue bound | Per process | At most `MAP_RENDER_MAX_QUEUE` foreground blocks may wait for a permit. Beyond that the tile route answers **503 + `Retry-After: 5`** immediately instead of letting the request sit until the platform kills it. | Everything above the database is a per-process optimisation, and losing it costs time rather than correctness. Nothing in the tile path requires a single instance. +### What one tile request costs + +The request handler resolves the event's map settings **once** — +`ensureEventMapRenderKey`, a metadata-only read of `map_files` — and +threads that object through the render path and the pre-cache kick-off. +The OCAD blob is read in exactly one place, `loadMapSource`, once per +render key per process; `ensureEventMapRenderKey` only touches +`file_data` when `file_hash` is still null (one-off backfill). A cache +hit is therefore three or four indexed reads and no blob traffic. Keep +it that way: in September 2026 the same helper selected `file_data` +unconditionally and was called three times per miss, which pulled ~30 MB +through Cloud SQL per tile and took the service down — see +[bugfix-map-tile-cold-render-cloud-timeouts.md](bugfix-map-tile-cold-render-cloud-timeouts.md). + +### Where a cold block's time goes + +Measured on a 9.8 MB forest map (45 k objects, 16.7 MB composite SVG), +one 4×4 block at zoom 15–16 on a dev machine: + +| Step | Cost | When | +|---|---|---| +| `readOcad` + `ocadToSvg` ×2 | ~7.5 s | Once per render key per process (`svgCache`) | +| resvg composite raster | ~6 s, **~5.7 s of it parsing the SVG** | Every block | +| resvg ink raster | ~2 s | Every block, in parallel with the composite | +| Sample 16 tiles + PNG encode + insert | <1 s | Every block | + +resvg re-parses the whole SVG per call and exposes no way to reuse the +tree, so the parse dominates and the block size is the lever: doubling +`MAP_TILE_BLOCK_TILES` halves parses per tile at ~4× the window memory. + Uploading a map fires `onMapUpload`, which drops the SVG cache entry and any in-flight blocks for that **render key**. `applyEventMap`, rotation changes, and colour-stack updates recompute `map_files.render_key` and @@ -163,6 +194,26 @@ is already inside the key; `f=` stays for week-old browser caches. Backup / showcase dumps omit `map_tiles` (pure cache; regenerates on first view). +### Deploying a render-key change + +Anything folded into the key — `TILE_FORMAT`, the colour-stack rules, +the hash inputs — orphans **every** cached tile on deploy, and the first +viewer of each map gets a fully cold render at every zoom they touch. +The overview zooms refill themselves (the progress poll drives +`preCacheChunk`; see below), but the deep zooms a course setter is +actually looking at render on demand, block by block, under the queue +bound. Plan for it: + +- Deploy when nobody is setting courses, or accept a few minutes of + progressive fill per map with tiles arriving under the 503/retry + cadence. +- Because tiles are content-addressed, rows rendered anywhere are valid + everywhere. A dev machine that has already viewed the same map holds + rows with the identical `render_key`; copying them into the production + `map_tiles` table (`pg_dump -t oxygen.map_tiles --data-only`) is a + legitimate pre-warm. +- Do not bump `TILE_FORMAT` for changes the key already covers. + ## Pre-caching and progress After the first tile of an event renders, a background pass fills zooms @@ -227,7 +278,8 @@ machine and a 4 GiB container. |---|---|---| | `MAP_TILE_BLOCK_TILES` | 4 | Tiles per side per window. Larger amortises the SVG parse further but squares the memory. | | `MAP_TILE_SUPERSAMPLE` | 2 | Window density relative to the tiles. 1 is cheaper and slightly softer. | -| `MAP_RENDER_CONCURRENCY` | 2 | Concurrent rasterisations per process. Cloud Run runs 3 (see `scripts/gcp/deploy.sh`), which its 2 vCPUs can actually overlap. | +| `MAP_RENDER_CONCURRENCY` | 2 | Concurrent block renders per process (each rasterises composite + ink in parallel). Cloud Run runs 3 (see `scripts/gcp/deploy.sh`), which its 2 vCPUs can actually overlap. | +| `MAP_RENDER_MAX_QUEUE` | 4 | Foreground blocks allowed to wait for a permit before further tile requests get 503 + `Retry-After`. `0` refuses any queueing. Background (pre-cache) work is never refused. | | `MAP_SVG_CACHE_EVENTS` | 4 | Parsed map SVGs held in memory. | | `MAP_WINDOW_MAX_PIXELS` | 64M | Backstop against a pathological projection; normally never binds. | | `MAP_TILE_PRECACHE` | `on` | `off` disables background pre-rendering. | @@ -235,8 +287,13 @@ machine and a 4 GiB container. | `MAP_PRECACHE_BLOCK_DELAY_MS` | 50 | Pause between pre-cache blocks. | Peak render memory is roughly -`4 bytes × (blockTiles × 256 × supersample × √2)² × concurrency`, about -300 MB at the defaults. +`4 bytes × (blockTiles × 256 × supersample × √2)² × 2 layers × concurrency`, +about 600 MB at the defaults. + +Sizing `MAP_RENDER_MAX_QUEUE`: a cold block costs 10–15 s on a 2 vCPU +Cloud Run instance, so with concurrency 3 and four waiters the worst +case is about a minute — well inside the platform's 300 s request +timeout, which is what the unbounded queue used to run into. ## North: georeference, meridian lines, display @@ -289,6 +346,7 @@ Current behaviour (`tile-fetcher.ts` + `tile-retry.ts`): |---|---| | Empty / out-of-map | Server 200 transparent PNG — normal success | | 429 | Back off, honour `Retry-After` when present | +| 503 (renderer busy) | Server refused to queue the block; retry after `Retry-After` (5 s). Expected during a cold fill, not an error. | | 500 / network error | Back off 2s → 10s → 30s → 60s | | Concurrency | Max 12 fetches in flight, nearest-to-centre first | | Scroll-out | `AbortController` cancels queued/in-flight work | diff --git a/packages/api/src/__tests__/integration/course-maps.test.ts b/packages/api/src/__tests__/integration/course-maps.test.ts index a45dcb1..5d6ab79 100644 --- a/packages/api/src/__tests__/integration/course-maps.test.ts +++ b/packages/api/src/__tests__/integration/course-maps.test.ts @@ -169,6 +169,33 @@ afterAll(async () => { await disconnect(); }); +describe("map file info and metadata", () => { + // `size` is now computed in SQL (octet_length) so the query no longer + // ships the blob to the API just to read `.length`. + it("reports the uploaded file's exact byte size without fetching it", async () => { + const info = await caller.course.mapFileInfo(); + expect(info).not.toBeNull(); + expect(info!.fileName).toBe("test.ocd"); + expect(info!.size).toBe(readFileSync(fixture).byteLength); + expect(Number.isInteger(info!.id)).toBe(true); + }); + + // The auto-profile classification reads and parses the OCAD; the + // result is memoised per render key so repeat calls agree and are cheap. + it("resolves the auto colour profile consistently across calls", async () => { + const first = await caller.course.mapMetadata(); + const second = await caller.course.mapMetadata(); + expect(first).not.toBeNull(); + expect(first!.colorProfile).toBe("auto"); + expect(["isom", "issprom", "isskiom", "ismtbom"]).toContain( + first!.resolvedProfile, + ); + expect(second!.resolvedProfile).toBe(first!.resolvedProfile); + expect(second!.resolvedBy).toBe(first!.resolvedBy); + expect(second!.renderKey).toBe(first!.renderKey); + }); +}); + describe("map templates and course maps", () => { it("creates, duplicates and applies an event template idempotently", async () => { const template = await caller.mapTemplate.create({ diff --git a/packages/api/src/__tests__/integration/map-tiles.test.ts b/packages/api/src/__tests__/integration/map-tiles.test.ts index 447e4b7..3ca574d 100644 --- a/packages/api/src/__tests__/integration/map-tiles.test.ts +++ b/packages/api/src/__tests__/integration/map-tiles.test.ts @@ -26,7 +26,10 @@ import { describe, it, expect, beforeAll, afterAll } from "vitest"; import { readFileSync } from "fs"; import { resolve } from "path"; import Fastify, { type FastifyInstance } from "fastify"; -import { registerMapTileRoutes } from "../../map-tiles.js"; +import { + RENDER_BUSY_RETRY_AFTER_S, + registerMapTileRoutes, +} from "../../map-tiles.js"; import { createTestEvent, disconnect } from "../helpers/test-db.js"; import { ensureEventMapRenderKey, gcOrphanTiles } from "../../map-render-cache.js"; import { makeCaller } from "../helpers/caller.js"; @@ -224,6 +227,61 @@ describe("map-tile endpoint", () => { expect([200, 204]).toContain(neighbour.statusCode); }, 60_000); + it("refuses with 503 + Retry-After when the render queue is full, then serves the tile on retry", async () => { + // Cloud Run holds a request for up to 300 s. With an unbounded queue a + // cold viewport queued far past that and every tile 504'd (September + // 2026). With the bound, surplus requests get an immediate 503 and the + // client's retry book comes back after Retry-After. + const savedQueue = process.env.MAP_RENDER_MAX_QUEUE; + process.env.MAP_RENDER_MAX_QUEUE = "0"; + try { + // Distinct, never-rendered blocks: the first `renderConcurrency` + // take the permits, the surplus must be refused rather than queued. + const Z = 18; + const { x, y } = centerTile(mapBounds, Z); + const size = DEFAULTS.blockTiles; + // Four blocks hugging the map centre so they all intersect the map + // (a block entirely off-map is answered without touching the gate). + const blocks = [ + { x, y }, + { x: x - size, y }, + { x, y: y - size }, + { x: x - size, y: y - size }, + ]; + const results = await Promise.all( + blocks.map((b) => + server.inject({ + method: "GET", + url: `/api/map-tile/${ctx.nameId}/${Z}/${b.x}/${b.y}`, + }), + ), + ); + const statuses = results.map((r) => r.statusCode); + expect(statuses.filter((s) => s === 200).length).toBeGreaterThanOrEqual( + DEFAULTS.renderConcurrency, + ); + const refused = results.filter((r) => r.statusCode === 503); + expect(refused.length).toBeGreaterThanOrEqual(1); + expect(statuses.filter((s) => s !== 200 && s !== 503)).toEqual([]); + for (const r of refused) { + expect(Number(r.headers["retry-after"])).toBe(RENDER_BUSY_RETRY_AFTER_S); + expect(r.headers["cache-control"]).toBe("no-store"); + expect(r.json()).toMatchObject({ error: "Map renderer busy" }); + } + + // Once the queue drains the same tile renders normally. + const retry = await server.inject({ + method: "GET", + url: `/api/map-tile/${ctx.nameId}/${Z}/${blocks.at(-1)!.x}/${blocks.at(-1)!.y}`, + }); + expect(retry.statusCode).toBe(200); + expect(retry.headers["content-type"]).toBe("image/png"); + } finally { + if (savedQueue === undefined) delete process.env.MAP_RENDER_MAX_QUEUE; + else process.env.MAP_RENDER_MAX_QUEUE = savedQueue; + } + }, 60_000); + it("renders deep-zoom tiles on demand", async () => { // Above the pre-cache ceiling nothing is pre-rendered, so this is the // path that used to resample a starved whole-map raster and go blurry. diff --git a/packages/api/src/__tests__/integration/ppen-import.test.ts b/packages/api/src/__tests__/integration/ppen-import.test.ts index 06ca297..79a9216 100644 --- a/packages/api/src/__tests__/integration/ppen-import.test.ts +++ b/packages/api/src/__tests__/integration/ppen-import.test.ts @@ -220,10 +220,18 @@ describe("course.previewImport — Purple Pen coordinate alignment", () => { replaceAll: true, }); const coords = await mapCaller.course.controlCoordinates(); - const start = coords.find((c) => c.mapX < -800); - expect(start).toBeDefined(); + // The file places start / control / finish at x, x+5, x+10 and the + // row order is not defined, so pick by position rather than by + // whichever the database happens to return first. + const imported = coords + .filter((c) => c.mapX < -800) + .sort((a, b) => a.mapX - b.mapX); + expect(imported.length).toBeGreaterThanOrEqual(3); + const [start, , finish] = imported; expect(start!.mapX).toBeCloseTo(-900, 1); expect(start!.mapY).toBeCloseTo(-400, 1); + expect(finish!.mapX).toBeCloseTo(-890, 1); + expect(finish!.mapY).toBeCloseTo(-390, 1); }, 60_000); it("imports codes and sequence without positions when asked", async () => { diff --git a/packages/api/src/__tests__/map-profile-cache.test.ts b/packages/api/src/__tests__/map-profile-cache.test.ts new file mode 100644 index 0000000..fd33e86 --- /dev/null +++ b/packages/api/src/__tests__/map-profile-cache.test.ts @@ -0,0 +1,56 @@ +import { beforeEach, describe, expect, it } from "vitest"; +import { + cachedProfileResolution, + clearProfileResolutionCache, + rememberProfileResolution, +} from "../map-profile-cache.js"; + +describe("map profile resolution cache", () => { + beforeEach(() => clearProfileResolutionCache()); + + it("returns undefined for an unknown key", () => { + expect(cachedProfileResolution("nope")).toBeUndefined(); + }); + + it("remembers a resolution by render key", () => { + rememberProfileResolution("k1", { + resolvedProfile: "issprom", + resolvedBy: "file-colour", + }); + expect(cachedProfileResolution("k1")).toEqual({ + resolvedProfile: "issprom", + resolvedBy: "file-colour", + }); + }); + + it("is bounded: the oldest entry goes first", () => { + for (let i = 0; i < 64; i++) { + rememberProfileResolution(`k${i}`, { + resolvedProfile: "isom", + resolvedBy: "default", + }); + } + rememberProfileResolution("k-new", { + resolvedProfile: "isom", + resolvedBy: "scale", + }); + expect(cachedProfileResolution("k0")).toBeUndefined(); + expect(cachedProfileResolution("k1")).toBeDefined(); + expect(cachedProfileResolution("k-new")).toBeDefined(); + }); + + it("overwriting an existing key does not evict anything", () => { + for (let i = 0; i < 64; i++) { + rememberProfileResolution(`k${i}`, { + resolvedProfile: "isom", + resolvedBy: "default", + }); + } + rememberProfileResolution("k5", { + resolvedProfile: "isskiom", + resolvedBy: "file-colour", + }); + expect(cachedProfileResolution("k0")).toBeDefined(); + expect(cachedProfileResolution("k5")?.resolvedProfile).toBe("isskiom"); + }); +}); diff --git a/packages/api/src/__tests__/map-render-cache.test.ts b/packages/api/src/__tests__/map-render-cache.test.ts new file mode 100644 index 0000000..9145913 --- /dev/null +++ b/packages/api/src/__tests__/map-render-cache.test.ts @@ -0,0 +1,174 @@ +/** + * The render-key helpers run on the map-tile hot path — once per tile + * request, including cache hits — so they must never pull the OCAD blob + * (`file_data`, often 5–40 MB) unless the hash genuinely has to be + * computed. The September 2026 Cloud Run incident + * (docs/bugfix-map-tile-cold-render-cloud-timeouts.md) came from exactly + * that: every tile request dragged the whole map through Cloud SQL. + */ + +import { describe, expect, it } from "vitest"; +import { + ensureClubMapRenderKey, + ensureEventMapRenderKey, + refreshClubMapRenderKey, + refreshMapFileRenderKey, +} from "../map-render-cache.js"; +import { computeRenderKey, hashMapFileData } from "../map-render-key.js"; + +const FILE = Buffer.from("fake ocad bytes"); +const FILE_HASH = hashMapFileData(FILE); + +type Row = { + id: bigint; + uploadedAt: Date; + bounds: unknown; + scale: number | null; + rotationCorrection: number; + colorProfile: string | null; + colorOverrides: unknown; + northLinesBelow: boolean; + fileHash: string | null; + renderKey: string | null; + fileData: Uint8Array; +}; + +function baseRow(over: Partial = {}): Row { + return { + id: 7n, + uploadedAt: new Date("2026-09-01T00:00:00Z"), + bounds: { north: 1, south: 0, east: 1, west: 0 }, + scale: 15000, + rotationCorrection: 0, + colorProfile: "auto", + colorOverrides: {}, + northLinesBelow: true, + fileHash: FILE_HASH, + renderKey: computeRenderKey({ + fileHash: FILE_HASH, + rotationCorrection: 0, + colorProfile: "auto", + colorOverrides: {}, + northLinesBelow: true, + }), + fileData: FILE, + ...over, + }; +} + +/** + * A stand-in for the Prisma delegate that records which columns every + * query asked for and applies updates to its single row. + */ +function fakeDelegate(row: Row) { + const selects: Array> = []; + const updates: Array> = []; + const pick = (select: Record) => { + selects.push(select); + const out: Record = {}; + for (const [k, v] of Object.entries(select)) { + if (v) out[k] = (row as unknown as Record)[k]; + } + return out; + }; + const delegate = { + findFirst: async (args: { select: Record }) => + pick(args.select), + findUnique: async (args: { select: Record }) => + pick(args.select), + findUniqueOrThrow: async (args: { select: Record }) => + pick(args.select), + update: async (args: { data: Record }) => { + updates.push(args.data); + Object.assign(row, args.data); + return row; + }, + }; + const askedForBlob = () => selects.filter((s) => s.fileData === true).length; + return { delegate, selects, updates, askedForBlob }; +} + +describe("ensureEventMapRenderKey", () => { + it("does not read file_data when the hash is already stored", async () => { + const row = baseRow(); + const fake = fakeDelegate(row); + const meta = await ensureEventMapRenderKey( + { mapFile: fake.delegate } as never, + 1n, + ); + expect(meta?.renderKey).toBe(row.renderKey); + expect(fake.askedForBlob()).toBe(0); + expect(fake.updates).toHaveLength(0); + }); + + it("reads file_data exactly once to backfill a missing hash, then persists it", async () => { + const row = baseRow({ fileHash: null, renderKey: null }); + const fake = fakeDelegate(row); + const meta = await ensureEventMapRenderKey( + { mapFile: fake.delegate } as never, + 1n, + ); + expect(meta?.fileHash).toBe(FILE_HASH); + expect(fake.askedForBlob()).toBe(1); + expect(fake.updates).toEqual([ + { fileHash: FILE_HASH, renderKey: meta!.renderKey }, + ]); + + // Second call: hash is stored now, so no blob read at all. + const again = fakeDelegate(row); + await ensureEventMapRenderKey({ mapFile: again.delegate } as never, 1n); + expect(again.askedForBlob()).toBe(0); + }); + + it("recomputes a stale render_key from the stored hash without touching the blob", async () => { + const row = baseRow({ renderKey: "stale" }); + const fake = fakeDelegate(row); + const meta = await ensureEventMapRenderKey( + { mapFile: fake.delegate } as never, + 1n, + ); + expect(meta?.renderKey).not.toBe("stale"); + expect(fake.askedForBlob()).toBe(0); + expect(fake.updates).toHaveLength(1); + }); +}); + +describe("ensureClubMapRenderKey", () => { + it("does not read file_data when the hash is already stored", async () => { + const fake = fakeDelegate(baseRow()); + await ensureClubMapRenderKey({ clubMapFile: fake.delegate } as never, 7n); + expect(fake.askedForBlob()).toBe(0); + }); + + it("backfills a missing hash with a single blob read", async () => { + const fake = fakeDelegate(baseRow({ fileHash: null, renderKey: null })); + const meta = await ensureClubMapRenderKey( + { clubMapFile: fake.delegate } as never, + 7n, + ); + expect(meta?.fileHash).toBe(FILE_HASH); + expect(fake.askedForBlob()).toBe(1); + }); +}); + +describe("refresh*RenderKey", () => { + it("reuses the stored hash instead of re-reading the blob", async () => { + const ev = fakeDelegate(baseRow({ colorProfile: "issprom" })); + await refreshMapFileRenderKey({ mapFile: ev.delegate } as never, 7n); + expect(ev.askedForBlob()).toBe(0); + + const club = fakeDelegate(baseRow({ colorProfile: "issprom" })); + await refreshClubMapRenderKey({ clubMapFile: club.delegate } as never, 7n); + expect(club.askedForBlob()).toBe(0); + }); + + it("hashes the blob when no hash is stored yet (fresh upload)", async () => { + const ev = fakeDelegate(baseRow({ fileHash: null, renderKey: null })); + const key = await refreshMapFileRenderKey( + { mapFile: ev.delegate } as never, + 7n, + ); + expect(ev.askedForBlob()).toBe(1); + expect(ev.updates[0]).toEqual({ fileHash: FILE_HASH, renderKey: key }); + }); +}); diff --git a/packages/api/src/__tests__/map-render-limits.test.ts b/packages/api/src/__tests__/map-render-limits.test.ts index d4eb86b..a70ac57 100644 --- a/packages/api/src/__tests__/map-render-limits.test.ts +++ b/packages/api/src/__tests__/map-render-limits.test.ts @@ -1,6 +1,7 @@ import { describe, it, expect, afterEach } from "vitest"; import { DEFAULTS, + RenderBusyError, Semaphore, evictForInsert, intSetting, @@ -8,6 +9,7 @@ import { precacheEnabled, precacheMaxZoom, precacheMinZoom, + renderMaxQueue, } from "../map-render-limits.js"; describe("intSetting", () => { @@ -168,4 +170,82 @@ describe("Semaphore", () => { await Promise.all([a, b]); expect(order).toEqual(["a-start", "a-end", "b-start"]); }); + + // Cloud Run holds a request open for up to 300 s; a tile that would wait + // longer than that behind other renders must be refused immediately so + // the client can back off and retry instead of the platform 504-ing it. + describe("maxQueue", () => { + function deferred() { + let resolve!: () => void; + const promise = new Promise((r) => (resolve = r)); + return { promise, resolve }; + } + + it("rejects a foreground task once the foreground queue is full", async () => { + const sem = new Semaphore(1); + const gate = deferred(); + const blocker = sem.run(() => gate.promise); + const release = gate.resolve; + const waiting = sem.run(async () => "waited", { maxQueue: 1 }); + await expect( + sem.run(async () => "refused", { maxQueue: 1 }), + ).rejects.toBeInstanceOf(RenderBusyError); + expect(sem.foregroundWaiting).toBe(1); + release(); + await expect(waiting).resolves.toBe("waited"); + await blocker; + }); + + it("runs immediately when a permit is free, regardless of maxQueue", async () => { + const sem = new Semaphore(1); + await expect(sem.run(async () => "ok", { maxQueue: 0 })).resolves.toBe("ok"); + }); + + it("never refuses background work and does not count it towards the bound", async () => { + const sem = new Semaphore(1); + const gate = deferred(); + const blocker = sem.run(() => gate.promise); + const release = gate.resolve; + const bg1 = sem.run(async () => "bg1", { background: true, maxQueue: 0 }); + const bg2 = sem.run(async () => "bg2", { background: true, maxQueue: 0 }); + // Only background waiters so far: a bounded foreground task still fits. + const fg = sem.run(async () => "fg", { maxQueue: 1 }); + expect(sem.foregroundWaiting).toBe(1); + release(); + await expect(Promise.all([bg1, bg2, fg])).resolves.toEqual(["bg1", "bg2", "fg"]); + await blocker; + }); + + it("waits without limit when maxQueue is not given", async () => { + const sem = new Semaphore(1); + const gate = deferred(); + const blocker = sem.run(() => gate.promise); + const release = gate.resolve; + const many = Array.from({ length: 20 }, (_, i) => sem.run(async () => i)); + expect(sem.foregroundWaiting).toBe(20); + release(); + await expect(Promise.all(many)).resolves.toHaveLength(20); + await blocker; + }); + }); +}); + +describe("renderMaxQueue", () => { + const saved = process.env.MAP_RENDER_MAX_QUEUE; + afterEach(() => { + if (saved === undefined) delete process.env.MAP_RENDER_MAX_QUEUE; + else process.env.MAP_RENDER_MAX_QUEUE = saved; + }); + + it("defaults to a handful of blocks so a full queue answers well inside a 300 s request cap", () => { + delete process.env.MAP_RENDER_MAX_QUEUE; + expect(renderMaxQueue()).toBe(DEFAULTS.renderMaxQueue); + expect(DEFAULTS.renderMaxQueue).toBeGreaterThanOrEqual(2); + expect(DEFAULTS.renderMaxQueue).toBeLessThanOrEqual(8); + }); + + it("accepts zero to refuse any queueing at all", () => { + process.env.MAP_RENDER_MAX_QUEUE = "0"; + expect(renderMaxQueue()).toBe(0); + }); }); diff --git a/packages/api/src/map-profile-cache.ts b/packages/api/src/map-profile-cache.ts new file mode 100644 index 0000000..6052b57 --- /dev/null +++ b/packages/api/src/map-profile-cache.ts @@ -0,0 +1,50 @@ +/** + * In-process memo of what the `auto` colour profile resolved to for a + * given render key. + * + * `course.mapMetadata` reports which IOF profile an `auto` map ended up + * with, and finding out means reading the OCAD blob and classifying its + * colour table (`applyIofColorStack`). The answer is a pure function of + * the file, the overrides and the scale — all of which are folded into + * the render key — so once one request has paid for it there is no reason + * for the next page load to pull 10 MB through the database again. + */ + +import type { ResolvedColorProfile } from "@oxygen/shared"; +import type { ColorStackResolvedBy } from "./map-color-stack.js"; +import { evictForInsert } from "./map-render-limits.js"; + +export type ProfileResolvedBy = ColorStackResolvedBy; + +export interface ProfileResolution { + resolvedProfile: ResolvedColorProfile; + resolvedBy: ProfileResolvedBy; +} + +/** Plenty for every map a single instance realistically serves. */ +const CAP = 64; + +const cache = new Map(); + +export function cachedProfileResolution( + renderKey: string, +): ProfileResolution | undefined { + return cache.get(renderKey); +} + +export function rememberProfileResolution( + renderKey: string, + resolution: ProfileResolution, +): void { + if (cache.has(renderKey)) { + cache.set(renderKey, resolution); + return; + } + evictForInsert(cache, CAP); + cache.set(renderKey, resolution); +} + +/** Test hook. */ +export function clearProfileResolutionCache(): void { + cache.clear(); +} diff --git a/packages/api/src/map-render-cache.ts b/packages/api/src/map-render-cache.ts index 15313b0..6fea6c6 100644 --- a/packages/api/src/map-render-cache.ts +++ b/packages/api/src/map-render-cache.ts @@ -2,6 +2,14 @@ * Ensure a map_files / club_map_files row has file_hash + render_key. * Used by tile serving, print SVG load, and mapMetadata so the key is * filled lazily (same pattern as the north_detection backfill). + * + * These run on the tile hot path — once per tile request, cache hits + * included — so they read metadata columns only. The OCAD blob + * (`file_data`, routinely 5–40 MB) is fetched with a second query and + * only when `file_hash` is still null, i.e. once per row for the life of + * the upload. Selecting it unconditionally is what saturated Cloud SQL + * in the September 2026 incident + * (docs/bugfix-map-tile-cold-render-cloud-timeouts.md). */ import type { ColorProfile, ColorStackOverrides } from "@oxygen/shared"; @@ -31,6 +39,41 @@ export interface MapStackSettings { scale: number | null; } +/** Metadata-only projection shared by every read in this module. */ +const STACK_COLUMNS = { + id: true, + scale: true, + rotationCorrection: true, + colorProfile: true, + colorOverrides: true, + northLinesBelow: true, + fileHash: true, + renderKey: true, +} as const; + +type StackRow = { + id: bigint; + scale: number | null; + rotationCorrection: number; + colorProfile: string | null; + colorOverrides: unknown; + northLinesBelow: boolean; + fileHash: string | null; + renderKey: string | null; +}; + +/** Either delegate, narrowed to the two calls this module makes. */ +type BlobDelegate = { + findUnique(args: { + where: { id: bigint }; + select: { fileData: true }; + }): Promise<{ fileData: Uint8Array } | null>; + update(args: { + where: { id: bigint }; + data: { fileHash: string; renderKey: string }; + }): Promise; +}; + function parseProfile(raw: string | null | undefined): ColorProfile { const parsed = colorProfileSchema.safeParse(raw ?? "auto"); return parsed.success ? parsed.data : "auto"; @@ -42,75 +85,79 @@ function parseOverrides(raw: unknown): ColorStackOverrides { } /** - * Read the event's current map stack settings, computing and persisting - * `file_hash` / `render_key` when missing. Returns null when the event - * has no map file. + * Resolve (and persist when changed) file_hash + render_key for one row. + * The blob is read only when no hash is stored yet. */ -export async function ensureEventMapRenderKey( - db: MapFileDb, - eventId: bigint, -): Promise<(MapStackSettings & { mapFileId: bigint; uploadedAtMs: number; bounds: unknown }) | null> { - const row = await db.mapFile.findFirst({ - where: { eventId }, - orderBy: { id: "desc" }, - select: { - id: true, - uploadedAt: true, - bounds: true, - scale: true, - rotationCorrection: true, - colorProfile: true, - colorOverrides: true, - northLinesBelow: true, - fileHash: true, - renderKey: true, - fileData: true, - }, - }); - if (!row) return null; - +async function settleRow( + delegate: BlobDelegate, + row: StackRow, +): Promise { const colorProfile = parseProfile(row.colorProfile); const colorOverrides = parseOverrides(row.colorOverrides); - const northLinesBelow = row.northLinesBelow; - const rotationCorrection = row.rotationCorrection; let fileHash = row.fileHash; if (!fileHash) { - fileHash = hashMapFileData(Buffer.from(row.fileData)); + const blob = await delegate.findUnique({ + where: { id: row.id }, + select: { fileData: true }, + }); + if (!blob) throw new Error("Map file row vanished during hash backfill"); + fileHash = hashMapFileData(Buffer.from(blob.fileData)); } - let renderKey = row.renderKey; - const expected = computeRenderKey({ + + const renderKey = computeRenderKey({ fileHash, - rotationCorrection, + rotationCorrection: row.rotationCorrection, colorProfile, colorOverrides, - northLinesBelow, + northLinesBelow: row.northLinesBelow, }); - if (renderKey !== expected) { - renderKey = expected; - } if (row.fileHash !== fileHash || row.renderKey !== renderKey) { - await db.mapFile.update({ + await delegate.update({ where: { id: row.id }, data: { fileHash, renderKey }, }); } return { - mapFileId: row.id, - uploadedAtMs: row.uploadedAt.getTime(), - bounds: row.bounds, scale: row.scale, colorProfile, colorOverrides, - northLinesBelow, - rotationCorrection, + northLinesBelow: row.northLinesBelow, + rotationCorrection: row.rotationCorrection, fileHash, renderKey, }; } +/** + * Read the event's current map stack settings, computing and persisting + * `file_hash` / `render_key` when missing. Returns null when the event + * has no map file. + */ +export async function ensureEventMapRenderKey( + db: MapFileDb, + eventId: bigint, +): Promise< + (MapStackSettings & { mapFileId: bigint; uploadedAtMs: number; bounds: unknown }) | null +> { + const row = await db.mapFile.findFirst({ + where: { eventId }, + orderBy: { id: "desc" }, + select: { ...STACK_COLUMNS, uploadedAt: true, bounds: true }, + }); + if (!row) return null; + + const settings = await settleRow(db.mapFile as unknown as BlobDelegate, row); + return { + ...settings, + mapFileId: row.id, + uploadedAtMs: row.uploadedAt.getTime(), + bounds: row.bounds, + }; +} + /** * Same as `ensureEventMapRenderKey` for a club-library row. */ @@ -120,53 +167,10 @@ export async function ensureClubMapRenderKey( ): Promise { const row = await db.clubMapFile.findUnique({ where: { id: clubMapId }, - select: { - id: true, - scale: true, - rotationCorrection: true, - colorProfile: true, - colorOverrides: true, - northLinesBelow: true, - fileHash: true, - renderKey: true, - fileData: true, - }, + select: STACK_COLUMNS, }); if (!row) return null; - - const colorProfile = parseProfile(row.colorProfile); - const colorOverrides = parseOverrides(row.colorOverrides); - const northLinesBelow = row.northLinesBelow; - const rotationCorrection = row.rotationCorrection; - - let fileHash = row.fileHash; - if (!fileHash) { - fileHash = hashMapFileData(Buffer.from(row.fileData)); - } - const renderKey = computeRenderKey({ - fileHash, - rotationCorrection, - colorProfile, - colorOverrides, - northLinesBelow, - }); - - if (row.fileHash !== fileHash || row.renderKey !== renderKey) { - await db.clubMapFile.update({ - where: { id: row.id }, - data: { fileHash, renderKey }, - }); - } - - return { - scale: row.scale, - colorProfile, - colorOverrides, - northLinesBelow, - rotationCorrection, - fileHash, - renderKey, - }; + return settleRow(db.clubMapFile as unknown as BlobDelegate, row); } /** @@ -196,28 +200,10 @@ export async function refreshMapFileRenderKey( ): Promise { const row = await db.mapFile.findUniqueOrThrow({ where: { id: mapFileId }, - select: { - rotationCorrection: true, - colorProfile: true, - colorOverrides: true, - northLinesBelow: true, - fileHash: true, - fileData: true, - }, + select: STACK_COLUMNS, }); - const fileHash = row.fileHash ?? hashMapFileData(Buffer.from(row.fileData)); - const renderKey = computeRenderKey({ - fileHash, - rotationCorrection: row.rotationCorrection, - colorProfile: parseProfile(row.colorProfile), - colorOverrides: parseOverrides(row.colorOverrides), - northLinesBelow: row.northLinesBelow, - }); - await db.mapFile.update({ - where: { id: mapFileId }, - data: { fileHash, renderKey }, - }); - return renderKey; + const settings = await settleRow(db.mapFile as unknown as BlobDelegate, row); + return settings.renderKey; } export async function refreshClubMapRenderKey( @@ -226,26 +212,11 @@ export async function refreshClubMapRenderKey( ): Promise { const row = await db.clubMapFile.findUniqueOrThrow({ where: { id: clubMapId }, - select: { - rotationCorrection: true, - colorProfile: true, - colorOverrides: true, - northLinesBelow: true, - fileHash: true, - fileData: true, - }, - }); - const fileHash = row.fileHash ?? hashMapFileData(Buffer.from(row.fileData)); - const renderKey = computeRenderKey({ - fileHash, - rotationCorrection: row.rotationCorrection, - colorProfile: parseProfile(row.colorProfile), - colorOverrides: parseOverrides(row.colorOverrides), - northLinesBelow: row.northLinesBelow, - }); - await db.clubMapFile.update({ - where: { id: clubMapId }, - data: { fileHash, renderKey }, + select: STACK_COLUMNS, }); - return renderKey; + const settings = await settleRow( + db.clubMapFile as unknown as BlobDelegate, + row, + ); + return settings.renderKey; } diff --git a/packages/api/src/map-render-limits.ts b/packages/api/src/map-render-limits.ts index 4718318..5cb945b 100644 --- a/packages/api/src/map-render-limits.ts +++ b/packages/api/src/map-render-limits.ts @@ -5,11 +5,12 @@ * * 4 bytes x (blockTiles x 256 x supersample x rotationSlack)^2 * - * doubled while the rasteriser hands its pixels over, times - * `renderConcurrency`. The defaults put that near 300 MB, which leaves - * plenty of headroom in a 4 GiB container — unlike the whole-map raster - * this replaced, which needed gigabytes for a single large map and had to - * be starved down to a blurry resolution to fit. + * doubled while the rasteriser hands its pixels over, doubled again + * because one permit rasterises the composite and the ink layer side by + * side, times `renderConcurrency`. The defaults put that near 600 MB, + * which leaves plenty of headroom in a 4 GiB container — unlike the + * whole-map raster this replaced, which needed gigabytes for a single + * large map and had to be starved down to a blurry resolution to fit. * * `supersample` is why deep zoom looks crisp: the window is rendered * denser than the tiles that come out of it, so the sampler in @@ -25,8 +26,16 @@ export const DEFAULTS = { supersample: 2, /** Backstop against a pathological projection blowing up a window. */ windowMaxPixels: 64_000_000, - /** Concurrent window renders per process. */ + /** Concurrent block renders per process (each rasterises composite + ink). */ renderConcurrency: 2, + /** + * Foreground blocks allowed to wait for a permit before further tile + * requests are refused with 503 + Retry-After. A cold block costs + * roughly 10–15 s on a 2 vCPU Cloud Run instance, so four waiters keep + * the worst case near a minute — far inside the platform's 300 s cap, + * which is where unbounded queueing ended up in September 2026. + */ + renderMaxQueue: 4, /** Parsed map SVGs kept in memory (a few MB each). */ svgCacheEvents: 4, } as const; @@ -66,6 +75,14 @@ export function renderConcurrency(): number { ); } +export function renderMaxQueue(): number { + return intSetting( + process.env.MAP_RENDER_MAX_QUEUE, + DEFAULTS.renderMaxQueue, + 0, + ); +} + export function svgCacheEvents(): number { return intSetting( process.env.MAP_SVG_CACHE_EVENTS, @@ -119,6 +136,19 @@ export function evictForInsert(cache: Map, cap: number): void { } } +/** + * Thrown by `Semaphore.run` when a bounded foreground task finds the + * queue already full. Callers turn it into a fast 503 + Retry-After so + * the client backs off instead of the request sitting in the platform's + * admission queue until it is killed. + */ +export class RenderBusyError extends Error { + constructor(readonly waiting: number) { + super(`render queue full (${waiting} waiting)`); + this.name = "RenderBusyError"; + } +} + /** * Counting semaphore bounding concurrent renders, with two priorities. * @@ -126,6 +156,12 @@ export function evictForInsert(cache: Map, cap: number): void { * the one block already in flight, so foreground waiters are always served * first. Without this a pre-cache sweep can hold every permit and a tile * request queues behind the entire sweep. + * + * Foreground tasks may also pass `maxQueue`: if that many foreground + * tasks are already waiting, the call fails immediately with + * `RenderBusyError` rather than joining the line. Background tasks are + * never refused — they are polite by construction and nothing is waiting + * on them. */ export class Semaphore { private available: number; @@ -136,11 +172,16 @@ export class Semaphore { this.available = Math.max(1, limit); } + /** Foreground tasks currently waiting for a permit. */ + get foregroundWaiting(): number { + return this.foreground.length; + } + async run( task: () => Promise, - opts: { background?: boolean } = {}, + opts: { background?: boolean; maxQueue?: number } = {}, ): Promise { - await this.acquire(opts.background === true); + await this.acquire(opts.background === true, opts.maxQueue); try { return await task(); } finally { @@ -148,11 +189,21 @@ export class Semaphore { } } - private async acquire(isBackground: boolean): Promise { + private async acquire( + isBackground: boolean, + maxQueue: number | undefined, + ): Promise { if (this.available > 0) { this.available--; return; } + if ( + !isBackground && + maxQueue !== undefined && + this.foreground.length >= maxQueue + ) { + throw new RenderBusyError(this.foreground.length); + } const queue = isBackground ? this.background : this.foreground; await new Promise((resolve) => queue.push(resolve)); } diff --git a/packages/api/src/map-tiles.ts b/packages/api/src/map-tiles.ts index 308f5cb..e6d6cdd 100644 --- a/packages/api/src/map-tiles.ts +++ b/packages/api/src/map-tiles.ts @@ -70,6 +70,7 @@ import { type ViewBox, } from "./map-window.js"; import { + RenderBusyError, Semaphore, blockTiles, evictForInsert, @@ -78,6 +79,7 @@ import { precacheMaxZoom, precacheMinZoom, renderConcurrency, + renderMaxQueue, supersample, svgCacheEvents, windowMaxPixels, @@ -89,10 +91,25 @@ import { type StackOcadFile, } from "./map-color-stack.js"; import { ensureEventMapRenderKey } from "./map-render-cache.js"; -import type { ColorProfile, ColorStackOverrides } from "@oxygen/shared"; const TILE_SIZE = 256; +/** + * Seconds a refused (503) tile client should wait before asking again. + * Long enough for a block to finish and free a permit; short enough that + * a viewport fills in visibly rather than stalling. + */ +export const RENDER_BUSY_RETRY_AFTER_S = 5; + +/** + * Everything a tile request needs to know about the event's map, read + * once per request from `map_files` (metadata columns only) and threaded + * through the render path. Earlier code re-resolved this at each step — + * three times per tile miss — and each read dragged the OCAD blob along; + * see docs/bugfix-map-tile-cold-render-cloud-timeouts.md. + */ +type MapMeta = NonNullable>>; + /** * Bumped when the on-wire tile format changes so browsers' week-long * cache cannot feed an old 256×256 PNG into the stacked-tile slicer. @@ -193,9 +210,7 @@ const tileKey = (z: number, x: number, y: number) => `${z}/${x}/${y}`; /** * The parsed SVG for an event's current map, keyed by renderKey. */ -async function getMapSource(eventId: bigint): Promise { - const meta = await ensureEventMapRenderKey(prisma(), eventId); - if (!meta) throw new Error("No map file uploaded"); +async function getMapSource(eventId: bigint, meta: MapMeta): Promise { const { renderKey } = meta; const cached = svgCache.get(renderKey); @@ -218,19 +233,13 @@ async function getMapSource(eventId: bigint): Promise { async function loadMapSource( eventId: bigint, - meta: { - renderKey: string; - rotationCorrection: number; - colorProfile: ColorProfile; - colorOverrides: ColorStackOverrides; - northLinesBelow: boolean; - scale: number | null; - }, + meta: MapMeta, ): Promise { - const row = await prisma().mapFile.findFirst({ - where: { eventId }, - orderBy: { id: "desc" }, - select: { fileData: true, rotationCorrection: true }, + // The one place on the tile path that reads the OCAD blob: once per + // render key per process, then the parsed SVG lives in `svgCache`. + const row = await prisma().mapFile.findUnique({ + where: { id: meta.mapFileId }, + select: { fileData: true }, }); if (!row) throw new Error("No map file uploaded"); @@ -531,35 +540,37 @@ async function renderBlockUncached( const rect = boundsOfPoints(corners, 2 / wanted); const density = clampDensity(rect, wanted, windowMaxPixels()); - const win = await gate().run( + // One permit per block. Composite and ink are rasterised side by side + // under it: resvg re-parses the SVG on every call and that parse is + // ~90 % of a render, so running the two in parallel cuts block latency + // to roughly the slower of the pair instead of their sum. Foreground + // requests are refused (RenderBusyError → 503) once the queue is full + // rather than being allowed to wait indefinitely. + const [win, inkWin] = await gate().run( () => - rasterise( - source.svg, - source.rootViewBox, - source.ocadBounds, - rect, - density, - false, - ), - { background }, - ); - if (!win) return result; - - let inkWin: RenderedWindow | null = null; - if (source.svgInk) { - inkWin = await gate().run( - () => + Promise.all([ rasterise( - source.svgInk!, + source.svg, source.rootViewBox, source.ocadBounds, rect, density, - true, + false, ), - { background }, - ); - } + source.svgInk + ? rasterise( + source.svgInk, + source.rootViewBox, + source.ocadBounds, + rect, + density, + true, + ) + : Promise.resolve(null), + ]), + background ? { background } : { maxQueue: renderMaxQueue() }, + ); + if (!win) return result; for (const [key, quad] of quads) { const composite = sampleTileRgba(quad, win, false); @@ -703,9 +714,8 @@ const chunkInFlight = new Set(); * Returns the number of tiles written so the caller can fold them into * the progress figures it already read. */ -async function preCacheChunk(eventId: bigint): Promise { - const meta = await ensureEventMapRenderKey(prisma(), eventId); - if (!meta || !precacheEnabled() || chunkInFlight.has(meta.renderKey)) return 0; +async function preCacheChunk(eventId: bigint, meta: MapMeta): Promise { + if (!precacheEnabled() || chunkInFlight.has(meta.renderKey)) return 0; const { renderKey } = meta; chunkInFlight.add(renderKey); try { @@ -731,7 +741,7 @@ async function preCacheChunk(eventId: bigint): Promise { const present = new Set(rows.map((r) => `${r.x}/${r.y}`)); const blocks = missingBlocks(range, size, present, CHUNK_BLOCKS); - const source = await getMapSource(eventId); + const source = await getMapSource(eventId, meta); for (const { bx, by } of blocks) { try { const tiles = await renderBlock(source, z, bx, by, true); @@ -767,27 +777,16 @@ function parseBounds(raw: unknown): WGS84Bounds | null { return bounds; } -/** - * The map's WGS84 bounds as stored at upload. Reading them back beats - * re-deriving them from the OCAD: it is one small query rather than a - * parse, so the progress endpoint and the pre-cache check stay cheap. - */ -async function storedBounds(eventId: bigint): Promise { - const meta = await ensureEventMapRenderKey(prisma(), eventId); - return meta ? parseBounds(meta.bounds) : null; -} - /** * Pre-cache progress straight from the database. The denominator is a - * function of the map's stored WGS84 bounds and the numerator is a row + * function of the map's stored WGS84 bounds (read back from `map_files` + * rather than re-derived from the OCAD) and the numerator is a row * count, so a request served by any instance reports the same figures — * unlike the in-process counter this replaced. */ async function tileProgress( - eventId: bigint, + meta: MapMeta, ): Promise<{ total: number; done: number; rendering: boolean }> { - const meta = await ensureEventMapRenderKey(prisma(), eventId); - if (!meta) return { total: 0, done: 0, rendering: false }; const bounds = parseBounds(meta.bounds); if (!bounds) return { total: 0, done: 0, rendering: false }; @@ -829,11 +828,13 @@ export function registerMapTileRoutes(server: FastifyInstance): void { if (eventId === null) { return reply.send({ total: 0, done: 0, rendering: false }); } - const progress = await tileProgress(eventId); + const meta = await ensureEventMapRenderKey(prisma(), eventId); + if (!meta) return reply.send({ total: 0, done: 0, rendering: false }); + const progress = await tileProgress(meta); if (!progress.rendering) return reply.send(progress); - await preCacheChunk(eventId); - return reply.send(await tileProgress(eventId)); + await preCacheChunk(eventId, meta); + return reply.send(await tileProgress(meta)); }); server.get<{ @@ -876,7 +877,7 @@ export function registerMapTileRoutes(server: FastifyInstance): void { select: { tileData: true }, }); if (cached) { - kickOffPreCache(eventId); + kickOffPreCache(eventId, meta); return reply .header("Content-Type", "image/png") .header("Cache-Control", "public, max-age=604800") @@ -884,7 +885,7 @@ export function registerMapTileRoutes(server: FastifyInstance): void { } try { - const source = await getMapSource(eventId); + const source = await getMapSource(eventId, meta); const rendered = await renderBlock(source, z, x, y); const png = rendered.get(tileKey(z, x, y)); if (!png) { @@ -900,13 +901,24 @@ export function registerMapTileRoutes(server: FastifyInstance): void { // Fill the overview zooms in the background so the next viewer's // first paint is instant. - kickOffPreCache(eventId); + kickOffPreCache(eventId, meta); return reply .header("Content-Type", "image/png") .header("Cache-Control", "public, max-age=604800") .send(png); } catch (err) { + if (err instanceof RenderBusyError) { + // The render queue is full. Answer now so the client backs off + // (its retry book honours Retry-After) instead of holding the + // request until the platform's admission timeout kills it — + // and starves every other route on the instance meanwhile. + return reply + .code(503) + .header("Retry-After", String(RENDER_BUSY_RETRY_AFTER_S)) + .header("Cache-Control", "no-store") + .send({ error: "Map renderer busy", waiting: err.waiting }); + } server.log.error({ err }, "Failed to render map tile"); return reply.code(500).send({ error: "Failed to render tile" }); } @@ -924,11 +936,11 @@ const preCacheConsidered = new Set(); /** * Start the background pre-cache if this event's render key still needs it. + * The `preCacheConsidered` check-and-mark happens before the first await + * so a viewport-sized burst of requests cannot all slip past it. */ -async function maybePreCache(eventId: bigint): Promise { +async function maybePreCache(eventId: bigint, meta: MapMeta): Promise { if (!precacheEnabled()) return; - const meta = await ensureEventMapRenderKey(prisma(), eventId); - if (!meta) return; if (preCacheConsidered.has(meta.renderKey)) return; preCacheConsidered.add(meta.renderKey); @@ -945,12 +957,12 @@ async function maybePreCache(eventId: bigint): Promise { }); if (done >= expectedTileCount(bounds, minZoom, maxZoom)) return; - const source = await getMapSource(eventId); + const source = await getMapSource(eventId, meta); await preCacheTiles(source); } -function kickOffPreCache(eventId: bigint): void { - void maybePreCache(eventId).catch((err) => +function kickOffPreCache(eventId: bigint, meta: MapMeta): void { + void maybePreCache(eventId, meta).catch((err) => console.error("[map-tiles] pre-cache failed:", err), ); } diff --git a/packages/api/src/routers/course.ts b/packages/api/src/routers/course.ts index 4276459..0271ede 100644 --- a/packages/api/src/routers/course.ts +++ b/packages/api/src/routers/course.ts @@ -56,6 +56,11 @@ import { colorStackOverridesSchema, } from "@oxygen/shared"; import { applyIofColorStack, type StackOcadFile } from "../map-color-stack.js"; +import { + cachedProfileResolution, + rememberProfileResolution, + type ProfileResolvedBy, +} from "../map-profile-cache.js"; import { canDownloadEventMap } from "../ocad-export.js"; import { loadEventCrs } from "../event-crs.js"; import { @@ -988,11 +993,7 @@ export const courseRouter = router({ let resolvedProfile = stackMeta.colorProfile === "auto" ? (scale != null && scale > 0 && scale <= 5000 ? "issprom" : "isom") : stackMeta.colorProfile; - let resolvedBy: - | "explicit" - | "file-colour" - | "scale" - | "default" = + let resolvedBy: ProfileResolvedBy = stackMeta.colorProfile === "auto" ? scale != null ? "scale" @@ -1000,30 +1001,47 @@ export const courseRouter = router({ : "explicit"; if (stackMeta.colorProfile === "auto") { - if (!blobBuffer) { - const blob = await ctx.db.mapFile.findUnique({ - where: { id: row.id }, - select: { fileData: true }, - }); - if (blob) blobBuffer = Buffer.from(blob.fileData); - } - if (blobBuffer) { - try { - const ocadMod = await import("ocad2geojson"); - const readOcad = (ocadMod as Record).readOcad as ( - buf: Buffer, - opts?: Record, - ) => Promise; - const ocad = await readOcad(blobBuffer, { quietWarnings: true }); - const classified = applyIofColorStack(ocad, { - profile: "auto", - overrides: stackMeta.colorOverrides, - scale, + // Classifying the colour table needs the OCAD blob. The outcome is + // fixed for a render key, so pay for it once per process rather + // than on every page load (this query runs on each map view). + const remembered = cachedProfileResolution(stackMeta.renderKey); + if (remembered) { + ({ resolvedProfile, resolvedBy } = remembered); + } else { + if (!blobBuffer) { + const blob = await ctx.db.mapFile.findUnique({ + where: { id: row.id }, + select: { fileData: true }, }); - resolvedProfile = classified.resolvedProfile; - resolvedBy = classified.resolvedBy; - } catch { - // Keep the scale heuristic. + if (blob) blobBuffer = Buffer.from(blob.fileData); + } + if (blobBuffer) { + try { + const ocadMod = await import("ocad2geojson"); + const readOcad = (ocadMod as Record).readOcad as ( + buf: Buffer, + opts?: Record, + ) => Promise; + const ocad = await readOcad(blobBuffer, { quietWarnings: true }); + const classified = applyIofColorStack(ocad, { + profile: "auto", + overrides: stackMeta.colorOverrides, + scale, + }); + resolvedProfile = classified.resolvedProfile; + resolvedBy = classified.resolvedBy; + rememberProfileResolution(stackMeta.renderKey, { + resolvedProfile, + resolvedBy, + }); + } catch (err) { + // Keep the scale heuristic, but say so: a map that cannot be + // classified is worth knowing about. + console.warn( + `[map-color-stack] event ${ctx.event.id}: profile classification failed, using scale heuristic:`, + err, + ); + } } } } @@ -1052,17 +1070,26 @@ export const courseRouter = router({ /** Info about the uploaded OCAD map file (if any). */ mapFileInfo: kioskOrCoursesViewProcedure.query(async ({ ctx }) => { - const f = await ctx.db.mapFile.findFirst({ - where: { eventId: ctx.event.id }, - orderBy: { uploadedAt: "desc" }, - select: { id: true, fileName: true, uploadedAt: true, fileData: true }, - }); + // Size comes from octet_length in SQL: this query runs on every map + // view and the blob itself is routinely 5–40 MB — fetching it just to + // read `.length` was a full download per page load. + const rows = await ctx.db.$queryRaw< + Array<{ id: bigint; fileName: string; uploadedAt: Date; size: number }> + >` + SELECT id, file_name AS "fileName", uploaded_at AS "uploadedAt", + octet_length(file_data)::int AS size + FROM oxygen.map_files + WHERE event_id = ${ctx.event.id} + ORDER BY uploaded_at DESC + LIMIT 1 + `; + const f = rows[0]; if (!f) return null; return { id: Number(f.id), fileName: f.fileName, uploadedAt: f.uploadedAt.toISOString(), - size: f.fileData.length, + size: f.size, }; }),