From dc63acdd5800dbf52262d342f9d64d3c2e784723 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 7 Nov 2026 01:31:11 +0000 Subject: [PATCH 1/3] scripts: read a file's failed parallel-bucket attempt in both job-log parsers, and report attempts per ci:slowest row A test file that fails in its `bun test --parallel` bucket has no `[N/M]` line for that run. The runner prints `--- - K failing in the parallel batch (X.XXs)` and runs the file again, alone. Both job-log parsers read only lines with `[N/M]`, so they dropped the bucket attempt. - scripts/ci-log-phase.mjs: failedBucketAttempt() reads that line. - scripts/ci-slowest-tests.ts: the bucket attempt is one more attempt of the file. A row has `attempts` and `maxAttemptMs`, and the table has the columns `attempts` and `longest_attempt`. addLog(), slowestRows() and tableLines() are exported for the tests. parseLog() is gone: the script folds each log with addLog(). - scripts/update-test-durations.mjs: the bucket attempt is the sample of the file, and its rerun alone gives none. Lines are split on `\r*\n`, so a line that ends in three CRs is read. --- .claude/skills/slowest-tests/SKILL.md | 3 + scripts/ci-log-phase.mjs | 16 ++ scripts/ci-slowest-tests.ts | 121 +++++++--- scripts/update-test-durations.mjs | 26 ++- test/internal/ci-slowest-tests.test.ts | 291 ++++++++++++++++++++++++- 5 files changed, 420 insertions(+), 37 deletions(-) diff --git a/.claude/skills/slowest-tests/SKILL.md b/.claude/skills/slowest-tests/SKILL.md index 5ba26c6837ed..194cb853082c 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. The time of a try that fails in the phase `Running N files that build many executables` is not in the row: the runner prints no seconds for it. - 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..9f339af63275 100644 --- a/scripts/ci-log-phase.mjs +++ b/scripts/ci-log-phase.mjs @@ -10,6 +10,10 @@ // - 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. Both say what the file took in the bucket. +// The group has no `[N/M]`: the file gets its number when it runs again, alone, +// as a serial test. failedBucketAttempt() reads 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 +43,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..8f644c9cccd3 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -18,14 +18,21 @@ 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 in the log, with what that attempt +// took. An attempt is a serial run (the first, or an `[attempt #K]`), a run in +// a parallel bucket whether it passed or failed there, 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 +43,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 +61,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 +74,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 +88,77 @@ 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); + if (!a) agg.set(file, (a = { maxMs: 0, maxPlat: "", 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 +231,6 @@ if (import.meta.main) { return out; } - type Agg = { maxMs: number; maxPlat: string; perPlat: Map }; const agg = new Map(); let done = 0; @@ -160,16 +242,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 +252,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 +260,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..2483686dec71 100644 --- a/scripts/update-test-durations.mjs +++ b/scripts/update-test-durations.mjs @@ -15,7 +15,7 @@ import { readFileSync, writeFileSync } from "node:fs"; import { dirname, join } from "node:path"; import { fileURLToPath } from "node:url"; import { parseArgs } from "node:util"; -import { isPhaseGroupHeader } from "./ci-log-phase.mjs"; +import { failedBucketAttempt, isPhaseGroupHeader } from "./ci-log-phase.mjs"; const __dirname = dirname(fileURLToPath(import.meta.url)); const outputPath = join(__dirname, "..", "test", "expected-durations.json"); @@ -69,19 +69,27 @@ 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. +// +// The sample of a file is its first attempt in the job. A retry (`[attempt #K]`) +// gives none. A file that fails in its parallel bucket gives what it took +// there, beside the other files: the runner divides the duration of a bucket +// file by the number of files that run at once. What that file then takes +// alone is a retry too. A file that did not finish in its bucket has no time +// from there, so its run alone is its sample. export function parseLog(raw) { const out = []; - const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r?\n/); + // A line ends in up to three CRs before its LF. + const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r*\n/); let path = null; let start = null; let concurrent = false; let lastTs = null; + let failedInBucket = null; const emit = ts => { if (path === null || start === null || ts === null) return; out.push([path, concurrent ? Math.min(ts - start, 500) : ts - start]); }; - for (let line of lines) { - if (line.endsWith("\r")) line = line.slice(0, -1); + for (const line of lines) { const m = /^\x1b_bk;t=(\d+)\x07(.*)$/.exec(line); const ts = m ? (lastTs = Number(m[1])) : null; const text = m ? m[2] : line; @@ -107,7 +115,7 @@ export function parseLog(raw) { concurrent = false; continue; } - const isPath = /\.(?:[cm]?[jt]sx?|json)$/.test(title); + const isPath = /\.(?:[cm]?[jt]sx?|json)$/.test(title) && !failedInBucket?.has(title); path = isPath ? title : null; start = isPath ? ts : null; concurrent = isPath && !hdr[1]; @@ -117,11 +125,17 @@ export function parseLog(raw) { // `napi prebuild: ...`, `Running N parallel-safe ...`, End) close the open // span so the preceding serial test is not charged for the phase that // follows. See scripts/ci-log-phase.mjs. - if (isPhaseGroupHeader(text)) { + if (!text.startsWith("--- ")) continue; + const failed = failedBucketAttempt(text); + if (failed || isPhaseGroupHeader(text)) { emit(ts); path = start = null; concurrent = false; } + if (failed) { + out.push([failed.path, failed.ms]); + (failedInBucket ??= new Set()).add(failed.path); + } } emit(lastTs); return out; diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index b4315f1886ce..5dab5d7facd6 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,284 @@ 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 samples the bucket attempt, and not the attempts alone", () => { + // The sample of a file is its first attempt in a job. A file of a bucket runs beside other files, and the runner + // divides its duration by the number of files at once. The rerun alone is a retry: alone `regexp` took a quarter + // of its time in the bucket. + expect(parseDurations(bucketThenPassAlone.join("\r\r\n"))).toEqual([ + [passed, 2070], + [mocked, 240230], + [regexp, 599930], + ]); + expect(parseDurations(bucketThenFailAlone.join("\r\r\n"))).toEqual([ + [slowPass, 344850], + [imported, 281800], + [twice, 186260], + ]); + expect(parseDurations(aloneIsLonger.join("\r\r\n"))).toEqual([ + [quick, 10], + [net, 5610], + ]); + }); + + 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", 4000], + ["test/unfinished.test.ts", 3000], + ["test/serial.test.ts", 500], + ]); + }); + + test("both parsers keep 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 }); + expect(parseDurations(killed)).toEqual([ + [slowPass, 344850], + [imported, 281800], + [twice, 186260], + ]); + }); + + test("both parsers read 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`. + const log = bucketThenPassAlone.join("\r\r\r\n"); + expect(Object.fromEntries(parseLog(log))).toEqual({ + [passed]: 2070, + [mocked]: 240230 + 35538, + [regexp]: 599930 + 149852, + }); + expect(parseDurations(log)).toEqual([ + [passed, 2070], + [mocked, 240230], + [regexp, 599930], + ]); + }); + + test("the group of a failed file ends the test that runs before it, as every header of the runner does", () => { + // The runner prints the header of the bucket first. A 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 }); + expect(parseDurations(log)).toEqual([ + ["test/serial.test.ts", 1000], + ["test/b.test.ts", 2000], + ]); + }); + + 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("what .buildkite/update-test-durations.yml runs with node imports no TypeScript", () => { const root = join(import.meta.dir, "..", ".."); const importsOf = (file: string): string[] => From bc8637f105e121286f8c66f80b4242f7d62bf2ff Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 7 Nov 2026 01:59:38 +0000 Subject: [PATCH 2/3] ci:slowest: give a row whose attempts all take 0 ms a platform A file whose attempts all take 0 ms never passed the `total > maxMs` test, so its row had an empty `maxPlat` and read its attempts for no platform. `maxPlat` now starts as the first platform that ran the file. --- scripts/ci-slowest-tests.ts | 3 ++- test/internal/ci-slowest-tests.test.ts | 28 ++++++++++++++++++++++++++ 2 files changed, 30 insertions(+), 1 deletion(-) diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index 8f644c9cccd3..06499ba453e9 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -108,7 +108,8 @@ export type Row = { file: string; maxMs: number; maxPlat: string; attempts: numb export function addLog(agg: Map, plat: string, log: string): void { eachAttempt(log, (file, ms) => { let a = agg.get(file); - if (!a) agg.set(file, (a = { maxMs: 0, maxPlat: "", perPlat: new Map() })); + // `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); diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index 5dab5d7facd6..08fe5050e216 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -454,6 +454,34 @@ describe("a file that fails in its parallel bucket", () => { `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", () => { From f64996337f306164c80ce0ac067df688c1bf4a79 Mon Sep 17 00:00:00 2001 From: robobun <117481402+robobun@users.noreply.github.com> Date: Sat, 7 Nov 2026 02:20:15 +0000 Subject: [PATCH 3/3] update-test-durations: keep the run alone as the sample of a file that fails in its bucket The durations parser goes back to what it does on main: a file that fails in its parallel bucket gets no sample from the bucket attempt, and its run alone is the sample. - The seconds of a bucket run that was interrupted are the time from its dispatch to the interruption, not a full run. - A file that fails in a bucket has a flaky or failed annotation, and update-parallel-allowlist.mjs takes such a file out of the buckets. It runs alone next, and the runner does not divide its duration then. failedBucketAttempt() stays in scripts/ci-log-phase.mjs for ci:slowest, which counts the time a file spent. --- .claude/skills/slowest-tests/SKILL.md | 2 +- scripts/ci-log-phase.mjs | 8 +++-- scripts/ci-slowest-tests.ts | 15 ++++---- scripts/update-test-durations.mjs | 30 ++++++---------- test/internal/ci-slowest-tests.test.ts | 47 ++++++++++---------------- 5 files changed, 42 insertions(+), 60 deletions(-) diff --git a/.claude/skills/slowest-tests/SKILL.md b/.claude/skills/slowest-tests/SKILL.md index 194cb853082c..0b09c0ec3a0e 100644 --- a/.claude/skills/slowest-tests/SKILL.md +++ b/.claude/skills/slowest-tests/SKILL.md @@ -24,7 +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. The time of a try that fails in the phase `Running N files that build many executables` is not in the row: the runner prints no seconds for it. +- 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. diff --git a/scripts/ci-log-phase.mjs b/scripts/ci-log-phase.mjs index 9f339af63275..286ef10095ba 100644 --- a/scripts/ci-log-phase.mjs +++ b/scripts/ci-log-phase.mjs @@ -11,9 +11,11 @@ // - 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. Both say what the file took in the bucket. -// The group has no `[N/M]`: the file gets its number when it runs again, alone, -// as a serial test. failedBucketAttempt() reads it +// 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`, diff --git a/scripts/ci-slowest-tests.ts b/scripts/ci-slowest-tests.ts index 06499ba453e9..3255accce99d 100644 --- a/scripts/ci-slowest-tests.ts +++ b/scripts/ci-slowest-tests.ts @@ -25,13 +25,14 @@ import { failedBucketAttempt, isPhaseGroupHeader } from "./ci-log-phase.mjs"; // scripts/ci-log-phase.mjs for the header shapes runner.node.ts emits and why // each one has to close the open span. // -// `record` gets each attempt of a file in the log, with what that attempt -// took. An attempt is a serial run (the first, or an `[attempt #K]`), a run in -// a parallel bucket whether it passed or failed there, 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. +// `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; diff --git a/scripts/update-test-durations.mjs b/scripts/update-test-durations.mjs index 2483686dec71..ac6bf80582de 100644 --- a/scripts/update-test-durations.mjs +++ b/scripts/update-test-durations.mjs @@ -15,7 +15,7 @@ import { readFileSync, writeFileSync } from "node:fs"; import { dirname, join } from "node:path"; import { fileURLToPath } from "node:url"; import { parseArgs } from "node:util"; -import { failedBucketAttempt, isPhaseGroupHeader } from "./ci-log-phase.mjs"; +import { isPhaseGroupHeader } from "./ci-log-phase.mjs"; const __dirname = dirname(fileURLToPath(import.meta.url)); const outputPath = join(__dirname, "..", "test", "expected-durations.json"); @@ -70,26 +70,24 @@ const api = async path => { // 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. // -// The sample of a file is its first attempt in the job. A retry (`[attempt #K]`) -// gives none. A file that fails in its parallel bucket gives what it took -// there, beside the other files: the runner divides the duration of a bucket -// file by the number of files that run at once. What that file then takes -// alone is a retry too. A file that did not finish in its bucket has no time -// from there, so its run alone is its sample. +// 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 = []; - // A line ends in up to three CRs before its LF. - const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r*\n/); + const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r?\n/); let path = null; let start = null; let concurrent = false; let lastTs = null; - let failedInBucket = null; const emit = ts => { if (path === null || start === null || ts === null) return; out.push([path, concurrent ? Math.min(ts - start, 500) : ts - start]); }; - for (const line of lines) { + 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 ? (lastTs = Number(m[1])) : null; const text = m ? m[2] : line; @@ -115,7 +113,7 @@ export function parseLog(raw) { concurrent = false; continue; } - const isPath = /\.(?:[cm]?[jt]sx?|json)$/.test(title) && !failedInBucket?.has(title); + const isPath = /\.(?:[cm]?[jt]sx?|json)$/.test(title); path = isPath ? title : null; start = isPath ? ts : null; concurrent = isPath && !hdr[1]; @@ -125,17 +123,11 @@ export function parseLog(raw) { // `napi prebuild: ...`, `Running N parallel-safe ...`, End) close the open // span so the preceding serial test is not charged for the phase that // follows. See scripts/ci-log-phase.mjs. - if (!text.startsWith("--- ")) continue; - const failed = failedBucketAttempt(text); - if (failed || isPhaseGroupHeader(text)) { + if (isPhaseGroupHeader(text)) { emit(ts); path = start = null; concurrent = false; } - if (failed) { - out.push([failed.path, failed.ms]); - (failedInBucket ??= new Set()).add(failed.path); - } } emit(lastTs); return out; diff --git a/test/internal/ci-slowest-tests.test.ts b/test/internal/ci-slowest-tests.test.ts index 08fe5050e216..baf9aea59b3a 100644 --- a/test/internal/ci-slowest-tests.test.ts +++ b/test/internal/ci-slowest-tests.test.ts @@ -297,23 +297,23 @@ describe("a file that fails in its parallel bucket", () => { }); }); - test("scripts/update-test-durations.mjs samples the bucket attempt, and not the attempts alone", () => { - // The sample of a file is its first attempt in a job. A file of a bucket runs beside other files, and the runner - // divides its duration by the number of files at once. The rerun alone is a retry: alone `regexp` took a quarter - // of its time in the bucket. + 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, 240230], - [regexp, 599930], + [mocked, 35538], + [regexp, 149852], ]); expect(parseDurations(bucketThenFailAlone.join("\r\r\n"))).toEqual([ [slowPass, 344850], - [imported, 281800], - [twice, 186260], + [imported, 30318], + [twice, 196705], ]); expect(parseDurations(aloneIsLonger.join("\r\r\n"))).toEqual([ [quick, 10], - [net, 5610], + [net, 6718], ]); }); @@ -339,40 +339,31 @@ describe("a file that fails in its parallel bucket", () => { }); expect(parseDurations(log)).toEqual([ ["test/ok.test.ts", 1000], - ["test/failed.test.ts", 4000], + ["test/failed.test.ts", 2000], ["test/unfinished.test.ts", 3000], ["test/serial.test.ts", 500], ]); }); - test("both parsers keep the bucket attempt when the log ends before the file runs alone", () => { + 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 }); - expect(parseDurations(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("both parsers read the line where it ends in three carriage returns", () => { + 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`. - const log = bucketThenPassAlone.join("\r\r\r\n"); - expect(Object.fromEntries(parseLog(log))).toEqual({ + expect(Object.fromEntries(parseLog(bucketThenPassAlone.join("\r\r\r\n")))).toEqual({ [passed]: 2070, [mocked]: 240230 + 35538, [regexp]: 599930 + 149852, }); - expect(parseDurations(log)).toEqual([ - [passed, 2070], - [mocked, 240230], - [regexp, 599930], - ]); }); - test("the group of a failed file ends the test that runs before it, as every header of the runner does", () => { - // The runner prints the header of the bucket first. A parser does not depend on that. + 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")), @@ -380,10 +371,6 @@ describe("a file that fails in its parallel bucket", () => { bk(9500, `--- End`), ].join("\n"); expect(Object.fromEntries(parseLog(log))).toEqual({ "test/serial.test.ts": 1000, "test/b.test.ts": 2000 + 500 }); - expect(parseDurations(log)).toEqual([ - ["test/serial.test.ts", 1000], - ["test/b.test.ts", 2000], - ]); }); test.each([