Merge pull request #266 from claude/server-timing
Server-Timing: show where a request's time goes
cnbrkdmrci authored 2 parents 0f651230480c10commit 0d85d7dcaa9c65d8f45a0e36e881fdd221e72e0cBrowse files
- CI / Typecheck and bundlesuccess
- CI / Unit tests (1/2)success
- CI / Unit tests (2/2)success
- Deploy / Deploy to Cloudflaresuccess
- Deploy / Main's current tipsuccess
- 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
- Live test / Containers, registry, sandboxes, webhooks, schedules, LFS and pull requestssuccess
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 | +}); |