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

Every git process the forge spawns is timed per subcommand, and the performance watcher files a finding when its p95 passes a budget #8162

Merged opened this

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

Merged

mason/forge:mason/8158-every-git-process-the-forge-spawns-is-ti → main 3 commits fork

  • Merged. mason/8158-every-git-process-the-forge-spawns-is-ti was merged into main as a15d261.

Review

Sign in to review this change.
12 files changed +233 −19
docs/features/performance-watcher.md +1 −1
@@ -1,5 +1,5 @@
11 # Performance watcher (#7559)
22
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.
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. `git.ts` keeps the same record for every git process the forge spawns (`git/env.ts`, `git/local.ts`), keyed `git <subcommand>` from a fixed list (never an argument, path or ref; anything else is `git other`), timed from before the spawn gate so a queue counts; a subcommand whose p95 passes its budget the same way (250 ms; 10 s for the pack-moving ones: clone, fetch, push, gc, repack, pack-objects and the like) files one issue naming it, its count, p50 and p95. `loop.ts` names the routes running across an event-loop stall in the `loop` log line; nothing is kept beyond that line.
44
55 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/git/env.ts +7
@@ -16,6 +16,8 @@ import { tmpdir } from "node:os";
1616 import { join } from "node:path";
1717 import { err, ok, type Result } from "../kernel/result.ts";
1818 import { memoryLimitBytes } from "../core/capacity.ts";
19 import { noteGit } from "../perf/git.ts";
20 import { gitRecord } from "../perf/live.ts";
1921
2022 /** Base env for all server-side git. Nothing from the host leaks in. */
2123 export function gitEnv(extra?: Record<string, string>): Record<string, string> {
@@ -252,6 +254,8 @@ export async function runGitRaw(
252254 args: readonly string[],
253255 options: RunOptions = {},
254256 ): Promise<Result<Uint8Array, GitFailure>> {
257 // Timed from before the gate: a wait for a permit is the queue #8158 names.
258 const start = performance.now();
255259 return gitGate.run(async () => {
256260 const proc = Bun.spawn(["git", ...args], {
257261 ...(options.cwd === undefined ? {} : { cwd: options.cwd }),
@@ -277,6 +281,7 @@ export async function runGitRaw(
277281 } finally {
278282 clearTimeout(timer);
279283 options.signal?.removeEventListener("abort", stop);
284 noteGit(gitRecord, args, start);
280285 }
281286 });
282287 }
@@ -308,6 +313,7 @@ export async function runGitCapture(
308313 args: readonly string[],
309314 options: RunOptions = {},
310315 ): Promise<GitCapture> {
316 const start = performance.now();
311317 return gitGate.run(async () => {
312318 const proc = Bun.spawn(["git", ...args], {
313319 ...(options.cwd === undefined ? {} : { cwd: options.cwd }),
@@ -333,6 +339,7 @@ export async function runGitCapture(
333339 return { code, stdout, stderr, ...(timedOut ? { timedOut } : {}) };
334340 } finally {
335341 clearTimeout(timer);
342 noteGit(gitRecord, args, start);
336343 }
337344 });
338345 }
src/git/local.ts +15 −5
@@ -19,6 +19,8 @@ import { err, ok, type Result } from "../kernel/result.ts";
1919 import { parseUnifiedDiff, type Diff, type Hunk } from "./diff.ts";
2020 import type { GitFailure } from "./env.ts";
2121 import { isSafeRef } from "./guard.ts";
22 import { noteGit } from "../perf/git.ts";
23 import { gitRecord } from "../perf/live.ts";
2224
2325 export type { GitFailure };
2426 export type LocalResult<T> = Result<T, GitFailure>;
@@ -62,6 +64,7 @@ export async function runLocal(
6264 args: readonly string[],
6365 opts: RunOpts,
6466 ): Promise<LocalResult<string>> {
67 const start = performance.now();
6568 const proc = Bun.spawn(["git", ...args], {
6669 cwd: opts.cwd,
6770 env: localGitEnv(opts.env),
@@ -83,6 +86,7 @@ export async function runLocal(
8386 return ok(stdout);
8487 } finally {
8588 clearTimeout(timer);
89 noteGit(gitRecord, args, start);
8690 }
8791 }
8892
@@ -357,17 +361,23 @@ export async function diff(
357361 "/dev/null",
358362 opts.path,
359363 ];
364 const start = performance.now();
360365 const proc = Bun.spawn(["git", ...args], {
361366 cwd: dir,
362367 env: localGitEnv(),
363368 stdout: "pipe",
364369 stderr: "pipe",
365370 });
366 const [text, stderr, code] = await Promise.all([
367 new Response(proc.stdout).text(),
368 new Response(proc.stderr).text(),
369 proc.exited,
370 ]);
371 let text: string, stderr: string, code: number;
372 try {
373 [text, stderr, code] = await Promise.all([
374 new Response(proc.stdout).text(),
375 new Response(proc.stderr).text(),
376 proc.exited,
377 ]);
378 } finally {
379 noteGit(gitRecord, args, start);
380 }
371381 if (code > 1) return err({ code, stderr: stderr.trim(), args });
372382 return ok(parseUnifiedDiff(text));
373383 }
src/main.ts +3 −3
@@ -83,9 +83,9 @@ import { reapLeftoverBridges } from "./crew/leftovers.ts";
8383 import { crewRoot } from "./crew/workdir.ts";
8484 import { createLog } from "./kernel/log.ts";
8585 import { watchStalls } from "./kernel/loop_lag.ts";
86 import { startPerfWatcher } from "./perf/duty.ts";
86 import { startPerfWatcher, TICK_MS } from "./perf/duty.ts";
8787 import { stallLine } from "./perf/loop.ts";
88 import { loopWatch, perfRecord } from "./perf/live.ts";
88 import { gitRecord, loopWatch, perfRecord } from "./perf/live.ts";
8989 import { timeStatements } from "./kernel/slow_sql.ts";
9090 import { waitForPeer } from "./runs/peer.ts";
9191
@@ -305,7 +305,7 @@ loadTrustedHosts(app.db);
305305 const bootSignup = signupFromEnv(process.env.FORGE_SIGNUP);
306306 if (bootSignup.ok && bootSignup.value !== null)
307307 setSignup(app.db, bootSignup.value, BOOT_ACTOR);
308 startPerfWatcher(app, perfRecord);
308 startPerfWatcher(app, perfRecord, Date.now, TICK_MS, gitRecord);
309309 const flagTimer = setInterval(() => flushFlagUses(app.db), 10_000);
310310 await reconcile(app);
311311 // Issues linked under a pillar's umbrella before pillars had labels.
src/perf/budgets.ts +19 −1
@@ -1,4 +1,4 @@
1 /** Budgets per route pattern, in words with the number beside it (#7559). One file. */
1 /** Budgets per route pattern and per git subcommand, in words with the number beside it (#7559, #8158). One file. */
22
33 export interface Budget {
44 /** The router pattern, or a prefix ending in `*`. */
@@ -24,3 +24,21 @@ export function budgetFor(pattern: string): Budget | undefined {
2424 BUDGETS.find((b) => b.pattern.endsWith("*") && pattern.startsWith(b.pattern.slice(0, -1)))
2525 );
2626 }
27
28 /** A plumbing git subcommand's budget (#8158): a single process past this at p95 is a queue or a loaded machine. */
29 export const GIT_BUDGET: Budget = { pattern: "git *", words: "each git process p95 under 250 ms", p95Ms: 250 };
30
31 /**
32 * Subcommands that move or rewrite whole packs are slow on a healthy machine,
33 * so 250 ms would file a finding per subcommand; they are held to 10 s.
34 */
35 const HEAVY_GIT = new Set([
36 "clone", "fetch", "pull", "push", "gc", "repack", "pack-objects", "index-pack",
37 "unpack-objects", "archive", "bundle", "upload-pack", "receive-pack", "fsck", "prune",
38 ]);
39 export const HEAVY_GIT_BUDGET: Budget = { pattern: "git *", words: "a pack-moving git process p95 under 10 s", p95Ms: 10_000 };
40
41 /** The budget a `git <subcommand>` key is held to. */
42 export function gitBudgetFor(key: string): Budget {
43 return HEAVY_GIT.has(key.slice(4)) ? HEAVY_GIT_BUDGET : GIT_BUDGET;
44 }
src/perf/duty.ts +8 −5
@@ -1,8 +1,8 @@
11 /**
22 * 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.
3 * file each new finding, of a route or of a git subcommand (#8158), as one
4 * issue in the forge's own repository, opened by its owner. A title already
5 * open is not filed twice, and neither is a key this process has filed.
66 */
77
88 import type { App } from "../app.ts";
@@ -10,8 +10,9 @@ import { openIssue } from "../actions/issues.ts";
1010 import { getUserById } from "../core/users.ts";
1111 import { getRepo } from "../core/repos.ts";
1212 import { listIssues } from "../core/issues.ts";
13 import { createGitRecord } from "./git.ts";
1314 import type { PerfRecord } from "./record.ts";
14 import { evaluate, fresh } from "./watch.ts";
15 import { evaluate, evaluateGit, fresh } from "./watch.ts";
1516
1617 export const TICK_MS = 60_000;
1718
@@ -20,6 +21,7 @@ export function startPerfWatcher(
2021 record: PerfRecord,
2122 now: () => number = Date.now,
2223 everyMs = TICK_MS,
24 gitRecord: PerfRecord = createGitRecord(),
2325 ): () => void {
2426 const filed = new Set<string>();
2527 const tick = (): void => {
@@ -31,7 +33,8 @@ export function startPerfWatcher(
3133 const actor = repo && getUserById(app.db, repo.ownerId);
3234 if (!repo || !actor) return;
3335 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)) {
36 const findings = [...evaluate(record, now()), ...evaluateGit(gitRecord, now())];
37 for (const f of fresh(findings, filed)) {
3538 if (open.has(f.title)) continue;
3639 openIssue(app, actor, repo, { title: f.title, body: f.evidence });
3740 }
src/perf/git.ts added +49
@@ -0,0 +1,49 @@
1 /**
2 * The rolling record of git processes (#8158): per subcommand, each spawn's
3 * wall time, waiting for a permit included, so a queue of git processes on a
4 * loaded machine is named rather than smeared across slow routes. The record
5 * is the route record's (`record.ts`: 15-minute window, bounded samples and
6 * keys); only the key differs. A key is `git <subcommand>` and the subcommand
7 * is from a fixed list, so no argument, path or ref can ever be kept: anything
8 * else is `git other`.
9 */
10
11 import { createPerfRecord, type PerfRecord } from "./record.ts";
12
13 const SUBCOMMANDS = new Set([
14 "add", "apply", "archive", "blame", "branch", "bundle", "cat-file", "checkout",
15 "checkout-index", "cherry-pick", "clean", "clone", "commit", "commit-tree",
16 "config", "count-objects", "diff", "diff-tree", "fetch", "for-each-ref", "fsck",
17 "gc", "grep", "hash-object", "index-pack", "init", "log", "ls-files", "ls-remote",
18 "ls-tree", "merge", "merge-base", "merge-file", "merge-tree", "mktree", "mv",
19 "name-rev", "pack-objects", "pack-refs", "prune", "pull", "push", "read-tree",
20 "rebase", "receive-pack", "reflog", "remote", "repack", "replay", "reset",
21 "restore", "rev-list", "rev-parse", "revert", "rm", "show", "show-ref", "stash",
22 "status", "switch", "symbolic-ref", "tag", "unpack-objects", "update-index",
23 "update-ref", "update-server-info", "upload-pack", "verify-pack", "worktree",
24 "write-tree",
25 ]);
26
27 /** Global options that take their value as the next argument. */
28 const VALUED = new Set(["-C", "-c", "--git-dir", "--work-tree", "--namespace", "--exec-path", "--config-env"]);
29
30 export const OTHER = "git other";
31
32 /** `git rev-parse` for `["-C", dir, "rev-parse", "--verify", ref]`; never an argument. */
33 export function gitKey(args: readonly string[]): string {
34 let i = 0;
35 while (i < args.length && args[i]!.startsWith("-")) i += VALUED.has(args[i]!) ? 2 : 1;
36 const sub = args[i];
37 return sub !== undefined && SUBCOMMANDS.has(sub) ? `git ${sub}` : OTHER;
38 }
39
40 const validKey = (key: string): boolean => key === OTHER || (key.startsWith("git ") && SUBCOMMANDS.has(key.slice(4)));
41
42 export function createGitRecord(): PerfRecord {
43 return createPerfRecord(validKey);
44 }
45
46 /** Note one finished git process that started at `start` (performance.now()). */
47 export function noteGit(record: PerfRecord, args: readonly string[], start: number): void {
48 record.add(gitKey(args), { at: Date.now(), ms: performance.now() - start, signedIn: false, phases: [] });
49 }
src/perf/live.ts +3 −1
@@ -1,7 +1,9 @@
1 /** The process's one record and loop watch (#7559): what the server feeds and the duty reads. */
1 /** The process's one record, git record (#8158) and loop watch (#7559): what the server feeds and the duty reads. */
22
3 import { createGitRecord } from "./git.ts";
34 import { createLoopWatch } from "./loop.ts";
45 import { createPerfRecord } from "./record.ts";
56
67 export const perfRecord = createPerfRecord();
78 export const loopWatch = createLoopWatch();
9 export const gitRecord = createGitRecord();
src/perf/record.ts +3 −2
@@ -48,12 +48,13 @@ export function percentile(xs: readonly number[], p: number): number | null {
4848 return sorted[Math.max(1, Math.ceil((p / 100) * sorted.length)) - 1]!;
4949 }
5050
51 export function createPerfRecord(): PerfRecord {
51 /** `valid` says which keys are kept: route patterns here, `git <subcommand>` in `git.ts`. */
52 export function createPerfRecord(valid: (key: string) => boolean = validPattern): PerfRecord {
5253 const real = new Map<string, Sample[]>();
5354 const firsts = new Map<string, number>();
5455 return {
5556 add(pattern, sample) {
56 if (!validPattern(pattern) || !Number.isFinite(sample.ms) || sample.ms < 0) return;
57 if (!valid(pattern) || !Number.isFinite(sample.ms) || sample.ms < 0) return;
5758 let list = real.get(pattern);
5859 if (list === undefined) {
5960 if (real.size >= MAX_PATTERNS) return;
src/perf/watch.ts +28 −1
@@ -6,7 +6,7 @@
66 */
77
88 import { found, type Finding } from "../hunt/finding.ts";
9 import { budgetFor } from "./budgets.ts";
9 import { budgetFor, gitBudgetFor } from "./budgets.ts";
1010 import { summarize, WINDOW_MS, type PerfRecord } from "./record.ts";
1111
1212 export { WINDOW_MS };
@@ -55,6 +55,33 @@ export function evaluate(record: PerfRecord, now: number): Finding[] {
5555 return out;
5656 }
5757
58 /**
59 * A git subcommand whose p95 has been over its `gitBudgetFor` for the window (#8158),
60 * held to the route rule: enough processes, watched most of the window. One
61 * key per subcommand, so one issue.
62 */
63 export function evaluateGit(record: PerfRecord, now: number): Finding[] {
64 const out: Finding[] = [];
65 for (const key of record.patterns()) {
66 const budget = gitBudgetFor(key);
67 const stat = summarize(record.traffic(key, now - WINDOW_MS));
68 if (stat === null || stat.n < MIN_REQUESTS || stat.p95 <= budget.p95Ms) continue;
69 if (now - (record.first(key) ?? now) < WINDOW_MS * 0.9) continue;
70 out.push(
71 found(
72 "performance-watcher",
73 key,
74 `${key} is over its budget`,
75 [
76 `Budget: ${budget.words} (${budget.p95Ms} ms), waiting for a permit included.`,
77 `Subcommand: ${key}, ${stat.n} processes in 15 min: p50 ${Math.round(stat.p50)} ms, p95 ${Math.round(stat.p95)} ms, p99 ${Math.round(stat.p99)} ms.`,
78 ].join("\n"),
79 ),
80 );
81 }
82 return out;
83 }
84
5885 /** The findings not filed before; `filed` remembers keys, so each is offered once. */
5986 export function fresh(findings: readonly Finding[], filed: Set<string>): Finding[] {
6087 const out = findings.filter((f) => !filed.has(f.key));
test/perf-duty.test.ts +10
@@ -8,6 +8,7 @@ import { listIssues } from "../src/core/issues.ts";
88 import { getRepo } from "../src/core/repos.ts";
99 import { createUser } from "../src/core/users.ts";
1010 import { startPerfWatcher } from "../src/perf/duty.ts";
11 import { createGitRecord } from "../src/perf/git.ts";
1112 import { createPerfRecord, WINDOW_MS } from "../src/perf/record.ts";
1213 import { quietLogs } from "./helpers/globals.ts";
1314 import { proveAll } from "./helpers/verified.ts";
@@ -74,3 +75,12 @@ test("a missing forge repo is skipped quietly", async () => {
7475 expect(warn).not.toHaveBeenCalled();
7576 expect(after.n).toBe(before.n);
7677 });
78 test("the watcher files a slow git subcommand once (#8158)", async () => {
79 const git = createGitRecord();
80 for (let i = 0; i < 100; i++)
81 git.add("git rev-parse", { at: now - WINDOW_MS + (i * WINDOW_MS) / 100, ms: 7000, signedIn: false, phases: [] });
82 const stop = startPerfWatcher(app, createPerfRecord(), () => now, 5, git);
83 await Bun.sleep(60);
84 stop();
85 expect(titles().filter((t) => t.startsWith("git "))).toEqual(["git rev-parse is over its budget"]);
86 });
test/perf-git.test.ts added +87
@@ -0,0 +1,87 @@
1 import { 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 { runGit, runGitCapture } from "../src/git/env.ts";
6 import { GIT_BUDGET, HEAVY_GIT_BUDGET } from "../src/perf/budgets.ts";
7 import { createGitRecord, gitKey, OTHER } from "../src/perf/git.ts";
8 import { gitRecord } from "../src/perf/live.ts";
9 import { MAX_PATTERNS, MAX_SAMPLES } from "../src/perf/record.ts";
10 import { evaluateGit, fresh, WINDOW_MS } from "../src/perf/watch.ts";
11
12 const now = 10_000_000;
13 function seed(sub: string, ms: number, n = 100) {
14 const r = createGitRecord();
15 for (let i = 0; i < n; i++)
16 r.add(`git ${sub}`, { at: now - WINDOW_MS + (i * WINDOW_MS) / n, ms, signedIn: false, phases: [] });
17 return r;
18 }
19
20 test("the key is the subcommand alone, past global options, never an argument", () => {
21 expect(gitKey(["rev-parse", "--verify", "refs/heads/secret"])).toBe("git rev-parse");
22 expect(gitKey(["-C", "/srv/repos/alice/x.git", "-c", "core.quotepath=off", "merge-tree", "a", "b"])).toBe("git merge-tree");
23 expect(gitKey(["--git-dir=/srv/x.git", "cat-file", "blob", "HEAD:secret.txt"])).toBe("git cat-file");
24 expect(gitKey(["/srv/repos/alice/x.git"])).toBe(OTHER);
25 expect(gitKey(["refs/heads/main"])).toBe(OTHER);
26 expect(gitKey([])).toBe(OTHER);
27 });
28
29 test("a key that is not git and a subcommand is dropped", () => {
30 const r = createGitRecord();
31 for (const key of ["git /srv/x.git", "/", "git refs/heads/main", "rev-parse"])
32 r.add(key, { at: now, ms: 5, signedIn: false, phases: [] });
33 expect(r.patterns()).toEqual([]);
34 });
35
36 test("the spawn helpers record each process under its subcommand, without arguments", async () => {
37 const dir = mkdtempSync(join(tmpdir(), "forge-perf-git-"));
38 try {
39 const before = gitRecord.traffic("git init", 0).length;
40 expect((await runGit(["init", "--quiet", join(dir, "secret-repo-name")])).ok).toBe(true);
41 await runGitCapture(["-C", join(dir, "secret-repo-name"), "rev-parse", "refs/heads/secret-branch"]);
42 expect(gitRecord.traffic("git init", 0).length).toBe(before + 1);
43 expect(gitRecord.traffic("git rev-parse", 0).length).toBeGreaterThan(0);
44 const kept = JSON.stringify(gitRecord.patterns().map((k) => [k, gitRecord.traffic(k, 0)]));
45 expect(kept).not.toContain("secret");
46 expect(kept).not.toContain(dir);
47 } finally {
48 rmSync(dir, { recursive: true, force: true });
49 }
50 });
51
52 test("a slow rev-parse past the budget files exactly one finding naming it, its count, p50 and p95", () => {
53 const filed = new Set<string>();
54 const f = evaluateGit(seed("rev-parse", 7000), now);
55 expect(f.length).toBe(1);
56 expect(f[0]!.key).toBe("performance-watcher:git rev-parse");
57 expect(f[0]!.title).toBe("git rev-parse is over its budget");
58 expect(f[0]!.evidence).toContain("git rev-parse, 100 processes in 15 min: p50 7000 ms, p95 7000 ms");
59 expect(f[0]!.evidence).toContain(`${GIT_BUDGET.p95Ms} ms`);
60 expect(fresh(f, filed).length).toBe(1);
61 expect(fresh(evaluateGit(seed("rev-parse", 7000), now), filed).length).toBe(0);
62 });
63
64 test("a fast subcommand, too few processes, or a young one file nothing", () => {
65 expect(evaluateGit(seed("rev-parse", 20), now)).toEqual([]);
66 expect(evaluateGit(seed("rev-parse", 7000, 5), now)).toEqual([]);
67 const r = createGitRecord();
68 for (let i = 0; i < 50; i++) r.add("git rev-parse", { at: now - 1000, ms: 7000, signedIn: false, phases: [] });
69 expect(evaluateGit(r, now)).toEqual([]);
70 });
71
72 test("a slow clone or repack past 250 ms files nothing; past its own budget it files one", () => {
73 for (const sub of ["clone", "repack", "fetch", "push", "gc", "pack-objects", "upload-pack", "receive-pack"])
74 expect(evaluateGit(seed(sub, 3000), now)).toEqual([]);
75 const f = evaluateGit(seed("repack", 12_000), now);
76 expect(f.length).toBe(1);
77 expect(f[0]!.evidence).toContain(`${HEAVY_GIT_BUDGET.p95Ms} ms`);
78 });
79
80 test("the record stays bounded in samples and keys", () => {
81 const r = createGitRecord();
82 for (let i = 0; i < MAX_SAMPLES * 2 + 10; i++) r.add("git rev-parse", { at: now, ms: 1, signedIn: false, phases: [] });
83 expect(r.traffic("git rev-parse", 0).length).toBeLessThanOrEqual(MAX_SAMPLES);
84 for (let i = 0; i < MAX_PATTERNS * 2; i++) r.add(gitKey([`sub${i}`]), { at: now, ms: 1, signedIn: false, phases: [] });
85 expect(r.patterns().length).toBeLessThanOrEqual(MAX_PATTERNS);
86 expect(r.patterns()).toEqual(["git rev-parse", OTHER]);
87 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs