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

opened this in answer to

Check · Review · Land · Live — Changes were asked on this head. Next: builder, changes were asked on this head.

A reviewer asked for changes Review

torque/forge:torque/11509-a-small-forge-is-not-stopped-for-cpu-in → main 1 commit fork

Review

Sign in to review this change.
7 files changed +115 −10
src/apps/contain.ts +30 −6
@@ -269,6 +269,8 @@ export interface CellSpec {
269269 * (`apps/background.ts`). The step runner sets it.
270270 */
271271 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;
272274 /**
273275 * Held to `limits.cpus` by the kernel (`cpu.max`) at an app's weight: a
274276 * whole child forge, whose checks and crew run inside it, is slowed when
@@ -717,7 +719,7 @@ export function openCell(
717719 breach = why;
718720 log(`stopped: ${why}`);
719721 stop(why);
720 });
722 }, spec.youngMs);
721723 };
722724 return {
723725 argv,
@@ -860,6 +862,8 @@ export const WATCH = { tickMs: 1_000, cpuWindowMs: 30_000, diskEveryTicks: 15 };
860862 /** A cell's process limit: the watch's every tick, and the kernel's `pids.max` where pids is delegated. */
861863 export const PROCESSES_MAX = 512;
862864 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;
863867 const DISK_WALK_MAX = 200_000;
864868
865869 interface Watched {
@@ -867,7 +871,10 @@ interface Watched {
867871 readonly limits: Limits;
868872 readonly writable: readonly string[];
869873 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;
871878 ticks: number;
872879 readonly key: number;
873880 readonly label: string | undefined;
@@ -1043,6 +1050,7 @@ export function watchTree(
10431050 writable: readonly string[],
10441051 label: string | undefined,
10451052 breach: (why: string) => void,
1053 youngMs = 0,
10461054 ): () => void {
10471055 const entry: Watched = {
10481056 root,
@@ -1050,6 +1058,8 @@ export function watchTree(
10501058 writable,
10511059 breach,
10521060 samples: [],
1061 since: Date.now(),
1062 youngMs,
10531063 ticks: 0,
10541064 key: nextKey++,
10551065 label,
@@ -1079,6 +1089,7 @@ export function watchLabelled(pid: number, label: string): () => void {
10791089 interface ProcessRow {
10801090 ppid: number;
10811091 ticks: number;
1092 comm: string;
10821093 }
10831094
10841095 function processTable(): {
@@ -1110,7 +1121,8 @@ function processTable(): {
11101121 Number(fields[13]) +
11111122 Number(fields[14]);
11121123 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 });
11141126 const list = children.get(ppid);
11151127 if (list) list.push(pid);
11161128 else children.set(ppid, [pid]);
@@ -1189,7 +1201,9 @@ function tick(): void {
11891201 );
11901202 continue;
11911203 }
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 });
11931207 while (
11941208 entry.samples.length > 1 &&
11951209 now - (entry.samples[1]?.at ?? now) >= WATCH.cpuWindowMs
@@ -1199,9 +1213,19 @@ function tick(): void {
11991213 if (oldest !== undefined && now - oldest.at >= WATCH.cpuWindowMs) {
12001214 const cores =
12011215 (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})`;
12031227 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}`,
12051229 );
12061230 continue;
12071231 }
src/looks/capture.ts +4
@@ -367,8 +367,12 @@ async function shoot(
367367 // and two forges in one process never share a browser's state.
368368 const profile = mkdtempSync(join(tmpdir(), "forge-look-"));
369369 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");
370373 const proc = Bun.spawn(
371374 [
375 ...(nice === null ? [] : [nice, "-n", "19"]),
372376 binary,
373377 "--headless=new",
374378 // 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;
147147 const CAPTURE_TIMEOUT_MS = 20_000;
148148 /** How long the grant in the URL is good for — the browser uses it at once. */
149149 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];
150156
151157 export const looksRoot = (dataDir: string): string => join(dataDir, "looks");
152158
@@ -221,6 +227,35 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
221227 let pump: Promise<void> = Promise.resolve();
222228 let pumping = false;
223229 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 }
224259
225260 prune();
226261 // Production missing a picture at its head — one never taken, or a
@@ -300,7 +335,11 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
300335 * place. The same head queued twice — `app.serving` and then
301336 * `run.finished` for the one deploy — is one entry, not two.
302337 */
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;
304343 const at = queue.findIndex(
305344 (q) => q.appId === item.appId && q.env === item.env,
306345 );
@@ -412,8 +451,14 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
412451 const isNewcomerLook = (page: string): boolean =>
413452 ownerLooks.some((l) => l.page === page && l.as === "newcomer");
414453 let allOk = true;
454 let failedHere = false;
455 let verdict: string | undefined;
415456 for (const { page, kind, theme } of wanted) {
416457 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 }
417462 const token = signGrant(
418463 dataDir,
419464 { app: record, env: item.env },
@@ -491,6 +536,8 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
491536 } else {
492537 rmSync(staged, { force: true });
493538 allOk = false;
539 const noBrowser = isNoBrowser(taken.error);
540 failedHere = failedHere || !noBrowser;
494541 log.warn("no picture", {
495542 app: record.slug,
496543 env: item.env,
@@ -500,8 +547,14 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
500547 error: taken.error,
501548 });
502549 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;
503554 }
504555 }
556 if (failedHere) failed(item);
557 else failures.delete(failKey(item));
505558 // A full set at this head is the environment's look now; the pictures
506559 // of heads before it have nothing left to say.
507560 if (allOk)
@@ -615,6 +668,7 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
615668
616669 /** An environment is gone: so are its pictures, waiting or taken. */
617670 function forget(appId: string, env: EnvName): void {
671 for (const key of failures.keys()) if (key.startsWith(`${appId}/${env}/`)) failures.delete(key);
618672 const at = queue.findIndex((q) => q.appId === appId && q.env === env);
619673 if (at !== -1) queue.splice(at, 1);
620674 deleteLooks(app.db, appId, env);
@@ -695,6 +749,8 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
695749 stopped = true;
696750 clearTimeout(firstSweep);
697751 clearInterval(sweeping);
752 for (const timer of retries) clearTimeout(timer);
753 retries.clear();
698754 unsubscribe();
699755 queue.length = 0;
700756 await pump;
src/spawn/cell.ts +4 −1
@@ -15,7 +15,7 @@ import { dirname, join } from "node:path";
1515 import { clientAddress } from "../http/peer.ts";
1616 import type { App } from "../app.ts";
1717 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";
1919 import { childEnv, freePort } from "../apps/process.ts";
2020 import { childDirOf } from "../actions/spawn.ts";
2121 import { openBeatDoor, parentLocal, type BeatDoor } from "./beat-door.ts";
@@ -161,6 +161,9 @@ export function cellSpecFor(input: {
161161 // A forge is busy in bursts (a check's shards, an install): the kernel
162162 // holds it to its cores; the watch stopping it killed the check with it.
163163 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,
164167 // Its disk bandwidth too, on the data volume: one child's install
165168 // cannot starve the forge's database of the disk (#10854).
166169 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", () => {
840840 expect(result.ok).toBe(false);
841841 if (!result.ok)
842842 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+\)$/,
844844 );
845845 }, 30_000);
846846
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
847856 test("over its disk limit", async () => {
848857 const result = await step(
849858 "head -c 200000000 /dev/zero > big; sleep 30",
test/looks.test.ts +8 −1
@@ -44,7 +44,7 @@ import {
4444 type Capture,
4545 type LookInput,
4646 } 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";
4848
4949 quietLogs();
5050
@@ -640,10 +640,17 @@ describe("the look", () => {
640640 });
641641 if (!moved.ok) throw new Error(JSON.stringify(moved.error));
642642 const third = moved.value.commitOid;
643 const callsBefore = callsAt(env).length;
643644 expect(
644645 (await settled((r) => r.env === env && r.commitOid === third)).state,
645646 ).toBe("ok");
646647 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);
647654 for (const look of rows) {
648655 expect(look.error).toBe("the browser fell over");
649656 expect(look.path).toBe("");
test/spawn-cell.test.ts +2
@@ -36,6 +36,8 @@ describe("a child forge's cell", () => {
3636 expect(spec.hide).toEqual(["/d", "/home/f", tmpdir()]);
3737 expect(spec.listen).toBe(4100);
3838 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);
3941 });
4042
4143 test("a child's lines reach the parent's log bounded and plain", () => {

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs