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

/:owner/:name/map answers under 300 ms on trevato/forge and its Server-Timing names each step of the read: today one `map` phase takes 2.5–3.6 s #8401

Merged opened this

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

Merged

torque/forge:torque/8381-owner-name-map-answers-under-300-ms-on-t → main 4 commits fork

  • Merged. torque/8381-owner-name-map-answers-under-300-ms-on-t was merged into main as 093d56b.

Review

Sign in to review this change.
4 files changed +313 −56
src/core/dependencies.ts +32 −14
@@ -282,10 +282,7 @@ export function deferredIn(
282282 for (const edge of graph.edges) {
283283 if (!open.has(edge.issueId)) continue;
284284 if (edge.blockedById === gate) out.add(edge.issueId);
285 waiters.set(edge.blockedById, [
286 ...(waiters.get(edge.blockedById) ?? []),
287 edge.issueId,
288 ]);
285 push(waiters, edge.blockedById, edge.issueId);
289286 }
290287 if (later !== undefined && open.has(later)) out.add(later);
291288 for (const id of also) if (open.has(id) && id !== gate) out.add(id);
@@ -303,6 +300,13 @@ export function deferredIn(
303300 return out;
304301 }
305302
303 /** Append to the list under `key`, which a spread would copy whole each time. */
304 function push(into: Map<string, string[]>, key: string, value: string): void {
305 const list = into.get(key);
306 if (list === undefined) into.set(key, [value]);
307 else list.push(value);
308 }
309
306310 const GRAPH_MAX = 400;
307311
308312 /**
@@ -505,10 +509,7 @@ function deferredWhy(
505509 if (edge.blockedById === gate) behind.add(edge.issueId);
506510 if (edge.issueId === later) filed.add(edge.blockedById);
507511 if (deferred.has(edge.issueId))
508 waiters.set(edge.blockedById, [
509 ...(waiters.get(edge.blockedById) ?? []),
510 edge.issueId,
511 ]);
512 push(waiters, edge.blockedById, edge.issueId);
512513 }
513514 // The deferred limbs an issue hangs from: what above it was itself filed.
514515 const limbs = (id: string, seen: Set<string>): Pick<Issue, "id" | "number" | "title">[] => {
@@ -619,11 +620,30 @@ function waitsForMap(
619620 return memo;
620621 }
621622
623 /**
624 * What the rankings of one graph share: its open ids and both reach maps.
625 * `readyNow`, `idleFurniture` and `blockedOn` each ask for them on the same
626 * graph in one page, and each walk is the costliest step of the read (#8381),
627 * so a graph is walked once. A graph is plain data that is built, not changed.
628 */
629 const reachMaps = new WeakMap<
630 Graph,
631 { open: Set<string>; holds: Map<string, Set<string>>; waits: Map<string, Set<string>> }
632 >();
633
634 export function reachOf(graph: Graph) {
635 let known = reachMaps.get(graph);
636 if (known === undefined) {
637 const open = openIds(graph);
638 known = { open, holds: holdsUpMap(graph, open), waits: waitsForMap(graph, open) };
639 reachMaps.set(graph, known);
640 }
641 return known;
642 }
643
622644 /** Open issues nothing open stands in front of, whoever they are for, in the ready order. */
623645 function clearNow(graph: Graph): Ranked[] {
624 const open = openIds(graph);
625 const holds = holdsUpMap(graph, open);
626 const waits = waitsForMap(graph, open);
646 const { open, holds, waits } = reachOf(graph);
627647 const held = new Set(graph.held.map((h) => h.issueId));
628648 return graph.issues
629649 .filter(
@@ -698,9 +718,7 @@ export function idleFurniture(graph: Graph): Issue[] {
698718
699719 /** Open issues that hold others up, the widest blockage first. */
700720 export function blockedOn(graph: Graph): Ranked[] {
701 const open = openIds(graph);
702 const holds = holdsUpMap(graph, open);
703 const waits = waitsForMap(graph, open);
721 const { open, holds, waits } = reachOf(graph);
704722 return graph.issues
705723 .filter((i) => open.has(i.id) && (holds.get(i.id)?.size ?? 0) > 0)
706724 .map((issue) => ({
src/core/pillars.ts +57 −22
@@ -380,33 +380,13 @@ export function askToLiveByPillar(
380380 scope: SealedScope = {},
381381 ): AskToLiveCount[] {
382382 const { pulls, issues } = mergedPulls(db, repoId, since, scope);
383 // Read from the window's merged pulls up, by `deploy_pull_issue` and the run's key,
384 // not from every run the repository ever made.
385 const live = new Map<string, string[]>();
386 const ids = pulls.map((pull) => pull.id);
387 for (let i = 0; i < ids.length; i += CHUNK) {
388 const chunk = ids.slice(i, i + CHUNK);
389 for (const row of db
390 .query<{ id: string; at: string }, string[]>(
391 `SELECT dp.issue_id AS id, COALESCE(r.serving_at, r.finished_at) AS at
392 FROM deploy_pull dp CROSS JOIN run r ON r.id = dp.run_id
393 WHERE dp.issue_id IN (${chunk.map((_, n) => `?${n + 3}`).join(",")})
394 AND r.repo_id = ?1 AND r.kind = 'deploy' AND r.env = 'production' AND r.state = 'ok'
395 AND COALESCE(r.serving_at, r.finished_at) >= ?2
396 ORDER BY COALESCE(r.serving_at, r.finished_at), r.id`,
397 )
398 .all(repoId, since, ...chunk)) {
399 const list = live.get(row.id) ?? [];
400 list.push(row.at);
401 live.set(row.id, list);
402 }
403 }
383 const firstLive = firstLiveOf(db, repoId, since);
404384 // One entry per asked issue: its first time live over every pull that closed it.
405385 const first = new Map<number, { pillar: string; createdAt: string; at: string }>();
406386 for (const pull of pulls) {
407387 const ask = pillarOf(pull.closes, issues, served);
408388 if (ask === undefined) continue;
409 const at = live.get(pull.id)?.find((t) => t >= pull.mergedAt);
389 const at = firstLive(pull.id, pull.mergedAt);
410390 if (at === undefined) continue;
411391 const seen = first.get(ask.number);
412392 if (seen === undefined || at < seen.at)
@@ -441,6 +421,61 @@ export function askToLiveByPillar(
441421
442422 const round1 = (n: number): number => Math.round(n * 10) / 10;
443423
424 /**
425 * When a merged pull first went live: the first successful production deploy
426 * since `since`, at or after its merge, that carries it. `deploy_pull` is
427 * cumulative (every deploy records every merged pull its commit contains), so
428 * reading a pull's rows reads one per later deploy: on trevato/forge, 992
429 * pulls by 644 deploys in a week were ~320k rows and 1.8 s (#8381). So the
430 * window's deploys are read once in time order, and each pull probes the
431 * first few from its merge on by primary key — the first one tried almost
432 * always carries it. A pull none of those carry (not live yet, or behind a
433 * lagging deploy) reads its own rows instead, which are few or none. Three
434 * statements however many pulls.
435 */
436 function firstLiveOf(
437 db: Database,
438 repoId: string,
439 since: string,
440 ): (pullId: string, mergedAt: string) => string | undefined {
441 const deploys = db
442 .query<{ id: string; at: string }, [string, string]>(
443 `SELECT id, COALESCE(serving_at, finished_at) AS at FROM run
444 WHERE repo_id = ?1 AND kind = 'deploy' AND env = 'production' AND state = 'ok'
445 AND COALESCE(serving_at, finished_at) >= ?2
446 ORDER BY 2, id`,
447 )
448 .all(repoId, since);
449 const carries = db.query<{ one: number }, [string, string]>(
450 "SELECT 1 AS one FROM deploy_pull WHERE run_id = ?1 AND issue_id = ?2",
451 );
452 const rest = db.query<{ at: string | null }, [string, string, string]>(
453 `SELECT MIN(COALESCE(r.serving_at, r.finished_at)) AS at
454 FROM deploy_pull dp CROSS JOIN run r ON r.id = dp.run_id
455 WHERE dp.issue_id = ?3 AND r.repo_id = ?1 AND r.kind = 'deploy'
456 AND r.env = 'production' AND r.state = 'ok'
457 AND COALESCE(r.serving_at, r.finished_at) >= ?2`,
458 );
459 return (pullId, mergedAt) => {
460 // The first deploy at or after the merge: ISO instants sort as strings.
461 let lo = 0;
462 let hi = deploys.length;
463 while (lo < hi) {
464 const mid = (lo + hi) >> 1;
465 if (deploys[mid]!.at < mergedAt) lo = mid + 1;
466 else hi = mid;
467 }
468 for (let i = lo; i < Math.min(lo + PROBES, deploys.length); i++)
469 if (carries.get(deploys[i]!.id, pullId) !== null) return deploys[i]!.at;
470 if (lo + PROBES >= deploys.length) return undefined;
471 const from = mergedAt > since ? mergedAt : since;
472 return rest.get(repoId, from, pullId)?.at ?? undefined;
473 };
474 }
475
476 /** Deploys a pull probes from its merge on before it reads its own rows. */
477 const PROBES = 4;
478
444479 /** Of these repositories, the ones with an open issue titled like an umbrella: one read. */
445480 export function reposWithUmbrellas(
446481 db: Database,
src/web/pages/map.ts +25 −20
@@ -1392,26 +1392,31 @@ export async function mapPage(ctx: Ctx): Promise<Response> {
13921392 const db = ctx.app.db;
13931393 const studio = studioRecord(ctx, repo) !== undefined;
13941394 const showDone = ctx.url.searchParams.get("done") === "1";
1395 // The read: graph, marks and pillars, one phase; `render` is the page's own.
1396 const { shown, graph, ready, blocked, critical, placed, marks, readySet, counts, pillars, ask } =
1397 timePhase(ctx.request, "map", () => {
1398 const graph = repoGraph(db, repo.id, {
1399 ...sealedScope(db, repo, ctx.auth.user),
1400 });
1401 const ready = readyNow(graph);
1402 const blocked = blockedOn(graph);
1403 const critical = criticalPath(graph);
1404 const shown = showDone ? graph : openOnly(graph);
1405 const placed = cachedLayout(shown, layout);
1406 const marks = marksFor(db, repo.id, graph, listActiveRuns(db, [repo.id]));
1407 const readySet = new Set(ready.map((r) => r.issue.id));
1408 const counts = countWords(
1409 graph.issues.map((i) => wordFor(i, readySet, marks)),
1410 );
1411 const pillars = pillarView(db, repo);
1412 const ask = askToLiveFor(ctx.app, repo, pillars, ctx.auth.user);
1413 return { shown, graph, ready, blocked, critical, placed, marks, readySet, counts, pillars, ask };
1414 });
1395 // The read, one Server-Timing phase per step (#8381); `render` is the page's own.
1396 const rq = ctx.request;
1397 const reading = performance.now();
1398 const graph = timePhase(rq, "map-graph", () =>
1399 repoGraph(db, repo.id, { ...sealedScope(db, repo, ctx.auth.user), lean: true }),
1400 );
1401 const ready = timePhase(rq, "map-ready", () => readyNow(graph));
1402 const blocked = timePhase(rq, "map-blocked", () => blockedOn(graph));
1403 const critical = timePhase(rq, "map-critical", () => criticalPath(graph));
1404 const shown = timePhase(rq, "map-shown", () => (showDone ? graph : openOnly(graph)));
1405 const placed = timePhase(rq, "map-layout", () => cachedLayout(shown, layout));
1406 const marks = timePhase(rq, "map-marks", () =>
1407 marksFor(db, repo.id, graph, listActiveRuns(db, [repo.id])),
1408 );
1409 const { readySet, counts } = timePhase(rq, "map-words", () => {
1410 const readySet = new Set(ready.map((r) => r.issue.id));
1411 return { readySet, counts: countWords(graph.issues.map((i) => wordFor(i, readySet, marks))) };
1412 });
1413 const pillars = timePhase(rq, "map-pillars", () => pillarView(db, repo));
1414 const ask = timePhase(rq, "map-ask", () =>
1415 askToLiveFor(ctx.app, repo, pillars, ctx.auth.user),
1416 );
1417 // The ten named steps above replace the old single `map` phase; `map` is
1418 // still noted, by hand, as their total, for readers of the header.
1419 notePhase(rq, "map", performance.now() - reading);
14151420 const rendering = performance.now();
14161421 const body = html`${repoHeader(ctx, repo, "map")}
14171422 <div class="page-head mt">
test/map-speed.test.ts added +199
@@ -0,0 +1,199 @@
1 /**
2 * The map at the size of trevato/forge answers fast (#8381): 3,000 closed and
3 * 300 open issues, 600 edges and 10 pillars were one `map` phase of 2.5–3.6 s.
4 * The forge's own /api/v1/repos/trevato/forge/map named the step: `asktolive`
5 * took 1.8 s of it, for 992 pulls merged in the week and 644 production deploys,
6 * each deploy recording every merged pull its commit contains. That shape is
7 * seeded here. The page names each step of its read in Server-Timing; the
8 * ask-to-live step stays under 100 ms (2 s before) and the whole read (`map`) under 300 ms,
9 * measured warm on the same machine as the test.
10 */
11 import { afterAll, beforeAll, expect, test } from "bun:test";
12 import { mkdtempSync, rmSync } from "node:fs";
13 import { tmpdir } from "node:os";
14 import { join } from "node:path";
15 import { seedFixture, type Fixture, type Shape } from "../bench/map-home.ts";
16 import { getUserByName } from "../src/core/users.ts";
17 import { getRepo } from "../src/core/repos.ts";
18 import { id } from "../src/kernel/id.ts";
19 import { serve, type Servers } from "../src/http/server.ts";
20 import { reachOf, repoGraph } from "../src/core/dependencies.ts";
21 import { clearMapCache } from "../src/web/map_cache.ts";
22 import { askToLiveFor } from "../src/web/ask_to_live.ts";
23 import { pillarView } from "../src/core/pillars.ts";
24 import { quietLogs } from "./helpers/globals.ts";
25
26 quietLogs();
27
28 const SHAPE: Shape = {
29 repos: 3,
30 bigIssues: 3_300,
31 bigOpen: 300,
32 bigGraph: 900,
33 bigEdges: 600,
34 bigPulls: 20,
35 lanes: [3],
36 privateLanes: 0,
37 sealed: 2,
38 runs: 3,
39 comments: 15,
40 events: 20_000,
41 };
42
43 const STEPS = [
44 "map-graph",
45 "map-ready",
46 "map-blocked",
47 "map-critical",
48 "map-layout",
49 "map-marks",
50 "map-pillars",
51 "map-ask",
52 "map-shown",
53 "map-words",
54 ];
55
56 let dir = "";
57 let f: Fixture;
58 let servers: Servers;
59
60 beforeAll(async () => {
61 dir = mkdtempSync(join(tmpdir(), "forge-map-speed-"));
62 clearMapCache();
63 f = await seedFixture(dir, SHAPE);
64 const db = f.app.db;
65 const owner = getUserByName(db, "keeper")!;
66 const repo = getRepo(db, "keeper", "forge")!;
67 // Ten pillar umbrellas, each waiting for three open issues.
68 const open = db
69 .query<{ id: string }, [string]>(
70 "SELECT id FROM issue WHERE repo_id = ?1 AND state = 'open' AND kind = 'issue' AND sealed = 0 ORDER BY number LIMIT 30",
71 )
72 .all(repo.id);
73 db.transaction(() => {
74 for (let p = 1; p <= 10; p++) {
75 const umbrella = id();
76 const number = db
77 .query<{ issue_seq: number }, [string]>(
78 "UPDATE repo SET issue_seq = issue_seq + 1 WHERE id = ?1 RETURNING issue_seq",
79 )
80 .get(repo.id)!.issue_seq;
81 db.query(
82 `INSERT INTO issue (id, repo_id, number, kind, title, body, author_id, state, sealed, created_at, updated_at)
83 VALUES (?1, ?2, ?3, 'issue', ?4, '', ?5, 'open', 0, ?6, ?6)`,
84 ).run(umbrella, repo.id, number, `P${p} Pillar ${p}: what it is for`, owner.id, new Date().toISOString());
85 for (const o of open.slice((p - 1) * 3, p * 3))
86 db.query("INSERT INTO issue_dependency (issue_id, blocked_by_id, actor_id) VALUES (?1, ?2, ?3)").run(umbrella, o.id, owner.id);
87 }
88 })();
89 // A real forge writes long bodies: trevato/forge's issues carry several kB each.
90 db.query("UPDATE issue SET body = ?1 WHERE repo_id = ?2").run("x".repeat(6_000), repo.id);
91 seedWeek(db, repo.id, open.slice(0, 30).map((o) => o.id));
92 servers = await serve(f.app);
93 }, 180_000);
94 /** The pulls of the week and the production deploys that carried them, as trevato/forge had them. */
95 const WEEK = { pulls: 992, deploys: 644 };
96
97 function seedWeek(db: Fixture["app"]["db"], repoId: string, served: string[]): void {
98 const owner = getUserByName(db, "keeper")!;
99 const T = Date.now();
100 const at = (hoursAgo: number) => new Date(T - hoursAgo * 3_600_000).toISOString();
101 const numbers = served.map(
102 (sid) => db.query<{ number: number }, [string]>("SELECT number FROM issue WHERE id = ?1").get(sid)!.number,
103 );
104 const issue = db.query(
105 `INSERT INTO issue (id, repo_id, number, kind, title, body, author_id, state, sealed, created_at, updated_at)
106 VALUES (?1, ?2, ?3, 'pull', ?4, ?5, ?6, 'closed', 0, ?7, ?7)`,
107 );
108 const pull = db.query(
109 `INSERT INTO pull (issue_id, base_branch, head_branch, base_oid, head_oid, merged_at, merged_oid)
110 VALUES (?1, 'main', ?2, 'a', 'b', ?3, ?4)`,
111 );
112 const run = db.query(
113 `INSERT INTO run (id, repo_id, kind, env, state, serving_at, finished_at)
114 VALUES (?1, ?2, 'deploy', 'production', 'ok', ?3, ?3)`,
115 );
116 const carry = db.query(
117 "INSERT INTO deploy_pull (run_id, issue_id, pull_number, merged_oid) VALUES (?1, ?2, ?3, 'o')",
118 );
119 db.transaction(() => {
120 const merged: { id: string; number: number }[] = [];
121 const hours = 165;
122 let next = 0;
123 for (let d = 0; d < WEEK.deploys; d++) {
124 const when = hours - ((d + 1) * hours) / WEEK.deploys;
125 // The pulls merged before this deploy; it carries all of them, as a rev-list does.
126 while (next < WEEK.pulls && hours - ((next + 1) * hours) / WEEK.pulls > when + 0.05) {
127 const pid = id();
128 const number = db
129 .query<{ issue_seq: number }, [string]>(
130 "UPDATE repo SET issue_seq = issue_seq + 1 WHERE id = ?1 RETURNING issue_seq",
131 )
132 .get(repoId)!.issue_seq;
133 const mergedAt = at(hours - ((next + 1) * hours) / WEEK.pulls);
134 issue.run(pid, repoId, number, `Land ${next}`, `Closes #${numbers[next % numbers.length]}\n\n${"x".repeat(2_000)}`, owner.id, mergedAt);
135 pull.run(pid, `crew/${next}`, mergedAt, `oid${next}`);
136 merged.push({ id: pid, number });
137 next++;
138 }
139 const rid = id();
140 run.run(rid, repoId, at(when));
141 for (const m of merged) carry.run(rid, m.id, m.number);
142 }
143 })();
144 }
145
146 afterAll(() => {
147 servers?.stop();
148 f?.app.close();
149 rmSync(dir, { recursive: true, force: true });
150 }, 60_000);
151
152 test("the map of a forge the size of trevato/forge reads in under 300 ms, each step named", async () => {
153 const hit = async () => {
154 const res = await fetch(`${servers.url}/keeper/forge/map`, { headers: { cookie: f.strangerCookie } });
155 await res.text();
156 expect(res.status).toBe(200);
157 const phases = new Map<string, number>();
158 for (const m of (res.headers.get("server-timing") ?? "").matchAll(/([a-z-]+);dur=([\d.]+)/g))
159 phases.set(m[1]!, Number(m[2]));
160 return phases;
161 };
162 await hit(); // cold: fills the layout cache
163 const phases = await hit();
164 for (const step of STEPS) expect(phases.has(step)).toBe(true);
165 // The step that was 1.8 s on trevato/forge: one read of the deploys, a probe or two per pull.
166 expect(phases.get("map-ask")!).toBeLessThan(100);
167 expect(phases.get("map")!).toBeLessThan(300);
168 // `map` is the sum of the named steps and a little glue, never more than they are.
169 const named = STEPS.reduce((n, step) => n + phases.get(step)!, 0);
170 expect(phases.get("map")!).toBeGreaterThanOrEqual(named - 1);
171 }, 60_000);
172
173 test("one graph's reach maps are built once, however many rankings ask", () => {
174 const repo = getRepo(f.app.db, "keeper", "forge")!;
175 const graph = repoGraph(f.app.db, repo.id, { sealed: true, lean: true });
176 const first = reachOf(graph);
177 expect(reachOf(graph)).toBe(first);
178 expect(reachOf(graph).holds).toBe(first.holds);
179 // A second graph is its own: nothing is shared across graphs.
180 expect(reachOf(repoGraph(f.app.db, repo.id, { sealed: true, lean: true }))).not.toBe(first);
181 });
182
183 test("a lean graph draws the same map as a full one", () => {
184 const repo = getRepo(f.app.db, "keeper", "forge")!;
185 const full = repoGraph(f.app.db, repo.id, { sealed: true });
186 const lean = repoGraph(f.app.db, repo.id, { sealed: true, lean: true });
187 const strip = (g: typeof full) => g.issues.map(({ body: _b, ...rest }) => rest);
188 expect(strip(lean)).toEqual(strip(full));
189 expect(lean.edges).toEqual(full.edges);
190 });
191
192 test("the week's merges reach production: every pillar's ask-to-live is read, not skipped", () => {
193 const repo = getRepo(f.app.db, "keeper", "forge")!;
194 const view = pillarView(f.app.db, repo)!;
195 const ask = askToLiveFor(f.app, repo, view, undefined);
196 expect(ask.length).toBe(10);
197 // Each pillar has merged work that went live, so each has a figure; none is skipped.
198 for (const row of ask) expect(row.askToLive?.slowest.number).toBeGreaterThan(0);
199 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs