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
Check · Review · Land · Live done — Landed and live in production.
torque/forge:torque/2065-the-check-s-full-gate-prints-its-wall-ti → main 3 commits fork 1 thread · 1 unresolved
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[] = [ | ||
| 202 | 202 | "test/git-trust.test.ts", |
| 203 | 203 | "test/helpers.test.ts", |
| 204 | 204 | "test/shards.test.ts", |
| 205 | "test/gate-summary.test.ts", | |
| 205 | 206 | "test/snapshot-drill.test.ts", |
| 206 | 207 | "test/drill-verdict.test.ts", |
| 207 | 208 | "test/drill-board-line.test.ts", |
scripts/test-shards.ts +29 −10
| @@ -49,6 +49,8 @@ import { | ||
| 49 | 49 | refreshTimes, |
| 50 | 50 | parseShardSpec, |
| 51 | 51 | parseTimes, |
| 52 | SHARDS_MAX, | |
| 53 | WORKER_MEMORY_BYTES, | |
| 52 | 54 | shardCount, |
| 53 | 55 | sliceFiles, |
| 54 | 56 | splitArgs, |
| @@ -58,6 +60,7 @@ import { | ||
| 58 | 60 | type ShardResult, |
| 59 | 61 | } from "./shards.ts"; |
| 60 | 62 | import { GATE, gateRefusal, presentTests } from "./gate.ts"; |
| 63 | import { cgroupMemory, summaryLines } from "./gate-summary.ts"; | |
| 61 | 64 | import { GATE_FILE, executedFiles, formatImpact, gateListAdds, handedImpact, mergeImpact, parseImpact } from "../src/checks/impact.ts"; |
| 62 | 65 | import { fastSet, importsOf, duration } from "../src/checks/tiers.ts"; |
| 63 | 66 | import { CHECK_CACHE } from "../src/checks/cache.ts"; |
| @@ -334,15 +337,13 @@ const readLimit = (path: string): string | undefined => { | ||
| 334 | 337 | return undefined; |
| 335 | 338 | } |
| 336 | 339 | }; |
| 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); | |
| 346 | 347 | if (!count.ok) { |
| 347 | 348 | console.error(`test-shards: ${count.error}`); |
| 348 | 349 | process.exit(2); |
| @@ -535,7 +536,8 @@ if (results.length < slices.length) { | ||
| 535 | 536 | `test-shards: fail-fast — skipped ${skipped} remaining shard${skipped === 1 ? "" : "s"} after a red exit`, |
| 536 | 537 | ); |
| 537 | 538 | } |
| 538 | const ending = tally(results, (performance.now() - started) / 1000); | |
| 539 | const wall = (performance.now() - started) / 1000; | |
| 540 | const ending = tally(results, wall); | |
| 539 | 541 | const spread = results.map((result) => result.seconds); |
| 540 | 542 | console.log(`\n${ending.lines.join("\n")}`); |
| 541 | 543 | if (!record && !timed && results.length > 1) |
| @@ -584,4 +586,21 @@ if (measure) { | ||
| 584 | 586 | console.log(`test-shards: wrote ${measured.size} test impacts to ${IMPACT_NAME}`); |
| 585 | 587 | } |
| 586 | 588 | } |
| 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( | |
| 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 | ); | |
| 587 | 606 | 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 | }); |
new above
offline
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.