Public: anyone can read this; the crew can change it.
Name git, session and render Server-Timing phases on /raw and /media #9641
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/9519-name-git-session-and-render-server-timin → main 5 commits fork 5 threads · 5 unresolved
4 files
changed +115
−5
docs/features/load-test.md +1 −1
| @@ -25,7 +25,7 @@ Not done here: the profile of tree/blob/raw/media under production's shape, the | ||
| 25 | 25 | |
| 26 | 26 | ## The per-phase profile (#9503) |
| 27 | 27 | |
| 28 | `bench/code-phases.ts` holds the same open-loop rate and tallies each answer's `Server-Timing` by page kind (tree, blob, raw, media), printing p50/p95 of wall time and of every named phase as a table. `git`, `render`, `highlight` and `session` are always listed; n = 0 means that page never names the phase (today `/raw` and `/media` name none, so only their wall time is profiled). | |
| 28 | `bench/code-phases.ts` holds the same open-loop rate and tallies each answer's `Server-Timing` by page kind (tree, blob, raw, media), printing p50/p95 of wall time and of every named phase as a table. `git`, `render`, `highlight` and `session` are always listed; n = 0 means that page never names the phase (`/raw` names `session` and `git`; `/media` names `session`, `git` and, only when it opens a stream of a file over 1 MB, `stream`; a phase that did not run is not named, so it never skews a percentile). | |
| 29 | 29 | |
| 30 | 30 | sh |
| 31 | 31 | bun bench/code-phases.ts --url https://copy.example --repo owner/name --rate 500 --seconds 20 |
src/web/pages/media.ts +28
| @@ -22,6 +22,7 @@ import { repoDir } from "../../git/repos.ts"; | ||
| 22 | 22 | import type { Ctx } from "../../http/context.ts"; |
| 23 | 23 | import { holds } from "../../http/etag.ts"; |
| 24 | 24 | import { parseRange } from "../../http/range.ts"; |
| 25 | import { notePhase, takeSessionTime } from "../../core/route_timing.ts"; | |
| 25 | 26 | import { loadRepo, notFoundPage } from "../chrome.ts"; |
| 26 | 27 | import { cachedMedia, keepMedia } from "./tree_cache.ts"; |
| 27 | 28 | import { HEAD_BYTES, mediaType } from "../render/kinds.ts"; |
| @@ -50,6 +51,24 @@ export const mediaHref = (base: string, ref: string, path: string): string => | ||
| 50 | 51 | `${base}/media/${encodeURIComponent(ref)}/${path}`; |
| 51 | 52 | |
| 52 | 53 | export async function mediaBlob(ctx: Ctx): Promise<Response> { |
| 54 | // Server-Timing: `session` as the router measured it, `git` the object | |
| 55 | // reads, `stream` the time to have a body to send (the stream opened). A phase | |
| 56 | // is named only when it ran: no `git` before a stat, no `stream` for a small | |
| 57 | // file, a 304 or a 416. | |
| 58 | notePhase(ctx.request, "session", takeSessionTime(ctx.request)); | |
| 59 | const clock: Clock = {}; | |
| 60 | try { | |
| 61 | return await mediaRead(ctx, clock); | |
| 62 | } finally { | |
| 63 | if (clock.git !== undefined) notePhase(ctx.request, "git", clock.git); | |
| 64 | if (clock.stream !== undefined) notePhase(ctx.request, "stream", clock.stream); | |
| 65 | } | |
| 66 | } | |
| 67 | ||
| 68 | /** Milliseconds per phase; a phase that never ran stays undefined. */ | |
| 69 | type Clock = { git?: number; stream?: number }; | |
| 70 | ||
| 71 | async function mediaRead(ctx: Ctx, clock: Clock): Promise<Response> { | |
| 53 | 72 | const repo = loadRepo(ctx); |
| 54 | 73 | if (!repo) return notFoundPage(ctx); |
| 55 | 74 | const ref = ctx.params.ref ?? ""; |
| @@ -59,8 +78,10 @@ export async function mediaBlob(ctx: Ctx): Promise<Response> { | ||
| 59 | 78 | const dir = repoDir(ctx.app.reposRoot, repo.ownerName, repo.name); |
| 60 | 79 | const reader = readerFor(dir); |
| 61 | 80 | // At a full commit id a small file never changes: a repeat read spawns no git (#9505). |
| 81 | // A held read names no `git` phase: it did not run. | |
| 62 | 82 | const pinned = /^[0-9a-f]{40}$/.test(ref); |
| 63 | 83 | const held = pinned ? cachedMedia(repo.id, ref, path) : undefined; |
| 84 | let at = performance.now(); | |
| 64 | 85 | let oid: string; |
| 65 | 86 | let size: number; |
| 66 | 87 | if (held !== undefined) { |
| @@ -68,6 +89,7 @@ export async function mediaBlob(ctx: Ctx): Promise<Response> { | ||
| 68 | 89 | size = held.body.length; |
| 69 | 90 | } else { |
| 70 | 91 | const stat = await reader.stat(`${ref}:${path}`).catch(() => undefined); |
| 92 | clock.git = (clock.git ?? 0) + (performance.now() - at); | |
| 71 | 93 | if (stat === undefined || !stat.ok || stat.value.type !== "blob") |
| 72 | 94 | return notFoundPage(ctx); |
| 73 | 95 | ({ oid, size } = stat.value); |
| @@ -105,15 +127,19 @@ export async function mediaBlob(ctx: Ctx): Promise<Response> { | ||
| 105 | 127 | body = held.body; |
| 106 | 128 | head = body.subarray(0, HEAD_BYTES); |
| 107 | 129 | } else if (size <= SMALL_BYTES) { |
| 130 | at = performance.now(); | |
| 108 | 131 | const object = await reader.object(oid).catch(() => undefined); |
| 132 | clock.git = (clock.git ?? 0) + (performance.now() - at); | |
| 109 | 133 | if (object === undefined || !object.ok) return notFoundPage(ctx); |
| 110 | 134 | body = object.value.body; |
| 111 | 135 | head = body.subarray(0, HEAD_BYTES); |
| 112 | 136 | if (pinned) keepMedia(repo.id, ref, path, { oid, body }); |
| 113 | 137 | } else { |
| 138 | at = performance.now(); | |
| 114 | 139 | const sniff = await blobStream(dir, oid, 0, HEAD_BYTES - 1, { signal: ctx.request.signal }); |
| 115 | 140 | if (sniff === "busy" || sniff === "gone") return busy(); |
| 116 | 141 | head = await new Response(sniff).bytes(); |
| 142 | clock.git = (clock.git ?? 0) + (performance.now() - at); | |
| 117 | 143 | } |
| 118 | 144 | const type = download ? "application/octet-stream" : mediaType(path, head); |
| 119 | 145 | headers["content-type"] = type; |
| @@ -138,7 +164,9 @@ export async function mediaBlob(ctx: Ctx): Promise<Response> { | ||
| 138 | 164 | // stream); `Content-Range` still names the whole size, which is what a |
| 139 | 165 | // seeking player reads. |
| 140 | 166 | if (body === undefined) { |
| 167 | at = performance.now(); | |
| 141 | 168 | const stream = await blobStream(dir, oid, start, end, { signal: ctx.request.signal }); |
| 169 | clock.stream = performance.now() - at; | |
| 142 | 170 | if (stream === "busy" || stream === "gone") return busy(); |
| 143 | 171 | return new Response(stream, { status, headers }); |
| 144 | 172 | } |
src/web/pages/repo.ts +14 −1
| @@ -1737,6 +1737,9 @@ export function capped(blob: Blob): Blob { | ||
| 1737 | 1737 | * a file in a repository can never execute as a page on this origin. |
| 1738 | 1738 | */ |
| 1739 | 1739 | export async function rawBlob(ctx: Ctx): Promise<Response> { |
| 1740 | // `session` first, so it is named on every answer, 404s included. There is | |
| 1741 | // no `stream` phase: the body is bytes already in memory, nothing to time. | |
| 1742 | notePhase(ctx.request, "session", takeSessionTime(ctx.request)); | |
| 1740 | 1743 | const repo = loadRepo(ctx); |
| 1741 | 1744 | if (!repo) return notFoundPage(ctx); |
| 1742 | 1745 | const ref = ctx.params.ref ?? ""; |
| @@ -1746,8 +1749,18 @@ export async function rawBlob(ctx: Ctx): Promise<Response> { | ||
| 1746 | 1749 | const dir = repoDir(ctx.app.reposRoot, repo.ownerName, repo.name); |
| 1747 | 1750 | // At a full commit id the bytes never change: a small file is kept (#9405). |
| 1748 | 1751 | const pinned = FULL_OID.test(ref); |
| 1752 | // A held read names no `git` phase: git did not run. A read that throws | |
| 1753 | // still names the time it took. | |
| 1749 | 1754 | const held = pinned ? cachedRaw(repo.id, ref, path) : undefined; |
| 1750 | const blob = held ?? (await blobForRender(dir, ref, path, 25_000_000)); | |
| 1755 | let blob = held; | |
outdated
Minor: if blobForRender throws, |
||
| 1756 | if (blob === undefined) { | |
| 1757 | const gitAt = performance.now(); | |
| 1758 | try { | |
| 1759 | blob = await blobForRender(dir, ref, path, 25_000_000); | |
| 1760 | } finally { | |
| 1761 | notePhase(ctx.request, "git", performance.now() - gitAt); | |
| 1762 | } | |
| 1763 | } | |
| 1751 | 1764 | if (blob.kind === "missing" || blob.kind === "too_large") |
outdated
|
||
| 1752 | 1765 | return notFoundPage(ctx); |
| 1753 | 1766 | if (pinned && held === undefined) keepRaw(repo.id, ref, path, blob); |
test/browse-timing.test.ts +72 −3
| @@ -21,7 +21,7 @@ async function git(args: string[], cwd: string): Promise<void> { | ||
| 21 | 21 | if (code !== 0) throw new Error(`git ${args.join(" ")}: ${err}`); |
| 22 | 22 | } |
| 23 | 23 | |
| 24 | let dataDir = "", work = ""; | |
| 24 | let dataDir = "", work = "", commit = ""; | |
| 25 | 25 | let app: App, servers: Servers, bearer = ""; |
| 26 | 26 | |
| 27 | 27 | beforeAll(async () => { |
| @@ -47,9 +47,12 @@ beforeAll(async () => { | ||
| 47 | 47 | const dir = join(work, "app"); |
| 48 | 48 | await Bun.write(join(dir, "a.ts"), "export const a = 1;\n"); |
| 49 | 49 | await Bun.write(join(dir, "README.md"), "# app\n"); |
| 50 | await Bun.write(join(dir, "big.bin"), "x".repeat(1_200_000)); | |
| 50 | 51 | await git(["add", "."], dir); |
| 51 | 52 | await git(["commit", "-m", "one"], dir); |
| 52 | 53 | await git(["push", "origin", "main"], dir); |
| 54 | const rev = Bun.spawnSync(["git", "rev-parse", "HEAD"], { cwd: dir, env }); | |
| 55 | commit = rev.stdout.toString().trim(); | |
| 53 | 56 | }, 60_000); |
| 54 | 57 | |
| 55 | 58 | afterAll(async () => { |
| @@ -59,10 +62,10 @@ afterAll(async () => { | ||
| 59 | 62 | await rm(work, { recursive: true, force: true }); |
| 60 | 63 | }); |
| 61 | 64 | |
| 62 | const names = async (path: string): Promise<string[]> => { | |
| 65 | const names = async (path: string, status = 200): Promise<string[]> => { | |
| 63 | 66 | const res = await fetch(`${servers.url}${path}`, { headers: { authorization: `Bearer ${bearer}` } }); |
| 64 | 67 | await res.arrayBuffer(); |
| 65 | expect(res.status).toBe(200); | |
| 68 | expect(res.status).toBe(status); | |
| 66 | 69 | return (res.headers.get("server-timing") ?? "").split(", ").map((p) => p.split(";")[0]!); |
| 67 | 70 | }; |
| 68 | 71 | |
| @@ -95,3 +98,69 @@ test("a rendered Markdown blob sends no highlight", async () => { | ||
| 95 | 98 | expect(got).not.toContain("highlight"); |
| 96 | 99 | once(got); |
| 97 | 100 | }); |
| 101 | ||
| 102 | test("raw names session and git once each, and no stream", async () => { | |
| 103 | const got = await names("/alice/app/raw/main/a.ts"); | |
| 104 | expect(got).toEqual(expect.arrayContaining(["app", "session", "git"])); | |
| 105 | expect(got).not.toContain("stream"); | |
| 106 | once(got); | |
| 107 | }); | |
| 108 | ||
| 109 | test("raw names session on a 404", async () => { | |
| 110 | const got = await names("/alice/app/raw/main/nope.ts", 404); | |
| 111 | expect(got).toContain("session"); | |
| 112 | once(got); | |
| 113 | }); | |
| 114 | ||
| 115 | test("media on a small file names session and git, no stream", async () => { | |
| 116 | const got = await names("/alice/app/media/main/a.ts"); | |
| 117 | expect(got).toEqual(expect.arrayContaining(["app", "session", "git"])); | |
| 118 | expect(got).not.toContain("stream"); | |
| 119 | once(got); | |
| 120 | }); | |
| 121 | ||
| 122 | test("media on a large file names stream once", async () => { | |
| 123 | const got = await names("/alice/app/media/main/big.bin"); | |
| 124 | expect(got).toEqual(expect.arrayContaining(["session", "git", "stream"])); | |
| 125 | once(got); | |
| 126 | }); | |
outdated
Missing test: media.ts deliberately names no |
||
| 127 | ||
| 128 | test("media on a 404 names session and git, not stream", async () => { | |
| 129 | const got = await names("/alice/app/media/main/nope.ts", 404); | |
| 130 | expect(got).toEqual(expect.arrayContaining(["session", "git"])); | |
| 131 | expect(got).not.toContain("stream"); | |
| 132 | once(got); | |
| 133 | }); | |
| 134 | ||
| 135 | test("a repeat media read at a full commit id is held and names no git", async () => { | |
| 136 | const first = await names(`/alice/app/media/${commit}/a.ts`); | |
| 137 | expect(first).toContain("git"); | |
| 138 | const again = await names(`/alice/app/media/${commit}/a.ts`); | |
| 139 | expect(again).toContain("session"); | |
| 140 | expect(again).not.toContain("git"); | |
| 141 | expect(again).not.toContain("stream"); | |
| 142 | once(again); | |
| 143 | }); | |
| 144 | ||
| 145 | test("a repeat raw read at a full commit id is held and names no git", async () => { | |
| 146 | const first = await names(`/alice/app/raw/${commit}/README.md`); | |
| 147 | expect(first).toContain("git"); | |
| 148 | const again = await names(`/alice/app/raw/${commit}/README.md`); | |
| 149 | expect(again).toContain("session"); | |
| 150 | expect(again).not.toContain("git"); | |
| 151 | once(again); | |
| 152 | }); | |
| 153 | ||
| 154 | test("a media 304 names git but no stream", async () => { | |
| 155 | const first = await fetch(`${servers.url}/alice/app/media/main/big.bin`, { headers: { authorization: `Bearer ${bearer}` } }); | |
| 156 | await first.arrayBuffer(); | |
| 157 | const res = await fetch(`${servers.url}/alice/app/media/main/big.bin`, { | |
| 158 | headers: { authorization: `Bearer ${bearer}`, "if-none-match": first.headers.get("etag") ?? "" }, | |
| 159 | }); | |
| 160 | await res.arrayBuffer(); | |
| 161 | expect(res.status).toBe(304); | |
| 162 | const got = (res.headers.get("server-timing") ?? "").split(", ").map((p) => p.split(";")[0]!); | |
| 163 | expect(got).toEqual(expect.arrayContaining(["session", "git"])); | |
| 164 | expect(got).not.toContain("stream"); | |
| 165 | once(got); | |
| 166 | }); |
new above
offline
Notes
gitandstreamas 0 on 304, 416 and 404, which skews the bench percentiles. Note a phase only when it ran.