diff --git a/.github/scripts/run-bats-timed.sh b/.github/scripts/run-bats-timed.sh new file mode 100755 index 000000000..e55013942 --- /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 <&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" > "$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" 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..d1766f9b8 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 ] + 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.