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

Merged opened this

Check · Review · Land · Live done — Landed and live in production.

Merged

scout/forge:scout/3311-the-front-door-s-server-timing-names-eve → main 7 commits fork

  • Merged. scout/3311-the-front-door-s-server-timing-names-eve was merged into main as 9773009.

Review

Sign in to review this change.
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: ()
220220 return value;
221221 }
222222
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
223229 export function takePhases(request: Request): Phase[] {
224230 const list = phaseLists.get(request) ?? [];
225231 phaseLists.delete(request);
src/feed/feed.ts +7 −1
@@ -120,8 +120,14 @@ export function readFeed(
120120 );
121121 const pageable =
122122 options.withoutAsks === true ? candidates.filter((c) => c.kind !== "ask") : candidates;
123 let ranked = rank(pageable, affinityFor(db, viewer, now), now);
124123 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 );
125131 if (cursor) {
126132 const at = ranked.findIndex((i) => i.id === cursor.id);
127133 ranked =
src/feed/rank.ts +25 −18
@@ -78,32 +78,39 @@ function affinityReason(c: Candidate, app: Weighted, actor: Weighted, now: numbe
7878 interface Scored {
7979 readonly c: Candidate;
8080 readonly base: number;
81 readonly reason: string;
8281 }
8382
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
84103 export function rank(
85104 candidates: readonly Candidate[],
86105 aff: Affinity,
87106 now: number,
107 /** Place only the best `upto`: the same first items, without ordering the rest. */
108 upto: number = Infinity,
88109 ): FeedItem[] {
89110 const scored: Scored[] = candidates.map((c) => {
90111 const app = aff.app(c.repoId);
91112 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) };
107114 });
108115
109116 // Greedy: place the best remaining, then charge its source against the
@@ -112,7 +119,7 @@ export function rank(
112119 const perApp = new Map<string, number>();
113120 const perActor = new Map<string, number>();
114121 const rest = [...scored];
115 while (rest.length > 0) {
122 while (rest.length > 0 && out.length < upto) {
116123 let best = 0;
117124 let bestScore = -Infinity;
118125 for (let i = 0; i < rest.length; i++) {
@@ -140,7 +147,7 @@ export function rank(
140147 at: s!.c.at,
141148 link: s!.c.link,
142149 what: s!.c.said ?? s!.c.what,
143 reason: s!.reason,
150 reason: reasonOf(s!.c, aff, now),
144151 score: Math.round(bestScore * 1e6) / 1e6,
145152 ...(s!.c.ask === undefined ? {} : { ask: s!.c.ask }),
146153 });
src/web/studio/home.ts +14 −6
@@ -50,7 +50,7 @@ import { flowCards } from "./flow_card.ts";
5050 import { composer, feedJs, feedNote, feedRegion } from "./feed.ts";
5151 import { kpiRow } from "./kpi_row.ts";
5252 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";
5454 import { kpiCache, panelCache } from "./home_cache.ts";
5555 import { pinnedPanels } from "./pinned.ts";
5656 import { homeTabs } from "./home_tabs.ts";
@@ -211,9 +211,8 @@ export async function studioHome(
211211 ctx: Ctx,
212212 user: User,
213213 ): Promise<Response> {
214 const { repos: appRepos } = writableAppsOf(ctx, user);
215214 // 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));
217216 const address = when(
218217 spawned?.url,
219218 (url) =>
@@ -223,8 +222,10 @@ export async function studioHome(
223222 );
224223 // On a spawned forge its owner's first steps come first, and carry the
225224 // 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 });
228229 // Its owner sees their apps first and nothing else until they ask (#1812).
229230 if (
230231 ctx.url.searchParams.get("all") === null &&
@@ -247,6 +248,11 @@ export async function studioHome(
247248 ...(firstSteps ? { scriptJs: passkeyJs } : {}),
248249 });
249250 }
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();
250256 const ask = firstSteps ?? everydayCard(ctx, user);
251257 const figures = user.isAdmin && steps === undefined;
252258 const ceilingUsd = ctx.app.config.crewCeilingUsd;
@@ -288,12 +294,14 @@ export async function studioHome(
288294 ${orgsCard(ctx, user)}
289295 </aside>
290296 </div>`;
291 return page({
297 const res = page({
292298 ctx,
293299 title: "Home",
294300 body,
295301 scriptJs: `${liveClientJs}\n${liveRegionsJs}\n${feedJs}${ask ? `\n${passkeyJs}` : ""}`,
296302 });
303 notePhaseRest(ctx.request, "render", rendering, ["kpis", "panels", "feed"]);
304 return res;
297305 }
298306
299307 /**
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 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs