ci:slowest: count a file's failed parallel-bucket attempt, and report attempts per row

.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-<build>/` so re-runs are instant.
 - Parses `_bk;t=<ms> ... --- [N/TOTAL] <file>` 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 (`--- <file> - 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 <headRefName>` 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,12 +40,14 @@ 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
    ```
 
    - 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.

scripts/ci-log-phase.mjs

@@ -10,6 +10,12 @@
 //   - retry/error label: `--- [N/M] <path> - <error>` (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] <path> (X.XXs)` per file
+//     that passed, and a group `--- <path> - K failing in the parallel batch (X.XXs)`
+//     per file whose tests failed there. The seconds of the group are what the file
+//     took in the bucket, up to the interruption where the bucket was cut short. The
+//     group has no `[N/M]`: the file gets its number when it runs again, alone, as a
+//     serial test. failedBucketAttempt() reads it for ci:slowest. The durations
+//     parser takes no sample from it
 //   - parallel-safe phase: `--- Running N parallel-safe tests`, then a bare
 //     `[N/M] <path>` per concurrent dispatch (no recoverable wall clock)
 //   - compiled-programs phase: `--- Running N programs compiled ahead of time`,
@@ -39,3 +45,15 @@ export const isPhaseGroupHeader = body =>
   /^--- (?:\[\d+-\d+\/\d+\]|napi prebuild:|Running \d+ (?:parallel-safe|programs compiled|files that build)|Disk and memory pressure\b|End\b|Summary\b|Received \w+, exiting)/.test(
     body,
   );
+
+/**
+ * The run of a file that failed in its `bun test --parallel` bucket, from the group that the runner opens for it:
+ * `--- <path> - 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) };
+};

scripts/ci-slowest-tests.ts

@@ -18,14 +18,22 @@ import { $, spawn } from "bun";
 import { existsSync, mkdirSync, readFileSync, writeFileSync } from "fs";
 import { tmpdir } from "os";
 import { join } from "path";
-import { isPhaseGroupHeader } from "./ci-log-phase.mjs";
+import { failedBucketAttempt, isPhaseGroupHeader } from "./ci-log-phase.mjs";
 
 // Per-file cost is the gap between the APC timestamps Buildkite injects into
 // consecutive `[N/M] <path>` headers (ESC `_bk;t=<ms>` 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<string, number> {
-  const out = new Map<string, number>();
+//
+// `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] <path> (X.XXs)`): a first try that
+// fails is no attempt, and a further try counts like a parallel-safe dispatch,
+// at most 500 ms.
+function eachAttempt(text: string, record: (file: string, ms: number) => void): void {
   let curName: string | null = null;
   let curStart = 0;
   let concurrent = false;
@@ -36,7 +44,7 @@ export function parseLog(text: string): Map<string, number> {
     // Concurrent-phase gaps are inter-dispatch deltas, not per-file wall
     // clock; clamp so the last-dispatched file on a shard does not absorb the
     // N-wide tail drain or a sibling's 5-15 s retry backoff.
-    out.set(curName, (out.get(curName) ?? 0) + (concurrent ? Math.min(span, 500) : span));
+    record(curName, concurrent ? Math.min(span, 500) : span);
     curName = null;
   };
   for (const line of text.split("\n")) {
@@ -54,7 +62,7 @@ export function parseLog(text: string): Map<string, number> {
       // 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,15 +75,92 @@ export function parseLog(text: string): Map<string, number> {
       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;
     }
   }
   // 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<string, number>;
+  retried?: Map<string, { attempts: number; maxAttemptMs: number }>;
+};
+
+// `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<string, Agg>, plat: string, log: string): void {
+  eachAttempt(log, (file, ms) => {
+    let a = agg.get(file);
+    // `maxPlat` starts as this platform, so a file whose attempts all take 0 ms has one too.
+    if (!a) agg.set(file, (a = { maxMs: 0, maxPlat: plat, perPlat: new Map() }));
+    const before = a.perPlat.get(plat);
+    const total = (before ?? 0) + ms;
+    a.perPlat.set(plat, total);
+    if (before !== undefined) {
+      const retried = (a.retried ??= new Map());
+      const onPlat = retried.get(plat);
+      if (onPlat) {
+        onPlat.attempts++;
+        onPlat.maxAttemptMs = Math.max(onPlat.maxAttemptMs, ms);
+      } else {
+        // Until now the sum was one attempt.
+        retried.set(plat, { attempts: 2, maxAttemptMs: Math.max(before, ms) });
+      }
+    }
+    if (total > a.maxMs) {
+      a.maxMs = total;
+      a.maxPlat = plat;
+    }
+  });
+}
+
+// `package.json` / `test/package.json` are setup steps, not tests.
+const isTest = (f: string) => /\.(m|c)?(j|t)sx?$/.test(f);
+
+export function slowestRows(agg: Map<string, Agg>, topN: number): Row[] {
+  return [...agg.entries()]
+    .filter(([file]) => isTest(file))
+    .map(([file, a]) => {
+      const retried = a.retried?.get(a.maxPlat);
+      return {
+        file,
+        maxMs: a.maxMs,
+        maxPlat: a.maxPlat,
+        attempts: retried?.attempts ?? 1,
+        maxAttemptMs: retried?.maxAttemptMs ?? a.maxMs,
+      };
+    })
+    .sort((a, b) => b.maxMs - a.maxMs)
+    .slice(0, topN);
+}
+
+export function tableLines(rows: Row[]): string[] {
+  const seconds = (ms: number) => (ms / 1000).toFixed(2);
+  return [
+    `rank\tseconds\tfile\tslowest_platform\tattempts\tlongest_attempt`,
+    ...rows.map(
+      (row, i) =>
+        `${i + 1}\t${seconds(row.maxMs)}\t${row.file}\t${row.maxPlat}\t${row.attempts}\t${seconds(row.maxAttemptMs)}`,
+    ),
+  ];
 }
 
 if (import.meta.main) {
@@ -148,7 +233,6 @@ if (import.meta.main) {
     return out;
   }
 
-  type Agg = { maxMs: number; maxPlat: string; perPlat: Map<string, number> };
   const agg = new Map<string, Agg>();
 
   let done = 0;
@@ -160,16 +244,7 @@ if (import.meta.main) {
       try {
         const log = await fetchLog(job);
         const plat = platOf(job.name);
-        for (const [file, ms] of parseLog(log)) {
-          let a = agg.get(file);
-          if (!a) agg.set(file, (a = { maxMs: 0, maxPlat: "", perPlat: new Map() }));
-          const total = (a.perPlat.get(plat) ?? 0) + ms;
-          a.perPlat.set(plat, total);
-          if (total > a.maxMs) {
-            a.maxMs = total;
-            a.maxPlat = plat;
-          }
-        }
+        addLog(agg, plat, log);
       } catch (e) {
         console.error(`  failed ${job.id}: ${(e as Error).message}`);
       }
@@ -179,23 +254,15 @@ 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}`);
 
   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);
 }

scripts/update-test-durations.mjs

@@ -69,6 +69,12 @@ const api = async path => {
 // prints the bare form. For that concurrent phase the gap is an inter-dispatch
 // delta, not wall clock; we clamp it so the last-dispatched file on each shard
 // does not absorb the N-wide tail drain or a sibling's 5-15 s retry backoff.
+//
+// A file that fails in its parallel bucket gets no sample from the group that
+// the runner prints for that run, `--- <path> - K failing in the parallel
+// batch (X.XXs)`. Its sample is its run alone: a bucket run that was
+// interrupted did not finish, and update-parallel-allowlist.mjs takes a file
+// with a flaky or failed annotation out of the buckets, so it runs alone next.
 export function parseLog(raw) {
   const out = [];
   const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r?\n/);