Server-Timing: show where a request's time goes
Signed-in answers that aren't errors now carry a Server-Timing header with the request's total time, its D1 queries and its Durable Object calls (count and summed time), and the Cloudflare location that served it. It shows up in browsers' developer tools and in curl, so slow pages can be measured on the live site before and after a fix. Errors get none, so the header can't tell a private repository from a missing one. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012y8bkPkN4zSgEJouMu1LFS
- CI / Typecheck and bundlesuccess
- CI / Unit tests (1/2)success
- CI / Unit tests (2/2)success
- End-to-end / End-to-end (agent reviews, tasks, Today)success
- End-to-end / End-to-end (git, PRs, Actions)success
- End-to-end / End-to-end (large pushes)success
- End-to-end / End-to-end (passkeys, registry, email)success
- End-to-end / End-to-end (real histories)success
- End-to-end / End-to-end (runner Docker)success
- End-to-end / End-to-end (security)success
4 files changed+163−2
Files (4)
modifiedapps/diffinery/docs/reference/rest-api.md+1−1View file
| @@ -291,7 +291,7 @@ | ||
| 291 | 291 | | `GET /repos/{owner}/{repo}/actions/jobs/{id}/logs` | `text/plain`, one line per log line prefixed with its timestamp. Add `?format=json` for an array of `{t, step, text}` objects. | |
| 292 | 292 | | `DELETE` endpoints and some `PUT` endpoints | No body (`204`) | |
| 293 | 293 | |
| 294 | -Every response also carries security headers (`Strict-Transport-Security`, `X-Content-Type-Options: nosniff`, `X-Frame-Options: DENY`, `Referrer-Policy`, `Permissions-Policy`) and, whenever the request read or wrote account-level data, the `x-d1-bookmark` header described above. Downloads (raw files, archives and release assets) are sent with `Content-Security-Policy: sandbox` and as attachments, so browsers never run them as pages. | |
| 294 | +Every response also carries security headers (`Strict-Transport-Security`, `X-Content-Type-Options: nosniff`, `X-Frame-Options: DENY`, `Referrer-Policy`, `Permissions-Policy`) and, whenever the request read or wrote account-level data, the `x-d1-bookmark` header described above. Answers to signed-in people and tokens that aren't errors also carry a `Server-Timing` header, which browsers' developer tools show under Timing: the whole request (`total`), the database queries it made (`d1`, with their count) and the calls to the repository's storage (`do`, with their count), in milliseconds, and the Cloudflare location that answered (`colo`). Parallel calls overlap, so their times can add up to more than the total. Downloads (raw files, archives and release assets) are sent with `Content-Security-Policy: sandbox` and as attachments, so browsers never run them as pages. | |
| 295 | 295 | |
| 296 | 296 | ## Errors |
| 297 | 297 |
modifiedapps/diffinery/src/app.ts+5−1View file
| @@ -46,6 +46,7 @@ | ||
| 46 | 46 | import { CliLogins } from "./auth/cli-login.js"; |
| 47 | 47 | import { OAUTH_API_PATH, oauthApi } from "./http/oauth.js"; |
| 48 | 48 | import { OAuth } from "./auth/oauth.js"; |
| 49 | +import { Timing, timedEnv } from "./lib/timing.js"; | |
| 49 | 50 | |
| 50 | 51 | export const app = new Hono<{ Bindings: Env; Variables: AppVars }>(); |
| 51 | 52 | |
| @@ -77,7 +78,8 @@ | ||
| 77 | 78 | const token = !oauthCall && !!credentialFrom(c.req.raw); |
| 78 | 79 | const cookie = getCookie(c, BOOKMARK_COOKIE); |
| 79 | 80 | const d1 = d1Session(c.env, sessionConstraint({ header: c.req.header(BOOKMARK_HEADER), cookie, token })); |
| 80 | - c.env = d1.env; | |
| 81 | + const timing = new Timing(); | |
| 82 | + c.env = timedEnv(d1.env, timing); | |
| 81 | 83 | const dir = new Directory(c.env); |
| 82 | 84 | c.set("dir", dir); |
| 83 | 85 | // The Actions runtime services authenticate with their own signed tokens and URLs (http/actions-runtime.ts). |
| @@ -102,6 +104,8 @@ | ||
| 102 | 104 | h.set("referrer-policy", "strict-origin-when-cross-origin"); |
| 103 | 105 | if (!h.has("x-frame-options")) h.set("x-frame-options", "DENY"); |
| 104 | 106 | h.set("permissions-policy", "camera=(), microphone=(), geolocation=()"); |
| 107 | + // Where the time went, for signed-in people's developer tools (lib/timing.ts). | |
| 108 | + if (c.get("principal").type === "account" && c.res.status < 400 && !h.has("server-timing")) h.set("server-timing", timing.header((c.req.raw.cf as { colo?: string } | undefined)?.colo)); | |
| 105 | 109 | }); |
| 106 | 110 | |
| 107 | 111 | app.get("/healthz", (c) => c.json({ ok: true })); |
addedapps/diffinery/src/lib/timing.ts+99−0View file
| @@ -1,0 +1,99 @@ | ||
| 1 | +import type { Env } from "../env.js"; | |
| 2 | + | |
| 3 | +/** | |
| 4 | + * Where a request's time goes, for the `Server-Timing` header that browsers' developer tools | |
| 5 | + * show: D1 queries and Durable Object calls, each counted and summed (parallel calls overlap, so | |
| 6 | + * a sum can pass the total), and the whole request. Signed-in callers get it on answers that | |
| 7 | + * aren't errors (app.ts): an error could tell a private repository from a missing one by how | |
| 8 | + * many lookups it took. | |
| 9 | + */ | |
| 10 | +export class Timing { | |
| 11 | + private readonly start = Date.now(); | |
| 12 | + private readonly spans = new Map<string, { n: number; ms: number }>(); | |
| 13 | + | |
| 14 | + /** Times `p` under `kind` and hands it back unchanged. */ | |
| 15 | + track<T>(kind: string, p: T): T { | |
| 16 | + if (!(p && typeof (p as { then?: unknown }).then === "function")) return p; | |
| 17 | + const t0 = Date.now(); | |
| 18 | + const done = () => { | |
| 19 | + const s = this.spans.get(kind) ?? { n: 0, ms: 0 }; | |
| 20 | + s.n++; | |
| 21 | + s.ms += Date.now() - t0; | |
| 22 | + this.spans.set(kind, s); | |
| 23 | + }; | |
| 24 | + (p as unknown as PromiseLike<unknown>).then(done, done); | |
| 25 | + return p; | |
| 26 | + } | |
| 27 | + | |
| 28 | + header(colo?: string): string { | |
| 29 | + const out = [`total;dur=${Date.now() - this.start}`]; | |
| 30 | + for (const [kind, s] of this.spans) out.push(`${kind};dur=${s.ms};desc="${s.n} ${kind === "d1" ? "quer" + (s.n === 1 ? "y" : "ies") : "call" + (s.n === 1 ? "" : "s")}"`); | |
| 31 | + if (colo && /^[A-Z]{3}$/.test(colo)) out.push(`colo;desc="${colo}"`); | |
| 32 | + return out.join(", "); | |
| 33 | + } | |
| 34 | +} | |
| 35 | + | |
| 36 | +const STATEMENT_RUNS = ["first", "all", "run", "raw"] as const; | |
| 37 | + | |
| 38 | +/** A D1 statement whose runs are timed. The statement itself stays the real one, so `batch` still takes it. */ | |
| 39 | +function timedStatement(t: Timing, s: D1PreparedStatement): D1PreparedStatement { | |
| 40 | + const st = s as unknown as Record<string, (...a: unknown[]) => unknown>; | |
| 41 | + try { | |
| 42 | + for (const m of STATEMENT_RUNS) { | |
| 43 | + const run = st[m]; | |
| 44 | + if (typeof run === "function") st[m] = (...a: unknown[]) => t.track("d1", run.apply(s, a)); | |
| 45 | + } | |
| 46 | + const bind = st.bind; | |
| 47 | + if (typeof bind === "function") st.bind = (...a: unknown[]) => timedStatement(t, bind.apply(s, a) as D1PreparedStatement); | |
| 48 | + } catch { | |
| 49 | + // A statement that can't take own methods runs untimed. | |
| 50 | + } | |
| 51 | + return s; | |
| 52 | +} | |
| 53 | + | |
| 54 | +function timedDb(t: Timing, db: D1Database): D1Database { | |
| 55 | + return new Proxy(db, { | |
| 56 | + get(target, prop) { | |
| 57 | + const v = Reflect.get(target, prop, target) as unknown; | |
| 58 | + if (typeof v !== "function") return v; | |
| 59 | + if (prop === "prepare") return (q: string) => timedStatement(t, (v as (q: string) => D1PreparedStatement).call(target, q)); | |
| 60 | + if (prop === "batch" || prop === "exec") return (...a: unknown[]) => t.track("d1", (v as (...a: unknown[]) => unknown).apply(target, a)); | |
| 61 | + return (v as (...a: unknown[]) => unknown).bind(target); | |
| 62 | + }, | |
| 63 | + }); | |
| 64 | +} | |
| 65 | + | |
| 66 | +/** Stub members that aren't calls to the object (or must stay as they are). */ | |
| 67 | +const NOT_CALLS = new Set<PropertyKey>(["then", "catch", "finally", "dup", "id", "name", "connect"]); | |
| 68 | + | |
| 69 | +function timedStub<S extends object>(t: Timing, stub: S): S { | |
| 70 | + return new Proxy(stub, { | |
| 71 | + get(target, prop) { | |
| 72 | + const v = Reflect.get(target, prop, target) as unknown; | |
| 73 | + if (typeof v !== "function" || typeof prop === "symbol" || NOT_CALLS.has(prop)) return v; | |
| 74 | + // Reflect.apply: the stub's members are RPC proxies, whose own `apply` would be a call to the object. | |
| 75 | + return (...a: unknown[]) => t.track("do", Reflect.apply(v as (...a: unknown[]) => unknown, target, a)); | |
| 76 | + }, | |
| 77 | + }); | |
| 78 | +} | |
| 79 | + | |
| 80 | +function timedNamespace<N extends object>(t: Timing, ns: N): N { | |
| 81 | + return new Proxy(ns, { | |
| 82 | + get(target, prop) { | |
| 83 | + const v = Reflect.get(target, prop, target) as unknown; | |
| 84 | + if (typeof v !== "function") return v; | |
| 85 | + const f = (v as (...a: unknown[]) => unknown).bind(target); | |
| 86 | + return prop === "get" || prop === "getByName" ? (...a: unknown[]) => timedStub(t, f(...a) as object) : f; | |
| 87 | + }, | |
| 88 | + }); | |
| 89 | +} | |
| 90 | + | |
| 91 | +/** `env` with its D1 database and the repository and agent-task Durable Objects timed into `t`. */ | |
| 92 | +export function timedEnv(env: Env, t: Timing): Env { | |
| 93 | + return { | |
| 94 | + ...env, | |
| 95 | + DB: env.DB ? timedDb(t, env.DB) : env.DB, | |
| 96 | + REPO: env.REPO ? timedNamespace(t, env.REPO) : env.REPO, | |
| 97 | + PROJECT: env.PROJECT ? timedNamespace(t, env.PROJECT) : env.PROJECT, | |
| 98 | + }; | |
| 99 | +} |
addedapps/diffinery/test/unit/timing.test.ts+58−0View file
| @@ -1,0 +1,58 @@ | ||
| 1 | +import { describe, expect, it } from "vitest"; | |
| 2 | +import { Timing, timedEnv } from "../../src/lib/timing.js"; | |
| 3 | +import type { Env } from "../../src/env.js"; | |
| 4 | + | |
| 5 | +class Statement { | |
| 6 | + constructor(readonly sql: string, readonly params: unknown[] = []) {} | |
| 7 | + bind(...params: unknown[]) { | |
| 8 | + return new Statement(this.sql, params); | |
| 9 | + } | |
| 10 | + async first() { | |
| 11 | + return { sql: this.sql, params: this.params }; | |
| 12 | + } | |
| 13 | + async all() { | |
| 14 | + return { results: [] }; | |
| 15 | + } | |
| 16 | +} | |
| 17 | + | |
| 18 | +const fakeDb = (batched: unknown[][]) => ({ | |
| 19 | + prepare: (q: string) => new Statement(q), | |
| 20 | + batch: async (s: Statement[]) => (batched.push(s), s.map(() => ({ results: [] }))), | |
| 21 | +}); | |
| 22 | + | |
| 23 | +const fakeNamespace = () => ({ | |
| 24 | + idFromName: (n: string) => ({ name: n }), | |
| 25 | + get: (id: { name: string }) => ({ id, name: id.name, info: async (x: number) => x * 2, fetch: async () => new Response("ok") }), | |
| 26 | +}); | |
| 27 | + | |
| 28 | +describe("Server-Timing", () => { | |
| 29 | + it("counts D1 queries and Durable Object calls without changing their results", async () => { | |
| 30 | + const t = new Timing(); | |
| 31 | + const batched: unknown[][] = []; | |
| 32 | + const env = timedEnv({ DB: fakeDb(batched), REPO: fakeNamespace() } as unknown as Env, t); | |
| 33 | + const row = await env.DB.prepare("SELECT ?").bind(1).first(); | |
| 34 | + expect(row).toEqual({ sql: "SELECT ?", params: [1] }); | |
| 35 | + await env.DB.prepare("SELECT 2").all(); | |
| 36 | + // Batches still get the real statements. | |
| 37 | + const s = env.DB.prepare("SELECT 3"); | |
| 38 | + await env.DB.batch([s]); | |
| 39 | + expect(batched[0]![0]).toBeInstanceOf(Statement); | |
| 40 | + const stub = env.REPO.get(env.REPO.idFromName("r")) as unknown as { name: string; info(x: number): Promise<number>; fetch(): Promise<Response> }; | |
| 41 | + expect(stub.name).toBe("r"); | |
| 42 | + expect(await stub.info(21)).toBe(42); | |
| 43 | + expect(await (await stub.fetch()).text()).toBe("ok"); | |
| 44 | + await Promise.resolve(); | |
| 45 | + const h = t.header("IST"); | |
| 46 | + expect(h).toMatch(/^total;dur=\d+, /); | |
| 47 | + expect(h).toContain('d1;dur=0;desc="3 queries"'); | |
| 48 | + expect(h).toContain('do;dur=0;desc="2 calls"'); | |
| 49 | + expect(h).toContain('colo;desc="IST"'); | |
| 50 | + expect(t.header("not a colo")).not.toContain("colo"); | |
| 51 | + }); | |
| 52 | + | |
| 53 | + it("leaves missing bindings alone", () => { | |
| 54 | + const env = timedEnv({} as Env, new Timing()); | |
| 55 | + expect(env.DB).toBeUndefined(); | |
| 56 | + expect(env.REPO).toBeUndefined(); | |
| 57 | + }); | |
| 58 | +}); |