Public: anyone can read this; the crew can change it.
A small forge is not stopped for CPU in its first minutes: the looks job retries a failing picture about once a second and drives it to 3.1 cores #11513
Check · Review · Land · Live — Changes were asked on this head.
torque/forge:torque/11509-a-small-forge-is-not-stopped-for-cpu-in → main 1 commit fork
7 files
changed +115
−10
src/apps/contain.ts +30 −6
| @@ -269,6 +269,8 @@ export interface CellSpec { | ||
| 269 | 269 | * (`apps/background.ts`). The step runner sets it. |
| 270 | 270 | */ |
| 271 | 271 | readonly background?: boolean | undefined; |
| 272 | /** A cell younger than this is throttled, not stopped, for CPU (#11509): a child forge's first minutes. */ | |
| 273 | readonly youngMs?: number | undefined; | |
| 272 | 274 | /** |
| 273 | 275 | * Held to `limits.cpus` by the kernel (`cpu.max`) at an app's weight: a |
| 274 | 276 | * whole child forge, whose checks and crew run inside it, is slowed when |
| @@ -717,7 +719,7 @@ export function openCell( | ||
| 717 | 719 | breach = why; |
| 718 | 720 | log(`stopped: ${why}`); |
| 719 | 721 | stop(why); |
| 720 | }); | |
| 722 | }, spec.youngMs); | |
| 721 | 723 | }; |
| 722 | 724 | return { |
| 723 | 725 | argv, |
| @@ -860,6 +862,8 @@ export const WATCH = { tickMs: 1_000, cpuWindowMs: 30_000, diskEveryTicks: 15 }; | ||
| 860 | 862 | /** A cell's process limit: the watch's every tick, and the kernel's `pids.max` where pids is delegated. */ |
| 861 | 863 | export const PROCESSES_MAX = 512; |
| 862 | 864 | const CLK_TCK = 100; |
| 865 | /** How young a child forge's cell is throttled, not stopped, for CPU: its first minutes are builds, boots and housekeeping (#11509). */ | |
| 866 | export const YOUNG_MS = 10 * 60_000; | |
| 863 | 867 | const DISK_WALK_MAX = 200_000; |
| 864 | 868 | |
| 865 | 869 | interface Watched { |
| @@ -867,7 +871,10 @@ interface Watched { | ||
| 867 | 871 | readonly limits: Limits; |
| 868 | 872 | readonly writable: readonly string[]; |
| 869 | 873 | readonly breach: (why: string) => void; |
| 870 | readonly samples: { at: number; ticks: number }[]; | |
| 874 | readonly samples: { at: number; ticks: number; by: Map<number, number> }[]; | |
| 875 | /** When the watch began: a tree younger than `YOUNG_MS` is throttled, not stopped, for CPU (#11509). */ | |
| 876 | readonly since: number; | |
| 877 | readonly youngMs: number; | |
| 871 | 878 | ticks: number; |
| 872 | 879 | readonly key: number; |
| 873 | 880 | readonly label: string | undefined; |
| @@ -1043,6 +1050,7 @@ export function watchTree( | ||
| 1043 | 1050 | writable: readonly string[], |
| 1044 | 1051 | label: string | undefined, |
| 1045 | 1052 | breach: (why: string) => void, |
| 1053 | youngMs = 0, | |
| 1046 | 1054 | ): () => void { |
| 1047 | 1055 | const entry: Watched = { |
| 1048 | 1056 | root, |
| @@ -1050,6 +1058,8 @@ export function watchTree( | ||
| 1050 | 1058 | writable, |
| 1051 | 1059 | breach, |
| 1052 | 1060 | samples: [], |
| 1061 | since: Date.now(), | |
| 1062 | youngMs, | |
| 1053 | 1063 | ticks: 0, |
| 1054 | 1064 | key: nextKey++, |
| 1055 | 1065 | label, |
| @@ -1079,6 +1089,7 @@ export function watchLabelled(pid: number, label: string): () => void { | ||
| 1079 | 1089 | interface ProcessRow { |
| 1080 | 1090 | ppid: number; |
| 1081 | 1091 | ticks: number; |
| 1092 | comm: string; | |
| 1082 | 1093 | } |
| 1083 | 1094 | |
| 1084 | 1095 | function processTable(): { |
| @@ -1110,7 +1121,8 @@ function processTable(): { | ||
| 1110 | 1121 | Number(fields[13]) + |
| 1111 | 1122 | Number(fields[14]); |
| 1112 | 1123 | const pid = Number(name); |
| 1113 | rows.set(pid, { ppid, ticks }); | |
| 1124 | const comm = stat.slice(stat.indexOf("(") + 1, stat.lastIndexOf(")")).slice(0, 40); | |
| 1125 | rows.set(pid, { ppid, ticks, comm }); | |
| 1114 | 1126 | const list = children.get(ppid); |
| 1115 | 1127 | if (list) list.push(pid); |
| 1116 | 1128 | else children.set(ppid, [pid]); |
| @@ -1189,7 +1201,9 @@ function tick(): void { | ||
| 1189 | 1201 | ); |
| 1190 | 1202 | continue; |
| 1191 | 1203 | } |
| 1192 | entry.samples.push({ at: now, ticks }); | |
| 1204 | const by = new Map<number, number>(); | |
| 1205 | for (const pid of tree) by.set(pid, rows.get(pid)?.ticks ?? 0); | |
| 1206 | entry.samples.push({ at: now, ticks, by }); | |
| 1193 | 1207 | while ( |
| 1194 | 1208 | entry.samples.length > 1 && |
| 1195 | 1209 | now - (entry.samples[1]?.at ?? now) >= WATCH.cpuWindowMs |
| @@ -1199,9 +1213,19 @@ function tick(): void { | ||
| 1199 | 1213 | if (oldest !== undefined && now - oldest.at >= WATCH.cpuWindowMs) { |
| 1200 | 1214 | const cores = |
| 1201 | 1215 | (ticks - oldest.ticks) / CLK_TCK / ((now - oldest.at) / 1000); |
| 1202 | if (cores > limits.cpus) { | |
| 1216 | if (cores > limits.cpus && now - entry.since >= entry.youngMs) { | |
| 1217 | // Name the process that spent it: the most ticks since the window began. | |
| 1218 | let top: { pid: number; spent: number } | undefined; | |
| 1219 | for (const pid of tree) { | |
| 1220 | const spent = (rows.get(pid)?.ticks ?? 0) - (oldest.by.get(pid) ?? 0); | |
| 1221 | if (top === undefined || spent > top.spent) top = { pid, spent }; | |
| 1222 | } | |
| 1223 | const who = | |
| 1224 | top === undefined || top.spent <= 0 | |
| 1225 | ? "" | |
| 1226 | : `; most of it by ${rows.get(top.pid)?.comm ?? "?"} (pid ${top.pid})`; | |
| 1203 | 1227 | entry.breach( |
| 1204 | `used ${cores.toFixed(1)} cores for ${Math.round((now - oldest.at) / 1000)}s, over its limit of ${limits.cpus}`, | |
| 1228 | `used ${cores.toFixed(1)} cores for ${Math.round((now - oldest.at) / 1000)}s, over its limit of ${limits.cpus}${who}`, | |
| 1205 | 1229 | ); |
| 1206 | 1230 | continue; |
| 1207 | 1231 | } |
src/looks/capture.ts +4
| @@ -367,8 +367,12 @@ async function shoot( | ||
| 367 | 367 | // and two forges in one process never share a browser's state. |
| 368 | 368 | const profile = mkdtempSync(join(tmpdir(), "forge-look-")); |
| 369 | 369 | rmSync(input.out, { force: true }); |
| 370 | // At the lowest CPU priority: a picture is housekeeping, and must never | |
| 371 | // take the cores an app or the forge's requests need (#11509). | |
| 372 | const nice = Bun.which("nice"); | |
| 370 | 373 | const proc = Bun.spawn( |
| 371 | 374 | [ |
| 375 | ...(nice === null ? [] : [nice, "-n", "19"]), | |
| 372 | 376 | binary, |
| 373 | 377 | "--headless=new", |
| 374 | 378 | // The forge runs as one unprivileged user with no user namespaces |
src/looks/service.ts +57 −1
| @@ -147,6 +147,12 @@ const FIRST_SWEEP_MS = 60_000; | ||
| 147 | 147 | const CAPTURE_TIMEOUT_MS = 20_000; |
| 148 | 148 | /** How long the grant in the URL is good for — the browser uses it at once. */ |
| 149 | 149 | const GRANT_TTL_MS = 60_000; |
| 150 | /** | |
| 151 | * After a picture fails, the whole look waits this long before the next | |
| 152 | * try, and gives up after the last (#11509): an app that is not answering | |
| 153 | * must not have a browser opened on it every second. | |
| 154 | */ | |
| 155 | export const LOOK_BACKOFF_MS: readonly number[] = [30_000, 120_000, 600_000]; | |
| 150 | 156 | |
| 151 | 157 | export const looksRoot = (dataDir: string): string => join(dataDir, "looks"); |
| 152 | 158 | |
| @@ -221,6 +227,35 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 221 | 227 | let pump: Promise<void> = Promise.resolve(); |
| 222 | 228 | let pumping = false; |
| 223 | 229 | let stopped = false; |
| 230 | /** Failed looks by app, environment and head: how many tries, and when the next may be. */ | |
| 231 | const failures = new Map<string, { tries: number; until: number }>(); | |
| 232 | const retries = new Set<ReturnType<typeof setTimeout>>(); | |
| 233 | const failKey = (q: { appId: string; env: EnvName; commitOid: string }): string => | |
| 234 | `${q.appId}/${q.env}/${q.commitOid}`; | |
| 235 | ||
| 236 | /** A look failed: try again after the next backoff, or give up with one line. */ | |
| 237 | function failed(item: Pending): void { | |
| 238 | const key = failKey(item); | |
| 239 | const tries = (failures.get(key)?.tries ?? 0) + 1; | |
| 240 | const wait = LOOK_BACKOFF_MS[tries - 1]; | |
| 241 | if (failures.size > 500) failures.clear(); | |
| 242 | if (wait === undefined) { | |
| 243 | failures.set(key, { tries, until: Infinity }); | |
| 244 | log.warn("look given up: the picture failed every time", { | |
| 245 | app: item.appId, | |
| 246 | env: item.env, | |
| 247 | tries, | |
| 248 | }); | |
| 249 | return; | |
| 250 | } | |
| 251 | failures.set(key, { tries, until: Date.now() + wait }); | |
| 252 | const timer = setTimeout(() => { | |
| 253 | retries.delete(timer); | |
| 254 | if (!stopped) enqueue({ ...item, at: Date.now() }, true); | |
| 255 | }, wait); | |
| 256 | timer.unref?.(); | |
| 257 | retries.add(timer); | |
| 258 | } | |
| 224 | 259 | |
| 225 | 260 | prune(); |
| 226 | 261 | // Production missing a picture at its head — one never taken, or a |
| @@ -300,7 +335,11 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 300 | 335 | * place. The same head queued twice — `app.serving` and then |
| 301 | 336 | * `run.finished` for the one deploy — is one entry, not two. |
| 302 | 337 | */ |
| 303 | function enqueue(item: Pending): void { | |
| 338 | function enqueue(item: Pending, retry = false): void { | |
| 339 | // A head whose picture failed waits out its backoff: an event for it | |
| 340 | // (a deploy announced twice, a sweep) is not a reason to try sooner. | |
| 341 | const failure = failures.get(failKey(item)); | |
| 342 | if (!retry && failure !== undefined && failure.until > Date.now()) return; | |
| 304 | 343 | const at = queue.findIndex( |
| 305 | 344 | (q) => q.appId === item.appId && q.env === item.env, |
| 306 | 345 | ); |
| @@ -412,8 +451,14 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 412 | 451 | const isNewcomerLook = (page: string): boolean => |
| 413 | 452 | ownerLooks.some((l) => l.page === page && l.as === "newcomer"); |
| 414 | 453 | let allOk = true; |
| 454 | let failedHere = false; | |
| 455 | let verdict: string | undefined; | |
| 415 | 456 | for (const { page, kind, theme } of wanted) { |
| 416 | 457 | if (stopped) return; |
| 458 | if (verdict !== undefined) { | |
| 459 | recordLook(app.db, { appId: item.appId, env: item.env, commitOid: item.commitOid, page, theme, kind, path: "", error: verdict }); | |
| 460 | continue; | |
| 461 | } | |
| 417 | 462 | const token = signGrant( |
| 418 | 463 | dataDir, |
| 419 | 464 | { app: record, env: item.env }, |
| @@ -491,6 +536,8 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 491 | 536 | } else { |
| 492 | 537 | rmSync(staged, { force: true }); |
| 493 | 538 | allOk = false; |
| 539 | const noBrowser = isNoBrowser(taken.error); | |
| 540 | failedHere = failedHere || !noBrowser; | |
| 494 | 541 | log.warn("no picture", { |
| 495 | 542 | app: record.slug, |
| 496 | 543 | env: item.env, |
| @@ -500,8 +547,14 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 500 | 547 | error: taken.error, |
| 501 | 548 | }); |
| 502 | 549 | recordLook(app.db, { ...row, kind, path: "", error: taken.error }); |
| 550 | // One failure is the verdict for this try: the other pictures | |
| 551 | // would meet the same page, so they are filed with its reason | |
| 552 | // and no browser is opened for them. | |
| 553 | if (!noBrowser) verdict = taken.error; | |
| 503 | 554 | } |
| 504 | 555 | } |
| 556 | if (failedHere) failed(item); | |
| 557 | else failures.delete(failKey(item)); | |
| 505 | 558 | // A full set at this head is the environment's look now; the pictures |
| 506 | 559 | // of heads before it have nothing left to say. |
| 507 | 560 | if (allOk) |
| @@ -615,6 +668,7 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 615 | 668 | |
| 616 | 669 | /** An environment is gone: so are its pictures, waiting or taken. */ |
| 617 | 670 | function forget(appId: string, env: EnvName): void { |
| 671 | for (const key of failures.keys()) if (key.startsWith(`${appId}/${env}/`)) failures.delete(key); | |
| 618 | 672 | const at = queue.findIndex((q) => q.appId === appId && q.env === env); |
| 619 | 673 | if (at !== -1) queue.splice(at, 1); |
| 620 | 674 | deleteLooks(app.db, appId, env); |
| @@ -695,6 +749,8 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle { | ||
| 695 | 749 | stopped = true; |
| 696 | 750 | clearTimeout(firstSweep); |
| 697 | 751 | clearInterval(sweeping); |
| 752 | for (const timer of retries) clearTimeout(timer); | |
| 753 | retries.clear(); | |
| 698 | 754 | unsubscribe(); |
| 699 | 755 | queue.length = 0; |
| 700 | 756 | await pump; |
src/spawn/cell.ts +4 −1
| @@ -15,7 +15,7 @@ import { dirname, join } from "node:path"; | ||
| 15 | 15 | import { clientAddress } from "../http/peer.ts"; |
| 16 | 16 | import type { App } from "../app.ts"; |
| 17 | 17 | import { connectUpstream, offeredProtocols, type AppSocket } from "../apps/proxy.ts"; |
| 18 | import { cellsAvailable, commandPid, killTree, openCell, type Cell, type CellSpec, type Limits } from "../apps/contain.ts"; | |
| 18 | import { cellsAvailable, commandPid, killTree, openCell, YOUNG_MS, type Cell, type CellSpec, type Limits } from "../apps/contain.ts"; | |
| 19 | 19 | import { childEnv, freePort } from "../apps/process.ts"; |
| 20 | 20 | import { childDirOf } from "../actions/spawn.ts"; |
| 21 | 21 | import { openBeatDoor, parentLocal, type BeatDoor } from "./beat-door.ts"; |
| @@ -161,6 +161,9 @@ export function cellSpecFor(input: { | ||
| 161 | 161 | // A forge is busy in bursts (a check's shards, an install): the kernel |
| 162 | 162 | // holds it to its cores; the watch stopping it killed the check with it. |
| 163 | 163 | cpuQuota: true, |
| 164 | // Its first ten minutes are throttled by that quota, never stopped for | |
| 165 | // CPU: a new forge's own housekeeping must not get it killed (#11509). | |
| 166 | youngMs: YOUNG_MS, | |
| 164 | 167 | // Its disk bandwidth too, on the data volume: one child's install |
| 165 | 168 | // cannot starve the forge's database of the disk (#10854). |
| 166 | 169 | io: SIZE_IO[input.size], |
test/contain.test.ts +10 −1
| @@ -840,10 +840,19 @@ describe.skipIf(noCells)("cells: limits stop a step, and say which", () => { | ||
| 840 | 840 | expect(result.ok).toBe(false); |
| 841 | 841 | if (!result.ok) |
| 842 | 842 | expect(result.error).toMatch( |
| 843 | /^check stopped: it used [\d.]+ cores for \d+s, over its limit of 0\.02$/, | |
| 843 | /^check stopped: it used [\d.]+ cores for \d+s, over its limit of 0\.02; most of it by \w+ \(pid \d+\)$/, | |
| 844 | 844 | ); |
| 845 | 845 | }, 30_000); |
| 846 | 846 | |
| 847 | test("a young cell over its CPU limit is not stopped (#11509)", async () => { | |
| 848 | // The same loop, for six seconds, twice the window: a cell younger than its grace lives. | |
| 849 | const result = await step( | |
| 850 | `bun -e "const end = Date.now() + 6500; while (Date.now() < end) {}"`, | |
| 851 | { ...cell({ cpus: 0.02 }), youngMs: 600_000 }, | |
| 852 | ); | |
| 853 | expect(result.ok).toBe(true); | |
| 854 | }, 30_000); | |
| 855 | ||
| 847 | 856 | test("over its disk limit", async () => { |
| 848 | 857 | const result = await step( |
| 849 | 858 | "head -c 200000000 /dev/zero > big; sleep 30", |
test/looks.test.ts +8 −1
| @@ -44,7 +44,7 @@ import { | ||
| 44 | 44 | type Capture, |
| 45 | 45 | type LookInput, |
| 46 | 46 | } from "../src/looks/capture.ts"; |
| 47 | import { startLooks, type LooksHandle } from "../src/looks/service.ts"; | |
| 47 | import { LOOK_BACKOFF_MS, startLooks, type LooksHandle } from "../src/looks/service.ts"; | |
| 48 | 48 | |
| 49 | 49 | quietLogs(); |
| 50 | 50 | |
| @@ -640,10 +640,17 @@ describe("the look", () => { | ||
| 640 | 640 | }); |
| 641 | 641 | if (!moved.ok) throw new Error(JSON.stringify(moved.error)); |
| 642 | 642 | const third = moved.value.commitOid; |
| 643 | const callsBefore = callsAt(env).length; | |
| 643 | 644 | expect( |
| 644 | 645 | (await settled((r) => r.env === env && r.commitOid === third)).state, |
| 645 | 646 | ).toBe("ok"); |
| 646 | 647 | const rows = await pictured(env, third); |
| 648 | // #11509: a page that gives no picture is tried once, not once per | |
| 649 | // kind, and the next try waits out its backoff; an event for the same | |
| 650 | // head in the meantime is not a reason to try sooner. | |
| 651 | expect(callsAt(env).length - callsBefore).toBe(1); | |
| 652 | expect(rows).toHaveLength(3); | |
| 653 | expect(LOOK_BACKOFF_MS[0]).toBeGreaterThanOrEqual(30_000); | |
| 647 | 654 | for (const look of rows) { |
| 648 | 655 | expect(look.error).toBe("the browser fell over"); |
| 649 | 656 | expect(look.path).toBe(""); |
test/spawn-cell.test.ts +2
| @@ -36,6 +36,8 @@ describe("a child forge's cell", () => { | ||
| 36 | 36 | expect(spec.hide).toEqual(["/d", "/home/f", tmpdir()]); |
| 37 | 37 | expect(spec.listen).toBe(4100); |
| 38 | 38 | expect(spec.dir).toBe("/d/children/c1"); |
| 39 | // #11509: a child forge's first ten minutes are throttled by its quota, never stopped for CPU. | |
| 40 | expect(spec.youngMs).toBe(10 * 60_000); | |
| 39 | 41 | }); |
| 40 | 42 | |
| 41 | 43 | test("a child's lines reach the parent's log bounded and plain", () => { |