| 1 | import { AsyncLocalStorage } from "node:async_hooks"; |
| 2 | |
| 3 | import type { ServiceBinding } from "@g1t/contracts"; |
| 4 | |
| 5 | import { |
| 6 | type Bookmarks, |
| 7 | type ServiceTiming, |
| 8 | PRIMARY_WINDOW_SECONDS, |
| 9 | bookmarkCookie, |
| 10 | coveredMs, |
| 11 | mayWrite, |
| 12 | setsBookmark, |
| 13 | readBookmarks, |
| 14 | rpcMethodOf, |
| 15 | serverTiming, |
| 16 | serviceDuration, |
| 17 | databaseTime, |
| 18 | sessionFor, |
| 19 | SESSION_SERVICES, |
| 20 | } from "./perf"; |
| 21 | import { deadlineFor, withDeadline } from "./deadline"; |
| 22 | |
| 23 | /** |
| 24 | * What one request to the site did: when it started, each service call |
| 25 | * and how long it took, each loader, and the D1 bookmarks it read with and |
| 26 | * got back. Kept per request with AsyncLocalStorage, so the service |
| 27 | * clients, which are shared by every request in the isolate, can record |
| 28 | * into the right one. |
| 29 | */ |
| 30 | type RequestPerf = { |
| 31 | started: number; |
| 32 | /** Not GET or HEAD: an action, a form post. */ |
| 33 | writing: boolean; |
| 34 | /** A service call that may have written (lib/perf.ts `mayWrite`). */ |
| 35 | wrote: boolean; |
| 36 | bookmarks: Bookmarks; |
| 37 | returned: Record<string, string>; |
| 38 | intervals: [number, number][]; |
| 39 | services: Record<string, ServiceTiming>; |
| 40 | loaders: { id: string; ms: number; kind: "loader" | "action" }[]; |
| 41 | /** How each session-capable service was asked to read, for the header. */ |
| 42 | sessions: Map<string, string>; |
| 43 | }; |
| 44 | |
| 45 | const scope = new AsyncLocalStorage<RequestPerf>(); |
| 46 | |
| 47 | /** Runs `handle` with a fresh record for `request`. */ |
| 48 | export function withRequestPerf<T>(request: Request, handle: () => Promise<T>): Promise<T> { |
| 49 | const writing = request.method !== "GET" && request.method !== "HEAD"; |
| 50 | return scope.run( |
| 51 | { |
| 52 | started: Date.now(), |
| 53 | writing, |
| 54 | wrote: false, |
| 55 | bookmarks: readBookmarks(request.headers.get("cookie")), |
| 56 | returned: {}, |
| 57 | intervals: [], |
| 58 | services: {}, |
| 59 | loaders: [], |
| 60 | sessions: new Map(), |
| 61 | }, |
| 62 | handle, |
| 63 | ); |
| 64 | } |
| 65 | |
| 66 | /** |
| 67 | * `binding` with its calls timed, and, for a service that reads D1 with |
| 68 | * sessions, the `x-d1-bookmark` each call should carry (lib/perf.ts |
| 69 | * `sessionFor`). Only `fetch` is wrapped: the clients use nothing else. |
| 70 | */ |
| 71 | export function instrumented(name: string, binding: ServiceBinding): ServiceBinding { |
| 72 | return { |
| 73 | async fetch(input: string, init?: RequestInit) { |
| 74 | const perf = scope.getStore(); |
| 75 | const method = rpcMethodOf(input); |
| 76 | if (!perf) return answerInTime(binding, name, method, input, init); |
| 77 | const session = sessionFor(name, perf.bookmarks, perf.writing, Math.floor(Date.now() / 1000)); |
| 78 | let sent = init; |
| 79 | if (session) { |
| 80 | const headers = new Headers(init?.headers); |
| 81 | headers.set("x-d1-bookmark", session); |
| 82 | sent = { ...init, headers }; |
| 83 | perf.sessions.set(name, session.startsWith("first-") ? session.slice(6) : "bookmark"); |
| 84 | } |
| 85 | if (SESSION_SERVICES.has(name) && mayWrite(method)) perf.wrote = true; |
| 86 | const from = Date.now(); |
| 87 | let response: Response; |
| 88 | try { |
| 89 | response = await answerInTime(binding, name, method, input, sent); |
| 90 | } finally { |
| 91 | // A call that failed or ran out of time still took the page's time. |
| 92 | perf.intervals.push([from, Date.now()]); |
| 93 | } |
| 94 | const to = Date.now(); |
| 95 | const timing = (perf.services[name] ??= { calls: 0, wallMs: 0, serviceMs: 0 }); |
| 96 | timing.calls += 1; |
| 97 | timing.wallMs += to - from; |
| 98 | const reported = response.headers.get("server-timing"); |
| 99 | timing.serviceMs += serviceDuration(reported) ?? 0; |
| 100 | const database = databaseTime(reported); |
| 101 | if (database) { |
| 102 | timing.dbMs = (timing.dbMs ?? 0) + database.ms; |
| 103 | timing.dbTrips = (timing.dbTrips ?? 0) + database.trips; |
| 104 | } |
| 105 | const bookmark = response.headers.get("x-d1-bookmark"); |
| 106 | if (bookmark && SESSION_SERVICES.has(name)) perf.returned[name] = bookmark; |
| 107 | return response; |
| 108 | }, |
| 109 | }; |
| 110 | } |
| 111 | |
| 112 | /** |
| 113 | * One call to `binding`, answered in full (body read) within its deadline |
| 114 | * (lib/deadline.ts): a service that stops answering fails the call rather |
| 115 | * than holding the page open. RPC answers are small JSON, so reading the |
| 116 | * body here costs nothing and puts it under the deadline too. |
| 117 | */ |
| 118 | async function answerInTime(binding: ServiceBinding, name: string, method: string, input: string, init?: RequestInit): Promise<Response> { |
| 119 | const ms = deadlineFor(name, method, mayWrite(method)); |
| 120 | return withDeadline( |
| 121 | `${name} ${method || input}`, |
| 122 | ms, |
| 123 | async (signal) => { |
| 124 | const response = await binding.fetch(input, { ...init, signal }); |
| 125 | const body = await response.arrayBuffer(); |
| 126 | // A 204 or 304 may not be rebuilt with a body, even an empty one. |
| 127 | return new Response(body.byteLength > 0 ? body : null, response); |
| 128 | }, |
| 129 | init?.signal, |
| 130 | ); |
| 131 | } |
| 132 | |
| 133 | /** |
| 134 | * Whether this request must read current data: it writes, or the person |
| 135 | * wrote moments ago (lib/perf.ts `PRIMARY_WINDOW_SECONDS`). Caches step |
| 136 | * aside then (lib/cache.server.ts). |
| 137 | */ |
| 138 | export function mustReadFresh(): boolean { |
| 139 | const perf = scope.getStore(); |
| 140 | if (!perf) return true; |
| 141 | if (perf.writing) return true; |
| 142 | const at = perf.bookmarks.at; |
| 143 | return at != null && Math.floor(Date.now() / 1000) - at < PRIMARY_WINDOW_SECONDS; |
| 144 | } |
| 145 | |
| 146 | /** Records a loader's or action's time, from the route instrumentation. */ |
| 147 | export function recordHandler(id: string, kind: "loader" | "action", ms: number) { |
| 148 | scope.getStore()?.loaders.push({ id, kind, ms }); |
| 149 | } |
| 150 | |
| 151 | /** |
| 152 | * `response` with the request's `Server-Timing`, and, after a request |
| 153 | * that may have written, the bookmarks its services returned, so the |
| 154 | * person's next pages read at least what they just did. |
| 155 | */ |
| 156 | export function finishResponse(request: Request, response: Response): Response { |
| 157 | const perf = scope.getStore(); |
| 158 | if (!perf) return response; |
| 159 | // A WebSocket handed over (chat's live socket) goes back as it is: a |
| 160 | // copy would lose the socket. |
| 161 | if (response.status === 101 || (response as Response & { webSocket?: unknown }).webSocket) return response; |
| 162 | // A redirect's headers cannot be changed; a copy's can. |
| 163 | const answered = new Response(response.body, response); |
| 164 | const sessions = [...perf.sessions].map(([service, how]) => `${service}=${how}`).join(" "); |
| 165 | answered.headers.append( |
| 166 | "server-timing", |
| 167 | serverTiming({ |
| 168 | totalMs: Date.now() - perf.started, |
| 169 | loaders: perf.loaders, |
| 170 | rpcMs: coveredMs(perf.intervals), |
| 171 | services: perf.services, |
| 172 | sessions, |
| 173 | }), |
| 174 | ); |
| 175 | // Signing in with GitHub writes on a GET; the session it starts says so. |
| 176 | const signedIn = answered.headers.getSetCookie().some((cookie) => cookie.startsWith("g1t_session=")); |
| 177 | const hasSession = /(?:^|;\s*)g1t_session=/.test(request.headers.get("cookie") ?? ""); |
| 178 | if (setsBookmark({ writing: perf.writing, wrote: perf.wrote, hasSession, signedIn })) { |
| 179 | const next: Bookmarks = { |
| 180 | at: Math.floor(Date.now() / 1000), |
| 181 | services: { ...perf.bookmarks.services, ...perf.returned }, |
| 182 | }; |
| 183 | answered.headers.append("set-cookie", bookmarkCookie(next, new URL(request.url).protocol === "https:")); |
| 184 | } |
| 185 | return answered; |
| 186 | } |