ci: record per-file bats timings

.github/scripts/run-bats-timed.sh

@@ -0,0 +1,78 @@
+#!/usr/bin/env bash
+# Run one bats file at a time and append machine-readable wall-clock timings.
+#
+# Usage: run-bats-timed.sh <manifest> <timings.tsv>
+#
+# The TSV is intentionally append-only while the suite runs. If the job reaches
+# its wall-clock cap, every completed file remains useful evidence instead of
+# disappearing with the unfinished bats invocation. Files from several runs can
+# be concatenated directly: the run metadata is repeated on every row.
+set -u
+
+usage() {
+  echo "usage: ${0##*/} <manifest> <timings.tsv>" >&2
+  exit 2
+}
+
+[ "$#" -eq 2 ] || usage
+manifest="$1"
+timings="$2"
+[ -s "$manifest" ] || { echo "${0##*/}: empty or missing manifest: $manifest" >&2; exit 1; }
+
+run_id="${GITHUB_RUN_ID:-local}"
+run_attempt="${GITHUB_RUN_ATTEMPT:-1}"
+sha="${GITHUB_SHA:-unknown}"
+runner_os="${RUNNER_OS:-unknown}"
+shard="${SHARD:-unknown}"
+shard_total="${SHARD_TOTAL:-unknown}"
+
+printf 'schema\trecord\trun_id\trun_attempt\tsha\tos\tshard\tshard_total\tfile\tstarted_at\tended_at\telapsed_seconds\tstatus\n' > "$timings"
+
+suite_started_epoch="$(date -u +%s)"
+suite_started_at="$(date -u +%Y-%m-%dT%H:%M:%SZ)"
+suite_status=0
+completed=0
+
+finish() {
+  rc=$?
+  suite_ended_epoch="$(date -u +%s)"
+  suite_ended_at="$(date -u +%Y-%m-%dT%H:%M:%SZ)"
+  suite_elapsed=$((suite_ended_epoch - suite_started_epoch))
+  [ "$suite_status" -ne 0 ] || suite_status="$rc"
+  printf '1\tshard\t%s\t%s\t%s\t%s\t%s\t%s\t-\t%s\t%s\t%s\t%s\n' \
+    "$run_id" "$run_attempt" "$sha" "$runner_os" "$shard" "$shard_total" \
+    "$suite_started_at" "$suite_ended_at" "$suite_elapsed" "$suite_status" >> "$timings"
+  echo "bats timing: shard $shard/$shard_total completed $completed file(s) in ${suite_elapsed}s (status $suite_status)"
+}
+trap finish EXIT
+stop() {
+  suite_status=143
+  exit 143
+}
+trap stop INT TERM
+
+while IFS= read -r file <&3; do
+  [ -n "$file" ] || continue
+  started_epoch="$(date -u +%s)"
+  started_at="$(date -u +%Y-%m-%dT%H:%M:%SZ)"
+  printf '1\tfile_start\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t-\t-\t-\n' \
+    "$run_id" "$run_attempt" "$sha" "$runner_os" "$shard" "$shard_total" \
+    "$file" "$started_at" >> "$timings"
+  echo "bats timing: start $file at $started_at"
+
+  bats --print-output-on-failure "$file" </dev/null
+  status=$?
+
+  ended_epoch="$(date -u +%s)"
+  ended_at="$(date -u +%Y-%m-%dT%H:%M:%SZ)"
+  elapsed=$((ended_epoch - started_epoch))
+  printf '1\tfile_end\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \
+    "$run_id" "$run_attempt" "$sha" "$runner_os" "$shard" "$shard_total" \
+    "$file" "$started_at" "$ended_at" "$elapsed" "$status" >> "$timings"
+  echo "bats timing: end $file at $ended_at (${elapsed}s, status $status)"
+
+  completed=$((completed + 1))
+  [ "$status" -eq 0 ] || suite_status="$status"
+done 3< "$manifest"
+
+exit "$suite_status"

.github/scripts/shard-tests.sh

@@ -22,6 +22,9 @@
 # come out at 125s/298s/366s/71s. Per-test cost varies from ~0.0s to ~8s
 # depending on how much a file forks or waits. So the real speedup here is
 # 860s -> 366s (~2.4x), not 4x.
+# These are historical design measurements, not current weights. Every CI shard
+# now uploads a bats-timings artifact with per-file and shard wall times; combine
+# several with summarize-bats-timings.sh before changing the partition.
 #
 # It is still the right weight to ship first. The alternative, a checked-in
 # table of measured per-file seconds, buys ~150s more but goes stale silently:

.github/scripts/summarize-bats-timings.sh

@@ -0,0 +1,56 @@
+#!/usr/bin/env bash
+# Summarize one or more run-bats-timed.sh TSV artifacts.
+#
+# Usage: summarize-bats-timings.sh [--timeout-seconds N] <timings.tsv>...
+#
+# File percentiles are nearest-rank values across every supplied run. Shard
+# headroom is kept per run and OS so a fast sample cannot hide a slow sibling.
+set -euo pipefail
+
+timeout=1800
+if [ "${1:-}" = --timeout-seconds ]; then
+  timeout="${2:-}"
+  shift 2
+fi
+case "$timeout" in ''|*[!0-9]*) echo "${0##*/}: timeout must be seconds" >&2; exit 2 ;; esac
+[ "$#" -gt 0 ] || { echo "usage: ${0##*/} [--timeout-seconds N] <timings.tsv>..." >&2; exit 2; }
+
+tmp="$(mktemp -d "${TMPDIR:-/tmp}/agmsg-bats-timings.XXXXXX")"
+cleanup() {
+  rm -f "$tmp/files" "$tmp/shards"
+  rmdir "$tmp" 2>/dev/null || true
+}
+trap cleanup EXIT
+
+awk -F '\t' '$1 == 1 && $2 == "file_end" && $13 == 0 { print $6 "\t" $9 "\t" $12 }' "$@" \
+  | LC_ALL=C sort -t '	' -k1,1 -k2,2 -k3,3n > "$tmp/files"
+
+printf 'record\tos\tfile\tsamples\tp50_seconds\tp95_seconds\tmax_seconds\n'
+awk -F '\t' '
+  function emit(   p50,p95) {
+    if (!n) return
+    p50 = int((n + 1) / 2)
+    p95 = int((95 * n + 99) / 100)
+    printf "file\t%s\t%s\t%d\t%d\t%d\t%d\n", os, file, n, value[p50], value[p95], value[n]
+  }
+  {
+    key = $1 FS $2
+    if (last != "" && key != last) { emit(); delete value; n=0 }
+    os=$1; file=$2; value[++n]=$3; last=key
+  }
+  END { emit() }
+' "$tmp/files"
+
+awk -F '\t' '$1 == 1 && $2 == "shard" { print $3 "\t" $4 "\t" $6 "\t" $7 "\t" $12 "\t" $13 }' "$@" \
+  | LC_ALL=C sort -t '	' -k1,1 -k2,2n -k3,3 -k5,5nr > "$tmp/shards"
+
+printf 'record\trun_id\trun_attempt\tos\tmax_shard\tmax_seconds\theadroom_seconds\tstatus\n'
+awk -F '\t' -v timeout="$timeout" '
+  {
+    key=$1 FS $2 FS $3
+    if (!(key in seen)) {
+      seen[key]=1
+      printf "run\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n", $1, $2, $3, $4, $5, timeout-$5, $6
+    }
+  }
+' "$tmp/shards"

.github/workflows/tests.yml

@@ -377,9 +377,11 @@ jobs:
 
       - name: Run bats suite (this shard)
         if: needs.changes.outputs.docs_only != 'true'
+        env:
+          SHARD: ${{ matrix.shard }}
         run: |
           set +e
-          xargs bats --print-output-on-failure < shard-files.txt
+          .github/scripts/run-bats-timed.sh shard-files.txt "$RUNNER_TEMP/bats-timings.tsv"
           status=$?
           : > "$RUNNER_TEMP/bats-done"
           exit $status
@@ -437,6 +439,16 @@ jobs:
           if-no-files-found: ignore
           retention-days: 3
 
+      - name: Upload bats timings
+        if: always() && needs.changes.outputs.docs_only != 'true'
+        continue-on-error: true
+        uses: actions/upload-artifact@v4
+        with:
+          name: bats-timings-${{ matrix.os }}-${{ matrix.shard }}
+          path: ${{ runner.temp }}/bats-timings.tsv
+          if-no-files-found: warn
+          retention-days: 30
+
       - name: Record which files this shard ran
         if: needs.changes.outputs.docs_only != 'true'
         uses: actions/upload-artifact@v4

tests/test_ci_sharding.bats

@@ -9,6 +9,25 @@ setup() {
   load 'test_helper'
   REPO_ROOT="$(cd "$BATS_TEST_DIRNAME/.." && pwd)"
   SHARD="$REPO_ROOT/.github/scripts/shard-tests.sh"
+  TIMED_RUNNER="$REPO_ROOT/.github/scripts/run-bats-timed.sh"
+  TIMING_SUMMARY="$REPO_ROOT/.github/scripts/summarize-bats-timings.sh"
+}
+
+@test "timing summary computes cross-run percentiles and per-run headroom" {
+  local timings
+  timings="$BATS_TEST_TMPDIR/timings.tsv"
+  printf '%s\n' \
+    $'schema\trecord\trun_id\trun_attempt\tsha\tos\tshard\tshard_total\tfile\tstarted_at\tended_at\telapsed_seconds\tstatus' \
+    $'1\tfile_end\t1\t1\ta\tmacOS\t1\t4\ttests/a.bats\ts\te\t10\t0' \
+    $'1\tfile_end\t2\t1\tb\tmacOS\t2\t4\ttests/a.bats\ts\te\t30\t0' \
+    $'1\tshard\t1\t1\ta\tmacOS\t1\t4\t-\ts\te\t70\t0' \
+    $'1\tshard\t1\t1\ta\tmacOS\t2\t4\t-\ts\te\t90\t0' > "$timings"
+
+  run "$TIMING_SUMMARY" --timeout-seconds 100 "$timings"
+
+  [ "$status" -eq 0 ]
+  grep -Fq $'file\tmacOS\ttests/a.bats\t2\t10\t30\t30' <<< "$output"
+  grep -Fq $'run\t1\t1\tmacOS\t2\t90\t10\t0' <<< "$output"
 }
 
 all_test_files() {
@@ -29,6 +48,119 @@ union_of_shards() {
   [[ "$output" == *"usage:"* ]]
 }
 
+@test "timed bats runner is executable and self-documents its usage" {
+  [ -x "$TIMED_RUNNER" ]
+  run "$TIMED_RUNNER"
+  [ "$status" -eq 2 ]
+  [[ "$output" == *"usage:"* ]]
+}
+
+@test "timed bats runner records each file and the shard total" {
+  local fixture manifest timings fake_bin
+  fixture="$BATS_TEST_TMPDIR/fixture.bats"
+  manifest="$BATS_TEST_TMPDIR/manifest.txt"
+  timings="$BATS_TEST_TMPDIR/timings.tsv"
+  fake_bin="$BATS_TEST_TMPDIR/bin"
+  mkdir -p "$fake_bin"
+  printf '@test "passes" { true; }\n' > "$fixture"
+  printf '%s\n' "$fixture" > "$manifest"
+  printf '#!/usr/bin/env bash\nexit 0\n' > "$fake_bin/bats"
+  chmod +x "$fake_bin/bats"
+
+  run env PATH="$fake_bin:$PATH" GITHUB_RUN_ID=42 GITHUB_RUN_ATTEMPT=3 \
+    GITHUB_SHA=abc RUNNER_OS=macOS SHARD=2 SHARD_TOTAL=4 \
+    "$TIMED_RUNNER" "$manifest" "$timings"
+
+  [ "$status" -eq 0 ]
+  [ "$(awk -F '\t' '$2 == "file_start" { n++ } END { print n+0 }' "$timings")" -eq 1 ]
+  [ "$(awk -F '\t' '$2 == "file_end" { n++ } END { print n+0 }' "$timings")" -eq 1 ]
+  [ "$(awk -F '\t' '$2 == "shard" { n++ } END { print n+0 }' "$timings")" -eq 1 ]
+  awk -F '\t' '$2 == "file_end" && $3 == 42 && $4 == 3 && $5 == "abc" && $6 == "macOS" && $7 == 2 && $8 == 4 && $9 != "" && $12 ~ /^[0-9]+$/ && $13 == 0 { ok=1 } END { exit !ok }' "$timings"
+}
+
+@test "timed bats runner records a failure and continues the shard" {
+  local manifest timings fake_bin calls
+  manifest="$BATS_TEST_TMPDIR/manifest.txt"
+  timings="$BATS_TEST_TMPDIR/timings.tsv"
+  fake_bin="$BATS_TEST_TMPDIR/bin"
+  calls="$BATS_TEST_TMPDIR/calls.txt"
+  mkdir -p "$fake_bin"
+  printf '%s\n' tests/fail.bats tests/pass.bats > "$manifest"
+  printf '%s\n' '#!/usr/bin/env bash' 'echo "$2" >> "$BATS_CALLS"' 'case "$2" in *fail*) exit 7 ;; esac' > "$fake_bin/bats"
+  chmod +x "$fake_bin/bats"
+
+  run env PATH="$fake_bin:$PATH" BATS_CALLS="$calls" "$TIMED_RUNNER" "$manifest" "$timings"
+
+  [ "$status" -eq 7 ]
+  [ "$(wc -l < "$calls" | tr -d ' ')" -eq 2 ]
+  [ "$(awk -F '\t' '$2 == "file_end" { n++ } END { print n+0 }' "$timings")" -eq 2 ]
+  awk -F '\t' '$2 == "shard" && $13 == 7 { ok=1 } END { exit !ok }' "$timings"
+}
+
+@test "timed bats runner does not pass the manifest as test stdin" {
+  local manifest timings fake_bin calls stdin_capture
+  manifest="$BATS_TEST_TMPDIR/manifest.txt"
+  timings="$BATS_TEST_TMPDIR/timings.tsv"
+  fake_bin="$BATS_TEST_TMPDIR/bin"
+  calls="$BATS_TEST_TMPDIR/calls.txt"
+  stdin_capture="$BATS_TEST_TMPDIR/stdin.txt"
+  mkdir -p "$fake_bin"
+  printf '%s\n' tests/first.bats tests/second.bats > "$manifest"
+  printf '%s\n' \
+    '#!/usr/bin/env bash' \
+    'echo "$2" >> "$BATS_CALLS"' \
+    'cat >> "$BATS_STDIN_CAPTURE"' \
+    'exit 0' > "$fake_bin/bats"
+  chmod +x "$fake_bin/bats"
+
+  run env PATH="$fake_bin:$PATH" BATS_CALLS="$calls" BATS_STDIN_CAPTURE="$stdin_capture" \
+    "$TIMED_RUNNER" "$manifest" "$timings"
+
+  [ "$status" -eq 0 ]
+  [ "$(wc -l < "$calls" | tr -d ' ')" -eq 2 ]
+  [ ! -s "$stdin_capture" ]
+}
+
+@test "timed bats runner records the interrupted shard on TERM" {
+  local manifest timings fake_bin ready release runner_pid rc i
+  manifest="$BATS_TEST_TMPDIR/manifest.txt"
+  timings="$BATS_TEST_TMPDIR/timings.tsv"
+  fake_bin="$BATS_TEST_TMPDIR/bin"
+  ready="$BATS_TEST_TMPDIR/ready"
+  release="$BATS_TEST_TMPDIR/release"
+  mkdir -p "$fake_bin"
+  printf '%s\n' tests/running.bats > "$manifest"
+  printf '%s\n' '#!/usr/bin/env bash' ': > "$BATS_READY"' 'while [ ! -f "$BATS_RELEASE" ]; do sleep 0.05; done' > "$fake_bin/bats"
+  chmod +x "$fake_bin/bats"
+
+  PATH="$fake_bin:$PATH" BATS_READY="$ready" BATS_RELEASE="$release" \
+    "$TIMED_RUNNER" "$manifest" "$timings" > "$BATS_TEST_TMPDIR/runner.log" 2>&1 &
+  runner_pid=$!
+  i=0
+  while [ ! -f "$ready" ] && [ "$i" -lt 100 ]; do
+    sleep 0.05
+    i=$((i + 1))
+  done
+  [ -f "$ready" ]
+
+  kill -TERM "$runner_pid"
+  : > "$release"
+  rc=0
+  wait "$runner_pid" || rc=$?
+
+  [ "$rc" -eq 143 ]
+  [ "$(awk -F '\t' '$2 == "file_start" { n++ } END { print n+0 }' "$timings")" -eq 1 ]
+  awk -F '\t' '$2 == "shard" && $13 == 143 { ok=1 } END { exit !ok }' "$timings"
+}
+
+@test "CI runs the timed runner and uploads each shard artifact" {
+  local workflow
+  workflow="$REPO_ROOT/.github/workflows/tests.yml"
+  grep -Fq '.github/scripts/run-bats-timed.sh shard-files.txt "$RUNNER_TEMP/bats-timings.tsv"' "$workflow"
+  grep -Fq 'name: bats-timings-${{ matrix.os }}-${{ matrix.shard }}' "$workflow"
+  grep -Fq 'path: ${{ runner.temp }}/bats-timings.tsv' "$workflow"
+}
+
 @test "the shards cover every test file exactly once" {
   # Checked across several totals: an off-by-one in the greedy loop can easily
   # be invisible at one shard count and drop a file at another.