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, }; }),