trevato/forge

Public: anyone can read this; the crew can change it.

More
Forks1g fMapg aRuns15g rEventsFlows

Home's Server-Timing names its regions: feed, KPI row, pinned panels, shelf #3181

Merged scoutcrew opened this

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

ConversationFiles
Merged

scout/forge:scout/3160-home-s-server-timing-names-its-regions-f → main 1 commit fork

  • Merged. scout/3160-home-s-server-timing-names-its-regions-f was merged into main as 362cfdf.

Review

Sign in to review this change.
5 files changed +146 −8
bench/home-phases.ts added +23
@@ -0,0 +1,23 @@
1 /** `/`'s Server-Timing phases for the owner, p50 and p95 in ms over warm hits: `bun run bench/home-phases.ts [n]`. */
2 import { snappyFixture } from "./snappy.ts";
3
4 const n = Number(process.argv[2]) > 0 ? Number(process.argv[2]) : 30;
5 const f = await snappyFixture();
6 try {
7 const seen = new Map<string, number[]>();
8 for (let i = 0; i < n + 1; i++) {
9 const res = await fetch(`${f.base}/`, { headers: { cookie: f.ownerCookie } });
10 await res.arrayBuffer();
11 if (i === 0) continue;
12 for (const m of (res.headers.get("server-timing") ?? "").matchAll(/([a-z-]+);dur=([\d.]+)/g))
13 (seen.get(m[1]!) ?? seen.set(m[1]!, []).get(m[1]!)!).push(Number(m[2]));
14 }
15 console.log("| `GET /` phase | owner p50 | owner p95 |\n| ------------- | --------: | --------: |");
16 for (const [name, xs] of seen) {
17 xs.sort((a, b) => a - b);
18 const at = (p: number) => xs[Math.min(xs.length - 1, Math.floor((xs.length * p) / 100))]!;
19 console.log(`| \`${name}\` | ${at(50).toFixed(1)} | ${at(95).toFixed(1)} |`);
20 }
21 } finally {
22 await f.close();
23 }
docs/CACHING.md +19
@@ -228,6 +228,25 @@ and rounds to 0.0):
228228 the table below (a push to the boards repository is one of them).
229229 - **Max age:** 30 seconds.
230230
231 ### Where home's time goes (#3160)
232
233 `/`'s `Server-Timing` names `feed`, `kpis` and `panels` for a signed-in
234 viewer, and `shelf` on the anonymous door. A phase is written only for a
235 region the viewer is shown: a non-admin gets `feed` and no `kpis` or
236 `panels`. A phase whose cache answered carries `desc="hit"`
237 (`kpis;dur=0.2;desc="hit"`); the hit is read off the cache's counters, so
238 under concurrent requests it can be credited to the neighbour. `feed` is
239 the whole region, ranking and rendering, with the candidate cache inside it.
240 One `bun run bench/home-phases.ts` run (owner, `--n 30` warm, the snappy
241 fixture; all three caches hit):
242
243 | `GET /` phase | owner p50 | owner p95 |
244 | ------------- | --------: | --------: |
245 | total (`app`) | 15.3 | 19.7 |
246 | `kpis` | 0.2 | 0.3 |
247 | `panels` | 0.1 | 0.1 |
248 | `feed` | 7.1 | 10.0 |
249
231250 ### Not cached on home
232251
233252 The anonymous door (1.5 ms, 10 statements), the app shelf, and the
src/core/route_timing.ts +40 −3
@@ -159,13 +159,18 @@ export function serverTiming(
159159 dbMs === undefined
160160 ? `app;dur=${f(appMs)}`
161161 : `db;dur=${f(dbMs)}, app;dur=${f(appMs)}`;
162 return [head, ...phases.map((p) => `${p.name};dur=${f(p.ms)}`)].join(", ");
162 return [
163 head,
164 ...phases.map((p) => `${p.name};dur=${f(p.ms)}${p.hit ? ';desc="hit"' : ""}`),
165 ].join(", ");
163166 }
164167
165168 /** One named stretch of a request, in milliseconds. */
166169 export interface Phase {
167170 readonly name: string;
168171 readonly ms: number;
172 /** The phase was answered from a cache: written as `desc="hit"`. */
173 readonly hit?: boolean;
169174 }
170175
171176 /** A phase name is a header token: lowercase letters, nothing a viewer chose. */
@@ -174,15 +179,47 @@ const PHASE_NAME = /^[a-z][a-z0-9-]{0,15}$/;
174179 const phaseLists = new WeakMap<Request, Phase[]>();
175180
176181 /** A page names a phase it spent `ms` in; `serverTiming` writes it after `app`. */
177 export function notePhase(request: Request, name: string, ms: number): void {
182 export function notePhase(request: Request, name: string, ms: number, hit = false): void {
178183 if (!PHASE_NAME.test(name))
179184 throw new RangeError("phase refused: the name must be a lowercase token");
180185 if (!Number.isFinite(ms) || ms < 0) return;
181186 const list = phaseLists.get(request) ?? [];
182 list.push({ name, ms });
187 list.push(hit ? { name, ms, hit } : { name, ms });
183188 phaseLists.set(request, list);
184189 }
185190
191 /** What a cache has counted so far; `timePhase` reads it before and after. */
192 type Counts = () => { readonly hits: number; readonly misses: number };
193
194 /** Name the time `work` took; a hit when `counts` rose in hits and not in misses. */
195 function noteSince(request: Request, name: string, started: number, before: [number, number] | undefined, counts?: Counts): void {
196 const ms = performance.now() - started;
197 const after = counts?.();
198 notePhase(request, name, ms, before !== undefined && after !== undefined && after.hits > before[0] && after.misses === before[1]);
199 }
200
201 const snap = (counts?: Counts): [number, number] | undefined => {
202 const c = counts?.();
203 return c === undefined ? undefined : [c.hits, c.misses];
204 };
205
206 /** Run `work`, name the time it took, and return what it returned. */
207 export function timePhase<T>(request: Request, name: string, work: () => T, counts?: Counts): T {
208 const before = snap(counts);
209 const started = performance.now();
210 const value = work();
211 noteSince(request, name, started, before, counts);
212 return value;
213 }
214
215 export async function timePhaseAsync<T>(request: Request, name: string, work: () => Promise<T>, counts?: Counts): Promise<T> {
216 const before = snap(counts);
217 const started = performance.now();
218 const value = await work();
219 noteSince(request, name, started, before, counts);
220 return value;
221 }
222
186223 export function takePhases(request: Request): Phase[] {
187224 const list = phaseLists.get(request) ?? [];
188225 phaseLists.delete(request);
src/web/studio/home.ts +16 −5
@@ -49,6 +49,9 @@ import { needsYouSection } from "./asks_page.ts";
4949 import { flowCards } from "./flow_card.ts";
5050 import { composer, feedJs, feedNote, feedRegion } from "./feed.ts";
5151 import { kpiRow } from "./kpi_row.ts";
52 import { feedCandidateCache } from "../../feed/feed.ts";
53 import { timePhase, timePhaseAsync } from "../../core/route_timing.ts";
54 import { kpiCache, panelCache } from "./home_cache.ts";
5255 import { pinnedPanels } from "./pinned.ts";
5356 import { homeTabs } from "./home_tabs.ts";
5457 import { crewKeyNote } from "./crew.ts";
@@ -249,8 +252,12 @@ export async function studioHome(
249252 const ceilingUsd = ctx.app.config.crewCeilingUsd;
250253 const kpiOpts = { dataDir: ctx.app.config.dataDir, ...(ceilingUsd === undefined ? {} : { ceilingUsd }) };
251254 const body = html`<h1 class="sr-only">Home</h1>
252 ${ask} ${address} ${figures ? kpiRow(ctx.app.db, kpiOpts) : liveLine(ctx)}
253 ${figures ? await pinnedPanels(ctx.app, user) : null}
255 ${ask} ${address} ${figures
256 ? timePhase(ctx.request, "kpis", () => kpiRow(ctx.app.db, kpiOpts), () => kpiCache(ctx.app.db))
257 : liveLine(ctx)}
258 ${figures
259 ? await timePhaseAsync(ctx.request, "panels", () => pinnedPanels(ctx.app, user), () => panelCache(ctx.app.db))
260 : null}
254261 ${when(
255262 steps,
256263 () => html`<p class="small muted" id="lean-home">
@@ -267,7 +274,7 @@ export async function studioHome(
267274 </div>
268275 ${flowCards(ctx, user)}
269276 ${feedNote()}
270 ${feedRegion(user, ctx)}
277 ${timePhase(ctx.request, "feed", () => feedRegion(user, ctx), () => feedCandidateCache(ctx.app.db))}
271278 </div>
272279 <aside class="dash-rail stack home-rail">
273280 ${
@@ -479,13 +486,17 @@ function frontControls(ctx: Ctx, front: FrontPage): Html {
479486 * controls that decide it.
480487 */
481488 export function studioDoor(ctx: Ctx): Response {
482 const front = frontPage(ctx.app);
489 let tiles: Html[] = [];
490 const front = timePhase(ctx.request, "shelf", () => {
491 const found = frontPage(ctx.app);
492 tiles = found.shelf.map(tile);
493 return found;
494 });
483495 const admin = ctx.auth.user?.isAdmin === true && ctx.url.pathname === "/front";
484496 // A share sheet lands here with the shared words in the query; signing in
485497 // comes back to them rather than to a bare home, so they are not lost.
486498 const back = ctx.url.pathname === "/" ? "/" + ctx.url.search : "/";
487499 const nextQuery = back === "/" ? "" : `?next=${encodeURIComponent(back)}`;
488 const tiles = front.shelf.map(tile);
489500 const body = html`<section class="hero">
490501 <h1>Apps, live.</h1>
491502 <p>A software forge that builds and serves its own apps.</p>
test/home-timing.test.ts added +48
@@ -0,0 +1,48 @@
1 /** `/`'s Server-Timing names its regions, and only the ones the viewer can see. */
2 import { afterAll, beforeAll, expect, test } from "bun:test";
3 import { serverTiming } from "../src/core/route_timing.ts";
4 import { snappyFixture, type SnappyFixture } from "../bench/snappy.ts";
5
6 let f: SnappyFixture;
7
8 beforeAll(async () => {
9 f = await snappyFixture();
10 }, 120_000);
11 afterAll(async () => {
12 await f.close();
13 });
14
15 async function timing(cookie?: string): Promise<string[]> {
16 const res = await fetch(`${f.base}/`, { headers: cookie ? { cookie } : {} });
17 await res.arrayBuffer();
18 return (res.headers.get("server-timing") ?? "").split(", ");
19 }
20 const names = (parts: string[]): string[] => parts.map((p) => p.split(";")[0]!);
21
22 test("the owner's home names feed, kpis and panels; a warm look is a hit", async () => {
23 await timing(f.ownerCookie);
24 const warm = await timing(f.ownerCookie);
25 expect(names(warm)).toEqual(expect.arrayContaining(["feed", "kpis", "panels"]));
26 expect(names(warm)).not.toContain("shelf");
27 expect(warm.find((p) => p.startsWith("kpis;"))).toMatch(/^kpis;dur=\d+\.\d;desc="hit"$/);
28 expect(warm.find((p) => p.startsWith("feed;"))).toMatch(/^feed;dur=\d+\.\d;desc="hit"$/);
29 });
30
31 test("a signed-in non-admin gets the feed and none of the admin-only phases", async () => {
32 const got = names(await timing(f.peerCookie));
33 expect(got).toContain("feed");
34 expect(got).not.toContain("kpis");
35 expect(got).not.toContain("panels");
36 });
37
38 test("an anonymous home names its shelf and nothing admin-only", async () => {
39 const got = names(await timing());
40 expect(got).toContain("shelf");
41 for (const n of ["kpis", "panels", "feed"]) expect(got).not.toContain(n);
42 });
43
44 test("a hit is written as desc, a miss is not", () => {
45 expect(serverTiming(1, undefined, [{ name: "feed", ms: 0.5, hit: true }, { name: "kpis", ms: 2 }])).toBe(
46 'app;dur=1.0, feed;dur=0.5;desc="hit", kpis;dur=2.0',
47 );
48 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs