From 5b1c418593eeb5202e1887d29e16fd95f378816c Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Fri, 24 Jul 2026 10:01:00 +0000 Subject: [PATCH 1/7] scripts/ci-slowest-tests: stop charging the parallel phase to the last serial test parseLog measured each file as (next-header - this-header) but only matched the `--- [N/M] path` form. runner.node.mjs prints parallel-safe headers without the `--- ` prefix, so the last serial file on every shard absorbed the entire parallel phase (79.5s reported for a 4.8s test on build 79247). Match the header with or without `--- `, close the open span at the `--- Running N parallel-safe tests` / `--- End` group boundaries, clamp concurrent-phase spans (they are inter-dispatch deltas, not wall clock), and drop the retry backoff between a failure label and the next attempt. This matches the parseLog already used by scripts/update-test-durations.mjs. parseLog is now exported behind an import.meta.main guard so the new test/internal/ci-slowest-tests.test.ts can exercise it directly. --- scripts/ci-slowest-tests.ts | 268 +++++++++++++------------ test/internal/ci-slowest-tests.test.ts | 73 +++++++ 2 files changed, 218 insertions(+), 123 deletions(-) create mode 100644 test/internal/ci-slowest-tests.test.ts diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index 2033ddf0e1ca..ffe358155e77 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -3,8 +3,8 @@ // // Downloads every test-bun job log from a BuildKite build, parses per-file // wall-clock from the `_bk;t=` timestamps that prefix each -// `--- [N/TOTAL] ` group header, aggregates as MAX across all -// platforms, and prints the top N. +// `[N/TOTAL] ` header, aggregates as MAX across all platforms, and +// prints the top N. // // Usage: // bun scripts/ci-slowest-tests.ts # auto-pick a recent merged-PR build, top 500 @@ -19,143 +19,165 @@ import { existsSync, mkdirSync, readFileSync, writeFileSync } from "fs"; import { tmpdir } from "os"; import { join } from "path"; -const args = process.argv.slice(2); -const json = args.includes("--json"); -const positional = args.filter(a => !a.startsWith("-")); -let BUILD = positional[0]; -const TOP_N = parseInt(positional[1] || "500", 10); - -const TOKEN = process.env.BUILDKITE_TOKEN || process.env.BUILDKITE_API_TOKEN; -if (!TOKEN) { - console.error("error: BUILDKITE_TOKEN not set"); - process.exit(1); -} - -// Auto-pick a build: most-recent merged PR whose branch has a finished build. -// Merged-PR builds usually report state=failed (flaky tests) — that's fine, -// we only need the timing data. -if (!BUILD) { - console.error("no build given, finding a recent merged-PR build..."); - const prs = await $`gh pr list --state merged --limit 10 --json number,headRefName`.json(); - for (const pr of prs) { - const builds = await $`bk build list --branch ${pr.headRefName}` - .quiet() - .json() - .catch(() => []); - const done = builds.find((b: any) => b.finished_at && b.state !== "canceled" && b.state !== "running"); - if (done) { - BUILD = String(done.number); - console.error(` using build #${BUILD} (PR #${pr.number}, ${pr.headRefName}, state=${done.state})`); - break; - } - } - if (!BUILD) { - console.error("error: no finished build found among the last 10 merged PRs"); - process.exit(1); - } -} - -const CACHE = join(tmpdir(), `bun-ci-logs-${BUILD}`); -mkdirSync(CACHE, { recursive: true }); - -type Job = { id: string; name: string; raw_log_url: string; retried?: boolean }; - -const buildJson = JSON.parse( - await new Response(spawn({ cmd: ["bk", "build", "view", BUILD], stdout: "pipe" }).stdout).text(), -); -const jobs: Job[] = buildJson.jobs.filter( - (j: any) => j.name && j.raw_log_url && j.name.includes("test-bun") && !j.retried, -); -console.error(`build #${BUILD}: ${jobs.length} test-bun jobs across ${new Set(jobs.map(j => j.name)).size} platforms`); - -const platOf = (name: string) => - name - .replace(/ - test-bun$/, "") - .replace(/^:([a-z]+):/, "$1") - .trim(); - -function parseLog(text: string): Map { +// Per-file cost is the gap between the APC timestamps Buildkite injects into +// consecutive `[N/M] ` headers (ESC `_bk;t=` BEL). Serial-phase +// tests print `--- [N/M] path` via startGroup; the parallel-safe phase +// (runner.node.mjs runTest with concurrent=true) prints the bare `[N/M] path` +// without `--- `. If the `--- ` is treated as mandatory the last serial test +// on every shard absorbs the entire parallel phase's wall clock. +export function parseLog(text: string): Map { const out = new Map(); - const startRe = /_bk;t=(\d+).*?--- .*?\[90m\[\d+\/\d+\].*?\[0m (.+)/; let curName: string | null = null; let curStart = 0; + let concurrent = false; + const close = (ts: number) => { + if (!curName) return; + const span = ts - curStart; + // 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)); + curName = null; + }; for (const line of text.split("\n")) { - const m = startRe.exec(line); - if (!m) continue; - const ts = parseInt(m[1], 10); - if (curName) { - const clean = curName - .replace(/\s+\x1b\[90m\[attempt #\d+\]\x1b\[0m\r*$/, "") - .replace(/\r+$/, "") - .replace(/\\/g, "/") - .trim(); - out.set(clean, (out.get(clean) ?? 0) + (ts - curStart)); + const apc = /_bk;t=(\d+)\x07(.*)/.exec(line); + if (!apc) continue; + const ts = parseInt(apc[1], 10); + const body = apc[2].replace(/\x1b\[[0-9;]*m/g, "").replace(/\r+$/, ""); + const hdr = /^(--- )?\[\d+\/\d+\] (.+)$/.exec(body); + if (hdr) { + close(ts); + const title = hdr[2].replace(/ \[attempt #\d+\]$/, "").replace(/\\/g, "/").trim(); + // Retry/error labels (` - code 1`) are not file paths; treat them + // as a delimiter so the preceding span closes without the retry backoff + // landing on either attempt. + const isPath = /\.(?:[cm]?[jt]sx?|json)$/.test(title); + curName = isPath ? title : null; + curStart = ts; + concurrent = !hdr[1]; + continue; } - curStart = ts; - curName = m[2].replace(/\r+$/, "").replace(/\\/g, "/").trim(); + if (/^--- (?:End\b|Running \d+ parallel-safe)/.test(body)) close(ts); } return out; } -// Do NOT use `bk job log` — it hangs indefinitely on some Windows/alpine jobs. -// Fetching raw_log_url directly with the token works for all of them. -async function fetchLog(job: Job): Promise { - const path = join(CACHE, `${job.id}.log`); - if (existsSync(path)) return readFileSync(path, "utf8"); - const res = await fetch(job.raw_log_url, { headers: { Authorization: `Bearer ${TOKEN}` } }); - if (!res.ok) throw new Error(`${res.status} ${job.raw_log_url}`); - const out = await res.text(); - writeFileSync(path, out); - return out; -} +if (import.meta.main) { + const args = process.argv.slice(2); + const json = args.includes("--json"); + const positional = args.filter(a => !a.startsWith("-")); + let BUILD = positional[0]; + const TOP_N = parseInt(positional[1] || "500", 10); + + const TOKEN = process.env.BUILDKITE_TOKEN || process.env.BUILDKITE_API_TOKEN; + if (!TOKEN) { + console.error("error: BUILDKITE_TOKEN not set"); + process.exit(1); + } + + // Auto-pick a build: most-recent merged PR whose branch has a finished build. + // Merged-PR builds usually report state=failed (flaky tests) — that's fine, + // we only need the timing data. + if (!BUILD) { + console.error("no build given, finding a recent merged-PR build..."); + const prs = await $`gh pr list --state merged --limit 10 --json number,headRefName`.json(); + for (const pr of prs) { + const builds = await $`bk build list --branch ${pr.headRefName}` + .quiet() + .json() + .catch(() => []); + const done = builds.find((b: any) => b.finished_at && b.state !== "canceled" && b.state !== "running"); + if (done) { + BUILD = String(done.number); + console.error(` using build #${BUILD} (PR #${pr.number}, ${pr.headRefName}, state=${done.state})`); + break; + } + } + if (!BUILD) { + console.error("error: no finished build found among the last 10 merged PRs"); + process.exit(1); + } + } -type Agg = { maxMs: number; maxPlat: string; perPlat: Map }; -const agg = new Map(); - -let done = 0; -const queue = [...jobs]; -async function worker() { - for (;;) { - const job = queue.shift(); - if (!job) return; - 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; + const CACHE = join(tmpdir(), `bun-ci-logs-${BUILD}`); + mkdirSync(CACHE, { recursive: true }); + + type Job = { id: string; name: string; raw_log_url: string; retried?: boolean }; + + const buildJson = JSON.parse( + await new Response(spawn({ cmd: ["bk", "build", "view", BUILD], stdout: "pipe" }).stdout).text(), + ); + const jobs: Job[] = buildJson.jobs.filter( + (j: any) => j.name && j.raw_log_url && j.name.includes("test-bun") && !j.retried, + ); + console.error(`build #${BUILD}: ${jobs.length} test-bun jobs across ${new Set(jobs.map(j => j.name)).size} platforms`); + + const platOf = (name: string) => + name + .replace(/ - test-bun$/, "") + .replace(/^:([a-z]+):/, "$1") + .trim(); + + // Do NOT use `bk job log` — it hangs indefinitely on some Windows/alpine jobs. + // Fetching raw_log_url directly with the token works for all of them. + async function fetchLog(job: Job): Promise { + const path = join(CACHE, `${job.id}.log`); + if (existsSync(path)) return readFileSync(path, "utf8"); + const res = await fetch(job.raw_log_url, { headers: { Authorization: `Bearer ${TOKEN}` } }); + if (!res.ok) throw new Error(`${res.status} ${job.raw_log_url}`); + const out = await res.text(); + writeFileSync(path, out); + return out; + } + + type Agg = { maxMs: number; maxPlat: string; perPlat: Map }; + const agg = new Map(); + + let done = 0; + const queue = [...jobs]; + async function worker() { + for (;;) { + const job = queue.shift(); + if (!job) return; + 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; + } } + } catch (e) { + console.error(` failed ${job.id}: ${(e as Error).message}`); } - } catch (e) { - console.error(` failed ${job.id}: ${(e as Error).message}`); + done++; + if (done % 20 === 0 || done === jobs.length) console.error(` ${done}/${jobs.length} logs`); } - done++; - if (done % 20 === 0 || done === jobs.length) console.error(` ${done}/${jobs.length} logs`); } -} -await Promise.all(Array.from({ length: 16 }, worker)); + 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); + // `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 = [...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); -console.error(`${agg.size} unique entries, ${sorted.length} test files after filtering`); -console.error(`logs cached at ${CACHE}`); + console.error(`${agg.size} unique entries, ${sorted.length} test files after filtering`); + console.error(`logs cached at ${CACHE}`); -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}`)); + 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}`)); + } + process.exit(0); } -process.exit(0); diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts new file mode 100644 index 000000000000..e37119902e0c --- /dev/null +++ b/test/internal/ci-slowest-tests.test.ts @@ -0,0 +1,73 @@ +import { describe, expect, test } from "bun:test"; +import { parseLog } from "../../scripts/ci-slowest-tests"; + +// 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", () => { + test("does not charge the parallel-safe phase to the last serial test", () => { + // runner.node.mjs prints serial headers via startGroup (`--- [N/M] path`) + // and parallel-safe headers via plain console.log (`[N/M] path`). A regex + // that insists on `--- ` treats the first parallel header as invisible and + // the last serial test swallows the whole phase (79.5s observed for a + // 4.8s test on build #79247). + const log = [ + bk(1000, `--- ${gray("[1/6]")} test/a.test.ts`), + bk(2000, "Ran 1 test across 1 file."), + bk(2000, `--- ${gray("[2/6]")} test/last-serial.test.ts`), + bk(6800, "Ran 1 test across 1 file."), + bk(6800, `--- Running 3 parallel-safe tests (4-wide)`), + bk(6801, `${gray("[3/6]")} test/js/node/test/parallel/p1.js`), + bk(6803, `${gray("[4/6]")} test/js/node/test/parallel/p2.js`), + bk(6810, `${gray("[5/6]")} test/js/node/test/parallel/p3.js`), + bk(86800, `--- ${gray("[6/6]")} vendor/x/package.json`), + bk(87000, `--- End`), + ].join("\r\r\n"); + + const out = parseLog(log); + expect(out.get("test/last-serial.test.ts")).toBe(4800); + // p3 is the last dispatch before an 80s tail; header-gap timing would + // charge it 79_990 ms. Parallel-safe spans are clamped. + expect(out.get("test/js/node/test/parallel/p3.js")).toBeLessThanOrEqual(500); + expect(out.get("test/a.test.ts")).toBe(1000); + expect(out.get("vendor/x/package.json")).toBe(200); + }); + + test("sums retry attempts and normalizes Windows path separators", () => { + const log = [ + bk(0, `--- ${gray("[1/2]")} test\\cli\\install\\flaky.test.ts`), + bk(3000, `--- \x1b[33m[1/2] test\\cli\\install\\flaky.test.ts - code 1\x1b[0m`), + bk(10000, `--- ${gray("[1/2]")} test\\cli\\install\\flaky.test.ts ${gray("[attempt #2]")}`), + bk(14000, `--- ${gray("[2/2]")} test\\next.test.ts`), + bk(15000, `--- End`), + ].join("\n"); + + const out = parseLog(log); + // First attempt 3s + second attempt 4s; the retry backoff between the + // failure label and attempt #2 is not the test's wall clock. + expect(out.get("test/cli/install/flaky.test.ts")).toBe(7000); + expect(out.get("test/next.test.ts")).toBe(1000); + }); + + test("closes the last serial test at the parallel-phase group header when no parallel headers follow", () => { + // Shard with zero parallel-safe tests: the group header never prints, but + // `--- End` still terminates the open span. + const noParallel = [ + bk(100, `--- ${gray("[1/1]")} test/only.test.ts`), + bk(900, `--- End`), + ].join("\n"); + expect(parseLog(noParallel).get("test/only.test.ts")).toBe(800); + + // Shard where the parallel phase prints its group header but (e.g. via a + // filter) runs nothing: the open serial span must close there, not at the + // next `[N/M]` header an arbitrary distance later. + const emptyParallel = [ + bk(100, `--- ${gray("[1/2]")} test/last.test.ts`), + bk(1100, `--- Running 0 parallel-safe tests (4-wide)`), + bk(60000, `--- ${gray("[2/2]")} vendor/x/package.json`), + bk(60100, `--- End`), + ].join("\n"); + expect(parseLog(emptyParallel).get("test/last.test.ts")).toBe(1000); + }); +}); From b15c7410607ef5e1415c50a16e576f747080f076 Mon Sep 17 00:00:00 2001 From: "autofix-ci[bot]" <114827586+autofix-ci[bot]@users.noreply.github.com> Date: Fri, 24 Jul 2026 10:03:23 +0000 Subject: [PATCH 2/7] [autofix.ci] apply automated fixes --- scripts/ci-slowest-tests.ts | 9 +++++++-- test/internal/ci-slowest-tests.test.ts | 5 +---- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index ffe358155e77..c65f9f929902 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -47,7 +47,10 @@ export function parseLog(text: string): Map { const hdr = /^(--- )?\[\d+\/\d+\] (.+)$/.exec(body); if (hdr) { close(ts); - const title = hdr[2].replace(/ \[attempt #\d+\]$/, "").replace(/\\/g, "/").trim(); + const title = hdr[2] + .replace(/ \[attempt #\d+\]$/, "") + .replace(/\\/g, "/") + .trim(); // Retry/error labels (` - code 1`) are not file paths; treat them // as a delimiter so the preceding span closes without the retry backoff // landing on either attempt. @@ -110,7 +113,9 @@ if (import.meta.main) { const jobs: Job[] = buildJson.jobs.filter( (j: any) => j.name && j.raw_log_url && j.name.includes("test-bun") && !j.retried, ); - console.error(`build #${BUILD}: ${jobs.length} test-bun jobs across ${new Set(jobs.map(j => j.name)).size} platforms`); + console.error( + `build #${BUILD}: ${jobs.length} test-bun jobs across ${new Set(jobs.map(j => j.name)).size} platforms`, + ); const platOf = (name: string) => name diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index e37119902e0c..223892c20ee5 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -53,10 +53,7 @@ describe("scripts/ci-slowest-tests.ts parseLog", () => { test("closes the last serial test at the parallel-phase group header when no parallel headers follow", () => { // Shard with zero parallel-safe tests: the group header never prints, but // `--- End` still terminates the open span. - const noParallel = [ - bk(100, `--- ${gray("[1/1]")} test/only.test.ts`), - bk(900, `--- End`), - ].join("\n"); + const noParallel = [bk(100, `--- ${gray("[1/1]")} test/only.test.ts`), bk(900, `--- End`)].join("\n"); expect(parseLog(noParallel).get("test/only.test.ts")).toBe(800); // Shard where the parallel phase prints its group header but (e.g. via a From a73809dd96e917684d9364375a6c53e46b95f180 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Fri, 24 Jul 2026 10:47:46 +0000 Subject: [PATCH 3/7] ci: retrigger From 1b8991a1e2c175433267b81785553523730809f5 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Fri, 31 Jul 2026 10:04:52 +0000 Subject: [PATCH 4/7] also handle the parallel-bucket phase and apply the same fix to the sibling parsers Since #36175, runner.node.mjs also emits: --- napi prebuild: N addon(s), Xs --- [A-B/M] K files in parallel (Nx) [N/M] (X.XXs) (bucket per-file summary) none of which match '^--- [N/M] '. Close the open span on any '--- ' group header so the test preceding the bucket is not charged the whole bucket run, and read the inline '(X.XXs)' timing from bucket summary lines. buildkite-slow-tests.js and update-test-durations.mjs share the same header contract and get the same fix. --- scripts/buildkite-slow-tests.js | 76 ++++++++++++++---------- scripts/ci-slowest-tests.ts | 28 +++++++-- scripts/update-test-durations.mjs | 6 +- test/internal/ci-slowest-tests.test.ts | 82 ++++++++++++++++++++++++++ 4 files changed, 153 insertions(+), 39 deletions(-) diff --git a/scripts/buildkite-slow-tests.js b/scripts/buildkite-slow-tests.js index ccbbde967839..3a8e4f85ed75 100755 --- a/scripts/buildkite-slow-tests.js +++ b/scripts/buildkite-slow-tests.js @@ -5,41 +5,53 @@ import { readFileSync } from "fs"; function parseLogFile(filename) { const testDetails = new Map(); // Track individual attempts and total for each test let currentTest = null; + let currentAttempt = 1; let startTime = null; - // Pattern to match test group start: --- [90m[N/TOTAL][0m test/path - // Note: there are escape sequences before _bk - const startPattern = /_bk;t=(\d+).*?--- .*?\[90m\[(\d+)\/(\d+)\].*?\[0m (.+)/; - - const content = readFileSync(filename, "utf-8"); - const lines = content.split("\n"); - - for (const line of lines) { - const match = line.match(startPattern); - if (match) { - // If we have a previous test, calculate its duration - if (currentTest && startTime) { - const endTime = parseInt(match[1]); - const duration = endTime - startTime; - - // Extract attempt info - match the actual ANSI pattern - const attemptMatch = currentTest.match(/\s+\x1b\[90m\[attempt #(\d+)\]\x1b\[0m$/); - const cleanName = currentTest.replace(/\s+\x1b\[90m\[attempt #\d+\]\x1b\[0m$/, "").trim(); - const attemptNum = attemptMatch ? parseInt(attemptMatch[1]) : 1; - - if (!testDetails.has(cleanName)) { - testDetails.set(cleanName, { total: 0, attempts: [] }); - } - - const testInfo = testDetails.get(cleanName); - testInfo.total += duration; - testInfo.attempts.push({ attempt: attemptNum, duration }); - } - - // Start new test - startTime = parseInt(match[1]); - currentTest = match[4].trim(); + const content = readFileSync(filename, "utf-8").replace(/\x1b\[[0-9;]*m/g, ""); + + const record = (name, attempt, duration) => { + const cleanName = name.replace(/\\/g, "/"); + if (!testDetails.has(cleanName)) testDetails.set(cleanName, { total: 0, attempts: [] }); + const testInfo = testDetails.get(cleanName); + testInfo.total += duration; + testInfo.attempts.push({ attempt, duration }); + }; + const close = ts => { + if (currentTest === null || startTime === null) return; + record(currentTest, currentAttempt, ts - startTime); + currentTest = null; + startTime = null; + }; + + for (const raw of content.split("\n")) { + const line = raw.replace(/\r+$/, ""); + const m = /^\x1b?_bk;t=(\d+)\x07(.*)$/.exec(line); + if (!m) continue; + const ts = parseInt(m[1], 10); + const body = m[2]; + + if (!body.startsWith("--- ")) { + // Parallel-bucket summary lines carry their own wall-clock. + const timed = /^\[\d+\/\d+\] (.+?) \((\d+(?:\.\d+)?)s\)$/.exec(body); + if (timed) record(timed[1].trim(), 1, Math.round(parseFloat(timed[2]) * 1000)); + continue; } + + // Every `--- ` header is a group boundary: close the open timer so the + // preceding test is not charged for a following batch phase (napi + // prebuild, `[A-B/M] K files in parallel`, `Running N parallel-safe ...`). + close(ts); + + const hdr = /^--- \[\d+\/\d+\] (.+)$/.exec(body); + if (!hdr) continue; + const attemptMatch = hdr[1].match(/\s+\[attempt #(\d+)\]\s*$/); + const title = hdr[1].replace(/\s+\[attempt #\d+\]\s*$/, "").trim(); + // Retry/error headers (`title - code 1`) close the run but do not start one. + if (!/\.(?:[cm]?[jt]sx?|json)$/.test(title)) continue; + currentTest = title; + currentAttempt = attemptMatch ? parseInt(attemptMatch[1], 10) : 1; + startTime = ts; } // Convert to array and sort by total duration diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index c65f9f929902..ab112ae68e71 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -20,11 +20,17 @@ import { tmpdir } from "os"; import { join } from "path"; // Per-file cost is the gap between the APC timestamps Buildkite injects into -// consecutive `[N/M] ` headers (ESC `_bk;t=` BEL). Serial-phase -// tests print `--- [N/M] path` via startGroup; the parallel-safe phase -// (runner.node.mjs runTest with concurrent=true) prints the bare `[N/M] path` -// without `--- `. If the `--- ` is treated as mandatory the last serial test -// on every shard absorbs the entire parallel phase's wall clock. +// consecutive `[N/M] ` headers (ESC `_bk;t=` BEL). runner.node.mjs +// emits several header shapes that must each close the open span: +// - serial test start: `--- [N/M] ` (startGroup) +// - 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 +// - parallel-safe phase: `--- Running N parallel-safe tests`, then a bare +// `[N/M] ` per concurrent dispatch (no recoverable wall clock) +// - other startGroup phases: `--- napi prebuild: ...`, `--- End` +// A parser that only recognises the first shape folds the entire following +// phase into whichever serial test happened to precede it. export function parseLog(text: string): Map { const out = new Map(); let curName: string | null = null; @@ -51,6 +57,13 @@ export function parseLog(text: string): Map { .replace(/ \[attempt #\d+\]$/, "") .replace(/\\/g, "/") .trim(); + // Parallel-bucket summaries carry the authoritative wall clock inline. + const timed = !hdr[1] && /^(.+?) \((\d+(?:\.\d+)?)s\)$/.exec(title); + if (timed) { + out.set(timed[1], (out.get(timed[1]) ?? 0) + Math.round(parseFloat(timed[2]) * 1000)); + concurrent = false; + continue; + } // Retry/error labels (` - code 1`) are not file paths; treat them // as a delimiter so the preceding span closes without the retry backoff // landing on either attempt. @@ -60,7 +73,10 @@ export function parseLog(text: string): Map { concurrent = !hdr[1]; continue; } - if (/^--- (?:End\b|Running \d+ parallel-safe)/.test(body)) close(ts); + if (body.startsWith("--- ")) { + close(ts); + concurrent = false; + } } return out; } diff --git a/scripts/update-test-durations.mjs b/scripts/update-test-durations.mjs index b295f8f87658..71822f03d114 100644 --- a/scripts/update-test-durations.mjs +++ b/scripts/update-test-durations.mjs @@ -100,7 +100,11 @@ function parseLog(raw) { concurrent = isPath && !hdr[1]; continue; } - if (/^--- (?:End\b|Running \d+ parallel-safe)/.test(text)) { + // Any other `--- ` group header (End, `Running N parallel-safe ...`, + // `napi prebuild: ...`, `[A-B/M] K files in parallel`, etc.) closes the + // open span so the preceding serial test is not charged for the phase + // that follows. + if (text.startsWith("--- ")) { emit(ts); path = start = null; concurrent = false; diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index 223892c20ee5..6b5fb6e16cbc 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -1,4 +1,6 @@ import { describe, expect, test } from "bun:test"; +import { bunEnv, bunExe, tempDir } from "harness"; +import { join } from "node:path"; import { parseLog } from "../../scripts/ci-slowest-tests"; // Buildkite prefixes each line with an APC timestamp: ESC `_bk;t=` BEL. @@ -67,4 +69,84 @@ describe("scripts/ci-slowest-tests.ts parseLog", () => { ].join("\n"); expect(parseLog(emptyParallel).get("test/last.test.ts")).toBe(1000); }); + + test("does not charge the parallel-bucket phase to the preceding serial test", () => { + // runParallelBucket opens a `--- [A-B/M] K files in parallel` group (not a + // `[N/M]` header), runs one `bun test --parallel`, then prints a summary + // `[N/M] (X.XXs)` per file. The summary's inline timing is the only + // usable per-file number; the APC timestamps on those lines are all the + // moment the summary flushed. `--- napi prebuild: ...` is another + // non-[N/M] startGroup that precedes the bucket on shards with native + // addons. + const log = [ + bk(0, `--- ${gray("[1/8]")} test/before.test.ts`), + bk(61, `--- napi prebuild: 3 addon(s), 23.9s`), + bk(61, `prebuild: 3 built`), + bk(24000, `--- ${gray("[2-5/8]")} 4 files in parallel (3\u00d7)`), + bk(24010, `bun test v1.4.0 3\u00d7 PARALLEL`), + bk(83500, Buffer.alloc(50, ".").toString()), + bk(84000, `${gray("[2/8]")} test/b.test.ts ${gray("(0.50s)")}`), + bk(84000, `${gray("[3/8]")} test/c.test.ts ${gray("(1.25s)")}`), + bk(84000, `${gray("[4/8]")} test/d.test.ts ${gray("(0.01s)")}`), + bk(84001, `parallel bucket: retrying 1 failed file(s) one at a time`), + bk(84010, `--- ${gray("[5/8]")} test/e.test.ts`), + bk(84210, `--- ${gray("[6/8]")} test/after.test.ts`), + bk(84310, `--- End`), + ].join("\r\r\n"); + + expect(Object.fromEntries(parseLog(log))).toEqual({ + "test/before.test.ts": 61, + "test/b.test.ts": 500, + "test/c.test.ts": 1250, + "test/d.test.ts": 10, + "test/e.test.ts": 200, + "test/after.test.ts": 100, + }); + }); +}); + +test("scripts/buildkite-slow-tests.js does not fold batch phases into the preceding serial test", async () => { + // Same fixture as the parallel-bucket case above plus the parallel-safe + // phase; the standalone script shares parseLog's header contract. + const t0 = 1700000000000; + const fixture = [ + bk(t0 + 0, `--- ${gray("[1/10]")} test/a.test.ts`), + bk(t0 + 100, `--- napi prebuild: 3 addon(s), 23.9s`), + bk(t0 + 24000, `--- ${gray("[2-5/10]")} 4 files in parallel (3\u00d7)`), + bk(t0 + 84000, `${gray("[2/10]")} test/b.test.ts ${gray("(0.50s)")}`), + bk(t0 + 84000, `${gray("[3/10]")} test/c.test.ts ${gray("(1.25s)")}`), + bk(t0 + 84000, `${gray("[4/10]")} test/d.test.ts ${gray("(0.01s)")}`), + bk(t0 + 84010, `--- ${gray("[5/10]")} test/e.test.ts`), + bk(t0 + 84210, `--- \x1b[33m[5/10] test/e.test.ts - code 1\x1b[0m`), + bk(t0 + 94000, `--- ${gray("[5/10]")} test/e.test.ts ${gray("[attempt #2]")}`), + bk(t0 + 94180, `--- Running 3 parallel-safe tests (3-wide)`), + bk(t0 + 94181, `${gray("[6/10]")} test/f.test.ts`), + bk(t0 + 94185, `${gray("[7/10]")} test/g.test.ts`), + bk(t0 + 116000, `--- ${gray("[8/10]")} vendor/x/package.json`), + bk(t0 + 118000, `--- End`), + ].join("\r\r\n"); + + using dir = tempDir("bk-slow-tests", { "job.log": fixture }); + await using proc = Bun.spawn({ + cmd: [bunExe(), join(import.meta.dir, "..", "..", "scripts", "buildkite-slow-tests.js"), join(String(dir), "job.log")], + env: bunEnv, + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect(stderr).toBe(""); + + const rows = new Map(); + for (const m of stdout.matchAll(/^\s*\d+\.\s+(\d+\.\d+)s\s+(\S+)/gm)) rows.set(m[2], parseFloat(m[1])); + + // a.test.ts ran for 100 ms; the 23.9 s napi prebuild and 60 s bucket run + // that follow must not be charged to it. The script only lists files > 1 s. + expect(rows.get("test/a.test.ts")).toBeUndefined(); + expect(stdout).not.toMatch(/test\/a\.test\.ts/); + // e.test.ts ran twice (200 ms + 180 ms); the 9.8 s retry backoff between the + // error header and attempt #2 is harness overhead. + expect(rows.get("test/e.test.ts")).toBeUndefined(); + expect(rows.get("test/c.test.ts")).toBe(1.25); + expect(rows.get("vendor/x/package.json")).toBe(2.0); + expect(stdout).not.toMatch(/code 1/); + expect(exitCode).toBe(0); }); From ca050cc180597da76b12d4eecf40a1a5e921439b Mon Sep 17 00:00:00 2001 From: "autofix-ci[bot]" <114827586+autofix-ci[bot]@users.noreply.github.com> Date: Fri, 31 Jul 2026 10:07:12 +0000 Subject: [PATCH 5/7] [autofix.ci] apply automated fixes --- test/internal/ci-slowest-tests.test.ts | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index 6b5fb6e16cbc..a583d289fc45 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -128,7 +128,11 @@ test("scripts/buildkite-slow-tests.js does not fold batch phases into the preced using dir = tempDir("bk-slow-tests", { "job.log": fixture }); await using proc = Bun.spawn({ - cmd: [bunExe(), join(import.meta.dir, "..", "..", "scripts", "buildkite-slow-tests.js"), join(String(dir), "job.log")], + cmd: [ + bunExe(), + join(import.meta.dir, "..", "..", "scripts", "buildkite-slow-tests.js"), + join(String(dir), "job.log"), + ], env: bunEnv, stderr: "pipe", }); From 96e8f93dc5c68ffe24350c03f14018cca7526dc3 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Fri, 31 Jul 2026 10:14:25 +0000 Subject: [PATCH 6/7] address review: EOF flush, exact clamp assertion, validate timed-summary path - flush the open span at end-of-log in all three parsers so a job killed or timed out mid-run still records the last file instead of dropping it - require a test-file extension in the parallel-bucket summary name, matching update-test-durations.mjs - assert toBe(500) for the clamped parallel-safe span (fixture is deterministic) and cover the truncated-log case --- scripts/buildkite-slow-tests.js | 8 ++++++-- scripts/ci-slowest-tests.ts | 8 ++++++-- scripts/update-test-durations.mjs | 4 +++- test/internal/ci-slowest-tests.test.ts | 17 ++++++++++++++++- 4 files changed, 31 insertions(+), 6 deletions(-) diff --git a/scripts/buildkite-slow-tests.js b/scripts/buildkite-slow-tests.js index 3a8e4f85ed75..c5c492791c2a 100755 --- a/scripts/buildkite-slow-tests.js +++ b/scripts/buildkite-slow-tests.js @@ -7,6 +7,7 @@ function parseLogFile(filename) { let currentTest = null; let currentAttempt = 1; let startTime = null; + let lastTs = null; const content = readFileSync(filename, "utf-8").replace(/\x1b\[[0-9;]*m/g, ""); @@ -28,12 +29,12 @@ function parseLogFile(filename) { const line = raw.replace(/\r+$/, ""); const m = /^\x1b?_bk;t=(\d+)\x07(.*)$/.exec(line); if (!m) continue; - const ts = parseInt(m[1], 10); + const ts = (lastTs = parseInt(m[1], 10)); const body = m[2]; if (!body.startsWith("--- ")) { // Parallel-bucket summary lines carry their own wall-clock. - const timed = /^\[\d+\/\d+\] (.+?) \((\d+(?:\.\d+)?)s\)$/.exec(body); + const timed = /^\[\d+\/\d+\] (.+\.(?:[cm]?[jt]sx?|json)) \((\d+(?:\.\d+)?)s\)$/.exec(body); if (timed) record(timed[1].trim(), 1, Math.round(parseFloat(timed[2]) * 1000)); continue; } @@ -53,6 +54,9 @@ function parseLogFile(filename) { currentAttempt = attemptMatch ? parseInt(attemptMatch[1], 10) : 1; startTime = ts; } + // 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. + if (lastTs !== null) close(lastTs); // Convert to array and sort by total duration const testGroups = Array.from(testDetails.entries()) diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index ab112ae68e71..0875c664ccbb 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -36,6 +36,7 @@ export function parseLog(text: string): Map { let curName: string | null = null; let curStart = 0; let concurrent = false; + let lastTs = 0; const close = (ts: number) => { if (!curName) return; const span = ts - curStart; @@ -48,7 +49,7 @@ export function parseLog(text: string): Map { for (const line of text.split("\n")) { const apc = /_bk;t=(\d+)\x07(.*)/.exec(line); if (!apc) continue; - const ts = parseInt(apc[1], 10); + const ts = (lastTs = parseInt(apc[1], 10)); const body = apc[2].replace(/\x1b\[[0-9;]*m/g, "").replace(/\r+$/, ""); const hdr = /^(--- )?\[\d+\/\d+\] (.+)$/.exec(body); if (hdr) { @@ -58,7 +59,7 @@ export function parseLog(text: string): Map { .replace(/\\/g, "/") .trim(); // Parallel-bucket summaries carry the authoritative wall clock inline. - const timed = !hdr[1] && /^(.+?) \((\d+(?:\.\d+)?)s\)$/.exec(title); + 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)); concurrent = false; @@ -78,6 +79,9 @@ export function parseLog(text: string): Map { concurrent = false; } } + // 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; } diff --git a/scripts/update-test-durations.mjs b/scripts/update-test-durations.mjs index 71822f03d114..9eaa73494022 100644 --- a/scripts/update-test-durations.mjs +++ b/scripts/update-test-durations.mjs @@ -72,6 +72,7 @@ function parseLog(raw) { let path = null; let start = null; let concurrent = false; + let lastTs = null; const emit = ts => { if (path === null || start === null || ts === null) return; out.push([path, concurrent ? Math.min(ts - start, 500) : ts - start]); @@ -79,7 +80,7 @@ function parseLog(raw) { for (let line of lines) { if (line.endsWith("\r")) line = line.slice(0, -1); const m = /^\x1b_bk;t=(\d+)\x07(.*)$/.exec(line); - const ts = m ? Number(m[1]) : null; + const ts = m ? (lastTs = Number(m[1])) : null; const text = m ? m[2] : line; const hdr = /^(--- )?\[\d+\/\d+\] (.+)$/.exec(text); if (hdr) { @@ -110,6 +111,7 @@ function parseLog(raw) { concurrent = false; } } + emit(lastTs); return out; } diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index a583d289fc45..58401dcc5b14 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -31,7 +31,7 @@ describe("scripts/ci-slowest-tests.ts parseLog", () => { expect(out.get("test/last-serial.test.ts")).toBe(4800); // p3 is the last dispatch before an 80s tail; header-gap timing would // charge it 79_990 ms. Parallel-safe spans are clamped. - expect(out.get("test/js/node/test/parallel/p3.js")).toBeLessThanOrEqual(500); + expect(out.get("test/js/node/test/parallel/p3.js")).toBe(500); expect(out.get("test/a.test.ts")).toBe(1000); expect(out.get("vendor/x/package.json")).toBe(200); }); @@ -68,6 +68,21 @@ describe("scripts/ci-slowest-tests.ts parseLog", () => { bk(60100, `--- End`), ].join("\n"); expect(parseLog(emptyParallel).get("test/last.test.ts")).toBe(1000); + + // Job killed mid-run: no `--- End`. The still-open span (usually the test + // that caused the timeout) is charged to the last timestamp seen rather + // than dropped, since it is exactly the file a slow-test report should + // surface. + const truncated = [ + bk(100, `--- ${gray("[1/2]")} test/fast.test.ts`), + bk(300, `--- ${gray("[2/2]")} test/hung.test.ts`), + bk(400, "bun test v1.4.0"), + bk(600300, "still running..."), + ].join("\n"); + expect(Object.fromEntries(parseLog(truncated))).toEqual({ + "test/fast.test.ts": 200, + "test/hung.test.ts": 600000, + }); }); test("does not charge the parallel-bucket phase to the preceding serial test", () => { From 94fadaec17df2799a699b1b0eb0fbf99fe984444 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Fri, 31 Jul 2026 10:52:56 +0000 Subject: [PATCH 7/7] narrow the '--- ' boundary to runner.node.mjs phase headers and test update-test-durations.mjs Closing the open span on any '--- ' line also matched test stdout that slipped past pipeTestStdout's sanitiser: unified-diff '--- a/' inside bun-patch.test.ts (under-counted by ~33% on build #86086) and '--- ps ---' / '--- logs ---' from test/docker/index.ts inside test/package.json (~58%). Limit the boundary to the startGroup titles runner.node.mjs actually emits and cover the false positives in the fixture. Export parseLog from update-test-durations.mjs behind an entrypoint check so the test can run the same fixture through the parser CI shard bin-packing consumes. --- scripts/buildkite-slow-tests.js | 48 ++++++---- scripts/ci-slowest-tests.ts | 12 ++- scripts/update-test-durations.mjs | 117 ++++++++++++++----------- test/internal/ci-slowest-tests.test.ts | 78 ++++++++++++++++- 4 files changed, 181 insertions(+), 74 deletions(-) diff --git a/scripts/buildkite-slow-tests.js b/scripts/buildkite-slow-tests.js index c5c492791c2a..e35c0bb3fdd3 100755 --- a/scripts/buildkite-slow-tests.js +++ b/scripts/buildkite-slow-tests.js @@ -32,27 +32,37 @@ function parseLogFile(filename) { const ts = (lastTs = parseInt(m[1], 10)); const body = m[2]; - if (!body.startsWith("--- ")) { - // Parallel-bucket summary lines carry their own wall-clock. - const timed = /^\[\d+\/\d+\] (.+\.(?:[cm]?[jt]sx?|json)) \((\d+(?:\.\d+)?)s\)$/.exec(body); - if (timed) record(timed[1].trim(), 1, Math.round(parseFloat(timed[2]) * 1000)); + const hdr = /^--- \[\d+\/\d+\] (.+)$/.exec(body); + if (hdr) { + close(ts); + const attemptMatch = hdr[1].match(/\s+\[attempt #(\d+)\]\s*$/); + const title = hdr[1].replace(/\s+\[attempt #\d+\]\s*$/, "").trim(); + // Retry/error headers (`title - code 1`) close the run but do not start one. + if (!/\.(?:[cm]?[jt]sx?|json)$/.test(title)) continue; + currentTest = title; + currentAttempt = attemptMatch ? parseInt(attemptMatch[1], 10) : 1; + startTime = ts; continue; } - - // Every `--- ` header is a group boundary: close the open timer so the - // preceding test is not charged for a following batch phase (napi - // prebuild, `[A-B/M] K files in parallel`, `Running N parallel-safe ...`). - close(ts); - - const hdr = /^--- \[\d+\/\d+\] (.+)$/.exec(body); - if (!hdr) continue; - const attemptMatch = hdr[1].match(/\s+\[attempt #(\d+)\]\s*$/); - const title = hdr[1].replace(/\s+\[attempt #\d+\]\s*$/, "").trim(); - // Retry/error headers (`title - code 1`) close the run but do not start one. - if (!/\.(?:[cm]?[jt]sx?|json)$/.test(title)) continue; - currentTest = title; - currentAttempt = attemptMatch ? parseInt(attemptMatch[1], 10) : 1; - startTime = ts; + // Parallel-bucket summary lines carry their own wall-clock. + const timed = /^\[\d+\/\d+\] (.+\.(?:[cm]?[jt]sx?|json)) \((\d+(?:\.\d+)?)s\)$/.exec(body); + if (timed) { + close(ts); + record(timed[1].trim(), 1, Math.round(parseFloat(timed[2]) * 1000)); + continue; + } + // Non-[N/M] phase headers (napi prebuild, `[A-B/M] K files in parallel`, + // `Running N parallel-safe ...`, End) close the open timer so the + // preceding serial test is not charged for the batch that follows. + // Limited to the titles runner.node.mjs actually emits so a stray + // `--- a/` diff line in test stdout does not truncate a span. + if ( + /^--- (?:\[\d+-\d+\/\d+\]|napi prebuild:|Running \d+ parallel-safe|End\b|Summary\b|Received \w+, exiting)/.test( + body, + ) + ) { + close(ts); + } } // 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. diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index 0875c664ccbb..b19d8f20e187 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -31,6 +31,16 @@ import { join } from "path"; // - other startGroup phases: `--- napi prebuild: ...`, `--- End` // A parser that only recognises the first shape folds the entire following // phase into whichever serial test happened to precede it. +// +// runner.node.mjs's pipeTestStdout sanitises `--- ` in streamed test output, +// but a chunk boundary mid-token or one of the raw-write paths (coordinator +// stdout, retry stdoutPreview) can still deliver a line that starts `--- ` +// without being a group header (unified-diff `--- a/`, `--- ps ---`). +// The boundary check is therefore limited to the phase headers runner.node.mjs +// actually emits rather than any `--- `. +export const isPhaseGroupHeader = (body: string) => + /^--- (?:\[\d+-\d+\/\d+\]|napi prebuild:|Running \d+ parallel-safe|End\b|Summary\b|Received \w+, exiting)/.test(body); + export function parseLog(text: string): Map { const out = new Map(); let curName: string | null = null; @@ -74,7 +84,7 @@ export function parseLog(text: string): Map { concurrent = !hdr[1]; continue; } - if (body.startsWith("--- ")) { + if (isPhaseGroupHeader(body)) { close(ts); concurrent = false; } diff --git a/scripts/update-test-durations.mjs b/scripts/update-test-durations.mjs index 9eaa73494022..9994394dd22e 100644 --- a/scripts/update-test-durations.mjs +++ b/scripts/update-test-durations.mjs @@ -20,6 +20,7 @@ const __dirname = dirname(fileURLToPath(import.meta.url)); const outputPath = join(__dirname, "..", "test", "expected-durations.json"); const { values: opts } = parseArgs({ + strict: false, options: { builds: { type: "string", default: "5" }, org: { type: "string", default: "bun" }, @@ -28,10 +29,6 @@ const { values: opts } = parseArgs({ }); const token = process.env.BUILDKITE_API_TOKEN || process.env.BUILDKITE_TOKEN; -if (!token) { - console.error("BUILDKITE_API_TOKEN is required"); - process.exit(1); -} // default + asan are both linux-x64-debian-13 (lowest-variance runner pool); // windows and musl get their own columns because process-spawn cost and @@ -66,7 +63,7 @@ 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. -function parseLog(raw) { +export function parseLog(raw) { const out = []; const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r?\n/); let path = null; @@ -101,11 +98,18 @@ function parseLog(raw) { concurrent = isPath && !hdr[1]; continue; } - // Any other `--- ` group header (End, `Running N parallel-safe ...`, - // `napi prebuild: ...`, `[A-B/M] K files in parallel`, etc.) closes the - // open span so the preceding serial test is not charged for the phase - // that follows. - if (text.startsWith("--- ")) { + // The runner's other startGroup phase headers (End, `Running N + // parallel-safe ...`, `napi prebuild: ...`, `[A-B/M] K files in + // parallel`) close the open span so the preceding serial test is not + // charged for the phase that follows. Limited to the titles + // runner.node.mjs actually emits; pipeTestStdout sanitises `--- ` in + // streamed test output, but a chunk boundary mid-token or one of the + // raw-write paths can still deliver `--- a/` or `--- ps ---`. + if ( + /^--- (?:\[\d+-\d+\/\d+\]|napi prebuild:|Running \d+ parallel-safe|End\b|Summary\b|Received \w+, exiting)/.test( + text, + ) + ) { emit(ts); path = start = null; concurrent = false; @@ -175,50 +179,57 @@ async function collect(build, stepKey, into) { await Promise.all(Array.from({ length: 4 }, worker)); } -const want = Math.max(1, parseInt(opts.builds, 10) || 5); -console.error(`looking for ${want} recent builds with complete ${Object.values(lanes).join(" + ")} lanes`); -const builds = await findSourceBuilds(want); -if (builds.length === 0) { - console.error("no suitable builds found"); - process.exit(1); -} -console.error(`using builds: ${builds.join(", ")}`); - -// lane -> path -> [ms, ...] -const samples = Object.fromEntries(Object.keys(lanes).map(lane => [lane, {}])); -for (const b of builds) { - for (const [lane, step] of Object.entries(lanes)) { - console.error(` build ${b} ${lane}`); - await collect(b, step, samples[lane]); +if (process.argv[1] === fileURLToPath(import.meta.url)) { + if (!token) { + console.error("BUILDKITE_API_TOKEN is required"); + process.exit(1); } -} -const paths = new Set(Object.values(samples).flatMap(s => Object.keys(s))); -// Guard the implicit contract with utils.mjs startGroup(): if the group-header -// format ever changes, parseLog() quietly returns nothing. Fail loudly rather -// than committing an empty table that would collapse every shard onto shard 0. -if (paths.size < 1000) { - console.error( - `only parsed ${paths.size} test paths; expected >1000. ` + - `This usually means the '--- [N/M] ' log header format changed.`, - ); - process.exit(1); -} -const out = { - // Consumers should tolerate missing paths (new tests) and missing lanes. - _meta: { - generated_at: new Date().toISOString(), - source_builds: builds, - lanes, - }, -}; -for (const p of [...paths].sort()) { - const entry = {}; - for (const lane of Object.keys(lanes)) { - if (samples[lane][p]?.length) entry[lane] = median(samples[lane][p]); + const want = Math.max(1, parseInt(opts.builds, 10) || 5); + console.error(`looking for ${want} recent builds with complete ${Object.values(lanes).join(" + ")} lanes`); + const builds = await findSourceBuilds(want); + if (builds.length === 0) { + console.error("no suitable builds found"); + process.exit(1); } - out[p] = entry; -} + console.error(`using builds: ${builds.join(", ")}`); -writeFileSync(outputPath, JSON.stringify(out, null, 2) + "\n"); -console.error(`wrote ${paths.size} entries to ${outputPath}`); + // lane -> path -> [ms, ...] + const samples = Object.fromEntries(Object.keys(lanes).map(lane => [lane, {}])); + for (const b of builds) { + for (const [lane, step] of Object.entries(lanes)) { + console.error(` build ${b} ${lane}`); + await collect(b, step, samples[lane]); + } + } + + const paths = new Set(Object.values(samples).flatMap(s => Object.keys(s))); + // Guard the implicit contract with utils.mjs startGroup(): if the group-header + // format ever changes, parseLog() quietly returns nothing. Fail loudly rather + // than committing an empty table that would collapse every shard onto shard 0. + if (paths.size < 1000) { + console.error( + `only parsed ${paths.size} test paths; expected >1000. ` + + `This usually means the '--- [N/M] ' log header format changed.`, + ); + process.exit(1); + } + const out = { + // Consumers should tolerate missing paths (new tests) and missing lanes. + _meta: { + generated_at: new Date().toISOString(), + source_builds: builds, + lanes, + }, + }; + for (const p of [...paths].sort()) { + const entry = {}; + for (const lane of Object.keys(lanes)) { + if (samples[lane][p]?.length) entry[lane] = median(samples[lane][p]); + } + out[p] = entry; + } + + writeFileSync(outputPath, JSON.stringify(out, null, 2) + "\n"); + console.error(`wrote ${paths.size} entries to ${outputPath}`); +} diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index 58401dcc5b14..3cbcb0ac0fb1 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -1,7 +1,8 @@ import { describe, expect, test } from "bun:test"; import { bunEnv, bunExe, tempDir } from "harness"; import { join } from "node:path"; -import { parseLog } from "../../scripts/ci-slowest-tests"; +import { isPhaseGroupHeader, parseLog } from "../../scripts/ci-slowest-tests"; +import { 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}`; @@ -118,6 +119,81 @@ describe("scripts/ci-slowest-tests.ts parseLog", () => { "test/after.test.ts": 100, }); }); + + test("ignores stray `--- ` lines that are test output, not group headers", () => { + // pipeTestStdout in runner.node.mjs sanitises `--- ` in streamed test + // output, but a chunk boundary can split the token and the coordinator/ + // retry-preview paths write raw. Seen in build #86086: a `bun patch` diff + // inside `test/cli/install/bun-patch.test.ts`'s span and `--- ps ---` + // from test/docker/index.ts inside the `test/package.json` span. + const log = [ + bk(100, `--- ${gray("[1/3]")} test/package.json`), + bk(150, `--- ps ---`), + bk(160, `--- logs ---`), + bk(1000, `--- ${gray("[2/3]")} test/cli/install/bun-patch.test.ts`), + bk(1500, `diff --git a/index.js b/index.js`), + bk(1500, `--- a/index.js`), + bk(1500, `+++ b/index.js`), + bk(12643, `--- ${gray("[3/3]")} test/next.test.ts`), + bk(12743, `--- End`), + ].join("\n"); + expect(Object.fromEntries(parseLog(log))).toEqual({ + "test/package.json": 900, + "test/cli/install/bun-patch.test.ts": 11643, + "test/next.test.ts": 100, + }); + }); +}); + +describe("phase-header boundary", () => { + // The three log parsers share this allowlist; if runner.node.mjs grows a new + // phase between the serial tests and the next `[N/M]` header, add it here and + // to isPhaseGroupHeader. + test.each([ + [true, `--- napi prebuild: 3 addon(s), 23.9s`], + [true, `--- [52-257/829] 206 files in parallel (3\u00d7)`], + [true, `--- Running 444 parallel-safe tests (3-wide)`], + [true, `--- End`], + [true, `--- Summary`], + [true, `--- Received SIGTERM, exiting...`], + [false, `--- a/index.js`], + [false, `--- ps ---`], + [false, `--- logs ---`], + [false, `------`], + [false, `--- `], + [false, `--- [52/829] test/a.test.ts`], + ])("%p %s", (expected, body) => { + expect(isPhaseGroupHeader(body)).toBe(expected); + }); +}); + +describe("scripts/update-test-durations.mjs parseLog", () => { + test("does not charge napi prebuild or the parallel-bucket phase to the preceding serial test", () => { + const log = [ + bk(0, `--- ${gray("[1/8]")} test/before.test.ts`), + bk(61, `--- napi prebuild: 3 addon(s), 23.9s`), + bk(24000, `--- ${gray("[2-5/8]")} 4 files in parallel (3\u00d7)`), + bk(84000, `${gray("[2/8]")} test/b.test.ts ${gray("(0.50s)")}`), + bk(84000, `${gray("[3/8]")} test/c.test.ts ${gray("(1.25s)")}`), + bk(84010, `--- ${gray("[4/8]")} test/cli/install/bun-patch.test.ts`), + bk(84500, `--- a/index.js`), + bk(95653, `--- Running 2 parallel-safe tests (4-wide)`), + bk(95654, `${gray("[5/8]")} test/js/node/test/parallel/p1.js`), + bk(95657, `${gray("[6/8]")} test/js/node/test/parallel/p2.js`), + bk(98000, `--- End`), + ].join("\r\r\n"); + + // parseDurations returns [path, ms][]; multiple entries per path are + // median'd downstream so we can compare raw output. + expect(parseDurations(log)).toEqual([ + ["test/before.test.ts", 61], + ["test/b.test.ts", 500], + ["test/c.test.ts", 1250], + ["test/cli/install/bun-patch.test.ts", 11643], + ["test/js/node/test/parallel/p1.js", 3], + ["test/js/node/test/parallel/p2.js", 500], + ]); + }); }); test("scripts/buildkite-slow-tests.js does not fold batch phases into the preceding serial test", async () => {