Public: anyone can read this; the crew can change it.
A proxied page's Server-Timing says where forge-upstream went: connect, first byte and body #8281
Check · Review · Land · Live done — Landed and live in production.
torque/forge:torque/8270-a-proxied-page-s-server-timing-says-wher → main 2 commits fork 4 threads · 4 unresolved
3 files
changed +112
−25
docs/APPS.md +17 −10
| @@ -256,16 +256,23 @@ Server-Timing phase. The prefix was already the forge's, so an app's own | ||
| 256 | 256 | |
| 257 | 257 | **Reading a slow app's Server-Timing.** A response the proxy relays keeps the |
| 258 | 258 | app's own entries (`db`, `app`, …) and gains the forge's, each `forge-` named |
| 259 | and in milliseconds only: `forge-route` (finding the target and its grant), | |
| 260 | `forge-wake` (waiting for a sleeping or starting environment; 0 when none), | |
| 261 | `forge-upstream` (until the app's headers) and `forge-rewrite` (pill injection, | |
| 262 | when it ran). Big `forge-wake` is a cold start, big `forge-upstream` is the | |
| 263 | app; if all are small, the time went before the request reached the forge. The | |
| 264 | "app stopped answering" page carries `route`, `wake` and `upstream` too; the | |
| 265 | forge's own `/__forge/*` pages and the WebSocket upgrade name no forge- phases. | |
| 266 | A refused answer (sign in, not found, not running) names none either: the wake | |
| 267 | runs before the door is asked, so its time would tell a caller who may not read | |
| 268 | the app whether it was asleep. The proxy has one writer for these | |
| 259 | and in milliseconds only: `forge-route` (finding the target and its grant: | |
| 260 | the sum of `forge-lookup`, the server finding the app by its host, | |
| 261 | `forge-state`, the doors and the environment's state, and `forge-session`, the | |
| 262 | grant read), `forge-wake` (waiting for a sleeping or starting environment; 0 | |
| 263 | when none), `forge-upstream` and `forge-ttfb` (the same wait, until the app's | |
| 264 | headers: `fetch` reports nothing of its connection, so the socket's opening | |
| 265 | is inside it), `forge-body` (reading a page whole for the pill) and | |
| 266 | `forge-rewrite` (pill injection with that read, when it ran). Big `forge-wake` | |
| 267 | is a cold start, big `forge-ttfb` is the app or its listener, big `forge-body` | |
| 268 | is an app slow to finish its page; if all are small, the time went before the | |
| 269 | request reached the forge. The forge opens no second socket to time the | |
| 270 | connect: it would take a backlog slot in the very case it is meant to find. | |
| 271 | The "app stopped answering" page carries `route`, `wake` and `upstream` too; | |
| 272 | the forge's own `/__forge/*` pages and the WebSocket upgrade name no forge- | |
| 273 | phases. A refused answer (sign in, not found, not running) names none either: | |
| 274 | the wake runs before the door is asked, so its time would tell a caller who may | |
| 275 | not read the app whether it was asleep. The proxy has one writer for these | |
| 269 | 276 | (`withPhases` over `notePhase`), which appends to the app's header. |
| 270 | 277 | |
| 271 | 278 | **Tell the crew from the pill.** Signed in as someone who may direct the crew, |
src/apps/proxy.ts +32 −4
| @@ -406,11 +406,29 @@ function withPhases(request: Request, res: Response): Response { | ||
| 406 | 406 | return res; |
| 407 | 407 | } |
| 408 | 408 | |
| 409 | /** | |
| 410 | * The forge's phases of relaying an app answer, `forge-` named. Durations | |
| 411 | * only, under these fixed names: `route` is `lookup` + `state` + `session`. | |
| 412 | */ | |
| 413 | type RelayPhase = | |
| 414 | | "route" | "lookup" | "state" | "session" | "wake" | |
| 415 | | "upstream" | "ttfb" | "body" | "rewrite"; | |
| 416 | ||
| 409 | 417 | /** Name one of the forge's phases of relaying an app answer. Durations only. */ |
| 410 | function relayPhase(request: Request, name: "route" | "wake" | "upstream" | "rewrite", ms: number): void { | |
| 418 | function relayPhase(request: Request, name: RelayPhase, ms: number): void { | |
| 411 | 419 | notePhase(request, `forge-${name}`, ms); |
| 412 | 420 | } |
| 413 | 421 | |
| 422 | /** | |
| 423 | * Name `ttfb` and `upstream` for headers that took `headersMs`. `fetch` says | |
| 424 | * nothing of its connection, so the two are the same wait: `ttfb` is the name | |
| 425 | * the split reads by, `upstream` the total older readers know. | |
| 426 | */ | |
| 427 | function relayUpstream(request: Request, headersMs: number): void { | |
| 428 | relayPhase(request, "ttfb", headersMs); | |
| 429 | relayPhase(request, "upstream", headersMs); | |
| 430 | } | |
| 431 | ||
| 414 | 432 | /** |
| 415 | 433 | * What the pill says: the app, the environment and, for a preview, the pull |
| 416 | 434 | * and its title. The title goes only to a viewer who may read the pull. |
| @@ -815,6 +833,7 @@ export async function proxyApp( | ||
| 815 | 833 | target: AppTarget, |
| 816 | 834 | server: Bun.Server<AppSocket>, |
| 817 | 835 | ): Promise<Response | undefined> { |
| 836 | const entered = performance.now(); | |
| 818 | 837 | const url = new URL(request.url); |
| 819 | 838 | // A grant with this forge's own token is answered here. On a nested |
| 820 | 839 | // hostname a grant this forge did not sign is the guest forge's, and |
| @@ -1042,7 +1061,9 @@ export async function proxyApp( | ||
| 1042 | 1061 | await runtime.wake(target.app, target.env); |
| 1043 | 1062 | wakeMs = performance.now() - woke; |
| 1044 | 1063 | } |
| 1064 | const admitting = performance.now(); | |
| 1045 | 1065 | const admitted = admit(runtime, request, target); |
| 1066 | const sessionMs = performance.now() - admitting; | |
| 1046 | 1067 | // A refused answer names no phases: wake runs before `admit`, so its time |
| 1047 | 1068 | // would tell a caller who may not read the app whether it was asleep. |
| 1048 | 1069 | if (!admitted.ok) |
| @@ -1052,7 +1073,13 @@ export async function proxyApp( | ||
| 1052 | 1073 | const { status, port, grant: vouched } = admitted.value; |
| 1053 | 1074 | runtime.touch(target.app, target.env); |
| 1054 | 1075 | const began = performance.now(); |
| 1055 | relayPhase(request, "route", Math.max(0, began - (startedAt(request) ?? began) - wakeMs)); | |
| 1076 | // `route` split where it goes: the server finding the app (`lookup`), the | |
| 1077 | // doors and the environment's state (`state`), the grant read (`session`). | |
| 1078 | const lookupMs = Math.max(0, entered - (startedAt(request) ?? entered)); | |
| 1079 | relayPhase(request, "route", lookupMs + Math.max(0, began - entered - wakeMs)); | |
| 1080 | relayPhase(request, "lookup", lookupMs); | |
| 1081 | relayPhase(request, "state", Math.max(0, began - entered - wakeMs - sessionMs)); | |
| 1082 | relayPhase(request, "session", sessionMs); | |
| 1056 | 1083 | relayPhase(request, "wake", wakeMs); |
| 1057 | 1084 | |
| 1058 | 1085 | const upstream = new URL(url); |
| @@ -1120,10 +1147,10 @@ export async function proxyApp( | ||
| 1120 | 1147 | } as RequestInit); |
| 1121 | 1148 | } catch { |
| 1122 | 1149 | answered(); |
| 1123 | relayPhase(request, "upstream", performance.now() - sent); | |
| 1150 | relayUpstream(request, performance.now() - sent); | |
| 1124 | 1151 | return withPhases(request, unavailable(runtime, target, status, "the app stopped answering")); |
| 1125 | 1152 | } |
| 1126 | relayPhase(request, "upstream", performance.now() - sent); | |
| 1153 | relayUpstream(request, performance.now() - sent); | |
| 1127 | 1154 | const out = new Headers(response.headers); |
| 1128 | 1155 | for (const name of HOP_BY_HOP) out.delete(name); |
| 1129 | 1156 | // Which app answered: a probe from outside (`spawn/reach.ts`) tells this |
| @@ -1174,6 +1201,7 @@ export async function proxyApp( | ||
| 1174 | 1201 | ); |
| 1175 | 1202 | bytes = read.bytes; |
| 1176 | 1203 | } |
| 1204 | relayPhase(request, "body", performance.now() - rewriting); | |
| 1177 | 1205 | } catch { |
| 1178 | 1206 | return withPhases(request, unavailable(runtime, target, status, "the app stopped answering")); |
| 1179 | 1207 | } |
test/apps-proxy-timing.test.ts +63 −11
| @@ -16,17 +16,33 @@ import { serve, type Servers } from "../src/http/server.ts"; | ||
| 16 | 16 | import { deploySettled } from "./helpers/apps-forge.ts"; |
| 17 | 17 | |
| 18 | 18 | const DOMAIN = "apps.test"; |
| 19 | const SLOW = `const server = Bun.serve({ | |
| 20 | port: Number(process.env.PORT), | |
| 21 | hostname: "127.0.0.1", | |
| 22 | async fetch(request) { | |
| 23 | if (new URL(request.url).pathname === "/healthz") { | |
| 24 | await Bun.sleep(300); | |
| 25 | return new Response("ok", { headers: { "server-timing": "db;dur=0.1, app;dur=1.1" } }); | |
| 26 | } | |
| 27 | return new Response("<html><body><h1>hello</h1></body></html>", { headers: { "content-type": "text/html" } }); | |
| 28 | }, | |
| 29 | }); | |
| 19 | // node:http, not Bun.serve: Bun drops a streamed Response's content-length, | |
| 20 | // and /slowbody needs one so the forge reads the page whole however slow. | |
| 21 | const SLOW = `import { createServer } from "node:http"; | |
| 22 | createServer((request, res) => { | |
| 23 | const path = new URL(request.url, "http://app").pathname; | |
| 24 | if (path === "/healthz") { | |
| 25 | setTimeout(() => { | |
| 26 | res.writeHead(200, { "server-timing": "db;dur=0.1, app;dur=1.1" }); | |
| 27 | res.end("ok"); | |
| 28 | }, 300); | |
| 29 | } else if (path === "/ttfb") { | |
| 30 | setTimeout(() => { | |
| 31 | res.writeHead(200, { "content-type": "text/plain" }); | |
| 32 | res.end("late"); | |
| 33 | }, 30); | |
| 34 | } else if (path === "/slowbody") { | |
| 35 | // Headers at once, the page's end 300 ms later: the wait is the body's. | |
| 36 | const head = "<html><body><h1>slow"; | |
| 37 | const tail = " body</h1></body></html>"; | |
| 38 | res.writeHead(200, { "content-type": "text/html", "content-length": String(head.length + tail.length) }); | |
| 39 | res.write(head); | |
| 40 | setTimeout(() => res.end(tail), 300); | |
| 41 | } else { | |
| 42 | res.writeHead(200, { "content-type": "text/html" }); | |
| 43 | res.end("<html><body><h1>hello</h1></body></html>"); | |
| 44 | } | |
| 45 | }).listen(Number(process.env.PORT), "127.0.0.1"); | |
| 30 | 46 | `; |
| 31 | 47 | |
| 32 | 48 | const dur = (header: string, name: string): number | undefined => { |
| @@ -106,6 +122,42 @@ describe("a proxied answer's Server-Timing", () => { | ||
| 106 | 122 | expect(header).not.toContain("hello"); |
| 107 | 123 | }); |
| 108 | 124 | |
| 125 | test("an app slow to its headers shows in forge-ttfb, which is forge-upstream", async () => { | |
| 126 | const res = await viaHost("/ttfb"); | |
| 127 | expect(res.status).toBe(200); | |
| 128 | expect(await res.text()).toBe("late"); | |
| 129 | const header = res.headers.get("server-timing")!; | |
| 130 | expect(dur(header, "forge-ttfb")!).toBeGreaterThanOrEqual(30); | |
| 131 | expect(dur(header, "forge-ttfb")).toBe(dur(header, "forge-upstream")!); | |
| 132 | // No probe socket: the connect is inside ttfb, never named apart. | |
| 133 | expect(dur(header, "forge-connect")).toBeUndefined(); | |
| 134 | expect(header).toMatch(/^[a-z0-9.;=, -]+$/); | |
| 135 | }); | |
| 136 | ||
| 137 | test("forge-route splits into forge-lookup, forge-state and forge-session", async () => { | |
| 138 | const header = (await viaHost("/healthz")).headers.get("server-timing")!; | |
| 139 | const parts = ["forge-lookup", "forge-state", "forge-session"].map((name) => dur(header, name)); | |
| 140 | for (const ms of parts) expect(ms).toBeGreaterThanOrEqual(0); | |
| 141 | const sum = parts.reduce((a, b) => a! + b!, 0)!; | |
| 142 | expect(Math.abs(sum - dur(header, "forge-route")!)).toBeLessThanOrEqual(0.2); | |
| 143 | }); | |
| 144 | ||
| 145 | test("a page read whole for the pill names the wait for its body, forge-body", async () => { | |
| 146 | const header = (await viaHost("/")).headers.get("server-timing")!; | |
| 147 | expect(dur(header, "forge-body")).toBeGreaterThanOrEqual(0); | |
| 148 | expect(dur(header, "forge-body")!).toBeLessThanOrEqual(dur(header, "forge-rewrite")!); | |
| 149 | }); | |
| 150 | ||
| 151 | test("a page whose body comes late puts the wait in forge-body, not forge-ttfb", async () => { | |
| 152 | const res = await viaHost("/slowbody"); | |
| 153 | expect(res.status).toBe(200); | |
| 154 | expect(await res.text()).toContain("slow body"); | |
| 155 | const header = res.headers.get("server-timing")!; | |
| 156 | expect(dur(header, "forge-body")!).toBeGreaterThanOrEqual(250); | |
| 157 | expect(dur(header, "forge-ttfb")!).toBeLessThan(dur(header, "forge-body")!); | |
| 158 | expect(dur(header, "forge-upstream")!).toBeLessThan(dur(header, "forge-body")!); | |
| 159 | }); | |
| 160 | ||
| 109 | 161 | test("a page the pill is written into names forge-rewrite", async () => { |
| 110 | 162 | const res = await viaHost("/"); |
| 111 | 163 | const header = res.headers.get("server-timing")!; |
new above
offline
Fixed 5 ms and 50 ms sleeps can flake on a loaded runner. Poll against a deadline for both the opened and the not-opened cases.