trevato/forge

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

More
Forks1g fMapg aRuns16g rEventsFlows

Performance watcher: Server-Timing budgets for home, boards and repo pages from real traffic, slow phase filed with numbers #7951

Merged scoutcrew opened this in answer to trevatoowner

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

ConversationFiles
Merged

scout/forge:scout/7559-performance-watcher-server-timing-budget → main 3 commits fork

  • Merged. scout/7559-performance-watcher-server-timing-budget was merged into main as bedf34d.

Review

Sign in to review this change.
16 files changed +587 −2
docs/features/performance-watcher.md added +5
@@ -0,0 +1,5 @@
1 # Performance watcher (#7559)
2
3 `src/perf/` keeps a capped in-memory record of real requests per route pattern (total, each Server-Timing phase, signed in or out; no paths, ids or queries). `budgets.ts` holds the budgets in words with the number beside them. Once a minute `duty.ts` files one issue per route and phase in the forge's repo when p95 has been over budget for 15 min with 20+ real requests; the finding names the slowest phase, its share and the cache hit rate. `loop.ts` names the routes running across an event-loop stall in the `loop` log line; nothing is kept beyond that line.
4
5 Not yet: a synthetic probe for routes with no traffic (a client-written label would let anyone hide requests; it needs an admin-only door first), live route stats in the terminal and MCP (findings reach both doors as issues), browser timings, 24 h/7 d history, the board page, release before/after.
src/http/server.ts +10 −1
@@ -512,6 +512,8 @@ import {
512512 takeDbTime,
513513 type RouteTiming,
514514 } from "../core/route_timing.ts";
515 import { loopWatch, perfRecord } from "../perf/live.ts";
516 import { parseServerTiming } from "../perf/record.ts";
515517 import { methodOf, noteUsage, roleOf, surfaceOf, takeUsage } from "./usage_tag.ts";
516518 import { bearerChallenge, oauthRoutes } from "./oauth.ts";
517519 import { flushAccess, recordAccess } from "./access_log.ts";
@@ -2249,7 +2251,14 @@ export async function serve(app: App): Promise<Servers> {
22492251 const tag = takeUsage(request);
22502252 const ms = performance.now() - started;
22512253 try {
2252 response.headers.set("server-timing", serverTiming(ms, takeDbTime(request), takePhases(request)));
2254 const header = serverTiming(ms, takeDbTime(request), takePhases(request));
2255 response.headers.set("server-timing", header);
2256 const end = performance.now();
2257 perfRecord.add(
2258 tag.pattern,
2259 { at: Date.now(), ms, signedIn: tag.role !== "anon", phases: parseServerTiming(header) },
2260 );
2261 loopWatch.finished(tag.pattern, started, end);
22532262 } catch {
22542263 // A response the forge is only carrying keeps the headers it came with.
22552264 }
src/kernel/loop_lag.ts +2
@@ -74,8 +74,10 @@ export function watchStalls(
7474 warnMs = STALL_WARN_MS,
7575 everyMs = LAG_EVERY_MS,
7676 now: () => number = () => performance.now(),
77 onStall?: (lateMs: number, at: number) => void,
7778 ): () => void {
7879 const lag = startLoopLag(everyMs, now, (late) => {
80 onStall?.(late, now());
7981 if (late >= warnMs) log.warn("event loop stalled", { lateMs: Math.round(late) });
8082 });
8183 return lag.stop;
src/main.ts +9 −1
@@ -82,6 +82,9 @@ import { reapLeftoverBridges } from "./crew/leftovers.ts";
8282 import { crewRoot } from "./crew/workdir.ts";
8383 import { createLog } from "./kernel/log.ts";
8484 import { watchStalls } from "./kernel/loop_lag.ts";
85 import { startPerfWatcher } from "./perf/duty.ts";
86 import { stallLine } from "./perf/loop.ts";
87 import { loopWatch, perfRecord } from "./perf/live.ts";
8588 import { timeStatements } from "./kernel/slow_sql.ts";
8689 import { waitForPeer } from "./runs/peer.ts";
8790
@@ -206,7 +209,11 @@ if (parentProblem !== null) {
206209 // The loop's lateness, from the first line of the boot: a stall over a
207210 // second is a warning that names its minute (kernel/loop_lag.ts, #6957),
208211 // draining included.
209 watchStalls(createLog("loop"));
212 const loopLog = createLog("loop");
213 watchStalls(loopLog, undefined, undefined, undefined, (late, at) => {
214 const stall = loopWatch.stalled(late, at);
215 if (stall !== null) loopLog.warn(stallLine(stall));
216 });
210217
211218 const app = createApp({
212219 dataDir,
@@ -297,6 +304,7 @@ loadTrustedHosts(app.db);
297304 const bootSignup = signupFromEnv(process.env.FORGE_SIGNUP);
298305 if (bootSignup.ok && bootSignup.value !== null)
299306 setSignup(app.db, bootSignup.value, BOOT_ACTOR);
307 startPerfWatcher(app, perfRecord);
300308 const flagTimer = setInterval(() => flushFlagUses(app.db), 10_000);
301309 await reconcile(app);
302310 // Issues linked under a pillar's umbrella before pillars had labels.
src/perf/budgets.ts added +26
@@ -0,0 +1,26 @@
1 /** Budgets per route pattern, in words with the number beside it (#7559). One file. */
2
3 export interface Budget {
4 /** The router pattern, or a prefix ending in `*`. */
5 readonly pattern: string;
6 readonly words: string;
7 /** p95 over this many ms, warm, is a finding. */
8 readonly p95Ms: number;
9 }
10
11 export const BUDGETS: readonly Budget[] = [
12 { pattern: "/", words: "home p95 under 800 ms warm", p95Ms: 800 },
13 { pattern: "/boards", words: "boards p95 under 800 ms warm", p95Ms: 800 },
14 { pattern: "/explore", words: "explore p95 under 800 ms warm", p95Ms: 800 },
15 { pattern: "/api/v1/health", words: "health p95 under 100 ms", p95Ms: 100 },
16 { pattern: "/:owner/:name", words: "repo page p95 under 800 ms warm", p95Ms: 800 },
17 { pattern: "/:owner/:name/*", words: "repo sub-page p95 under 1000 ms warm", p95Ms: 1000 },
18 ];
19
20 /** The budget a route pattern is held to, or undefined for a route with none. */
21 export function budgetFor(pattern: string): Budget | undefined {
22 return (
23 BUDGETS.find((b) => b.pattern === pattern) ??
24 BUDGETS.find((b) => b.pattern.endsWith("*") && pattern.startsWith(b.pattern.slice(0, -1)))
25 );
26 }
src/perf/duty.ts added +45
@@ -0,0 +1,45 @@
1 /**
2 * The `performance-watcher` duty (#7559): once a minute, judge the record and
3 * file each new finding as one issue in the forge's own repository, opened by
4 * its owner. A title already open is not filed twice, and neither is a key
5 * this process has filed.
6 */
7
8 import type { App } from "../app.ts";
9 import { openIssue } from "../actions/issues.ts";
10 import { getUserById } from "../core/users.ts";
11 import { getRepo } from "../core/repos.ts";
12 import { listIssues } from "../core/issues.ts";
13 import type { PerfRecord } from "./record.ts";
14 import { evaluate, fresh } from "./watch.ts";
15
16 export const TICK_MS = 60_000;
17
18 export function startPerfWatcher(
19 app: App,
20 record: PerfRecord,
21 now: () => number = Date.now,
22 everyMs = TICK_MS,
23 ): () => void {
24 const filed = new Set<string>();
25 const tick = (): void => {
26 try {
27 const slug = app.config.forgeRepo;
28 if (slug === undefined) return;
29 const [owner, name] = slug.split("/") as [string, string];
30 const repo = getRepo(app.db, owner, name);
31 const actor = repo && getUserById(app.db, repo.ownerId);
32 if (!repo || !actor) return;
33 const open = new Set(listIssues(app.db, repo.id, { state: "open" }).map((i) => i.title));
34 for (const f of fresh(evaluate(record, now()), filed)) {
35 if (open.has(f.title)) continue;
36 openIssue(app, actor, repo, { title: f.title, body: f.evidence });
37 }
38 } catch (error) {
39 app.log.warn("performance watcher failed", { error: String(error) });
40 }
41 };
42 const timer = setInterval(tick, everyMs);
43 timer.unref();
44 return () => clearInterval(timer);
45 }
src/perf/live.ts added +7
@@ -0,0 +1,7 @@
1 /** The process's one record and loop watch (#7559): what the server feeds and the duty reads. */
2
3 import { createLoopWatch } from "./loop.ts";
4 import { createPerfRecord } from "./record.ts";
5
6 export const perfRecord = createPerfRecord();
7 export const loopWatch = createLoopWatch();
src/perf/loop.ts added +50
@@ -0,0 +1,50 @@
1 /**
2 * Event-loop block attribution (#7559): which route was running when the loop
3 * stalled. Each finished request is noted with its start and end; a stall of
4 * `lateMs` ending at `at` blocked `[at - lateMs, at]`, and the requests whose
5 * run overlaps that window are named, longest first. Patterns only; the stall
6 * is logged, not kept.
7 */
8
9 export const LIMIT_MS = 250;
10 const RECENT = 256;
11
12 export interface Stall {
13 readonly at: number;
14 readonly lateMs: number;
15 readonly routes: readonly string[];
16 }
17
18 export interface LoopWatch {
19 /** A request for `pattern` ran from `start` to `end` (ms on one clock). */
20 finished(pattern: string, start: number, end: number): void;
21 /** A wake `lateMs` late at `at`; over the limit it is named. */
22 stalled(lateMs: number, at: number): Stall | null;
23 }
24
25 export function createLoopWatch(limitMs = LIMIT_MS): LoopWatch {
26 const recent: { pattern: string; start: number; end: number }[] = [];
27 return {
28 finished(pattern, start, end) {
29 recent.push({ pattern, start, end });
30 if (recent.length > RECENT) recent.shift();
31 },
32 stalled(lateMs, at) {
33 if (!(lateMs > limitMs)) return null;
34 const from = at - lateMs;
35 const routes = [
36 ...new Set(
37 recent
38 .filter((r) => r.end >= from && r.start <= at)
39 .sort((a, b) => b.end - b.start - (a.end - a.start))
40 .map((r) => r.pattern),
41 ),
42 ];
43 return { at, lateMs, routes };
44 },
45 };
46 }
47
48 /** The stall as a finding line. */
49 export const stallLine = (s: Stall): string =>
50 `event loop blocked ${Math.round(s.lateMs)} ms; running then: ${s.routes.length === 0 ? "no request" : s.routes.join(", ")}`;
src/perf/record.ts added +130
@@ -0,0 +1,130 @@
1 /**
2 * The rolling record of real requests (#7559): per route pattern, the
3 * requests of the last `WINDOW_MS` with their total and each Server-Timing
4 * phase. Memory only, sized by time: older samples are dropped, and a route so
5 * busy that it passes `MAX_SAMPLES` is thinned to every second sample, which
6 * keeps the whole window and its percentiles. Keys are router patterns, never
7 * paths, ids or query strings; nothing about the viewer is kept but signed in
8 * or not. `first` is when a pattern was first seen, so a busy route is not
9 * mistaken for a young one.
10 */
11
12 export const WINDOW_MS = 15 * 60_000;
13 export const MAX_SAMPLES = 20_000;
14 export const MAX_PATTERNS = 200;
15 const MAX_PATTERN = 200;
16 const MAX_PHASES = 16;
17
18 export interface PhaseSample {
19 readonly name: string;
20 readonly ms: number;
21 readonly hit: boolean;
22 }
23
24 export interface Sample {
25 readonly at: number;
26 readonly ms: number;
27 readonly signedIn: boolean;
28 readonly phases: readonly PhaseSample[];
29 }
30
31 export interface PerfRecord {
32 /** Add one request; a pattern that is not a route pattern is dropped. */
33 add(pattern: string, sample: Sample): void;
34 /** Requests for `pattern` at or after `since`. */
35 traffic(pattern: string, since: number): Sample[];
36 /** When `pattern` was first seen in this process, undefined if never. */
37 first(pattern: string): number | undefined;
38 patterns(): string[];
39 }
40
41 const validPattern = (p: string): boolean =>
42 p.startsWith("/") && p.length <= MAX_PATTERN && !/[?#\s\u0000-\u001f]/.test(p);
43
44 /** Nearest-rank percentile of `xs`, null when empty. */
45 export function percentile(xs: readonly number[], p: number): number | null {
46 if (xs.length === 0) return null;
47 const sorted = [...xs].sort((a, b) => a - b);
48 return sorted[Math.max(1, Math.ceil((p / 100) * sorted.length)) - 1]!;
49 }
50
51 export function createPerfRecord(): PerfRecord {
52 const real = new Map<string, Sample[]>();
53 const firsts = new Map<string, number>();
54 return {
55 add(pattern, sample) {
56 if (!validPattern(pattern) || !Number.isFinite(sample.ms) || sample.ms < 0) return;
57 let list = real.get(pattern);
58 if (list === undefined) {
59 if (real.size >= MAX_PATTERNS) return;
60 list = [];
61 real.set(pattern, list);
62 firsts.set(pattern, sample.at);
63 }
64 const phases = sample.phases
65 .filter((p) => Number.isFinite(p.ms) && p.ms >= 0)
66 .slice(0, MAX_PHASES);
67 list.push({ ...sample, phases });
68 // A minute of slack past the window, so the drop is rare, not per request.
69 if (list[0]!.at < sample.at - WINDOW_MS - 60_000) {
70 const keep = list.findIndex((s) => s.at >= sample.at - WINDOW_MS);
71 list.splice(0, keep === -1 ? list.length : keep);
72 }
73 if (list.length > MAX_SAMPLES) {
74 const thinned = list.filter((_, i) => i % 2 === 1);
75 list.length = 0;
76 list.push(...thinned);
77 }
78 },
79 traffic: (pattern, since) => (real.get(pattern) ?? []).filter((s) => s.at >= since),
80 first: (pattern) => firsts.get(pattern),
81 patterns: () => [...real.keys()],
82 };
83 }
84
85 export interface PhaseStat {
86 readonly name: string;
87 readonly p95: number;
88 readonly share: number;
89 readonly hits: number;
90 readonly n: number;
91 }
92
93 export interface RouteStat {
94 readonly n: number;
95 readonly p50: number;
96 readonly p95: number;
97 readonly p99: number;
98 /** Phases, slowest p95 first. */
99 readonly phases: readonly PhaseStat[];
100 }
101
102 /** p50/p95/p99 of the totals, and each phase's p95, its share of the total p95 and its cache hits. */
103 export function summarize(samples: readonly Sample[]): RouteStat | null {
104 if (samples.length === 0) return null;
105 const totals = samples.map((s) => s.ms);
106 const p95 = percentile(totals, 95)!;
107 const byName = new Map<string, PhaseSample[]>();
108 for (const s of samples)
109 for (const ph of s.phases) {
110 const list = byName.get(ph.name);
111 if (list === undefined) byName.set(ph.name, [ph]);
112 else list.push(ph);
113 }
114 const phases = [...byName].map(([name, list]) => {
115 const own = percentile(list.map((x) => x.ms), 95)!;
116 return { name, p95: own, share: p95 > 0 ? Math.min(1, own / p95) : 0, hits: list.filter((x) => x.hit).length, n: list.length };
117 });
118 phases.sort((a, b) => b.p95 - a.p95);
119 return { n: samples.length, p50: percentile(totals, 50)!, p95, p99: percentile(totals, 99)!, phases };
120 }
121
122 /** `app;dur=1.0, kpis;dur=4400.0;desc="hit"` as the phases it names; `app`, `db` included. */
123 export function parseServerTiming(header: string): PhaseSample[] {
124 const out: PhaseSample[] = [];
125 for (const part of header.split(",").slice(0, MAX_PHASES)) {
126 const m = /^\s*([a-z][a-z0-9.-]{0,15});dur=([0-9.]+)(;desc="hit")?\s*$/.exec(part);
127 if (m) out.push({ name: m[1]!, ms: Number(m[2]), hit: m[3] !== undefined });
128 }
129 return out;
130 }
src/perf/watch.ts added +63
@@ -0,0 +1,63 @@
1 /**
2 * The performance watcher's judgement (#7559): a route whose p95 has been over
3 * its budget for the whole window, with enough real requests, is a finding
4 * naming the route, its slowest phase and that phase's share, and the cache hit
5 * rate when the phase is a cache. One key per route and phase, so one issue.
6 */
7
8 import { found, type Finding } from "../hunt/finding.ts";
9 import { budgetFor } from "./budgets.ts";
10 import { summarize, WINDOW_MS, type PerfRecord } from "./record.ts";
11
12 export { WINDOW_MS };
13 export const MIN_REQUESTS = 20;
14
15 /** A phase is a cache when it ever answered `hit`, or it is named like one and has not hit. */
16 const CACHE_PHASE = /(cache|kpis|panel|vitals)/;
17 /** `app`, `db` and `route` wrap the others; the blame goes to a part. */
18 const WRAPPERS = new Set(["app", "db", "route", "compress"]);
19
20 export function evaluate(record: PerfRecord, now: number): Finding[] {
21 const out: Finding[] = [];
22 for (const pattern of record.patterns()) {
23 const budget = budgetFor(pattern);
24 if (budget === undefined) continue;
25 const samples = record.traffic(pattern, now - WINDOW_MS);
26 const stat = summarize(samples);
27 if (stat === null || stat.n < MIN_REQUESTS || stat.p95 <= budget.p95Ms) continue;
28 // Over budget "for 15 min": the route must have been watched most of the window.
29 if (now - (record.first(pattern) ?? now) < WINDOW_MS * 0.9) continue;
30 const slow = stat.phases.find((p) => !WRAPPERS.has(p.name));
31 const phase = slow?.name ?? "app";
32 const lines = [
33 `Budget: ${budget.words} (${budget.p95Ms} ms).`,
34 `Route: ${pattern}, ${stat.n} real requests in 15 min: p50 ${Math.round(stat.p50)} ms, p95 ${Math.round(stat.p95)} ms, p99 ${Math.round(stat.p99)} ms.`,
35 ];
36 if (slow !== undefined) {
37 lines.push(`Slowest phase: ${slow.name}, p95 ${Math.round(slow.p95)} ms, ${Math.round(slow.share * 100)}% of the route's p95.`);
38 if (slow.hits > 0 || CACHE_PHASE.test(slow.name))
39 lines.push(
40 slow.hits === 0
41 ? `Cache: ${slow.name} never hit in ${slow.n} requests.`
42 : `Cache: ${slow.name} hit ${slow.hits} of ${slow.n} requests (${Math.round((slow.hits / slow.n) * 100)}%).`,
43 );
44 }
45 out.push(
46 found(
47 "performance-watcher",
48 `${pattern}:${phase}`,
49 // Stable: the numbers move every tick, the title is how "already open" matches.
50 `${pattern} is over its budget: ${phase}`,
51 lines.join("\n"),
52 ),
53 );
54 }
55 return out;
56 }
57
58 /** The findings not filed before; `filed` remembers keys, so each is offered once. */
59 export function fresh(findings: readonly Finding[], filed: Set<string>): Finding[] {
60 const out = findings.filter((f) => !filed.has(f.key));
61 for (const f of out) filed.add(f.key);
62 return out;
63 }
test/perf-aggregate.test.ts added +24
@@ -0,0 +1,24 @@
1 import { expect, test } from "bun:test";
2 import { createPerfRecord, MAX_SAMPLES, parseServerTiming, summarize } from "../src/perf/record.ts";
3
4 const at = 1_000_000;
5 test("p50/p95/p99 and each phase are kept per pattern", () => {
6 const r = createPerfRecord();
7 for (let i = 1; i <= 100; i++)
8 r.add("/", { at, ms: i, signedIn: false, phases: [{ name: "kpis", ms: i / 2, hit: i % 2 === 0 }] });
9 const s = summarize(r.traffic("/", 0))!;
10 expect([s.n, s.p50, s.p95, s.p99]).toEqual([100, 50, 95, 99]);
11 expect(s.phases[0]).toMatchObject({ name: "kpis", hits: 50, n: 100 });
12 expect(s.phases[0]!.share).toBeCloseTo(0.5);
13 });
14 test("memory is capped", () => {
15 const r = createPerfRecord();
16 for (let i = 0; i < MAX_SAMPLES + 50; i++) r.add("/x", { at, ms: 1, signedIn: true, phases: [] });
17 expect(r.traffic("/x", 0).length).toBeLessThanOrEqual(MAX_SAMPLES);
18 });
19 test("a Server-Timing header becomes phases, hits marked", () => {
20 expect(parseServerTiming('app;dur=5.0, kpis;dur=4400.0;desc="hit"')).toEqual([
21 { name: "app", ms: 5, hit: false },
22 { name: "kpis", ms: 4400, hit: true },
23 ]);
24 });
test/perf-budget-fire.test.ts added +56
@@ -0,0 +1,56 @@
1 import { expect, test } from "bun:test";
2 import { createPerfRecord } from "../src/perf/record.ts";
3 import { evaluate, fresh, WINDOW_MS } from "../src/perf/watch.ts";
4
5 const now = 10_000_000;
6 function seed(pattern: string, total: number, phase: number, n = 100, hit = false) {
7 const r = createPerfRecord();
8 for (let i = 0; i < n; i++)
9 r.add(pattern, {
10 at: now - WINDOW_MS + (i * WINDOW_MS) / n,
11 ms: total,
12 signedIn: false,
13 phases: [{ name: "app", ms: total, hit: false }, { name: "kpis", ms: phase, hit }],
14 });
15 return r;
16 }
17 test("home with kpis at 4.4 s files one finding naming route, phase, p95, share", () => {
18 const f = evaluate(seed("/", 4600, 4400), now);
19 expect(f.length).toBe(1);
20 expect(f[0]!.key).toBe("performance-watcher:/:kpis");
21 expect(f[0]!.evidence).toContain("Slowest phase: kpis, p95 4400 ms, 96%");
22 expect(f[0]!.evidence).toContain("p95 4600 ms");
23 });
24 test("a cache that never hits is named", () => {
25 expect(evaluate(seed("/", 4600, 4400), now)[0]!.evidence).toContain("kpis never hit in 100 requests");
26 });
27 test("a fast route, too few requests, or a short spell file nothing", () => {
28 expect(evaluate(seed("/", 30, 20), now)).toEqual([]);
29 expect(evaluate(seed("/", 4600, 4400, 5), now)).toEqual([]);
30 const r = createPerfRecord();
31 for (let i = 0; i < 50; i++) r.add("/", { at: now - 1000, ms: 5000, signedIn: false, phases: [] });
32 expect(evaluate(r, now)).toEqual([]);
33 });
34 test("a finding is offered once", () => {
35 const filed = new Set<string>();
36 const f = evaluate(seed("/", 4600, 4400), now);
37 expect(fresh(f, filed).length).toBe(1);
38 expect(fresh(f, filed).length).toBe(0);
39 });
40 test("a busy route with far more than 1000 requests in the window still files", () => {
41 const r = seed("/", 4600, 4400, 5000);
42 expect(r.traffic("/", 0).length).toBeGreaterThan(1000);
43 expect(evaluate(r, now).length).toBe(1);
44 });
45 test("samples older than the window are dropped; a young route is not judged", () => {
46 const r = createPerfRecord();
47 for (let i = 0; i < 100; i++) r.add("/", { at: i, ms: 5000, signedIn: false, phases: [] });
48 r.add("/", { at: 3 * WINDOW_MS, ms: 5000, signedIn: false, phases: [] });
49 expect(r.traffic("/", 0).length).toBe(1);
50 expect(r.first("/")).toBe(0);
51 });
52 test("the title is stable, the numbers are in the body", () => {
53 const f = evaluate(seed("/", 4600, 4400), now)[0]!;
54 expect(f.title).toBe("/ is over its budget: kpis");
55 expect(f.evidence).toContain("p95 4600 ms");
56 });
test/perf-duty.test.ts added +76
@@ -0,0 +1,76 @@
1 import { afterAll, beforeAll, expect, spyOn, test } from "bun:test";
2 import { mkdtempSync, rmSync } from "node:fs";
3 import { tmpdir } from "node:os";
4 import { join } from "node:path";
5 import { createRepo } from "../src/actions/repos.ts";
6 import { createApp, type App } from "../src/app.ts";
7 import { listIssues } from "../src/core/issues.ts";
8 import { getRepo } from "../src/core/repos.ts";
9 import { createUser } from "../src/core/users.ts";
10 import { startPerfWatcher } from "../src/perf/duty.ts";
11 import { createPerfRecord, WINDOW_MS } from "../src/perf/record.ts";
12 import { quietLogs } from "./helpers/globals.ts";
13 import { proveAll } from "./helpers/verified.ts";
14
15 quietLogs();
16
17 let root = "";
18 let app: App;
19 const now = 50_000_000;
20
21 beforeAll(async () => {
22 root = mkdtempSync(join(tmpdir(), "forge-perf-duty-"));
23 app = createApp({ dataDir: root, port: 0, forgeRepo: "alice/forge" });
24 const u = await createUser(app.db, {
25 origin: "seed",
26 trusted: true,
27 username: "alice",
28 email: "[email protected]",
29 password: "a-good-passphrase",
30 adminIfFirst: true,
31 });
32 if (!u.ok) throw new Error(u.error);
33 proveAll(app);
34 const made = await createRepo(app, { id: u.value.id, username: "alice" } as never, { name: "forge" });
35 if (!made.ok) throw new Error(made.error);
36 });
37 afterAll(() => {
38 app.close();
39 rmSync(root, { recursive: true, force: true });
40 });
41
42 const titles = () => listIssues(app.db, getRepo(app.db, "alice", "forge")!.id, { state: "open" }).map((i) => i.title);
43 const slow = () => {
44 const r = createPerfRecord();
45 for (let i = 0; i < 100; i++)
46 r.add("/", {
47 at: now - WINDOW_MS + (i * WINDOW_MS) / 100,
48 ms: 4600,
49 signedIn: false,
50 phases: [{ name: "kpis", ms: 4400, hit: false }],
51 });
52 return r;
53 };
54
55 test("the watcher files a slow route once, and a restart skips the title already open", async () => {
56 const stop = startPerfWatcher(app, slow(), () => now, 5);
57 await Bun.sleep(60);
58 stop();
59 expect(titles()).toEqual(["/ is over its budget: kpis"]);
60 const again = startPerfWatcher(app, slow(), () => now, 5);
61 await Bun.sleep(60);
62 again();
63 expect(titles()).toEqual(["/ is over its budget: kpis"]);
64 });
65 test("a missing forge repo is skipped quietly", async () => {
66 const other = createApp({ dataDir: mkdtempSync(join(tmpdir(), "forge-perf-none-")), port: 0, forgeRepo: "nobody/none" });
67 const warn = spyOn(other.log, "warn");
68 const before = other.db.query("SELECT count(*) AS n FROM issue").get() as { n: number };
69 const stop = startPerfWatcher(other, slow(), () => now, 5);
70 await Bun.sleep(30);
71 stop();
72 const after = other.db.query("SELECT count(*) AS n FROM issue").get() as { n: number };
73 other.close();
74 expect(warn).not.toHaveBeenCalled();
75 expect(after.n).toBe(before.n);
76 });
test/perf-loop-lag-attribution.test.ts added +23
@@ -0,0 +1,23 @@
1 import { expect, test } from "bun:test";
2 import { createLoopWatch, stallLine } from "../src/perf/loop.ts";
3
4 test("a stall is named after the route that ran across it", () => {
5 const w = createLoopWatch(250);
6 w.finished("/health", 100, 101);
7 w.finished("/boards", 1000, 9000);
8 const s = w.stalled(8000, 9050)!;
9 expect(s.routes).toEqual(["/boards"]);
10 expect(stallLine(s)).toContain("8000 ms");
11 expect(stallLine(s)).toContain("/boards");
12 });
13 test("a short lag is not a stall", () => {
14 const w = createLoopWatch(250);
15 expect(w.stalled(100, 1)).toBeNull();
16 });
17 test("a stall with no request running says so", () => {
18 const w = createLoopWatch(250);
19 w.finished("/boards", 0, 10);
20 const s = w.stalled(300, 5000)!;
21 expect(s.routes).toEqual([]);
22 expect(stallLine(s)).toContain("no request");
23 });
test/perf-no-pii.test.ts added +17
@@ -0,0 +1,17 @@
1 import { expect, test } from "bun:test";
2 import { createPerfRecord } from "../src/perf/record.ts";
3
4 test("only route patterns are keys: paths with queries, spaces or no slash are dropped", () => {
5 const r = createPerfRecord();
6 const s = { at: 1, ms: 1, signedIn: false, phases: [] };
7 r.add("/alice/secret?token=abc", s);
8 r.add("/alice x", s);
9 r.add("alice", s);
10 r.add("/:owner/:name", s);
11 expect(r.patterns()).toEqual(["/:owner/:name"]);
12 });
13 test("a sample holds timings and signed-in or not, nothing of the viewer", () => {
14 const r = createPerfRecord();
15 r.add("/", { at: 1, ms: 2, signedIn: true, phases: [{ name: "app", ms: 1, hit: false }] });
16 expect(Object.keys(r.traffic("/", 0)[0]!).sort()).toEqual(["at", "ms", "phases", "signedIn"]);
17 });
test/perf-server-hook.test.ts added +44
@@ -0,0 +1,44 @@
1 import { afterAll, beforeAll, expect, test } from "bun:test";
2 import { mkdtempSync, rmSync } from "node:fs";
3 import { tmpdir } from "node:os";
4 import { join } from "node:path";
5 import { createApp, type App } from "../src/app.ts";
6 import { serve, type Servers } from "../src/http/server.ts";
7 import { watchStalls } from "../src/kernel/loop_lag.ts";
8 import { perfRecord } from "../src/perf/live.ts";
9 import { quietLogs } from "./helpers/globals.ts";
10
11 quietLogs();
12
13 let root = "";
14 let app: App;
15 let servers: Servers;
16 beforeAll(async () => {
17 root = mkdtempSync(join(tmpdir(), "forge-perf-hook-"));
18 app = createApp({ dataDir: root, port: 0 });
19 servers = await serve(app);
20 });
21 afterAll(() => {
22 servers.stop();
23 app.close();
24 rmSync(root, { recursive: true, force: true });
25 });
26
27 test("a served request lands in the record under its route pattern; a client label hides nothing", async () => {
28 const before = perfRecord.traffic("/api/v1/health", 0).length;
29 await fetch(`${servers.url}/api/v1/health`);
30 await fetch(`${servers.url}/api/v1/health`, { headers: { "x-forge-synthetic": "1" } });
31 const after = perfRecord.traffic("/api/v1/health", 0);
32 expect(after.length).toBe(before + 2);
33 expect(after.at(-1)!.signedIn).toBe(false);
34 expect(after.at(-1)!.phases.some((p) => p.name === "app")).toBe(true);
35 });
36
37 test("watchStalls hands every wake's lateness to onStall", async () => {
38 const seen: number[] = [];
39 const quiet = { debug() {}, info() {}, warn() {}, error() {} };
40 const stop = watchStalls(quiet, 1e9, 10, undefined, (late) => void seen.push(late));
41 await Bun.sleep(80);
42 stop();
43 expect(seen.length).toBeGreaterThan(0);
44 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs