diff --git a/.claude/skills/slowest-tests/SKILL.md b/.claude/skills/slowest-tests/SKILL.md index 5ba26c6837ed..0b09c0ec3a0e 100644 --- a/.claude/skills/slowest-tests/SKILL.md +++ b/.claude/skills/slowest-tests/SKILL.md @@ -24,6 +24,7 @@ The script (`scripts/ci-slowest-tests.ts`) does the heavy lifting: - Caches logs to `$TMPDIR/bun-ci-logs-/` so re-runs are instant. - Parses `_bk;t= ... --- [N/TOTAL] ` group headers, normalising backslashes to `/` and stripping `[attempt #N]` retries. - Aggregates each file's duration as the **max across all platforms** (a file appears once per platform; shards within a platform are disjoint). +- Adds up every attempt of a file on a platform: a run in the parallel batch that failed (`--- - K failing in the parallel batch (X.XXs)`), the rerun alone, and each `[attempt #N]`. `attempts` and `maxAttemptMs` in the JSON, `attempts` and `longest_attempt` (seconds) in the table, say how many attempts the time of a row adds up on its slowest platform and how long the longest took. A row with more than 1 attempt is a file that failed and ran again: its time is a sum, not one slow run. An attempt that the runner prints no seconds for is not in the row: a try that fails in the phase `Running N files that build many executables`, or a failed run in the parallel batch that has no failure case in the junit report. - Drops `package.json` / non-JS entries — those are setup steps, not tests. If the script can't find a build automatically (rare — it walks the last 10 merged PRs), pick one yourself: `gh pr list --state merged --limit 10 --json number,headRefName`, then `bk build list --branch ` and pass the first build with a `finished_at`. Merged-PR builds usually report `state: failed` because of flaky tests — that's fine, the timing data is still valid. @@ -39,6 +40,7 @@ Procedure: 3. Post the **main** message: header (build link + gist link, "Rest in thread.") followed by the **top 20** bullets. Row format: ``` + • 973s `test/aot/modules-in-a-test-run-twice.test.ts` 🐧 x64-asan (5 attempts, longest 197s) • 325s `test/js/bun/cron/in-process-cron.test.ts` 🐧 x64-baseline • 96s `test/js/bun/http/serve-body-leak.test.ts` 🐧 x64-asan ``` @@ -46,5 +48,6 @@ Procedure: - seconds: plain text, left-aligned, padded so the backticks line up - filepath: code-font, **full path including `test/` prefix and extension** — do not strip anything - platform: standard Unicode emoji only (🐧 linux, 🪟 windows, 🍎 macOS — never workspace-custom shortcodes) followed by the arch/variant **verbatim** from the job name (`x64-asan`, `aarch64`, `x64-baseline` — do not abbreviate) + - attempts: only for a row with more than 1. Put `(N attempts, longest Xs)` after the platform. The seconds of that row are the sum of runs that failed and ran again, not one slow run 4. Reply in-thread (`thread_ts` = the main message) with rows 21–N in the same bullet format, packed into chunks under 4800 chars each (~70 rows per chunk). Post chunks sequentially so they stay ordered. diff --git a/scripts/ci-log-phase.mjs b/scripts/ci-log-phase.mjs index f19052b97824..286ef10095ba 100644 --- a/scripts/ci-log-phase.mjs +++ b/scripts/ci-log-phase.mjs @@ -10,6 +10,12 @@ // - retry/error label: `--- [N/M] - ` (not a path) // - parallel-bucket phase: `--- [A-B/M] K files in parallel`, then after the // single `bun test --parallel` run a summary `[N/M] (X.XXs)` per file +// that passed, and a group `--- - K failing in the parallel batch (X.XXs)` +// per file whose tests failed there. The seconds of the group are what the file +// took in the bucket, up to the interruption where the bucket was cut short. The +// group has no `[N/M]`: the file gets its number when it runs again, alone, as a +// serial test. failedBucketAttempt() reads it for ci:slowest. The durations +// parser takes no sample from it // - parallel-safe phase: `--- Running N parallel-safe tests`, then a bare // `[N/M] ` per concurrent dispatch (no recoverable wall clock) // - compiled-programs phase: `--- Running N programs compiled ahead of time`, @@ -39,3 +45,15 @@ export const isPhaseGroupHeader = body => /^--- (?:\[\d+-\d+\/\d+\]|napi prebuild:|Running \d+ (?:parallel-safe|programs compiled|files that build)|Disk and memory pressure\b|End\b|Summary\b|Received \w+, exiting)/.test( body, ); + +/** + * The run of a file that failed in its `bun test --parallel` bucket, from the group that the runner opens for it: + * `--- - K failing in the parallel batch (X.XXs)`. + * + * @param {string} body one log line with its APC timestamp and SGR codes removed + * @returns {{ path: string, ms: number } | null} the file, and what it took in the bucket + */ +export const failedBucketAttempt = body => { + const failed = /^--- (.+\.[cm]?[jt]sx?) - \d+ failing in the parallel batch \((\d+(?:\.\d+)?)s\)$/.exec(body); + return failed && { path: failed[1], ms: Math.round(parseFloat(failed[2]) * 1000) }; +}; diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index 188b70cdad80..3255accce99d 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -18,14 +18,22 @@ import { $, spawn } from "bun"; import { existsSync, mkdirSync, readFileSync, writeFileSync } from "fs"; import { tmpdir } from "os"; import { join } from "path"; -import { isPhaseGroupHeader } from "./ci-log-phase.mjs"; +import { failedBucketAttempt, isPhaseGroupHeader } from "./ci-log-phase.mjs"; // Per-file cost is the gap between the APC timestamps Buildkite injects into // consecutive `[N/M] ` headers (ESC `_bk;t=` BEL). See // scripts/ci-log-phase.mjs for the header shapes runner.node.ts emits and why // each one has to close the open span. -export function parseLog(text: string): Map { - const out = new Map(); +// +// `record` gets each attempt of a file that the log has seconds for, with +// what that attempt took. An attempt is a serial run (the first, or an +// `[attempt #K]`), a run in a parallel bucket (one that passed, or one that +// failed and has its group), or a dispatch of the parallel-safe phase. In the +// phase of the files that build many executables this loop times only a file +// that passes at its first try (`[N/M] (X.XXs)`): a first try that +// fails is no attempt, and a further try counts like a parallel-safe dispatch, +// at most 500 ms. +function eachAttempt(text: string, record: (file: string, ms: number) => void): void { let curName: string | null = null; let curStart = 0; let concurrent = false; @@ -36,7 +44,7 @@ export function parseLog(text: string): Map { // Concurrent-phase gaps are inter-dispatch deltas, not per-file wall // clock; clamp so the last-dispatched file on a shard does not absorb the // N-wide tail drain or a sibling's 5-15 s retry backoff. - out.set(curName, (out.get(curName) ?? 0) + (concurrent ? Math.min(span, 500) : span)); + record(curName, concurrent ? Math.min(span, 500) : span); curName = null; }; for (const line of text.split("\n")) { @@ -54,7 +62,7 @@ export function parseLog(text: string): Map { // Parallel-bucket summaries carry the authoritative wall clock inline. const timed = !hdr[1] && /^(.+\.(?:[cm]?[jt]sx?|json)) \((\d+(?:\.\d+)?)s\)$/.exec(title); if (timed) { - out.set(timed[1], (out.get(timed[1]) ?? 0) + Math.round(parseFloat(timed[2]) * 1000)); + record(timed[1], Math.round(parseFloat(timed[2]) * 1000)); concurrent = false; continue; } @@ -67,7 +75,13 @@ export function parseLog(text: string): Map { concurrent = !hdr[1]; continue; } - if (isPhaseGroupHeader(body)) { + // The runner's other headers are groups. + if (!body.startsWith("--- ")) continue; + const failed = failedBucketAttempt(body); + if (failed) { + close(ts); + record(failed.path, failed.ms); + } else if (isPhaseGroupHeader(body)) { close(ts); concurrent = false; } @@ -75,7 +89,78 @@ export function parseLog(text: string): Map { // A truncated log (job killed / timed out mid-run) has no `--- End`; charge // the open span to the last timestamp seen so the culprit is not dropped. close(lastTs); - return out; +} + +// One file over the jobs of a build. `perPlat` is the sum of the file's +// attempts on each platform. `retried` has the platforms where that sum is +// more than one attempt. +export type Agg = { + maxMs: number; + maxPlat: string; + perPlat: Map; + retried?: Map; +}; + +// `maxMs` is the sum of `attempts` attempts on `maxPlat`, the platform where +// the file took the longest. The longest of them took `maxAttemptMs`. More +// than one attempt is a file that failed and ran again, not one slow run. +export type Row = { file: string; maxMs: number; maxPlat: string; attempts: number; maxAttemptMs: number }; + +export function addLog(agg: Map, plat: string, log: string): void { + eachAttempt(log, (file, ms) => { + let a = agg.get(file); + // `maxPlat` starts as this platform, so a file whose attempts all take 0 ms has one too. + if (!a) agg.set(file, (a = { maxMs: 0, maxPlat: plat, perPlat: new Map() })); + const before = a.perPlat.get(plat); + const total = (before ?? 0) + ms; + a.perPlat.set(plat, total); + if (before !== undefined) { + const retried = (a.retried ??= new Map()); + const onPlat = retried.get(plat); + if (onPlat) { + onPlat.attempts++; + onPlat.maxAttemptMs = Math.max(onPlat.maxAttemptMs, ms); + } else { + // Until now the sum was one attempt. + retried.set(plat, { attempts: 2, maxAttemptMs: Math.max(before, ms) }); + } + } + if (total > a.maxMs) { + a.maxMs = total; + a.maxPlat = plat; + } + }); +} + +// `package.json` / `test/package.json` are setup steps, not tests. +const isTest = (f: string) => /\.(m|c)?(j|t)sx?$/.test(f); + +export function slowestRows(agg: Map, topN: number): Row[] { + return [...agg.entries()] + .filter(([file]) => isTest(file)) + .map(([file, a]) => { + const retried = a.retried?.get(a.maxPlat); + return { + file, + maxMs: a.maxMs, + maxPlat: a.maxPlat, + attempts: retried?.attempts ?? 1, + maxAttemptMs: retried?.maxAttemptMs ?? a.maxMs, + }; + }) + .sort((a, b) => b.maxMs - a.maxMs) + .slice(0, topN); +} + +export function tableLines(rows: Row[]): string[] { + const seconds = (ms: number) => (ms / 1000).toFixed(2); + return [ + `rank\tseconds\tfile\tslowest_platform\tattempts\tlongest_attempt`, + ...rows.map( + (row, i) => + `${i + 1}\t${seconds(row.maxMs)}\t${row.file}\t${row.maxPlat}\t${row.attempts}\t${seconds(row.maxAttemptMs)}`, + ), + ]; } if (import.meta.main) { @@ -148,7 +233,6 @@ if (import.meta.main) { return out; } - type Agg = { maxMs: number; maxPlat: string; perPlat: Map }; const agg = new Map(); let done = 0; @@ -160,16 +244,7 @@ if (import.meta.main) { try { const log = await fetchLog(job); const plat = platOf(job.name); - for (const [file, ms] of parseLog(log)) { - let a = agg.get(file); - if (!a) agg.set(file, (a = { maxMs: 0, maxPlat: "", perPlat: new Map() })); - const total = (a.perPlat.get(plat) ?? 0) + ms; - a.perPlat.set(plat, total); - if (total > a.maxMs) { - a.maxMs = total; - a.maxPlat = plat; - } - } + addLog(agg, plat, log); } catch (e) { console.error(` failed ${job.id}: ${(e as Error).message}`); } @@ -179,14 +254,7 @@ if (import.meta.main) { } await Promise.all(Array.from({ length: 16 }, worker)); - // `package.json` / `test/package.json` are setup steps, not tests. - const isTest = (f: string) => /\.(m|c)?(j|t)sx?$/.test(f); - - const sorted = [...agg.entries()] - .filter(([file]) => isTest(file)) - .map(([file, a]) => ({ file, maxMs: a.maxMs, maxPlat: a.maxPlat })) - .sort((a, b) => b.maxMs - a.maxMs) - .slice(0, TOP_N); + const sorted = slowestRows(agg, TOP_N); console.error(`${agg.size} unique entries, ${sorted.length} test files after filtering`); console.error(`logs cached at ${CACHE}`); @@ -194,8 +262,7 @@ if (import.meta.main) { if (json) { console.log(JSON.stringify({ build: BUILD, count: agg.size, top: sorted }, null, 2)); } else { - console.log(`rank\tseconds\tfile\tslowest_platform`); - sorted.forEach((t, i) => console.log(`${i + 1}\t${(t.maxMs / 1000).toFixed(2)}\t${t.file}\t${t.maxPlat}`)); + for (const line of tableLines(sorted)) console.log(line); } process.exit(0); } diff --git a/scripts/update-test-durations.mjs b/scripts/update-test-durations.mjs index 7578241c3df3..ac6bf80582de 100644 --- a/scripts/update-test-durations.mjs +++ b/scripts/update-test-durations.mjs @@ -69,6 +69,12 @@ const api = async path => { // prints the bare form. For that concurrent phase the gap is an inter-dispatch // delta, not wall clock; we clamp it so the last-dispatched file on each shard // does not absorb the N-wide tail drain or a sibling's 5-15 s retry backoff. +// +// A file that fails in its parallel bucket gets no sample from the group that +// the runner prints for that run, `--- - K failing in the parallel +// batch (X.XXs)`. Its sample is its run alone: a bucket run that was +// interrupted did not finish, and update-parallel-allowlist.mjs takes a file +// with a flaky or failed annotation out of the buckets, so it runs alone next. export function parseLog(raw) { const out = []; const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r?\n/); diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index b4315f1886ce..baf9aea59b3a 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -1,15 +1,22 @@ import { describe, expect, test } from "bun:test"; import { readFileSync } from "node:fs"; import { dirname, join } from "node:path"; -import { isPhaseGroupHeader } from "../../scripts/ci-log-phase.mjs"; -import { parseLog } from "../../scripts/ci-slowest-tests"; +import { failedBucketAttempt, isPhaseGroupHeader } from "../../scripts/ci-log-phase.mjs"; +import { addLog, slowestRows, tableLines, type Agg } from "../../scripts/ci-slowest-tests"; import { entryOfProgram, parseLog as parseDurations } from "../../scripts/update-test-durations.mjs"; // Buildkite prefixes each line with an APC timestamp: ESC `_bk;t=` BEL. const bk = (ts: number, body: string) => `\x1b_bk;t=${ts}\x07${body}`; const gray = (s: string) => `\x1b[90m${s}\x1b[0m`; -describe("scripts/ci-slowest-tests.ts parseLog", () => { +// What ci:slowest has for each file of one job log, the sum of the file's attempts, by the fold that the script runs. +const parseLog = (log: string) => { + const agg = new Map(); + addLog(agg, "one platform", log); + return new Map([...agg].map(([file, a]) => [file, a.perPlat.get("one platform")!])); +}; + +describe("scripts/ci-slowest-tests.ts addLog", () => { test("does not charge the parallel-safe phase to the last serial test", () => { // runner.node.ts prints serial headers via startGroup (`--- [N/M] path`) // and parallel-safe headers via plain console.log (`[N/M] path`). A regex @@ -171,6 +178,299 @@ describe("phase-header boundary", () => { }); }); +// A file that fails in its `bun test --parallel` bucket has no `[N/M]` line for that run. The runner opens a group for +// it, `--- - K failing in the parallel batch (X.XXs)`, and then runs the file again, alone, as a serial test. +describe("a file that fails in its parallel bucket", () => { + const failedInBucket = (path: string, failing: number, seconds: string) => + `--- ${path} - ${failing} failing in the parallel batch ${gray(`(${seconds}s)`)}`; + const retryingAlone = (failed: number, unfinished = 0) => + `\x1b[33mparallel bucket: retrying ${failed} failed and ${unfinished} unfinished file(s) one at a time\x1b[0m`; + + // Lines of build 137632, debian 13 x64-asan, job 01a1a834-7687-4bcc-8a22-115e18a35494. The timestamps count from the + // header of the bucket. The bucket reached its limit of 10 minutes while `regexp` still ran. Five files failed in + // it. Two are kept here, and the counts in the headers and in the retry line are adjusted to that. Both pass alone. + const passed = "test/bundler/compile-trim-capabilities.test.ts"; + const mocked = "test/aot/a-mocked-commonjs-file-keeps-its-own-exports.test.ts"; + const regexp = "test/aot/a-regexp-literal-of-two-layers-is-made-once.test.ts"; + const bucketThenPassAlone = [ + bk(0, `--- ${gray("[372-406/684]")} 35 files in parallel (7\u00d7)`), + bk(600230, `\x1b[31mInterrupted\x1b[0m while still running:`), + // `bun test` says what the file took too. That is the run of the runner's line below, not one more. + bk(600230, ` ${regexp} \x1b[2m(599s)\x1b[0m`), + bk(600852, ``), + bk(600854, `${gray("[404/684]")} ${passed} ${gray("(2.07s)")}`), + bk(600854, failedInBucket(mocked, 1, "240.23")), + bk(600854, `\x1b[31m\u2717\x1b[0m it says what plain Bun says, as one program and in layers`), + bk(600854, ` test timed out`), + bk(600854, ``), + bk(600854, failedInBucket(regexp, 1, "599.93")), + bk(600854, `\x1b[31m\u2717\x1b[0m (interrupted)`), + bk(600854, ` interrupted while still running`), + bk(600854, ``), + bk(600855, retryingAlone(2)), + bk(600855, `--- ${gray("[405/684]")} ${mocked}`), + bk(636393, `--- ${gray("[406/684]")} ${regexp}`), + bk(786245, `--- ${gray("[407-494/684]")} 88 files in parallel (7\u00d7)`), + ]; + + // Lines of build 137815, debian 13 x64-asan, job 01a1adc4-0c2e-4ee7-9d0b-430120ef94ae, cut down the same way. + // `imported` passes alone. `twice` fails each of the 4 times it runs alone, and its last attempt is its longest. + const slowPass = "test/aot/a-source-file-that-a-test-writes-anew-is-read-from-disk.test.ts"; + const imported = "test/aot/a-name-imported-from-a-built-in-module-keeps-what-the-module-had-at-the-link.test.ts"; + const twice = "test/aot/modules-in-a-test-run-twice.test.ts"; + const bucketThenFailAlone = [ + bk(0, `--- ${gray("[322-362/633]")} 41 files in parallel (7\u00d7)`), + bk(600314, `\x1b[31mInterrupted\x1b[0m while still running:`), + bk(600314, ` ${twice} \x1b[2m(186s)\x1b[0m`), + bk(600917, `${gray("[326/633]")} ${slowPass} ${gray("(344.85s)")}`), + bk(600919, failedInBucket(imported, 7, "281.80")), + bk(600919, `\x1b[31m\u2717\x1b[0m names of node:module that are first used behind the stores`), + bk(600919, ` test timed out`), + bk(600920, failedInBucket(twice, 4, "186.26")), + bk(600920, `\x1b[31m\u2717\x1b[0m mock.module of a file that has run: twice`), + bk(600920, ` expect(received).toEqual(expected)`), + bk(600920, retryingAlone(2)), + bk(908108, `--- ${gray("[361/633]")} ${imported}`), + bk(938426, `--- ${gray("[362/633]")} ${twice}`), + bk(1135131, `--- \x1b[33m[362/633] ${twice} - code 1\x1b[0m`), + // Between a failure and the next attempt the runner waits 5 to 15 s. No attempt is charged for that. + bk(1142767, `--- ${gray("[362/633]")} ${twice} ${gray("[attempt #2]")}`), + bk(1339346, `--- \x1b[33m[362/633] ${twice} - code 1\x1b[0m`), + bk(1345503, `--- ${gray("[362/633]")} ${twice} ${gray("[attempt #3]")}`), + bk(1541980, `--- \x1b[33m[362/633] ${twice} - code 1\x1b[0m`), + bk(1548046, `--- ${gray("[362/633]")} ${twice} ${gray("[attempt #4]")}`), + bk(1744979, `--- \x1b[31m[362/633] ${twice} - code 1\x1b[0m`), + bk(1745052, `--- ${gray("[363-447/633]")} 85 files in parallel (7\u00d7)`), + ]; + + // Lines of build 137632, debian 13 x64-asan, job 01a1a834-7685-4bc3-9831-b229ee18ba12: the two files that failed in + // this bucket. `run` fails each of the 4 times it runs alone, and its bucket attempt is its longest. + const library = "test/aot/library-modules-in-a-layered-test-run.test.ts"; + const run = "test/aot/modules-in-a-test-run.test.ts"; + const bucketAttemptIsLongest = [ + bk(0, `--- ${gray("[395-428/703]")} 34 files in parallel (7\u00d7)`), + bk(350833, failedInBucket(library, 1, "120.21")), + bk(350833, failedInBucket(run, 2, "300.36")), + bk(350833, retryingAlone(2)), + bk(350833, `--- ${gray("[427/703]")} ${library}`), + bk(371159, `--- ${gray("[428/703]")} ${run}`), + bk(554113, `--- \x1b[33m[428/703] ${run} - code 1\x1b[0m`), + bk(566487, `--- ${gray("[428/703]")} ${run} ${gray("[attempt #2]")}`), + bk(751531, `--- \x1b[33m[428/703] ${run} - code 1\x1b[0m`), + bk(765709, `--- ${gray("[428/703]")} ${run} ${gray("[attempt #3]")}`), + bk(947859, `--- \x1b[33m[428/703] ${run} - code 1\x1b[0m`), + bk(962775, `--- ${gray("[428/703]")} ${run} ${gray("[attempt #4]")}`), + bk(1147497, `--- \x1b[31m[428/703] ${run} - code 1\x1b[0m`), + bk(1147580, `--- ${gray("[429-517/703]")} 89 files in parallel (7\u00d7)`), + ]; + + // Lines of build 137815, ubuntu 25.04 x64, job 01a1adc4-0c39-4421-97f9-7f64e804f163: a file that builds no + // executable. One test fails in the bucket. Alone the file passes, and takes longer than in the bucket. + const quick = "test/snippets/segfault-todo.test.js"; + const net = "test/js/node/net/node-net.test.ts"; + const aloneIsLonger = [ + bk(0, `--- ${gray("[316-405/592]")} 90 files in parallel (3\u00d7)`), + bk(45942, `${gray("[404/592]")} ${quick} ${gray("(0.01s)")}`), + bk(45942, failedInBucket(net, 1, "5.61")), + bk(45942, `\x1b[31m\u2717\x1b[0m a partial writev keeps exactly the unsent suffix`), + bk(45942, ` client failed (exit 3): precondition failed: no direct write left data in the native buffer`), + bk(45942, retryingAlone(1)), + bk(45943, `--- ${gray("[405/592]")} ${net}`), + bk(52661, `--- Running 187 parallel-safe tests (3-wide)`), + ]; + + test("scripts/ci-slowest-tests.ts adds the bucket attempt to the attempts alone", () => { + // Without its bucket attempt `regexp` is a file of 150 s. Where it passes in its bucket, it takes 576 s. + expect(Object.fromEntries(parseLog(bucketThenPassAlone.join("\r\r\n")))).toEqual({ + [passed]: 2070, + [mocked]: 240230 + 35538, + [regexp]: 599930 + 149852, + }); + expect(Object.fromEntries(parseLog(bucketThenFailAlone.join("\r\r\n")))).toEqual({ + [slowPass]: 344850, + [imported]: 281800 + 30318, + [twice]: 186260 + 196705 + 196579 + 196477 + 196933, + }); + expect(Object.fromEntries(parseLog(aloneIsLonger.join("\r\r\n")))).toEqual({ + [quick]: 10, + [net]: 5610 + 6718, + }); + }); + + test("scripts/update-test-durations.mjs keeps the run alone as the sample, and takes none from the bucket", () => { + // The table is for the packing of shards. A file that fails in its bucket has a flaky or failed annotation, and + // scripts/update-parallel-allowlist.mjs takes a file with one out of the buckets, so it runs alone next. A bucket + // run that was interrupted, like that of `regexp`, did not finish either. A retry gives no sample, as before. + expect(parseDurations(bucketThenPassAlone.join("\r\r\n"))).toEqual([ + [passed, 2070], + [mocked, 35538], + [regexp, 149852], + ]); + expect(parseDurations(bucketThenFailAlone.join("\r\r\n"))).toEqual([ + [slowPass, 344850], + [imported, 30318], + [twice, 196705], + ]); + expect(parseDurations(aloneIsLonger.join("\r\r\n"))).toEqual([ + [quick, 10], + [net, 6718], + ]); + }); + + test("a file that did not finish in the bucket has no such line, and both parsers take its run alone", () => { + // No log of the three builds has an unfinished file. These lines follow runParallelBucket in + // scripts/runner.node.ts: a file that a crash or the time limit kept from finishing gets no line, and runs alone + // after the files that failed. + const log = [ + bk(0, `--- ${gray("[1-3/5]")} 3 files in parallel (3\u00d7)`), + bk(9000, `${gray("[1/5]")} test/ok.test.ts ${gray("(1.00s)")}`), + bk(9000, failedInBucket("test/failed.test.ts", 1, "4.00")), + bk(9001, retryingAlone(1, 1)), + bk(9001, `--- ${gray("[2/5]")} test/failed.test.ts`), + bk(11001, `--- ${gray("[3/5]")} test/unfinished.test.ts`), + bk(14001, `--- ${gray("[4/5]")} test/serial.test.ts`), + bk(14501, `--- End`), + ].join("\n"); + expect(Object.fromEntries(parseLog(log))).toEqual({ + "test/ok.test.ts": 1000, + "test/failed.test.ts": 4000 + 2000, + "test/unfinished.test.ts": 3000, + "test/serial.test.ts": 500, + }); + expect(parseDurations(log)).toEqual([ + ["test/ok.test.ts", 1000], + ["test/failed.test.ts", 2000], + ["test/unfinished.test.ts", 3000], + ["test/serial.test.ts", 500], + ]); + }); + + test("scripts/ci-slowest-tests.ts keeps the bucket attempt when the log ends before the file runs alone", () => { + // The job is killed after the runner has printed what failed in the bucket. + const killed = bucketThenFailAlone.slice(0, 10).join("\r\r\n"); + expect(Object.fromEntries(parseLog(killed))).toEqual({ [slowPass]: 344850, [imported]: 281800, [twice]: 186260 }); + // No file ran alone, so the durations have no sample for the two that failed. + expect(parseDurations(killed)).toEqual([[slowPass, 344850]]); + }); + + test("scripts/ci-slowest-tests.ts reads the line where it ends in three carriage returns", () => { + // Most lines of a log end in `\r\r\n`. In the darwin logs some of the runner's lines end in `\r\r\r\n`. + expect(Object.fromEntries(parseLog(bucketThenPassAlone.join("\r\r\r\n")))).toEqual({ + [passed]: 2070, + [mocked]: 240230 + 35538, + [regexp]: 599930 + 149852, + }); + }); + + test("scripts/ci-slowest-tests.ts: the group of a failed file ends the test before it, as every header does", () => { + // The runner prints the header of the bucket first. The parser does not depend on that. + const log = [ + bk(0, `--- ${gray("[1/3]")} test/serial.test.ts`), + bk(1000, failedInBucket("test/b.test.ts", 1, "2.00")), + bk(9000, `--- ${gray("[2/3]")} test/b.test.ts`), + bk(9500, `--- End`), + ].join("\n"); + expect(Object.fromEntries(parseLog(log))).toEqual({ "test/serial.test.ts": 1000, "test/b.test.ts": 2000 + 500 }); + }); + + test.each([ + [`--- ${regexp} - 1 failing in the parallel batch (599.93s)`, { path: regexp, ms: 599930 }], + [`--- test/a.test.ts - 12 failing in the parallel batch (0.04s)`, { path: "test/a.test.ts", ms: 40 }], + // 64.88 * 1000 is 64879.99999999999. + [`--- test/a.test.ts - 1 failing in the parallel batch (64.88s)`, { path: "test/a.test.ts", ms: 64880 }], + // The one line of the 389 in the three builds that names no .ts file. + [ + `--- test/js/web/websocket/websocket.test.js - 1 failing in the parallel batch (1.00s)`, + { path: "test/js/web/websocket/websocket.test.js", ms: 1000 }, + ], + // Other groups and lines that name a file. + [`--- scripts/ci-remap-server/package.json`, null], + [`--- a/index.js`, null], + [`--- test/a.test.ts`, null], + [`--- [5/8] test/a.test.ts - code 1`, null], + [`[3/8] test/a.test.ts (1.25s)`, null], + [` test/a.test.ts (599s)`, null], + // Not the whole line, or no test file. + [`test/a.test.ts - 1 failing in the parallel batch (1.00s)`, null], + [`--- test/a.test.ts - 1 failing in the parallel batch (1.00s) and more`, null], + [`--- test/package.json - 1 failing in the parallel batch (1.00s)`, null], + ])("failedBucketAttempt(%j)", (body, expected) => { + expect(failedBucketAttempt(body)).toEqual(expected); + }); + + test("a row of ci:slowest says how many attempts its time adds up, and how long the longest took", () => { + const agg = new Map(); + // Three shards of one platform. + addLog(agg, "debian 13 x64-asan", bucketThenFailAlone.join("\r\r\n")); + addLog(agg, "debian 13 x64-asan", bucketThenPassAlone.join("\r\r\n")); + addLog(agg, "debian 13 x64-asan", bucketAttemptIsLongest.join("\r\r\n")); + addLog(agg, "ubuntu 25.04 x64", aloneIsLonger.join("\r\r\n")); + // On this platform `imported` passes in its bucket, and that one attempt takes longer than its two on + // debian 13 x64-asan. `twice` fails in the bucket and passes alone. + addLog( + agg, + "debian 13 x64", + [ + bk(0, `--- ${gray("[90-180/367]")} 91 files in parallel (3\u00d7)`), + bk(350400, `${gray("[95/367]")} ${imported} ${gray("(350.00s)")}`), + bk(350400, failedInBucket(twice, 4, "77.53")), + bk(350401, retryingAlone(1)), + bk(350401, `--- ${gray("[180/367]")} ${twice}`), + bk(405639, `--- ${gray("[181/367]")} vendor/elysia/package.json`), + bk(406000, `--- End`), + ].join("\n"), + ); + + // `attempts` and `maxAttemptMs` are those of `maxPlat`: `maxMs` is the sum of that many attempts. The longest is + // the first of 5 for `run`, the last of 5 for `twice`, the first of 2 for `regexp` and the second of 2 for `net`. + expect(slowestRows(agg, 500)).toEqual([ + { file: run, maxMs: 1035230, maxPlat: "debian 13 x64-asan", attempts: 5, maxAttemptMs: 300360 }, + { file: twice, maxMs: 972954, maxPlat: "debian 13 x64-asan", attempts: 5, maxAttemptMs: 196933 }, + { file: regexp, maxMs: 749782, maxPlat: "debian 13 x64-asan", attempts: 2, maxAttemptMs: 599930 }, + { file: imported, maxMs: 350000, maxPlat: "debian 13 x64", attempts: 1, maxAttemptMs: 350000 }, + { file: slowPass, maxMs: 344850, maxPlat: "debian 13 x64-asan", attempts: 1, maxAttemptMs: 344850 }, + { file: mocked, maxMs: 275768, maxPlat: "debian 13 x64-asan", attempts: 2, maxAttemptMs: 240230 }, + { file: library, maxMs: 140536, maxPlat: "debian 13 x64-asan", attempts: 2, maxAttemptMs: 120210 }, + { file: net, maxMs: 12328, maxPlat: "ubuntu 25.04 x64", attempts: 2, maxAttemptMs: 6718 }, + { file: passed, maxMs: 2070, maxPlat: "debian 13 x64-asan", attempts: 1, maxAttemptMs: 2070 }, + { file: quick, maxMs: 10, maxPlat: "ubuntu 25.04 x64", attempts: 1, maxAttemptMs: 10 }, + ]); + expect(tableLines(slowestRows(agg, 2))).toEqual([ + "rank\tseconds\tfile\tslowest_platform\tattempts\tlongest_attempt", + `1\t1035.23\t${run}\tdebian 13 x64-asan\t5\t300.36`, + `2\t972.95\t${twice}\tdebian 13 x64-asan\t5\t196.93`, + ]); + }); + + test("a row whose attempts all take 0 ms has a platform, and the attempts of that platform", () => { + // Lines of build 137815, ubuntu 25.04 x64, job 01a1adc4-0c3a-436b-ad84-5c83a716d85c. A program compiled ahead of + // time fails, and the runner prints its header and its failure in the same millisecond. It fails like that on + // three platforms of the build. + const program = "test/aot/parallel/module-loaders/raw-behind-a-path-asks-for-the-text-of-the-file/main.mjs"; + const failsAtOnce = [ + bk(0, `--- ${gray("[294/687]")} ${program}`), + bk(0, ``), + bk( + 0, + `--- \x1b[31m[294/687] ${program} - compare: with --aot-erase-types: it does not exit and print as plain Bun does\x1b[0m`, + ), + bk(1, `bun test/aot/run-parallel.ts ${program}`), + ].join("\r\r\n"); + const agg = new Map(); + addLog(agg, "ubuntu 25.04 x64", failsAtOnce); + addLog(agg, "debian 13 x64-asan", failsAtOnce); + // No platform took longer than the first one, so the row stays with it. + expect(slowestRows(agg, 500)).toEqual([ + { file: program, maxMs: 0, maxPlat: "ubuntu 25.04 x64", attempts: 1, maxAttemptMs: 0 }, + ]); + // One more attempt of 0 ms on that platform adds no time, and it is an attempt. + addLog(agg, "ubuntu 25.04 x64", failsAtOnce); + expect(slowestRows(agg, 500)).toEqual([ + { file: program, maxMs: 0, maxPlat: "ubuntu 25.04 x64", attempts: 2, maxAttemptMs: 0 }, + ]); + }); +}); + test("what .buildkite/update-test-durations.yml runs with node imports no TypeScript", () => { const root = join(import.meta.dir, "..", ".."); const importsOf = (file: string): string[] =>