Public: anyone can read this; the crew can change it.
Find what stalled the forge's event loop ~2.8 s just after 0.7.287 booted (the /healthz the release proof saw) #8688
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/7688-find-what-stalled-the-forge-s-event-loop → main 2 commits fork 1 thread · 1 unresolved
4 files
changed +72
−38
src/checks/service.ts +40 −22
| @@ -12,7 +12,8 @@ | ||
| 12 | 12 | */ |
| 13 | 13 | |
| 14 | 14 | import { pullDir, runDir } from "../core/pulls.ts"; |
| 15 | import { chmodSync, existsSync, lstatSync, mkdirSync, readFileSync, readdirSync, rmSync } from "node:fs"; | |
| 15 | import { existsSync, lstatSync, mkdirSync, readFileSync, readdirSync } from "node:fs"; | |
| 16 | import { chmod, lstat, readdir, rm } from "node:fs/promises"; | |
| 16 | 17 | import { tmpdir } from "node:os"; |
| 17 | 18 | import { join } from "node:path"; |
| 18 | 19 | import type { App } from "../app.ts"; |
| @@ -317,8 +318,9 @@ export function requeueAbandonedChecks(app: App, staleMs: number): number { | ||
| 317 | 318 | appendRunLog(app.config.dataDir, run.id, run.summary); |
| 318 | 319 | announceRun(app, run); |
| 319 | 320 | } |
| 320 | // On the same timer: what a dead or lapsed run left on the disk. | |
| 321 | sweepCheckouts(app); | |
| 321 | // On the same timer: what a dead or lapsed run left on the disk. Removing | |
| 322 | // a checkout is thousands of unlinks: off the loop, never in front of /healthz (#7688). | |
| 323 | sweepSoon(app); | |
| 322 | 324 | return swept.requeued.length + swept.failed.length + swept.cancelled.length; |
| 323 | 325 | } |
| 324 | 326 | |
| @@ -328,32 +330,48 @@ export function requeueAbandonedChecks(app: App, staleMs: number): number { | ||
| 328 | 330 | * permission, so permissions are restored and the removal tried again. A |
| 329 | 331 | * removal that still fails is logged, never swallowed. |
| 330 | 332 | */ |
| 331 | export function removeRunDir(path: string): void { | |
| 333 | export async function removeRunDir(path: string): Promise<void> { | |
| 332 | 334 | try { |
| 333 | rmSync(path, { recursive: true, force: true }); | |
| 335 | await rm(path, { recursive: true, force: true }); | |
| 334 | 336 | return; |
| 335 | 337 | } catch { |
| 336 | 338 | /* fall through to restore permissions */ |
| 337 | 339 | } |
| 338 | const open = (p: string): void => { | |
| 340 | const open = async (p: string): Promise<void> => { | |
| 339 | 341 | try { |
| 340 | if (lstatSync(p).isSymbolicLink()) return; | |
| 341 | if (lstatSync(p).isDirectory()) { | |
| 342 | chmodSync(p, 0o700); | |
| 343 | for (const n of readdirSync(p)) open(join(p, n)); | |
| 342 | if ((await lstat(p)).isSymbolicLink()) return; | |
| 343 | if ((await lstat(p)).isDirectory()) { | |
| 344 | await chmod(p, 0o700); | |
| 345 | for (const n of await readdir(p)) await open(join(p, n)); | |
| 344 | 346 | } |
| 345 | 347 | } catch { |
| 346 | 348 | /* gone, or not ours: the retry says */ |
| 347 | 349 | } |
| 348 | 350 | }; |
| 349 | open(path); | |
| 351 | await open(path); | |
| 350 | 352 | try { |
| 351 | rmSync(path, { recursive: true, force: true }); | |
| 353 | await rm(path, { recursive: true, force: true }); | |
| 352 | 354 | } catch (error) { |
| 353 | 355 | log.error("could not remove a run directory", { path, error: String(error) }); |
| 354 | 356 | } |
| 355 | 357 | } |
| 356 | 358 | |
| 359 | /** The sweep of the checkouts under way, if any: one at a time. */ | |
| 360 | let sweeping: Promise<void> | undefined; | |
| 361 | ||
| 362 | /** | |
| 363 | * Sweep the checkouts in the background and answer when done. A sweep | |
| 364 | * already running is the one answered, not doubled; a failure is logged. | |
| 365 | */ | |
| 366 | export function sweepSoon(app: App, now: number = Date.now()): Promise<void> { | |
| 367 | sweeping ??= sweepCheckouts(app, now) | |
| 368 | .catch((error) => log.error("could not sweep the checkouts", { error: String(error) })) | |
| 369 | .finally(() => { | |
| 370 | sweeping = undefined; | |
| 371 | }); | |
| 372 | return sweeping; | |
| 373 | } | |
| 374 | ||
| 357 | 375 | /** Where a check's checkout lives while it runs. */ |
| 358 | 376 | const checksRoot = (dataDir: string): string => join(dataDir, "checks"); |
| 359 | 377 | |
| @@ -377,7 +395,7 @@ function gateMayBeRunning(path: string, now: number): boolean { | ||
| 377 | 395 | * while it is younger than a gate's deadline, and past that while its |
| 378 | 396 | * `check_gate` row is open, for as long as a check may run. |
| 379 | 397 | */ |
| 380 | export function sweepCheckouts(app: App, now: number = Date.now()): void { | |
| 398 | export async function sweepCheckouts(app: App, now: number = Date.now()): Promise<void> { | |
| 381 | 399 | const root = checksRoot(app.config.dataDir); |
| 382 | 400 | if (!existsSync(root)) return; |
| 383 | 401 | const since = new Date(now - CHECK_TIMEOUT_MAX * 1000); |
| @@ -388,7 +406,7 @@ export function sweepCheckouts(app: App, now: number = Date.now()): void { | ||
| 388 | 406 | const id = name.endsWith(".home") ? name.slice(0, -5) : name; |
| 389 | 407 | const gate = GATE_DIR.exec(id); |
| 390 | 408 | if (gate !== null) { |
| 391 | if (!gateHolding(app.db, gate[1]!, since)) removeRunDir(join(root, name)); | |
| 409 | if (!gateHolding(app.db, gate[1]!, since)) await removeRunDir(join(root, name)); | |
| 392 | 410 | continue; |
| 393 | 411 | } |
| 394 | 412 | const run = getRun(app.db, id); |
| @@ -396,7 +414,7 @@ export function sweepCheckouts(app: App, now: number = Date.now()): void { | ||
| 396 | 414 | run !== undefined && |
| 397 | 415 | run.state === "running" && |
| 398 | 416 | !leaseLapsed(run, STALE_AFTER_MS, now); |
| 399 | if (!live) removeRunDir(join(root, name)); | |
| 417 | if (!live) await removeRunDir(join(root, name)); | |
| 400 | 418 | } |
| 401 | 419 | } |
| 402 | 420 | |
| @@ -405,9 +423,9 @@ export function sweepCheckouts(app: App, now: number = Date.now()): void { | ||
| 405 | 423 | * (#6945): checkouts leaked by a crash sat on the disk until the next boot |
| 406 | 424 | * while every check failed red on it. Answers whether it swept. |
| 407 | 425 | */ |
| 408 | export function reclaimIfFull(app: App, now: number = Date.now()): boolean { | |
| 426 | export async function reclaimIfFull(app: App, now: number = Date.now()): Promise<boolean> { | |
| 409 | 427 | if (diskRecovered(app.config.dataDir)) return false; |
| 410 | sweepCheckouts(app, now); | |
| 428 | await sweepCheckouts(app, now); | |
| 411 | 429 | return true; |
| 412 | 430 | } |
| 413 | 431 | |
| @@ -449,7 +467,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 449 | 467 | const settle = options.landSettleMs ?? 0; |
| 450 | 468 | let stopped = false; |
| 451 | 469 | |
| 452 | sweepCheckouts(app); | |
| 470 | sweepSoon(app); | |
| 453 | 471 | |
| 454 | 472 | async function request( |
| 455 | 473 | repo: Repo, |
| @@ -1068,7 +1086,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 1068 | 1086 | write(`already proven green by ${earlier}`); |
| 1069 | 1087 | return { ok: true, proven: earlier }; |
| 1070 | 1088 | } |
| 1071 | if (reclaimIfFull(app)) write("disk under its free floor: swept unused checkouts"); | |
| 1089 | if (await reclaimIfFull(app)) write("disk under its free floor: swept unused checkouts"); | |
| 1072 | 1090 | const dir = join(checksRoot(app.config.dataDir), run.id); |
| 1073 | 1091 | mkdirSync(dir, { recursive: true }); |
| 1074 | 1092 | write(mergeLine === "" ? `checking out ${run.commitOid.slice(0, 7)}` : mergeLine); |
| @@ -1077,7 +1095,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 1077 | 1095 | if (base !== undefined) { |
| 1078 | 1096 | const given = await giveHistory(bare, dir, base, run.commitOid); |
| 1079 | 1097 | if (!given.ok) { |
| 1080 | rmSync(dir, { recursive: true, force: true }); | |
| 1098 | await rm(dir, { recursive: true, force: true }); | |
| 1081 | 1099 | return { ok: false, error: given.error }; |
| 1082 | 1100 | } |
| 1083 | 1101 | } |
| @@ -1421,8 +1439,8 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 1421 | 1439 | if (key !== undefined) recordProven(app.db, key, x.id); |
| 1422 | 1440 | return { ok: true }; |
| 1423 | 1441 | } finally { |
| 1424 | if (existsSync(dir)) removeRunDir(dir); | |
| 1425 | removeRunDir(home); | |
| 1442 | if (existsSync(dir)) await removeRunDir(dir); | |
| 1443 | await removeRunDir(home); | |
| 1426 | 1444 | } |
| 1427 | 1445 | } |
| 1428 | 1446 |
test/checks-disk-red.test.ts +2 −2
| @@ -166,10 +166,10 @@ describe("a full check machine gives back unused checkouts", () => { | ||
| 166 | 166 | const orphan = join(dataDir, "checks", "orphan"); |
| 167 | 167 | mkdirSync(orphan, { recursive: true }); |
| 168 | 168 | diskReading.read = () => ({ freeBytes: 500, totalBytes: 1000 }); |
| 169 | expect(reclaimIfFull(app)).toBe(false); | |
| 169 | expect(await reclaimIfFull(app)).toBe(false); | |
| 170 | 170 | expect(existsSync(orphan)).toBe(true); |
| 171 | 171 | diskReading.read = () => ({ freeBytes: 50, totalBytes: 1000 }); |
| 172 | expect(reclaimIfFull(app)).toBe(true); | |
| 172 | expect(await reclaimIfFull(app)).toBe(true); | |
| 173 | 173 | expect(existsSync(orphan)).toBe(false); |
| 174 | 174 | } finally { |
| 175 | 175 | diskReading.read = statDisk; |
test/checks-home-sweep.test.ts +28 −14
| @@ -13,7 +13,7 @@ import { tmpdir } from "node:os"; | ||
| 13 | 13 | import { join } from "node:path"; |
| 14 | 14 | import { createApp, type App } from "../src/app.ts"; |
| 15 | 15 | import { createRepo } from "../src/actions/repos.ts"; |
| 16 | import { requeueAbandonedChecks, sweepCheckouts } from "../src/checks/service.ts"; | |
| 16 | import { requeueAbandonedChecks, sweepCheckouts, sweepSoon } from "../src/checks/service.ts"; | |
| 17 | 17 | import { beginGate, endGate } from "../src/checks/gate_record.ts"; |
| 18 | 18 | import { ensureEnvData, removeEnv } from "../src/apps/data.ts"; |
| 19 | 19 | import { claimRun, createRun, finishRun } from "../src/core/runs.ts"; |
| @@ -55,7 +55,7 @@ const populate = (id: string, readOnly = false): void => { | ||
| 55 | 55 | }; |
| 56 | 56 | const run = () => createRun(app.db, { repoId, kind: "check", env: "x", commitOid: "a".repeat(40) }); |
| 57 | 57 | |
| 58 | test("a finished run's home is removed, a live run's survives", () => { | |
| 58 | test("a finished run's home is removed, a live run's survives", async () => { | |
| 59 | 59 | const live = run(); |
| 60 | 60 | claimRun(app.db, live.id); |
| 61 | 61 | const done = run(); |
| @@ -64,13 +64,13 @@ test("a finished run's home is removed, a live run's survives", () => { | ||
| 64 | 64 | populate(live.id); |
| 65 | 65 | populate(done.id); |
| 66 | 66 | populate("no-such-run"); |
| 67 | sweepCheckouts(app); | |
| 67 | await sweepCheckouts(app); | |
| 68 | 68 | expect(existsSync(home(live.id))).toBe(true); |
| 69 | 69 | expect(existsSync(home(done.id))).toBe(false); |
| 70 | 70 | expect(existsSync(home("no-such-run"))).toBe(false); |
| 71 | 71 | }); |
| 72 | 72 | |
| 73 | test("the abandoned-checks timer sweeps a finished run's home, not a live one's", () => { | |
| 73 | test("the abandoned-checks timer sweeps a finished run's home, not a live one's", async () => { | |
| 74 | 74 | const live = run(); |
| 75 | 75 | claimRun(app.db, live.id); |
| 76 | 76 | const done = run(); |
| @@ -79,11 +79,25 @@ test("the abandoned-checks timer sweeps a finished run's home, not a live one's" | ||
| 79 | 79 | populate(live.id); |
| 80 | 80 | populate(done.id); |
| 81 | 81 | requeueAbandonedChecks(app, STALE_AFTER_MS); |
| 82 | // Removal is off the loop (#7688): the call returned with the home still there. | |
| 83 | expect(existsSync(home(done.id))).toBe(true); | |
| 84 | await sweepSoon(app); | |
| 82 | 85 | expect(existsSync(home(live.id))).toBe(true); |
| 83 | 86 | expect(existsSync(home(done.id))).toBe(false); |
| 84 | 87 | }); |
| 85 | 88 | |
| 86 | test("the timer leaves a running gate's checkout and home alone, and removes them once no gate could be using them", () => { | |
| 89 | test("sweeping a checkout hands the loop back before it finishes (#7688)", async () => { | |
| 90 | const done = run(); | |
| 91 | claimRun(app.db, done.id); | |
| 92 | finishRun(app.db, done.id, { state: "ok", summary: "ok" }); | |
| 93 | populate(done.id); | |
| 94 | const sweep = sweepSoon(app); | |
| 95 | expect(existsSync(home(done.id))).toBe(true); | |
| 96 | await sweep; | |
| 97 | expect(existsSync(home(done.id))).toBe(false); | |
| 98 | }); | |
| 99 | ||
| 100 | test("the timer leaves a running gate's checkout and home alone, and removes them once no gate could be using them", async () => { | |
| 87 | 101 | const root = join(dataDir, "checks"); |
| 88 | 102 | const dir = join(root, "gate-0123456789ab"); |
| 89 | 103 | const home = `${dir}.home`; |
| @@ -92,29 +106,29 @@ test("the timer leaves a running gate's checkout and home alone, and removes the | ||
| 92 | 106 | requeueAbandonedChecks(app, STALE_AFTER_MS); |
| 93 | 107 | expect(existsSync(dir)).toBe(true); |
| 94 | 108 | expect(existsSync(home)).toBe(true); |
| 95 | sweepCheckouts(app, Date.now() + GATE_DEADLINE_MS + 60_000); | |
| 109 | await sweepCheckouts(app, Date.now() + GATE_DEADLINE_MS + 60_000); | |
| 96 | 110 | expect(existsSync(dir)).toBe(false); |
| 97 | 111 | expect(existsSync(home)).toBe(false); |
| 98 | 112 | }); |
| 99 | 113 | |
| 100 | test("a lapsed run's home is removed", () => { | |
| 114 | test("a lapsed run's home is removed", async () => { | |
| 101 | 115 | const r = run(); |
| 102 | 116 | claimRun(app.db, r.id); |
| 103 | 117 | populate(r.id); |
| 104 | sweepCheckouts(app, Date.now() + 24 * 3600_000); | |
| 118 | await sweepCheckouts(app, Date.now() + 24 * 3600_000); | |
| 105 | 119 | expect(existsSync(home(r.id))).toBe(false); |
| 106 | 120 | }); |
| 107 | 121 | |
| 108 | test("a home with a read-only file is still removed", () => { | |
| 122 | test("a home with a read-only file is still removed", async () => { | |
| 109 | 123 | const r = run(); |
| 110 | 124 | claimRun(app.db, r.id); |
| 111 | 125 | finishRun(app.db, r.id, { state: "failed", summary: "red" }); |
| 112 | 126 | populate(r.id, true); |
| 113 | sweepCheckouts(app); | |
| 127 | await sweepCheckouts(app); | |
| 114 | 128 | expect(existsSync(home(r.id))).toBe(false); |
| 115 | 129 | }); |
| 116 | 130 | |
| 117 | test("tearing a preview down removes its home", () => { | |
| 131 | test("tearing a preview down removes its home", async () => { | |
| 118 | 132 | ensureEnvData(dataDir, "app1", "pull-1", "empty"); |
| 119 | 133 | const h = join(dataDir, "apps", "app1", "pull-1", "home"); |
| 120 | 134 | mkdirSync(h, { recursive: true }); |
| @@ -123,7 +137,7 @@ test("tearing a preview down removes its home", () => { | ||
| 123 | 137 | expect(existsSync(h)).toBe(false); |
| 124 | 138 | }); |
| 125 | 139 | |
| 126 | test("a gate's open row keeps its checkout and home past the deadline window; a finished gate's go", () => { | |
| 140 | test("a gate's open row keeps its checkout and home past the deadline window; a finished gate's go", async () => { | |
| 127 | 141 | const running = "b".repeat(40); |
| 128 | 142 | const finished = "c".repeat(40); |
| 129 | 143 | const open = beginGate(app.db, repoId, undefined, running); |
| @@ -133,13 +147,13 @@ test("a gate's open row keeps its checkout and home past the deadline window; a | ||
| 133 | 147 | populate(gateRunId(oid)); |
| 134 | 148 | } |
| 135 | 149 | // Past the young-checkout window a full suite still runs: the open row holds it. |
| 136 | sweepCheckouts(app, Date.now() + GATE_DEADLINE_MS + 60_000); | |
| 150 | await sweepCheckouts(app, Date.now() + GATE_DEADLINE_MS + 60_000); | |
| 137 | 151 | expect(existsSync(join(dataDir, "checks", gateRunId(running), "node_modules"))).toBe(true); |
| 138 | 152 | expect(existsSync(home(gateRunId(running)))).toBe(true); |
| 139 | 153 | expect(existsSync(join(dataDir, "checks", gateRunId(finished)))).toBe(false); |
| 140 | 154 | expect(existsSync(home(gateRunId(finished)))).toBe(false); |
| 141 | 155 | // A row a crash left open holds no longer than a check may run. |
| 142 | sweepCheckouts(app, Date.now() + 3 * 3600_000); | |
| 156 | await sweepCheckouts(app, Date.now() + 3 * 3600_000); | |
| 143 | 157 | expect(existsSync(join(dataDir, "checks", gateRunId(running)))).toBe(false); |
| 144 | 158 | endGate(app.db, open); |
| 145 | 159 | }); |
test/checks.test.ts +2
| @@ -22,6 +22,7 @@ import { | ||
| 22 | 22 | pickNext, |
| 23 | 23 | requeueAbandonedChecks, |
| 24 | 24 | startChecks, |
| 25 | sweepSoon, | |
| 25 | 26 | STARVATION_MS, |
| 26 | 27 | type ChecksHandle, |
| 27 | 28 | } from "../src/checks/service.ts"; |
| @@ -1316,6 +1317,7 @@ describe("startChecks: a booting forge removes only checkouts nobody is running | ||
| 1316 | 1317 | for (const id of [live.id, lapsed.id, "no-such-run"]) |
| 1317 | 1318 | mkdirSync(where(id), { recursive: true }); |
| 1318 | 1319 | const handle = startChecks(db, { forgeUrl: "http://localhost" }); |
| 1320 | await sweepSoon(db); | |
| 1319 | 1321 | await handle.stop(); |
| 1320 | 1322 | expect(existsSync(where(live.id))).toBe(true); |
| 1321 | 1323 | expect(existsSync(where(lapsed.id))).toBe(false); |
new above
offline
reclaimIfFull calls sweepCheckouts directly and can run beside this sweep; route it through sweepSoon so there is one sweep at a time. Note a second caller passing now gets the first sweep result.