From bdc963bbb4de2ed4ba6f1d8f8d38b5bcaa5c32a1 Mon Sep 17 00:00:00 2001 From: fujibee Date: Fri, 11 Sep 2026 10:04:18 -0700 Subject: [PATCH 1/5] ci: record per-file bats timings --- .github/scripts/run-bats-timed.sh | 78 +++++++++++++++++++++++ .github/scripts/shard-tests.sh | 3 + .github/scripts/summarize-bats-timings.sh | 56 ++++++++++++++++ .github/workflows/tests.yml | 14 +++- tests/test_ci_sharding.bats | 76 ++++++++++++++++++++++ 5 files changed, 226 insertions(+), 1 deletion(-) create mode 100755 .github/scripts/run-bats-timed.sh create mode 100755 .github/scripts/summarize-bats-timings.sh diff --git a/.github/scripts/run-bats-timed.sh b/.github/scripts/run-bats-timed.sh new file mode 100755 index 000000000..0caf6f259 --- /dev/null +++ b/.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 +# +# 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##*/} " >&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; 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" + 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 < "$manifest" + +exit "$suite_status" diff --git a/.github/scripts/shard-tests.sh b/.github/scripts/shard-tests.sh index 13db2f598..e6dcba9da 100755 --- a/.github/scripts/shard-tests.sh +++ b/.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: diff --git a/.github/scripts/summarize-bats-timings.sh b/.github/scripts/summarize-bats-timings.sh new file mode 100755 index 000000000..3edfbb353 --- /dev/null +++ b/.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] ... +# +# 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] ..." >&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" diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 544c5896c..4f95054f8 100644 --- a/.github/workflows/tests.yml +++ b/.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 diff --git a/tests/test_ci_sharding.bats b/tests/test_ci_sharding.bats index 98bf510b0..75f4b3ea4 100644 --- a/tests/test_ci_sharding.bats +++ b/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 ] + [[ "$output" == *$'file\tmacOS\ttests/a.bats\t2\t10\t30\t30'* ]] + [[ "$output" == *$'run\t1\t1\tmacOS\t2\t90\t10\t0'* ]] } all_test_files() { @@ -29,6 +48,63 @@ 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 "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. From 4d7f7ced3329995a77f4ef2cf45bb214f49582a3 Mon Sep 17 00:00:00 2001 From: fujibee Date: Fri, 11 Sep 2026 10:24:58 -0700 Subject: [PATCH 2/5] test: preserve timings when a shard is cancelled --- tests/test_ci_sharding.bats | 32 ++++++++++++++++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/tests/test_ci_sharding.bats b/tests/test_ci_sharding.bats index 75f4b3ea4..c4f0414bc 100644 --- a/tests/test_ci_sharding.bats +++ b/tests/test_ci_sharding.bats @@ -97,6 +97,38 @@ union_of_shards() { awk -F '\t' '$2 == "shard" && $13 == 7 { ok=1 } END { exit !ok }' "$timings" } +@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" From 2de79944c13bcbec6b87ad44afc6fe3dc01fa592 Mon Sep 17 00:00:00 2001 From: fujibee Date: Fri, 11 Sep 2026 15:29:52 -0700 Subject: [PATCH 3/5] test: make timing summary assertions enforceable --- tests/test_ci_sharding.bats | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_ci_sharding.bats b/tests/test_ci_sharding.bats index c4f0414bc..19b00be2b 100644 --- a/tests/test_ci_sharding.bats +++ b/tests/test_ci_sharding.bats @@ -26,8 +26,8 @@ setup() { run "$TIMING_SUMMARY" --timeout-seconds 100 "$timings" [ "$status" -eq 0 ] - [[ "$output" == *$'file\tmacOS\ttests/a.bats\t2\t10\t30\t30'* ]] - [[ "$output" == *$'run\t1\t1\tmacOS\t2\t90\t10\t0'* ]] + 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() { From 2e124f7744578ae3eba81a87ddbaf9601b82dda1 Mon Sep 17 00:00:00 2001 From: fujibee Date: Fri, 11 Sep 2026 18:22:54 -0700 Subject: [PATCH 4/5] fix(ci): isolate timed bats input from the shard manifest --- .github/scripts/run-bats-timed.sh | 2 +- tests/test_ci_sharding.bats | 21 +++++++++++++++++++++ 2 files changed, 22 insertions(+), 1 deletion(-) diff --git a/.github/scripts/run-bats-timed.sh b/.github/scripts/run-bats-timed.sh index 0caf6f259..1c3974661 100755 --- a/.github/scripts/run-bats-timed.sh +++ b/.github/scripts/run-bats-timed.sh @@ -60,7 +60,7 @@ while IFS= read -r file; do "$file" "$started_at" >> "$timings" echo "bats timing: start $file at $started_at" - bats --print-output-on-failure "$file" + bats --print-output-on-failure "$file" "$manifest" + printf '%s\n' \ + '#!/usr/bin/env bash' \ + 'echo "$2" >> "$BATS_CALLS"' \ + 'if IFS= read -r unexpected; then echo "unexpected stdin: $unexpected" >&2; exit 9; fi' \ + 'exit 0' > "$fake_bin/bats" + chmod +x "$fake_bin/bats" + + run env PATH="$fake_bin:$PATH" BATS_CALLS="$calls" "$TIMED_RUNNER" "$manifest" "$timings" + + [ "$status" -eq 0 ] + [ "$(wc -l < "$calls" | tr -d ' ')" -eq 2 ] +} + @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" From f1707262aecf95f41d63544ed920ad2e3efa5cc8 Mon Sep 17 00:00:00 2001 From: fujibee Date: Fri, 11 Sep 2026 18:25:40 -0700 Subject: [PATCH 5/5] test(ci): keep the shard manifest off standard input --- .github/scripts/run-bats-timed.sh | 4 ++-- tests/test_ci_sharding.bats | 9 ++++++--- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/.github/scripts/run-bats-timed.sh b/.github/scripts/run-bats-timed.sh index 1c3974661..e55013942 100755 --- a/.github/scripts/run-bats-timed.sh +++ b/.github/scripts/run-bats-timed.sh @@ -51,7 +51,7 @@ stop() { } trap stop INT TERM -while IFS= read -r file; do +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)" @@ -73,6 +73,6 @@ while IFS= read -r file; do completed=$((completed + 1)) [ "$status" -eq 0 ] || suite_status="$status" -done < "$manifest" +done 3< "$manifest" exit "$suite_status" diff --git a/tests/test_ci_sharding.bats b/tests/test_ci_sharding.bats index 86db0cb36..d1766f9b8 100644 --- a/tests/test_ci_sharding.bats +++ b/tests/test_ci_sharding.bats @@ -98,24 +98,27 @@ union_of_shards() { } @test "timed bats runner does not pass the manifest as test stdin" { - local manifest timings fake_bin calls + 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"' \ - 'if IFS= read -r unexpected; then echo "unexpected stdin: $unexpected" >&2; exit 9; fi' \ + 'cat >> "$BATS_STDIN_CAPTURE"' \ 'exit 0' > "$fake_bin/bats" chmod +x "$fake_bin/bats" - run env PATH="$fake_bin:$PATH" BATS_CALLS="$calls" "$TIMED_RUNNER" "$manifest" "$timings" + 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" {