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

The check's full gate prints its wall time, shard count, peak memory and ten slowest files, and names any file over 45 s #2067

Merged opened this

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

Merged

torque/forge:torque/2065-the-check-s-full-gate-prints-its-wall-ti → main 3 commits fork 1 thread · 1 unresolved

  • Merged. torque/2065-the-check-s-full-gate-prints-its-wall-ti was merged into main as 6bbccc8.

Review

Sign in to review this change.
4 files changed +314 −10
scripts/gate-summary.ts added +120
@@ -0,0 +1,120 @@
1 /**
2 * The one block a timed full gate ends its log with (#2065): how many
3 * shards and why, the wall time, the cell's peak memory, the ten slowest
4 * files, and a warning line for every file over {@link SLOW_SECONDS}.
5 *
6 * Plain data in, lines out. `scripts/test-shards.ts` gathers the numbers;
7 * the cgroup is read through a function handed in, so a test can say what
8 * the files hold, or that there are none. Nothing here changes the exit
9 * code: a slow file is a warning, not a red.
10 */
11
12 /** A file over this many seconds is named on its own warning line. */
13 export const SLOW_SECONDS = 45;
14 /** How many of the slowest files the block lists. */
15 export const SLOWEST = 10;
16
17 const GIB = 1024 ** 3;
18 /** cgroup v1 writes "no limit" as a page-rounded 2^63 − 1; anything this big is none. */
19 const V1_UNLIMITED = 2 ** 60;
20
21 /** Where a memory number came from: a cgroup file, by name. */
22 export type Memory = { bytes: number; from: string } | undefined;
23
24 export type CgroupMemory = { limit: Memory; peak: Memory };
25
26 /** Reads one file, or undefined when it is not there. */
27 export type Reader = (path: string) => string | undefined;
28
29 /** A whole number of bytes, or undefined: "max", v1's "unlimited", blanks and junk are no number. */
30 function bytesIn(text: string | undefined): number | undefined {
31 const trimmed = text?.trim();
32 if (trimmed === undefined || !/^[0-9]{1,20}$/.test(trimmed)) return undefined;
33 const n = Number(trimmed);
34 return n < V1_UNLIMITED ? n : undefined;
35 }
36
37 /**
38 * The cell's memory limit and peak, cgroup v2 first, then v1:
39 * `memory.max` / `memory.limit_in_bytes`, and `memory.peak` /
40 * `memory.max_usage_in_bytes`. A file that is missing, says "max", or
41 * holds v1's "unlimited" is no number, never a made-up one.
42 */
43 export function cgroupMemory(read: Reader): CgroupMemory {
44 const first = (paths: readonly string[]): Memory => {
45 for (const path of paths) {
46 const bytes = bytesIn(read(path));
47 if (bytes !== undefined)
48 return { bytes, from: path.slice(path.lastIndexOf("/") + 1) };
49 }
50 return undefined;
51 };
52 return {
53 limit: first(["/sys/fs/cgroup/memory.max", "/sys/fs/cgroup/memory/memory.limit_in_bytes"]),
54 peak: first(["/sys/fs/cgroup/memory.peak", "/sys/fs/cgroup/memory/memory.max_usage_in_bytes"]),
55 };
56 }
57
58 export type GateSummary = {
59 /** Shards the gate ran at once. */
60 shards: number;
61 /** `os.availableParallelism()`. */
62 cpus: number;
63 /** Most shards whatever the host (`SHARDS_MAX` in scripts/shards.ts). */
64 shardsMax: number;
65 /** Files the gate named. */
66 files: number;
67 /** `FORGE_CHECK_SHARDS` as it was set, if it was. */
68 override: string | undefined;
69 /** The memory `shardCount` was handed: the least of the machine's and the cgroup's. */
70 memoryBytes: number;
71 /** Room one worker is given (`WORKER_MEMORY_BYTES` in scripts/shards.ts). */
72 workerBytes: number;
73 memory: CgroupMemory;
74 /** Spawn of the first file to exit of the last, in seconds. */
75 wallSeconds: number;
76 /** Every file that ran, alone in its own `bun test`, and how long it took; fewer than `files` when fail-fast skipped some. */
77 times: readonly { file: string; seconds: number }[];
78 };
79
80 const gib = (bytes: number): string => `${(bytes / GIB).toFixed(2)} GiB`;
81
82 /**
83 * Why the gate ran `shards` at once: the bounds `shardCount` took the least
84 * of, and, when memory held it under one per CPU, that it did.
85 */
86 function why(s: GateSummary): string {
87 const set = s.override !== undefined && s.override.trim() !== "";
88 const byMemory = Math.floor(s.memoryBytes / s.workerBytes);
89 const room =
90 `${gib(s.memoryBytes)}${s.memory.limit ? ` (cgroup ${s.memory.limit.from})` : " (no cgroup limit)"} ` +
91 `at ${(s.workerBytes / 1024 ** 2).toFixed(0)} MiB each`;
92 const bounds = set
93 ? [`FORGE_CHECK_SHARDS ${s.override!.trim()}`, `${s.files} files`]
94 : [`${s.cpus} CPUs`, `${byMemory} by memory, ${room}`, `SHARDS_MAX ${s.shardsMax}`, `${s.files} files`];
95 const held = !set && s.shards < s.cpus && s.shards === byMemory && byMemory < Math.min(s.shardsMax, s.files);
96 return `${s.shards} = least of ${bounds.join("; ")}${held ? " — fewer than the CPUs because of memory" : ""}`;
97 }
98
99 /** The block, one line each, every line but the file list starting `test-shards:`. */
100 export function summaryLines(s: GateSummary): string[] {
101 const slowest = [...s.times]
102 .sort((a, b) => b.seconds - a.seconds || (a.file < b.file ? -1 : a.file > b.file ? 1 : 0));
103 const peak = s.memory.peak
104 ? `${gib(s.memory.peak.bytes)}${s.memory.limit ? ` of ${gib(s.memory.limit.bytes)}` : ""} (${s.memory.peak.from})`
105 : "unknown here";
106 const top = slowest.slice(0, SLOWEST);
107 // Fail-fast leaves files unstarted: the list is of the files that ran.
108 const skipped = s.files - s.times.length;
109 return [
110 "── gate summary",
111 `test-shards: shards: ${why(s)}`,
112 `test-shards: wall: ${s.wallSeconds.toFixed(1)}s`,
113 `test-shards: peak memory: ${peak}`,
114 `test-shards: slowest ${top.length} of ${s.times.length} files${skipped > 0 ? ` (${skipped} of ${s.files} skipped after a red file)` : ""}:`,
115 ...top.map((t) => ` ${t.seconds.toFixed(1).padStart(6)}s ${t.file}`),
116 ...slowest
117 .filter((t) => t.seconds > SLOW_SECONDS)
118 .map((t) => `test-shards: over ${SLOW_SECONDS} s: ${t.file} (${t.seconds.toFixed(1)}s)`),
119 ];
120 }
scripts/gate.ts +1
@@ -202,6 +202,7 @@ export const GATE: readonly string[] = [
202202 "test/git-trust.test.ts",
203203 "test/helpers.test.ts",
204204 "test/shards.test.ts",
205 "test/gate-summary.test.ts",
205206 "test/snapshot-drill.test.ts",
206207 "test/drill-verdict.test.ts",
207208 "test/drill-board-line.test.ts",
scripts/test-shards.ts +29 −10
@@ -49,6 +49,8 @@ import {
4949 refreshTimes,
5050 parseShardSpec,
5151 parseTimes,
52 SHARDS_MAX,
53 WORKER_MEMORY_BYTES,
5254 shardCount,
5355 sliceFiles,
5456 splitArgs,
@@ -58,6 +60,7 @@ import {
5860 type ShardResult,
5961 } from "./shards.ts";
6062 import { GATE, gateRefusal, presentTests } from "./gate.ts";
63 import { cgroupMemory, summaryLines } from "./gate-summary.ts";
6164 import { GATE_FILE, executedFiles, formatImpact, gateListAdds, handedImpact, mergeImpact, parseImpact } from "../src/checks/impact.ts";
6265 import { fastSet, importsOf, duration } from "../src/checks/tiers.ts";
6366 import { CHECK_CACHE } from "../src/checks/cache.ts";
@@ -334,15 +337,13 @@ const readLimit = (path: string): string | undefined => {
334337 return undefined;
335338 }
336339 };
337 const count = shardCount(
338 availableParallelism(),
339 files.length,
340 process.env["FORGE_CHECK_SHARDS"],
341 memoryLimit(totalmem(), [
342 readLimit("/sys/fs/cgroup/memory.max"),
343 readLimit("/sys/fs/cgroup/memory/memory.limit_in_bytes"),
344 ]),
345 );
340 const cpus = availableParallelism();
341 const shardsOverride = process.env["FORGE_CHECK_SHARDS"];
342 const memory = memoryLimit(totalmem(), [
343 readLimit("/sys/fs/cgroup/memory.max"),
344 readLimit("/sys/fs/cgroup/memory/memory.limit_in_bytes"),
345 ]);
346 const count = shardCount(cpus, files.length, shardsOverride, memory);
346347 if (!count.ok) {
347348 console.error(`test-shards: ${count.error}`);
348349 process.exit(2);
@@ -535,7 +536,8 @@ if (results.length < slices.length) {
535536 `test-shards: fail-fast — skipped ${skipped} remaining shard${skipped === 1 ? "" : "s"} after a red exit`,
536537 );
537538 }
538 const ending = tally(results, (performance.now() - started) / 1000);
539 const wall = (performance.now() - started) / 1000;
540 const ending = tally(results, wall);
539541 const spread = results.map((result) => result.seconds);
540542 console.log(`\n${ending.lines.join("\n")}`);
541543 if (!record && !timed && results.length > 1)
@@ -584,4 +586,21 @@ if (measure) {
584586 console.log(`test-shards: wrote ${measured.size} test impacts to ${IMPACT_NAME}`);
585587 }
586588 }
589 // The timed full gate is the check on the cell itself: its log ends with
590 // what the cell did, so nobody has to measure it by hand (#2065).
591 if (timed)
592 console.log(

result.files[0]! is only the whole shard's time if the timed gate runs one file per shard. Make that explicit (assert files.length === 1, or sum over files) so a future slicing change cannot silently mislabel timings.

593 `\n${summaryLines({
594 shards: count.value,
595 cpus,
596 shardsMax: SHARDS_MAX,
597 files: files.length,
598 override: shardsOverride,
599 memoryBytes: memory,
600 workerBytes: WORKER_MEMORY_BYTES,
601 memory: cgroupMemory(readLimit),
602 wallSeconds: wall,
603 times: results.map((result) => ({ file: result.files[0]!, seconds: result.seconds })),
604 }).join("\n")}`,
605 );
587606 process.exit(ending.code);
test/gate-summary.test.ts added +164
@@ -0,0 +1,164 @@
1 /**
2 * The block a timed full gate ends its log with (`scripts/gate-summary.ts`,
3 * #2065): the cgroup is read or said unknown, a file over 45 s is named on
4 * its own warning line, and fewer than ten files list what there is.
5 */
6 import { describe, expect, test } from "bun:test";
7 import {
8 SLOW_SECONDS,
9 cgroupMemory,
10 summaryLines,
11 type GateSummary,
12 } from "../scripts/gate-summary.ts";
13
14 const GIB = 1024 ** 3;
15 const none = (): undefined => undefined;
16 const files = (map: Record<string, string>) => (path: string) => map[path];
17
18 const base: GateSummary = {
19 shards: 12,
20 cpus: 16,
21 shardsMax: 32,
22 files: 12,
23 override: undefined,
24 memoryBytes: 96 * GIB,
25 workerBytes: 512 * 1024 ** 2,
26 memory: { limit: undefined, peak: undefined },
27 wallSeconds: 312.44,
28 times: Array.from({ length: 12 }, (_, i) => ({
29 file: `test/f${i}.test.ts`,
30 seconds: i * 2,
31 })),
32 };
33
34 describe("cgroupMemory", () => {
35 test("no cgroup file: neither a limit nor a peak", () => {
36 expect(cgroupMemory(none)).toEqual({ limit: undefined, peak: undefined });
37 });
38
39 test("cgroup v2: memory.max and memory.peak", () => {
40 expect(
41 cgroupMemory(
42 files({
43 "/sys/fs/cgroup/memory.max": "8589934592\n",
44 "/sys/fs/cgroup/memory.peak": "6442450944\n",
45 }),
46 ),
47 ).toEqual({
48 limit: { bytes: 8 * GIB, from: "memory.max" },
49 peak: { bytes: 6 * GIB, from: "memory.peak" },
50 });
51 });
52
53 test("cgroup v1 falls back to max_usage_in_bytes; its 'unlimited' is no limit", () => {
54 expect(
55 cgroupMemory(
56 files({
57 "/sys/fs/cgroup/memory/memory.limit_in_bytes": "9223372036854771712\n",
58 "/sys/fs/cgroup/memory/memory.max_usage_in_bytes": "1073741824\n",
59 }),
60 ),
61 ).toEqual({
62 limit: undefined,
63 peak: { bytes: GIB, from: "memory.max_usage_in_bytes" },
64 });
65 });
66
67 test("v2 'max' is no limit, and junk is no number", () => {
68 expect(
69 cgroupMemory(
70 files({ "/sys/fs/cgroup/memory.max": "max\n", "/sys/fs/cgroup/memory.peak": "lots" }),
71 ),
72 ).toEqual({ limit: undefined, peak: undefined });
73 });
74 });
75
76 describe("summaryLines", () => {
77 test("no cgroup file: peak memory is unknown here, not a number", () => {
78 const lines = summaryLines(base);
79 expect(lines).toContain("test-shards: peak memory: unknown here");
80 expect(lines).toContain(
81 "test-shards: shards: 12 = least of 16 CPUs; 192 by memory, 96.00 GiB (no cgroup limit) at 512 MiB each; SHARDS_MAX 32; 12 files",
82 );
83 });
84
85 test("the whole block, by hand: memory holds it under the CPUs, ten slowest of twelve", () => {
86 // 4 GiB / 512 MiB = 8 workers, fewer than 16 CPUs, SHARDS_MAX 32 or 12 files.
87 const lines = summaryLines({
88 ...base,
89 shards: 8,
90 memoryBytes: 4 * GIB,
91 memory: cgroupMemory(
92 files({
93 "/sys/fs/cgroup/memory.max": String(4 * GIB),
94 "/sys/fs/cgroup/memory.peak": String(3.5 * GIB),
95 }),
96 ),
97 });
98 expect(lines).toEqual([
99 "── gate summary",
100 "test-shards: shards: 8 = least of 16 CPUs; 8 by memory, 4.00 GiB (cgroup memory.max) at 512 MiB each; SHARDS_MAX 32; 12 files — fewer than the CPUs because of memory",
101 "test-shards: wall: 312.4s",
102 "test-shards: peak memory: 3.50 GiB of 4.00 GiB (memory.peak)",
103 "test-shards: slowest 10 of 12 files:",
104 " 22.0s test/f11.test.ts",
105 " 20.0s test/f10.test.ts",
106 " 18.0s test/f9.test.ts",
107 " 16.0s test/f8.test.ts",
108 " 14.0s test/f7.test.ts",
109 " 12.0s test/f6.test.ts",
110 " 10.0s test/f5.test.ts",
111 " 8.0s test/f4.test.ts",
112 " 6.0s test/f3.test.ts",
113 " 4.0s test/f2.test.ts",
114 ]);
115 });
116
117 test("a file over 45 s is named on its own line; 45 s itself is not", () => {
118 const lines = summaryLines({
119 ...base,
120 times: [
121 { file: "test/ok.test.ts", seconds: SLOW_SECONDS },
122 { file: "test/slow.test.ts", seconds: 52.06 },
123 { file: "test/slower.test.ts", seconds: 197 },
124 ],
125 });
126 const over = lines.filter((line) => line.startsWith("test-shards: over 45 s:"));
127 expect(over).toEqual([
128 "test-shards: over 45 s: test/slower.test.ts (197.0s)",
129 "test-shards: over 45 s: test/slow.test.ts (52.1s)",
130 ]);
131 });
132
133 test("fewer than ten files: every one is listed, and the heading says how many", () => {
134 const lines = summaryLines({
135 ...base,
136 files: 2,
137 shards: 2,
138 times: [
139 { file: "test/a.test.ts", seconds: 1.24 },
140 { file: "test/b.test.ts", seconds: 3 },
141 ],
142 });
143 expect(lines.slice(4)).toEqual([
144 "test-shards: slowest 2 of 2 files:",
145 " 3.0s test/b.test.ts",
146 " 1.2s test/a.test.ts",
147 ]);
148 });
149
150 test("fail-fast skipped files: the heading says how many of those named never ran", () => {
151 const lines = summaryLines({
152 ...base,
153 files: 40,
154 times: [{ file: "test/red.test.ts", seconds: 3 }],
155 });
156 expect(lines[4]).toBe("test-shards: slowest 1 of 1 files (39 of 40 skipped after a red file):");
157 });
158
159 test("FORGE_CHECK_SHARDS is named as the reason when it is set", () => {
160 expect(summaryLines({ ...base, shards: 1, override: "1" })[1]).toBe(
161 "test-shards: shards: 1 = least of FORGE_CHECK_SHARDS 1; 12 files",
162 );
163 });
164 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs