Public: anyone can read this; the crew can change it.
Every forge response carries Server-Timing, and each route's time is kept as a histogram #2724
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/2710-every-forge-response-carries-server-timi → main 1 commit fork 1 thread · 1 unresolved
6 files
changed +352
−4
bench/timing.ts added +32
| @@ -0,0 +1,32 @@ | ||
| 1 | /** | |
| 2 | * What recording a request's time costs: `record` plus the header, per | |
| 3 | * request. The budget is 0.2 ms; it is measured in microseconds. | |
| 4 | * | |
| 5 | * bun run bench/timing.ts | |
| 6 | */ | |
| 7 | ||
| 8 | import { Database } from "bun:sqlite"; | |
| 9 | import { createRouteTiming, serverTiming } from "../src/core/route_timing.ts"; | |
| 10 | import { migrate } from "../src/kernel/migrate.ts"; | |
| 11 | import { migrationFiles } from "../src/core/schema.ts"; | |
| 12 | ||
| 13 | const BUDGET_MS = 0.2; | |
| 14 | const N = 200_000; | |
| 15 | const db = new Database(":memory:"); | |
| 16 | migrate(db, migrationFiles); | |
| 17 | const timing = createRouteTiming(db); | |
| 18 | const patterns = ["/:owner/:name", "/api/v1/repos/:o/:n", "/", "/:owner/:name/pulls/:n"]; | |
| 19 | ||
| 20 | const start = performance.now(); | |
| 21 | for (let i = 0; i < N; i++) { | |
| 22 | const ms = performance.now() - start; | |
| 23 | timing.record(patterns[i % patterns.length]!, (i % 40) / 4); | |
| 24 | serverTiming(ms); | |
| 25 | } | |
| 26 | const per = (performance.now() - start) / N; | |
| 27 | timing.stop(); | |
| 28 | console.log(`record + header: ${(per * 1000).toFixed(2)} µs/request (budget ${BUDGET_MS * 1000} µs)`); | |
| 29 | if (per > BUDGET_MS) { | |
| 30 | console.error("over budget"); | |
| 31 | process.exit(1); | |
| 32 | } |
src/core/migration-pins.json +5 −1
| @@ -115,5 +115,9 @@ | ||
| 115 | 115 | "20261016190000-member": "9076848fe032dea6905927a1b454c2381a3129acb3ce357c2726e82f1c161bc4", |
| 116 | 116 | "20261016200000-invite": "72bc7e9be6a7223048d1d1cf0226bc93ee4dbea9f00dbb20a6d457305886cbf9", |
| 117 | 117 | "20261017195831-ceiling-reserved": "1e6756752ae06c78a5920ae839e911e837a14cff3ac766cbc38e117c0a40186b", |
| 118 | "20261018100000-incident-remembered": "61fefa1d0750f3be617fdc23c1e6e17abc1ba610d980d85aff8824f14bf3e253" | |
| 118 | "20261018100000-incident-remembered": "61fefa1d0750f3be617fdc23c1e6e17abc1ba610d980d85aff8824f14bf3e253", | |
| 119 | "20261018110000-limb-replan": "23d6a14e5ef934c4d8f1509377ac8a15dc6a0097313127558b4c5a655a24581e", | |
| 120 | "20261019120000-drill-phases": "574071a8576f982fe8483af90b472a03793ffa03e3b391c786d5c5144e3bb82e", | |
| 121 | "20261019130000-run-model-prompt": "ce2e94f439649fc042c0a951f1af4a740b91f674dc94521e865ec517f68994f5", | |
| 122 | "20261019140000-route-timing": "0fd7cfa4e0a50c4b2b36162601f9ddc3318e7fa445559732364b2b52a06de011" | |
| 119 | 123 | } |
src/core/migrations/20261019140000-route-timing.ts added +13
| @@ -0,0 +1,13 @@ | ||
| 1 | // Each route's time, kept as a histogram per hour (#2710): one row per hour, | |
| 2 | // route pattern (never the raw path) and bucket, with how many requests fell | |
| 3 | // in it and their summed microseconds. Pruned after 30 days. | |
| 4 | export default ` | |
| 5 | CREATE TABLE route_timing ( | |
| 6 | hour TEXT NOT NULL, | |
| 7 | pattern TEXT NOT NULL, | |
| 8 | bucket INTEGER NOT NULL, | |
| 9 | n INTEGER NOT NULL, | |
| 10 | sum_us INTEGER NOT NULL, | |
| 11 | PRIMARY KEY (hour, pattern, bucket) | |
| 12 | ) WITHOUT ROWID; | |
| 13 | `; |
src/core/route_timing.ts added +170
| @@ -0,0 +1,170 @@ | ||
| 1 | /** | |
| 2 | * Route timing: how long each route takes, as a histogram per hour. | |
| 3 | * | |
| 4 | * `record` is a map update and runs no query. `flush` writes every pending | |
| 5 | * key in one transaction as an upsert that adds to `n` and `sum_us`; it runs | |
| 6 | * by itself about a second after the first pending record, once 500 keys are | |
| 7 | * pending, and on `stop()`. The timer is `unref`'d. A failed write loses | |
| 8 | * nothing: the records go back and the timer retries. Rows older than | |
| 9 | * `KEEP_DAYS` are deleted, checked once per hour at flush. | |
| 10 | * | |
| 11 | * The key is the route pattern the router matched, never the raw path, so | |
| 12 | * `/alice/x` and `/bob/y` land in one bucket and the table does not grow | |
| 13 | * with what strangers type. Not the forge's health: that is `kernel/vitals`. | |
| 14 | */ | |
| 15 | ||
| 16 | import type { Database } from "bun:sqlite"; | |
| 17 | ||
| 18 | /** Upper edges in ms; bucket `i` holds durations `<= EDGES_MS[i]`, the last is everything slower. */ | |
| 19 | export const EDGES_MS = [1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 2500] as const; | |
| 20 | export const KEEP_DAYS = 30; | |
| 21 | const MAX_PATTERN = 200; | |
| 22 | const HOUR_MS = 3_600_000; | |
| 23 | const FLUSH_MS = 1000; | |
| 24 | const FLUSH_KEYS = 500; | |
| 25 | const SEP = "\u0000"; | |
| 26 | ||
| 27 | export interface TimingRow { | |
| 28 | readonly hour: string; | |
| 29 | readonly pattern: string; | |
| 30 | readonly bucket: number; | |
| 31 | readonly n: number; | |
| 32 | readonly sum_us: number; | |
| 33 | } | |
| 34 | ||
| 35 | export interface RouteTiming { | |
| 36 | record(pattern: string, ms: number): void; | |
| 37 | flush(): void; | |
| 38 | stop(): void; | |
| 39 | } | |
| 40 | ||
| 41 | /** The bucket a duration falls in. */ | |
| 42 | export function bucketOf(ms: number): number { | |
| 43 | for (let i = 0; i < EDGES_MS.length; i++) if (ms <= EDGES_MS[i]!) return i; | |
| 44 | return EDGES_MS.length; | |
| 45 | } | |
| 46 | ||
| 47 | const hourText = (hourNo: number): string => | |
| 48 | new Date(hourNo * HOUR_MS).toISOString().slice(0, 13); | |
| 49 | ||
| 50 | export function createRouteTiming( | |
| 51 | db: Database, | |
| 52 | now: () => number = Date.now, | |
| 53 | flushMs: number = FLUSH_MS, | |
| 54 | ): RouteTiming { | |
| 55 | const pending = new Map<string, { n: number; us: number }>(); | |
| 56 | let timer: ReturnType<typeof setTimeout> | null = null; | |
| 57 | let stopped = false; | |
| 58 | let prunedHour = -1; | |
| 59 | ||
| 60 | function clear(): void { | |
| 61 | if (timer) clearTimeout(timer); | |
| 62 | timer = null; | |
| 63 | } | |
| 64 | ||
| 65 | function schedule(delay: number): void { | |
| 66 | clear(); | |
| 67 | timer = setTimeout(() => { | |
| 68 | try { | |
| 69 | flush(); | |
| 70 | } catch { | |
| 71 | // flush put the records back and rearmed the retry. | |
| 72 | } | |
| 73 | }, delay); | |
| 74 | timer.unref(); | |
| 75 | } | |
| 76 | ||
| 77 | function flush(): void { | |
| 78 | clear(); | |
| 79 | if (pending.size === 0) return; | |
| 80 | const batch = [...pending]; | |
| 81 | pending.clear(); | |
| 82 | try { | |
| 83 | const upsert = db.query( | |
| 84 | `INSERT INTO route_timing (hour, pattern, bucket, n, sum_us) | |
| 85 | VALUES (?1, ?2, ?3, ?4, ?5) | |
| 86 | ON CONFLICT (hour, pattern, bucket) | |
| 87 | DO UPDATE SET n = n + excluded.n, sum_us = sum_us + excluded.sum_us`, | |
| 88 | ); | |
| 89 | const hourNo = Math.floor(now() / HOUR_MS); | |
| 90 | db.transaction(() => { | |
| 91 | for (const [key, v] of batch) { | |
| 92 | const [h, pattern, b] = key.split(SEP) as [string, string, string]; | |
| 93 | upsert.run(hourText(Number(h)), pattern, Number(b), v.n, v.us); | |
| 94 | } | |
| 95 | if (prunedHour !== hourNo) { | |
| 96 | db.query("DELETE FROM route_timing WHERE hour < ?1").run( | |
| 97 | hourText(hourNo - KEEP_DAYS * 24), | |
| 98 | ); | |
| 99 | prunedHour = hourNo; | |
| 100 | } | |
| 101 | })(); | |
| 102 | } catch (err) { | |
| 103 | prunedHour = -1; | |
| 104 | for (const [key, v] of batch) { | |
| 105 | const had = pending.get(key); | |
| 106 | if (had) { | |
| 107 | had.n += v.n; | |
| 108 | had.us += v.us; | |
| 109 | } else pending.set(key, v); | |
| 110 | } | |
| 111 | if (!stopped) schedule(Math.max(flushMs, 1)); | |
| 112 | throw err; | |
| 113 | } | |
| 114 | } | |
| 115 | ||
| 116 | function record(pattern: string, ms: number): void { | |
| 117 | if (stopped) return; | |
| 118 | if (pattern.length === 0 || pattern.length > MAX_PATTERN) | |
| 119 | throw new RangeError("route timing refused: bad pattern"); | |
| 120 | if (!Number.isFinite(ms) || ms < 0) | |
| 121 | throw new RangeError("route timing refused: bad duration"); | |
| 122 | const key = `${Math.floor(now() / HOUR_MS)}${SEP}${pattern}${SEP}${bucketOf(ms)}`; | |
| 123 | const us = Math.round(ms * 1000); | |
| 124 | const had = pending.get(key); | |
| 125 | if (had) { | |
| 126 | had.n++; | |
| 127 | had.us += us; | |
| 128 | } else pending.set(key, { n: 1, us }); | |
| 129 | if (pending.size >= FLUSH_KEYS) schedule(0); | |
| 130 | else if (timer === null) schedule(flushMs); | |
| 131 | } | |
| 132 | ||
| 133 | function stop(): void { | |
| 134 | stopped = true; | |
| 135 | flush(); | |
| 136 | } | |
| 137 | ||
| 138 | return { record, flush, stop }; | |
| 139 | } | |
| 140 | ||
| 141 | /** Every row from `sinceHour` (`2026-10-16T13`) on, oldest hour first. */ | |
| 142 | export function readTiming(db: Database, sinceHour: string): TimingRow[] { | |
| 143 | return db | |
| 144 | .query( | |
| 145 | `SELECT hour, pattern, bucket, n, sum_us FROM route_timing | |
| 146 | WHERE hour >= ?1 ORDER BY hour, pattern, bucket`, | |
| 147 | ) | |
| 148 | .all(sinceHour) as TimingRow[]; | |
| 149 | } | |
| 150 | ||
| 151 | /** The header every response carries: `app;dur=<ms>`, and `db` when known. */ | |
| 152 | export function serverTiming(appMs: number, dbMs?: number): string { | |
| 153 | const f = (n: number) => n.toFixed(1); | |
| 154 | return dbMs === undefined | |
| 155 | ? `app;dur=${f(appMs)}` | |
| 156 | : `db;dur=${f(dbMs)}, app;dur=${f(appMs)}`; | |
| 157 | } | |
| 158 | ||
| 159 | const dbTimes = new WeakMap<Request, number>(); | |
| 160 | ||
| 161 | /** A handler that knows how long it spent in the database says so here. */ | |
| 162 | export function noteDbTime(request: Request, ms: number): void { | |
| 163 | dbTimes.set(request, (dbTimes.get(request) ?? 0) + ms); | |
| 164 | } | |
| 165 | ||
| 166 | export function takeDbTime(request: Request): number | undefined { | |
| 167 | const ms = dbTimes.get(request); | |
| 168 | dbTimes.delete(request); | |
| 169 | return ms; | |
| 170 | } |
src/http/server.ts +42 −3
| @@ -445,6 +445,13 @@ import { feedRoutes } from "./feed.ts"; | ||
| 445 | 445 | import type { Database } from "bun:sqlite"; |
| 446 | 446 | import { mcpRoutes } from "./mcp.ts"; |
| 447 | 447 | import { createUsageCounter, type UsageCounter } from "../core/usage_count.ts"; |
| 448 | import { | |
| 449 | createRouteTiming, | |
| 450 | noteDbTime, | |
| 451 | serverTiming, | |
| 452 | takeDbTime, | |
| 453 | type RouteTiming, | |
| 454 | } from "../core/route_timing.ts"; | |
| 448 | 455 | import { methodOf, noteUsage, roleOf, surfaceOf, takeUsage } from "./usage_tag.ts"; |
| 449 | 456 | import { oauthRoutes } from "./oauth.ts"; |
| 450 | 457 | import { flushAccess, recordAccess } from "./access_log.ts"; |
| @@ -2038,8 +2045,30 @@ export async function serve(app: App): Promise<Servers> { | ||
| 2038 | 2045 | // One counter per database: a hosted child counts in its own. `count` is a |
| 2039 | 2046 | // map increment; a refused event would be a programming error, not worth a 500. |
| 2040 | 2047 | const counters = new Map<Database, UsageCounter>(); |
| 2041 | const counted = (owner: App, request: Request, response: Response): void => { | |
| 2048 | const timings = new Map<Database, RouteTiming>(); | |
| 2049 | const counted = ( | |
| 2050 | owner: App, | |
| 2051 | request: Request, | |
| 2052 | response: Response, | |
| 2053 | started: number, | |
| 2054 | ): void => { | |
| 2042 | 2055 | const tag = takeUsage(request); |
| 2056 | const ms = performance.now() - started; | |
| 2057 | try { | |
| 2058 | response.headers.set("server-timing", serverTiming(ms, takeDbTime(request))); | |
| 2059 | } catch { | |
| 2060 | // A response the forge is only carrying keeps the headers it came with. | |
| 2061 | } | |
| 2062 | try { | |
| 2063 | let timing = timings.get(owner.db); | |
| 2064 | if (timing === undefined) { | |
| 2065 | timing = createRouteTiming(owner.db); | |
| 2066 | timings.set(owner.db, timing); | |
| 2067 | } | |
| 2068 | timing.record(tag.pattern, ms); | |
| 2069 | } catch (error) { | |
| 2070 | owner.log.warn("could not time a request", { error: String(error) }); | |
| 2071 | } | |
| 2043 | 2072 | try { |
| 2044 | 2073 | let counter = counters.get(owner.db); |
| 2045 | 2074 | if (counter === undefined) { |
| @@ -2133,7 +2162,7 @@ export async function serve(app: App): Promise<Servers> { | ||
| 2133 | 2162 | notePeer(request, server.requestIP(request)?.address, trust); |
| 2134 | 2163 | armClose(request, () => server.timeout(request, 1)); |
| 2135 | 2164 | const response = await answered(child, request, () => http.handle(request)); |
| 2136 | counted(child, request, response); | |
| 2165 | counted(child, request, response, started); | |
| 2137 | 2166 | logged(key, request, response, started); |
| 2138 | 2167 | await settleBody(request); |
| 2139 | 2168 | if (!mustClose(request)) return response; |
| @@ -2152,7 +2181,7 @@ export async function serve(app: App): Promise<Servers> { | ||
| 2152 | 2181 | const response = await answered(app, request, () => |
| 2153 | 2182 | answer(app, router, apiRouter, limiter, request), |
| 2154 | 2183 | ); |
| 2155 | counted(app, request, response); | |
| 2184 | counted(app, request, response, started); | |
| 2156 | 2185 | logged(app.config.dataDir, request, response, started); |
| 2157 | 2186 | await settleBody(request); |
| 2158 | 2187 | if (!mustClose(request)) return response; |
| @@ -2229,6 +2258,14 @@ export async function serve(app: App): Promise<Servers> { | ||
| 2229 | 2258 | } |
| 2230 | 2259 | } |
| 2231 | 2260 | counters.clear(); |
| 2261 | for (const timing of timings.values()) { | |
| 2262 | try { | |
| 2263 | timing.stop(); | |
| 2264 | } catch (error) { | |
| 2265 | app.log.warn("could not flush route timings", { error: String(error) }); | |
| 2266 | } | |
| 2267 | } | |
| 2268 | timings.clear(); | |
| 2232 | 2269 | for (const http of childHttps.values()) http.close(); |
| 2233 | 2270 | childHttps.clear(); |
| 2234 | 2271 | closeHostedChildren(app); |
| @@ -2275,7 +2312,9 @@ async function answerGet( | ||
| 2275 | 2312 | const url = publicUrl(request, app.config.url); |
| 2276 | 2313 | if (url.pathname === "/healthz") { |
| 2277 | 2314 | noteUsage(request, { pattern: "/healthz", role: "anon" }); |
| 2315 | const dbStart = performance.now(); | |
| 2278 | 2316 | const live = liveResponse(() => app.db.query("select 1").get(), app.log); |
| 2317 | noteDbTime(request, performance.now() - dbStart); | |
| 2279 | 2318 | // A smoke test learns which release answered, old pod or new. |
| 2280 | 2319 | live.headers.set("X-Forge-Version", running().version); |
| 2281 | 2320 | return live; |
test/route-timing.test.ts added +90
| @@ -0,0 +1,90 @@ | ||
| 1 | /** Every response carries Server-Timing, and each route's time is a histogram (#2710). */ | |
| 2 | ||
| 3 | import { afterAll, beforeAll, expect, test } from "bun:test"; | |
| 4 | import { Database } from "bun:sqlite"; | |
| 5 | import { mkdtemp, rm } from "node:fs/promises"; | |
| 6 | import { tmpdir } from "node:os"; | |
| 7 | import { join } from "node:path"; | |
| 8 | import { createApp, type App } from "../src/app.ts"; | |
| 9 | import { | |
| 10 | bucketOf, | |
| 11 | createRouteTiming, | |
| 12 | KEEP_DAYS, | |
| 13 | readTiming, | |
| 14 | serverTiming, | |
| 15 | } from "../src/core/route_timing.ts"; | |
| 16 | import { serve } from "../src/http/server.ts"; | |
| 17 | import { migrate } from "../src/kernel/migrate.ts"; | |
| 18 | import { migrationFiles } from "../src/core/schema.ts"; | |
| 19 | ||
| 20 | let dataDir: string; | |
| 21 | let app: App; | |
| 22 | ||
| 23 | beforeAll(async () => { | |
| 24 | dataDir = await mkdtemp(join(tmpdir(), "forge-timing-")); | |
| 25 | app = createApp({ dataDir, port: 0 }); | |
| 26 | }); | |
| 27 | ||
| 28 | afterAll(async () => { | |
| 29 | app.close(); | |
| 30 | await rm(dataDir, { recursive: true, force: true }); | |
| 31 | }); | |
| 32 | ||
| 33 | test("a response carries Server-Timing, and /alice/x and /bob/y share one route bucket", async () => { | |
| 34 | const servers = await serve(app); | |
| 35 | const a = await fetch(`${servers.url}/alice/x`); | |
| 36 | await fetch(`${servers.url}/bob/y`); | |
| 37 | const health = await fetch(`${servers.url}/healthz`); | |
| 38 | expect(a.headers.get("server-timing")).toMatch(/^app;dur=\d+\.\d$/); | |
| 39 | expect(health.headers.get("server-timing")).toMatch(/^db;dur=\d+\.\d, app;dur=\d+\.\d$/); | |
| 40 | servers.stop(); | |
| 41 | ||
| 42 | const rows = readTiming(app.db, ""); | |
| 43 | const patterns = new Set(rows.map((r) => r.pattern)); | |
| 44 | expect([...patterns].some((p) => p.includes("alice") || p.includes("bob"))).toBe(false); | |
| 45 | const shared = rows.filter((r) => !r.pattern.startsWith("/healthz") && r.pattern !== "(unmatched)"); | |
| 46 | const total = shared.reduce((n, r) => n + r.n, 0); | |
| 47 | expect(total).toBe(2); | |
| 48 | expect(new Set(shared.map((r) => r.pattern)).size).toBe(1); | |
| 49 | }); | |
| 50 | ||
| 51 | function freshDb(): Database { | |
| 52 | const db = new Database(":memory:"); | |
| 53 | migrate(db, migrationFiles); | |
| 54 | return db; | |
| 55 | } | |
| 56 | ||
| 57 | test("durations fall in buckets, sums add up, and a bad record is refused", () => { | |
| 58 | expect(bucketOf(0.4)).toBe(0); | |
| 59 | expect(bucketOf(3)).toBe(2); | |
| 60 | expect(bucketOf(99999)).toBe(11); | |
| 61 | const db = freshDb(); | |
| 62 | const t = createRouteTiming(db, () => Date.UTC(2026, 9, 19, 5, 30)); | |
| 63 | t.record("/:a", 0.5); | |
| 64 | t.record("/:a", 0.5); | |
| 65 | t.record("/:a", 30); | |
| 66 | expect(() => t.record("", 1)).toThrow(RangeError); | |
| 67 | expect(() => t.record("/x", NaN)).toThrow(RangeError); | |
| 68 | t.stop(); | |
| 69 | expect(readTiming(db, "")).toEqual([ | |
| 70 | { hour: "2026-10-19T05", pattern: "/:a", bucket: 0, n: 2, sum_us: 1000 }, | |
| 71 | { hour: "2026-10-19T05", pattern: "/:a", bucket: 5, n: 1, sum_us: 30000 }, | |
| 72 | ]); | |
| 73 | }); | |
| 74 | ||
| 75 | test("rows older than 30 days are pruned at flush", () => { | |
| 76 | const db = freshDb(); | |
| 77 | let at = Date.UTC(2026, 8, 1, 0); | |
| 78 | const t = createRouteTiming(db, () => at); | |
| 79 | t.record("/old", 1); | |
| 80 | t.flush(); | |
| 81 | at += (KEEP_DAYS + 1) * 86_400_000; | |
| 82 | t.record("/new", 1); | |
| 83 | t.flush(); | |
| 84 | expect(readTiming(db, "").map((r) => r.pattern)).toEqual(["/new"]); | |
| 85 | }); | |
| 86 | ||
| 87 | test("the header names db time only when known", () => { | |
| 88 | expect(serverTiming(1.234)).toBe("app;dur=1.2"); | |
| 89 | expect(serverTiming(2, 0.5)).toBe("db;dur=0.5, app;dur=2.0"); | |
| 90 | }); |
new above
offline
Low:
limb-replan,drill-phasesandrun-model-promptbelong to other pulls. Pinning them is the release agent's step (bun scripts/pin-migrations.ts, persrc/core/releases.json). It is harmless here because those migrations are already on main, but next time pin only this pull's migration, or leave the pin for the release.