Public: anyone can read this; the crew can change it.
An app's Server-Timing tells the forge's own wait apart from the app's #10842
Check · Review · Land · Live done — Landed and live in production.
torque/forge:torque/10838-an-app-s-server-timing-tells-the-forge-s → main 2 commits fork 3 threads · 3 unresolved
5 files
changed +81
−5
docs/APPS.md +6 −2
| @@ -266,9 +266,13 @@ the sum of `forge-lookup`, the server finding the app by its host, | ||
| 266 | 266 | grant read), `forge-wake` (waiting for a sleeping or starting environment; 0 |
| 267 | 267 | when none), `forge-upstream` and `forge-ttfb` (the same wait, until the app's |
| 268 | 268 | headers: `fetch` reports nothing of its connection, so the socket's opening |
| 269 | is inside it), `forge-body` (reading a page whole for the pill) and | |
| 269 | is inside it), `forge-lag` (the forge's own worst event-loop lag of the last | |
| 270 | 10 s, written right after `forge-ttfb`: `forge-ttfb` is read on the forge's | |
| 271 | clock, so a loop busy with something else lands in it), `forge-body` (reading a page whole for the pill) and | |
| 270 | 272 | `forge-rewrite` (pill injection with that read, when it ran). Big `forge-wake` |
| 271 | is a cold start, big `forge-ttfb` is the app or its listener, big `forge-body` | |
| 273 | is a cold start, big `forge-ttfb` is the app or its listener — unless | |
| 274 | `forge-lag` is more than half of `forge-ttfb`, when the wait was the forge's, | |
| 275 | not the app's (`forgeWaited` in `src/perf/loop_worst.ts`) — big `forge-body` | |
| 272 | 276 | is an app slow to finish its page; if all are small, the time went before the |
| 273 | 277 | request reached the forge. The forge opens no second socket to time the |
| 274 | 278 | connect: it would take a backlog slot in the very case it is meant to find. |
docs/REFERENCE.md +4 −2
| @@ -19,8 +19,10 @@ git underneath is one click away — the switch in the top bar, or `?mode=dev` o | ||
| 19 | 19 | any URL — and it is the rest of this page. |
| 20 | 20 | |
| 21 | 21 | Slow app? Its response's `Server-Timing` keeps the app's entries and adds the |
| 22 | forge's `forge-route`, `forge-wake`, `forge-upstream` and `forge-rewrite` | |
| 23 | (milliseconds only; see `docs/APPS.md`). | |
| 22 | forge's `forge-route`, `forge-wake`, `forge-upstream`, `forge-ttfb`, | |
| 23 | `forge-lag`, `forge-body` and `forge-rewrite` (milliseconds only; see | |
| 24 | `docs/APPS.md`). When `forge-lag` is more than half of `forge-ttfb`, the wait | |
| 25 | was the forge's, not the app's. | |
| 24 | 26 | |
| 25 | 27 | A forge this one spawned (hosted) runs the apps it was given too: its `bakery` |
| 26 | 28 | answers at `bakery--<child>--<this forge's host>`, in this forge's lanes, on the |
src/apps/proxy.ts +8 −1
| @@ -65,6 +65,7 @@ import { notFound, securityFloor } from "../http/respond.ts"; | ||
| 65 | 65 | import { appMeasure } from "./measure.ts"; |
| 66 | 66 | import { holdPortRequest, holdPortSocket } from "./handoff.ts"; |
| 67 | 67 | import { secureFor } from "../http/cookie_secure.ts"; |
| 68 | import { currentLoopLag } from "../perf/loop_worst.ts"; | |
| 68 | 69 | import { cspNonce, htmlAnswer, readPage, rewritable, TOOLBAR_ASSET_PATH, TOOLBAR_ASSET_PREFIX, toolbarResponse, withToolbar, type PillWhere } from "./toolbar.ts"; |
| 69 | 70 | |
| 70 | 71 | const proxySecure = (request: Request, url: URL, forgeUrl: string): boolean => |
| @@ -441,7 +442,7 @@ function withPhases(request: Request, res: Response): Response { | ||
| 441 | 442 | */ |
| 442 | 443 | type RelayPhase = |
| 443 | 444 | | "route" | "lookup" | "state" | "session" | "wake" |
| 444 | | "upstream" | "ttfb" | "body" | "rewrite"; | |
| 445 | | "upstream" | "ttfb" | "lag" | "body" | "rewrite"; | |
| 445 | 446 | |
| 446 | 447 | /** Name one of the forge's phases of relaying an app answer. Durations only. */ |
| 447 | 448 | function relayPhase(request: Request, name: RelayPhase, ms: number): void { |
| @@ -452,9 +453,15 @@ function relayPhase(request: Request, name: RelayPhase, ms: number): void { | ||
| 452 | 453 | * Name `ttfb` and `upstream` for headers that took `headersMs`. `fetch` says |
| 453 | 454 | * nothing of its connection, so the two are the same wait: `ttfb` is the name |
| 454 | 455 | * the split reads by, `upstream` the total older readers know. |
| 456 | * | |
| 457 | * Beside them, `forge-lag` (#10838): the forge's worst event-loop lag of the | |
| 458 | * last 10 s (`perf/loop_worst.ts`). `forge-ttfb` is read on the forge's clock, | |
| 459 | * so a loop blocked by something else lands in it while the app sat idle; | |
| 460 | * `forgeWaited` (the one place the rule lives) says when the wait was the forge's. | |
| 455 | 461 | */ |
| 456 | 462 | function relayUpstream(request: Request, headersMs: number): void { |
| 457 | 463 | relayPhase(request, "ttfb", headersMs); |
| 464 | relayPhase(request, "lag", currentLoopLag()); | |
| 458 | 465 | relayPhase(request, "upstream", headersMs); |
| 459 | 466 | } |
| 460 | 467 |
src/perf/loop_worst.ts +12
| @@ -98,3 +98,15 @@ export function stopLoopWorst(): void { | ||
| 98 | 98 | export function currentLoopLag(): number { |
| 99 | 99 | return loopWorst.worst(windowClock()); |
| 100 | 100 | } |
| 101 | ||
| 102 | /** | |
Non-blocking: |
||
| 103 | * Was a relayed request's wait the forge's, not the app's (#10838)? True when | |
| 104 | * the forge's worst loop lag (`forge-lag`) is more than half of the time to | |
| 105 | * the app's headers (`forge-ttfb`): most of that wait was the forge's loop | |
| 106 | * busy elsewhere, so the app must not be called slow. A non-finite or | |
| 107 | * negative reading, or a zero wait, never blames the forge. | |
| 108 | */ | |
| 109 | export function forgeWaited(lagMs: number, ttfbMs: number): boolean { | |
| 110 | if (!Number.isFinite(lagMs) || !Number.isFinite(ttfbMs) || lagMs < 0 || ttfbMs <= 0) return false; | |
| 111 | return lagMs > ttfbMs / 2; | |
| 112 | } |
test/apps-proxy-timing.test.ts +51
| @@ -14,6 +14,7 @@ import type { Repo } from "../src/core/repos.ts"; | ||
| 14 | 14 | import { createUser, type User } from "../src/core/users.ts"; |
| 15 | 15 | import { serve, type Servers } from "../src/http/server.ts"; |
| 16 | 16 | import { deploySettled } from "./helpers/apps-forge.ts"; |
| 17 | import { forgeWaited, startLoopWorst, stopLoopWorst } from "../src/perf/loop_worst.ts"; | |
| 17 | 18 | |
| 18 | 19 | const DOMAIN = "apps.test"; |
| 19 | 20 | // node:http, not Bun.serve: Bun drops a streamed Response's content-length, |
| @@ -134,6 +135,36 @@ describe("a proxied answer's Server-Timing", () => { | ||
| 134 | 135 | expect(header).toMatch(/^[a-z0-9.;=, -]+$/); |
| 135 | 136 | }); |
| 136 | 137 | |
| 138 | test("forge-lag names the forge's own loop lag beside forge-ttfb, well-formed", async () => { | |
| 139 | const res = await viaHost("/ttfb"); | |
| 140 | expect(res.status).toBe(200); | |
| 141 | const header = res.headers.get("server-timing")!; | |
| 142 | // Exactly one, a duration with one decimal, right after forge-ttfb. | |
| 143 | expect(header.match(/(?:^|, )forge-lag;/g)?.length).toBe(1); | |
| 144 | expect(header).toMatch(/(?:^|, )forge-ttfb;dur=[0-9]+\.[0-9], forge-lag;dur=[0-9]+\.[0-9](?:,|$)/); | |
| 145 | expect(dur(header, "forge-lag")!).toBeGreaterThanOrEqual(0); | |
| 146 | }); | |
outdated
This relies on the loop-lag sampler already running in this suite. Start it explicitly (startLoopWorst/stopLoopWorst) so the test cannot flake under |
||
| 147 | ||
| 148 | test("a blocked forge loop shows in forge-lag, so the app is not blamed", async () => { | |
| 149 | // The sampler started here, not by whoever ran first: the test cannot depend on it. | |
| 150 | stopLoopWorst(); | |
| 151 | startLoopWorst({ everyMs: 5 }); | |
| 152 | try { | |
| 153 | await Bun.sleep(20); | |
| 154 | // Block the forge's loop for 250 ms; the sampler names it in the 10 s window. | |
| 155 | const until = performance.now() + 250; | |
| 156 | while (performance.now() < until) {} | |
| 157 | await Bun.sleep(30); | |
| 158 | const header = (await viaHost("/ttfb")).headers.get("server-timing")!; | |
| 159 | expect(dur(header, "forge-lag")!).toBeGreaterThanOrEqual(200); | |
| 160 | // /ttfb answers in ~30 ms: the lag is more than half of it, so the wait was the forge's. | |
| 161 | expect(forgeWaited(dur(header, "forge-lag")!, dur(header, "forge-ttfb")!)).toBe(true); | |
| 162 | } finally { | |
| 163 | stopLoopWorst(); | |
| 164 | startLoopWorst(); | |
| 165 | } | |
| 166 | }); | |
| 167 | ||
| 137 | 168 | test("forge-route splits into forge-lookup, forge-state and forge-session", async () => { |
| 138 | 169 | const header = (await viaHost("/healthz")).headers.get("server-timing")!; |
| 139 | 170 | const parts = ["forge-lookup", "forge-state", "forge-session"].map((name) => dur(header, name)); |
| @@ -256,3 +287,23 @@ describe("a proxied answer's Server-Timing", () => { | ||
| 256 | 287 | } |
| 257 | 288 | }); |
| 258 | 289 | }); |
| 290 | ||
| 291 | describe("forgeWaited: the forge's lag explains the wait when it is more than half of forge-ttfb", () => { | |
| 292 | test("the issue's own readings: 1490.7 ms ttfb with the app at 3.6 ms", () => { | |
| 293 | expect(forgeWaited(1400, 1490.7)).toBe(true); // 1400 > 745.35 | |
| 294 | expect(forgeWaited(700, 1490.7)).toBe(false); // 700 < 745.35: the app's to explain | |
| 295 | }); | |
| 296 | ||
| 297 | test("exactly half is not more than half", () => { | |
| 298 | expect(forgeWaited(50, 100)).toBe(false); | |
| 299 | expect(forgeWaited(50.1, 100)).toBe(true); | |
| 300 | expect(forgeWaited(0, 43.8)).toBe(false); | |
| 301 | }); | |
| 302 | ||
| 303 | test("a reading that is not a duration never blames the forge", () => { | |
| 304 | expect(forgeWaited(10, 0)).toBe(false); | |
| 305 | expect(forgeWaited(-1, 10)).toBe(false); | |
| 306 | expect(forgeWaited(Number.NaN, 10)).toBe(false); | |
| 307 | expect(forgeWaited(10, Number.POSITIVE_INFINITY)).toBe(false); | |
| 308 | }); | |
| 309 | }); |
Keep the "more than half" rule as one named function with a test (box 2), not only in the comment above.