scripts: keep docker-compose start-up out of per-file CI timings (stacked on #35418)

.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).
+- Subtracts the time a file sat waiting for its docker-compose service to come up (`test/docker/index.ts`'s `awaitService`, which `describeWithContainer` uses, prints `Container ready via docker-compose: ... (waited Nms)`; in the parallel bucket the line is attributed via bun's `<path>:` output block). That wait is paid by whichever file on the shard touches the service first, so it is not the file's cost and does not belong in the slow-test list; the `max_container_wait` column and a stderr list of the longest waits report it separately. A file in that list tagged `not in test/docker/prestart-map.mjs` is fixed by adding it to the map; an untagged one ran before its service was up anyway (the runner puts the files a PR modifies at the front of the shard, so on a PR build that is usually the PR's own docker-backed files; otherwise the shard had too little other work).
 - 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.

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
@@ -60,36 +57,63 @@ const api = async path => {
   }
 };
 
+// awaitService (test/docker/index.ts; describeWithContainer goes through it)
+// prints this from the test process with how long it sat blocked waiting for
+// docker-compose to bring the service up. That wait is inside the file's
+// measured time but is a cost of the shard, not the file (whichever file first
+// touches a cold service pays it, and the packing this table drives decides
+// which file that is), so it comes off the file's cost instead of being
+// committed as a 15-40 s test. The reported number is the only usable signal: a
+// file with several container describes runs real tests between its lines, so
+// the line's timestamp says nothing about the wait.
+const containerWaitLine = /Container ready via docker-compose: .*\(waited (\d+)ms\)/;
+// In the parallel bucket, `bun test --parallel` flushes each file's output as a
+// block introduced by `<path>:`; that is what attributes a wait printed there.
+const bucketOutputHeader = /^(\S+\.(?:[cm]?[jt]sx?)):$/;
+
 // Per-file cost is the gap between the APC timestamps Buildkite injects into
-// consecutive `[N/M] <path>` headers (ESC `_bk;t=<ms>` BEL). Serial tests
-// prefix the header with `--- `; the parallel-safe phase (runner.node.mjs)
-// 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) {
+// consecutive `[N/M] <path>` headers (ESC `_bk;t=<ms>` BEL), or for the
+// parallel bucket the per-file figure on its summary line, minus the container
+// wait above. Serial tests prefix the header with `--- `; the parallel-safe
+// phase (runner.node.mjs) 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.
+export function parseLog(raw) {
   const out = [];
   const lines = raw.replace(/\x1b\[[0-9;]*m/g, "").split(/\r?\n/);
   let path = null;
   let start = null;
+  let containerMs = 0;
   let concurrent = false;
+  let lastTs = null;
+  let inBucket = false;
+  let bucketFile = null;
+  const bucketWaits = new Map();
   const emit = ts => {
     if (path === null || start === null || ts === null) return;
-    out.push([path, concurrent ? Math.min(ts - start, 500) : ts - start]);
+    const own = Math.max(0, ts - start - containerMs);
+    out.push([path, concurrent ? Math.min(own, 500) : own]);
   };
   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) {
       emit(ts);
+      containerMs = 0;
+      inBucket = false;
+      bucketFile = null;
       // Retry/error headers (`... - code 1`, `... [attempt #2]`) are not file
       // paths; treat them as a delimiter so the preceding span closes cleanly.
       const title = hdr[2].trim();
       const timed = /^(.+\.(?:[cm]?[jt]sx?|json)) \((\d+(?:\.\d+)?)s\)$/.exec(title);
       if (timed) {
-        out.push([timed[1], Math.round(parseFloat(timed[2]) * 1000)]);
+        const waited = bucketWaits.get(timed[1]) ?? 0;
+        bucketWaits.delete(timed[1]);
+        out.push([timed[1], Math.max(0, Math.round(parseFloat(timed[2]) * 1000) - waited)]);
         path = start = null;
         concurrent = false;
         continue;
@@ -100,12 +124,41 @@ function parseLog(raw) {
       concurrent = isPath && !hdr[1];
       continue;
     }
-    if (/^--- (?:End\b|Running \d+ parallel-safe)/.test(text)) {
+    // 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/<file>` 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;
+      containerMs = 0;
       concurrent = false;
+      // `[N/M]` headers were handled above, so `--- [` here is the bucket's
+      // `[A-B/M] K files in parallel`.
+      inBucket = text.startsWith("--- [");
+      bucketFile = null;
+      continue;
+    }
+    if (inBucket) {
+      const block = bucketOutputHeader.exec(text);
+      if (block) {
+        bucketFile = block[1].replaceAll("\\", "/");
+        continue;
+      }
     }
+    const wait = containerWaitLine.exec(text);
+    if (!wait) continue;
+    if (path !== null) containerMs += Number(wait[1]);
+    else if (bucketFile !== null) bucketWaits.set(bucketFile, (bucketWaits.get(bucketFile) ?? 0) + Number(wait[1]));
   }
+  emit(lastTs);
   return out;
 }
 
@@ -169,50 +222,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] <path>' 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);
+  }
+  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]);
+    }
   }
-  out[p] = entry;
-}
 
-writeFileSync(outputPath, JSON.stringify(out, null, 2) + "\n");
-console.error(`wrote ${paths.size} entries to ${outputPath}`);
+  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] <path>' 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}`);
+}

test/docker/README.md

@@ -303,7 +303,8 @@ A: This tells Docker to pick any available port, preventing conflicts.
 2. **Use health checks**: Add healthcheck configurations for reliable startup
 3. **Clean up in tests**: Delete test data after each test (but keep containers running)
 4. **Prefer ensure()**: Always use `dockerCompose.ensure()` instead of assuming services are running
-5. **Handle failures gracefully**: Services might fail to start; handle errors appropriately
+5. **Block through `awaitService()`**: `describeWithContainer` does this for you. A test file that calls `ensure()` itself should `await dockerCompose.awaitService("postgres_plain")` instead: it prints the `Container ready via docker-compose: ... (waited Nms)` line that the CI slow-test and shard-duration scripts use to keep container start-up out of the file's measured time
+6. **Handle failures gracefully**: Services might fail to start; handle errors appropriately
 
 ## Troubleshooting
 

test/docker/index.ts

@@ -548,6 +548,31 @@ export async function ensure(service: ServiceName): Promise<ServiceInfo> {
   return getHelper().ensure(service);
 }
 
+/**
+ * `ensure()` for a test file that is blocked until the service is up. Prints
+ *
+ *     Container ready via docker-compose: <service> at <host>:<ports> (waited <ms>ms)
+ *
+ * which scripts/ci-slowest-tests.ts and scripts/update-test-durations.mjs key
+ * on: `waited` is how long this call blocked, and they take it off the file's
+ * measured duration, since the first file on a shard to touch a cold service
+ * otherwise shows up as a 15-40 s test. Pass `pending` when ensure() was kicked
+ * off earlier (describeWithContainer) so only the time actually blocked here is
+ * reported. Only a test process may print this line: the coordinator's output
+ * lands in whichever file's log section happens to be streaming.
+ */
+export async function awaitService(
+  service: ServiceName,
+  pending: Promise<ServiceInfo> = ensure(service),
+): Promise<ServiceInfo> {
+  const start = performance.now();
+  const info = await pending;
+  const waited = Math.round(performance.now() - start);
+  const ports = Object.values(info.ports).join(",");
+  console.log(`Container ready via docker-compose: ${service} at ${info.host}:${ports} (waited ${waited}ms)`);
+  return info;
+}
+
 export async function port(service: ServiceName, targetPort: number): Promise<number> {
   return getHelper().port(service, targetPort);
 }

test/harness.ts

@@ -1242,16 +1242,18 @@ export async function describeWithContainer(
     // up() de-duplicates in-flight calls per service, so two describes for
     // the same service share one `compose up`. beforeAll just awaits the
     // result so test failures still surface there.
-    const startPromise = import("./docker/index.ts").then(h => h.ensure(actualService as any));
+    const docker = import("./docker/index.ts");
+    const startPromise = docker.then(h => h.ensure(actualService as any));
     // Surface any rejection through `ready`; without a handler the runner
     // would see an unhandled rejection before beforeAll re-throws it.
     startPromise.catch(readyRejecter!);
 
     beforeAll(async () => {
-      const info = await startPromise;
+      // Reports the time this hook blocked, not the time since the kick-off
+      // above: an earlier describe's tests may have run in between.
+      const info = await (await docker).awaitService(actualService as any, startPromise);
       _host = info.host;
       _port = info.ports[servicePort];
-      console.log(`Container ready via docker-compose: ${image} at ${_host}:${_port}`);
       readyResolver!();
       // Cold container start is bounded by `compose up --wait-timeout 180` plus
       // a `compose build` step; the default 5s hook timeout fires first and the

test/internal/ci-slowest-tests.fixture.ts

@@ -0,0 +1,12 @@
+// Run by ci-slowest-tests.test.ts with BUN_TEST_SERVICE_mysql_plain set, so
+// describeWithContainer resolves the service from the environment (no docker)
+// and awaitService prints the `Container ready via docker-compose: ...` line
+// the CI log parsers key on.
+import { expect, test } from "bun:test";
+import { describeWithContainer } from "harness";
+
+describeWithContainer("container line fixture", { image: "mysql:8" }, container => {
+  test("service comes from the environment", () => {
+    expect(container.port).toBe(1);
+  });
+});