Public: anyone can read this; the crew can change it.
The front door's Server-Timing names every phase, and its feed read takes under 25 ms #3998
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/3311-the-front-door-s-server-timing-names-eve → main 7 commits fork
6 files
changed +164
−25
bench/front-door.ts added +39
| @@ -0,0 +1,39 @@ | ||
| 1 | /** | |
| 2 | * The front door's feed read (#3311): the signed-in home on a forge of two | |
| 3 | * thousand events, after a write so the feed phase is a cache miss. Its | |
| 4 | * budget is 25 ms. A wall-clock bound is not a test (it flakes on a busy | |
| 5 | * machine), so it lives here. | |
| 6 | * | |
| 7 | * bun run bench/front-door.ts | |
| 8 | */ | |
| 9 | ||
| 10 | import { openIssue } from "../src/actions/issues.ts"; | |
| 11 | import { snappyFixture } from "./snappy.ts"; | |
| 12 | ||
| 13 | const BUDGET_MS = 25; | |
| 14 | const ROUNDS = 15; | |
| 15 | ||
| 16 | const f = await snappyFixture({ repos: 50, issuesPerRepo: 40 }); | |
| 17 | const get = async (): Promise<string> => { | |
| 18 | const res = await fetch(`${f.base}/`, { headers: { cookie: f.ownerCookie } }); | |
| 19 | await res.arrayBuffer(); | |
| 20 | return res.headers.get("server-timing") ?? ""; | |
| 21 | }; | |
| 22 | await get(); | |
| 23 | const times: number[] = []; | |
| 24 | for (let i = 0; i < ROUNDS; i++) { | |
| 25 | const opened = openIssue(f.app, f.owner, f.repos[0]!, { title: `A write the feed must read again ${i}` }); | |
| 26 | if (!opened.ok) throw new Error(String(opened.error)); | |
| 27 | const feed = (await get()).split(", ").find((p) => p.startsWith("feed;")); | |
| 28 | const m = /dur=([\d.]+)/.exec(feed ?? ""); | |
| 29 | if (!m || feed?.includes("hit")) throw new Error(`feed was not a miss: ${feed}`); | |
| 30 | times.push(Number(m[1])); | |
| 31 | } | |
| 32 | await f.close(); | |
| 33 | times.sort((a, b) => a - b); | |
| 34 | const p50 = times[Math.floor(times.length / 2)]!; | |
| 35 | console.log(`feed read after a write: p50 ${p50.toFixed(1)} ms, max ${times.at(-1)!.toFixed(1)} ms (budget ${BUDGET_MS} ms)`); | |
| 36 | if (p50 > BUDGET_MS) { | |
| 37 | console.error("over budget"); | |
| 38 | process.exit(1); | |
| 39 | } |
src/core/route_timing.ts +6
| @@ -220,6 +220,12 @@ export async function timePhaseAsync<T>(request: Request, name: string, work: () | ||
| 220 | 220 | return value; |
| 221 | 221 | } |
| 222 | 222 | |
| 223 | /** Name `name` as the time since `started` less the phases in `except` already named: what is left of the page. */ | |
| 224 | export function notePhaseRest(request: Request, name: string, started: number, except: readonly string[]): void { | |
| 225 | const taken = (phaseLists.get(request) ?? []).reduce((sum, p) => (except.includes(p.name) ? sum + p.ms : sum), 0); | |
| 226 | notePhase(request, name, Math.max(0, performance.now() - started - taken)); | |
| 227 | } | |
| 228 | ||
| 223 | 229 | export function takePhases(request: Request): Phase[] { |
| 224 | 230 | const list = phaseLists.get(request) ?? []; |
| 225 | 231 | phaseLists.delete(request); |
src/feed/feed.ts +7 −1
| @@ -120,8 +120,14 @@ export function readFeed( | ||
| 120 | 120 | ); |
| 121 | 121 | const pageable = |
| 122 | 122 | options.withoutAsks === true ? candidates.filter((c) => c.kind !== "ask") : candidates; |
| 123 | let ranked = rank(pageable, affinityFor(db, viewer, now), now); | |
| 124 | 123 | const cursor = options.cursor; |
| 124 | // Without a cursor only the page and one more (to know there is a next) are placed. | |
| 125 | let ranked = rank( | |
| 126 | pageable, | |
| 127 | affinityFor(db, viewer, now), | |
| 128 | now, | |
| 129 | cursor === undefined ? limit + 1 : Infinity, | |
| 130 | ); | |
| 125 | 131 | if (cursor) { |
| 126 | 132 | const at = ranked.findIndex((i) => i.id === cursor.id); |
| 127 | 133 | ranked = |
src/feed/rank.ts +25 −18
| @@ -78,32 +78,39 @@ function affinityReason(c: Candidate, app: Weighted, actor: Weighted, now: numbe | ||
| 78 | 78 | interface Scored { |
| 79 | 79 | readonly c: Candidate; |
| 80 | 80 | readonly base: number; |
| 81 | readonly reason: string; | |
| 82 | 81 | } |
| 83 | 82 | |
| 83 | /** The sentence for the term that led, worded only for an item that is placed. */ | |
| 84 | function reasonOf(c: Candidate, aff: Affinity, now: number): string { | |
| 85 | if (c.said !== undefined) return c.said; | |
| 86 | const app = aff.app(c.repoId); | |
| 87 | const actor = c.actorId === null ? aff.get("actor:") : aff.actor(c.actorId); | |
| 88 | const affinity = affinityOf(app, actor); | |
| 89 | const recency = recencyOf(c, now); | |
| 90 | return c.urgency >= Math.max(affinity, recency) | |
| 91 | ? c.what | |
| 92 | : affinity >= recency | |
| 93 | ? affinityReason(c, app, actor, now) | |
| 94 | : `${c.what}, ${ago(Date.parse(c.at), now)}`; | |
| 95 | } | |
| 96 | ||
| 97 | const affinityOf = (app: Weighted, actor: Weighted): number => | |
| 98 | clamp(AFFINITY_WEIGHT * (app.score + 0.5 * actor.score), AFFINITY_MIN, AFFINITY_MAX); | |
| 99 | ||
| 100 | const recencyOf = (c: Candidate, now: number): number => | |
| 101 | RECENCY_MAX * decay(now - Date.parse(c.at), RECENCY_HALF_LIFE_MS); | |
| 102 | ||
| 84 | 103 | export function rank( |
| 85 | 104 | candidates: readonly Candidate[], |
| 86 | 105 | aff: Affinity, |
| 87 | 106 | now: number, |
| 107 | /** Place only the best `upto`: the same first items, without ordering the rest. */ | |
| 108 | upto: number = Infinity, | |
| 88 | 109 | ): FeedItem[] { |
| 89 | 110 | const scored: Scored[] = candidates.map((c) => { |
| 90 | 111 | const app = aff.app(c.repoId); |
| 91 | 112 | const actor = c.actorId === null ? aff.get("actor:") : aff.actor(c.actorId); |
| 92 | const raw = AFFINITY_WEIGHT * (app.score + 0.5 * actor.score); | |
| 93 | const affinity = clamp(raw, AFFINITY_MIN, AFFINITY_MAX); | |
| 94 | const recency = | |
| 95 | RECENCY_MAX * decay(now - Date.parse(c.at), RECENCY_HALF_LIFE_MS); | |
| 96 | const urgency = c.urgency; | |
| 97 | const base = urgency + affinity + recency; | |
| 98 | const reason = | |
| 99 | c.said !== undefined | |
| 100 | ? c.said | |
| 101 | : urgency >= Math.max(affinity, recency) | |
| 102 | ? c.what | |
| 103 | : affinity >= recency | |
| 104 | ? affinityReason(c, app, actor, now) | |
| 105 | : `${c.what}, ${ago(Date.parse(c.at), now)}`; | |
| 106 | return { c, base, reason }; | |
| 113 | return { c, base: c.urgency + affinityOf(app, actor) + recencyOf(c, now) }; | |
| 107 | 114 | }); |
| 108 | 115 | |
| 109 | 116 | // Greedy: place the best remaining, then charge its source against the |
| @@ -112,7 +119,7 @@ export function rank( | ||
| 112 | 119 | const perApp = new Map<string, number>(); |
| 113 | 120 | const perActor = new Map<string, number>(); |
| 114 | 121 | const rest = [...scored]; |
| 115 | while (rest.length > 0) { | |
| 122 | while (rest.length > 0 && out.length < upto) { | |
| 116 | 123 | let best = 0; |
| 117 | 124 | let bestScore = -Infinity; |
| 118 | 125 | for (let i = 0; i < rest.length; i++) { |
| @@ -140,7 +147,7 @@ export function rank( | ||
| 140 | 147 | at: s!.c.at, |
| 141 | 148 | link: s!.c.link, |
| 142 | 149 | what: s!.c.said ?? s!.c.what, |
| 143 | reason: s!.reason, | |
| 150 | reason: reasonOf(s!.c, aff, now), | |
| 144 | 151 | score: Math.round(bestScore * 1e6) / 1e6, |
| 145 | 152 | ...(s!.c.ask === undefined ? {} : { ask: s!.c.ask }), |
| 146 | 153 | }); |
src/web/studio/home.ts +14 −6
| @@ -50,7 +50,7 @@ import { flowCards } from "./flow_card.ts"; | ||
| 50 | 50 | import { composer, feedJs, feedNote, feedRegion } from "./feed.ts"; |
| 51 | 51 | import { kpiRow } from "./kpi_row.ts"; |
| 52 | 52 | import { feedCandidateCache } from "../../feed/feed.ts"; |
| 53 | import { timePhase, timePhaseAsync } from "../../core/route_timing.ts"; | |
| 53 | import { notePhase, notePhaseRest, takeSessionTime, timePhase, timePhaseAsync } from "../../core/route_timing.ts"; | |
| 54 | 54 | import { kpiCache, panelCache } from "./home_cache.ts"; |
| 55 | 55 | import { pinnedPanels } from "./pinned.ts"; |
| 56 | 56 | import { homeTabs } from "./home_tabs.ts"; |
| @@ -211,9 +211,8 @@ export async function studioHome( | ||
| 211 | 211 | ctx: Ctx, |
| 212 | 212 | user: User, |
| 213 | 213 | ): Promise<Response> { |
| 214 | const { repos: appRepos } = writableAppsOf(ctx, user); | |
| 215 | 214 | // A spawned forge says where it lives: the address its person shares. |
| 216 | const spawned = await spawnedOrg(ctx.app); | |
| 215 | const spawned = await timePhaseAsync(ctx.request, "spawned", () => spawnedOrg(ctx.app)); | |
| 217 | 216 | const address = when( |
| 218 | 217 | spawned?.url, |
| 219 | 218 | (url) => |
| @@ -223,8 +222,10 @@ export async function studioHome( | ||
| 223 | 222 | ); |
| 224 | 223 | // On a spawned forge its owner's first steps come first, and carry the |
| 225 | 224 | // everyday account themselves (#600); anywhere else, #803's card asks. |
| 226 | const steps = await nextStepsOf(ctx, user); | |
| 227 | const firstSteps = await nextStepsCard(ctx, user, steps); | |
| 225 | const { steps, firstSteps } = await timePhaseAsync(ctx.request, "steps", async () => { | |
| 226 | const steps = await nextStepsOf(ctx, user); | |
| 227 | return { steps, firstSteps: await nextStepsCard(ctx, user, steps) }; | |
| 228 | }); | |
| 228 | 229 | // Its owner sees their apps first and nothing else until they ask (#1812). |
| 229 | 230 | if ( |
| 230 | 231 | ctx.url.searchParams.get("all") === null && |
| @@ -247,6 +248,11 @@ export async function studioHome( | ||
| 247 | 248 | ...(firstSteps ? { scriptJs: passkeyJs } : {}), |
| 248 | 249 | }); |
| 249 | 250 | } |
| 251 | // The client's first screen names its own phases (`clientApps`). | |
| 252 | notePhase(ctx.request, "session", takeSessionTime(ctx.request)); | |
| 253 | const { repos: appRepos } = timePhase(ctx.request, "repos", () => writableAppsOf(ctx, user)); | |
| 254 | // Render is what is left of the page once the named reads are taken out. | |
| 255 | const rendering = performance.now(); | |
| 250 | 256 | const ask = firstSteps ?? everydayCard(ctx, user); |
| 251 | 257 | const figures = user.isAdmin && steps === undefined; |
| 252 | 258 | const ceilingUsd = ctx.app.config.crewCeilingUsd; |
| @@ -288,12 +294,14 @@ export async function studioHome( | ||
| 288 | 294 | ${orgsCard(ctx, user)} |
| 289 | 295 | </aside> |
| 290 | 296 | </div>`; |
| 291 | return page({ | |
| 297 | const res = page({ | |
| 292 | 298 | ctx, |
| 293 | 299 | title: "Home", |
| 294 | 300 | body, |
| 295 | 301 | scriptJs: `${liveClientJs}\n${liveRegionsJs}\n${feedJs}${ask ? `\n${passkeyJs}` : ""}`, |
| 296 | 302 | }); |
| 303 | notePhaseRest(ctx.request, "render", rendering, ["kpis", "panels", "feed"]); | |
| 304 | return res; | |
| 297 | 305 | } |
| 298 | 306 | |
| 299 | 307 | /** |
test/front-door-timing.test.ts added +73
| @@ -0,0 +1,73 @@ | ||
| 1 | /** The front door's Server-Timing names every phase, and a heavy feed reads fast (#3311). */ | |
| 2 | import { afterAll, beforeAll, expect, test } from "bun:test"; | |
| 3 | import { rm, writeFile } from "node:fs/promises"; | |
| 4 | import { join } from "node:path"; | |
| 5 | import { createOrg } from "../src/core/orgs.ts"; | |
| 6 | import { snappyFixture, type SnappyFixture } from "../bench/snappy.ts"; | |
| 7 | import { openIssue } from "../src/actions/issues.ts"; | |
| 8 | import { affinityFor } from "../src/feed/affinity.ts"; | |
| 9 | import { readFeed } from "../src/feed/feed.ts"; | |
| 10 | import { candidatesFor } from "../src/feed/items.ts"; | |
| 11 | import { rank } from "../src/feed/rank.ts"; | |
| 12 | ||
| 13 | let f: SnappyFixture; | |
| 14 | ||
| 15 | // 50 repositories, 40 issues each: two thousand events. | |
| 16 | beforeAll(async () => { | |
| 17 | f = await snappyFixture({ repos: 50, issuesPerRepo: 40 }); | |
| 18 | }, 300_000); | |
| 19 | afterAll(async () => { | |
| 20 | await f.close(); | |
| 21 | }); | |
| 22 | ||
| 23 | const parts = (res: Response): string[] => (res.headers.get("server-timing") ?? "").split(", "); | |
| 24 | ||
| 25 | test("the signed-in home names its session, reads and render and a cold feed read", async () => { | |
| 26 | const get = async (): Promise<Response> => { | |
| 27 | const res = await fetch(`${f.base}/`, { headers: { cookie: f.ownerCookie } }); | |
| 28 | await res.arrayBuffer(); | |
| 29 | return res; | |
| 30 | }; | |
| 31 | // Warm the statements, then write: the feed read that follows is a miss. | |
| 32 | await get(); | |
| 33 | const opened = openIssue(f.app, f.owner, f.repos[0]!, { title: "A write the feed must read again" }); | |
| 34 | if (!opened.ok) throw new Error(String(opened.error)); | |
| 35 | const res = await get(); | |
| 36 | const all = parts(res); | |
| 37 | const names = all.map((p) => p.split(";")[0]!); | |
| 38 | for (const n of ["session", "steps", "repos", "kpis", "panels", "feed", "render"]) | |
| 39 | expect(names.filter((x) => x === n).length).toBe(1); | |
| 40 | // A miss is a bare `feed;dur=…`: a hit would carry `desc="hit"`. | |
| 41 | expect(all.find((p) => p.startsWith("feed;"))).toMatch(/^feed;dur=\d+(\.\d+)?$/); | |
| 42 | // The next read of the same feed is the cache's. | |
| 43 | const again = parts(await get()); | |
| 44 | expect(again.find((p) => p.startsWith("feed;"))).toContain('desc="hit"'); | |
| 45 | }); | |
| 46 | ||
| 47 | test("a spawned forge's lean home names spawned and steps once each, and reads no feed", async () => { | |
| 48 | const file = join(f.dataDir, "parent.json"); | |
| 49 | const org = createOrg(f.app.db, "lean-child", f.owner.id); | |
| 50 | if (!org.ok) throw new Error(String(org.error)); | |
| 51 | await writeFile(file, JSON.stringify({ org: "lean-child" })); | |
| 52 | try { | |
| 53 | const res = await fetch(`${f.base}/`, { headers: { cookie: f.ownerCookie } }); | |
| 54 | await res.arrayBuffer(); | |
| 55 | const names = parts(res).map((p) => p.split(";")[0]!); | |
| 56 | for (const n of ["spawned", "steps"]) expect(names.filter((x) => x === n).length).toBe(1); | |
| 57 | expect(names).not.toContain("feed"); | |
| 58 | } finally { | |
| 59 | await rm(file, { force: true }); | |
| 60 | } | |
| 61 | }); | |
| 62 | ||
| 63 | test("placing only the page leaves the order of the whole ranking untouched", () => { | |
| 64 | const now = Date.now(); | |
| 65 | const candidates = candidatesFor(f.app.db, f.owner, now, undefined, true); | |
| 66 | const aff = affinityFor(f.app.db, f.owner, now); | |
| 67 | const whole = rank(candidates, aff, now); | |
| 68 | expect(whole.length).toBeGreaterThan(60); | |
| 69 | expect(rank(candidates, aff, now, 51)).toEqual(whole.slice(0, 51)); | |
| 70 | const page = readFeed(f.app.db, f.owner, { limit: 50, now }); | |
| 71 | expect(page.items).toEqual(whole.slice(0, 50)); | |
| 72 | expect(page.next_cursor).not.toBeNull(); | |
| 73 | }); |
new above
offline