test/run: per-test + per-phase wall-clock timing (test-perf step 0)

Emits a timing block (durations, phase walls, total) before the summary
line; the ok/FAIL and 'all N passed' contract is unchanged and the only
consumer (make's exit-code gate) is unaffected. Measured baseline at
4ff79bf: 211.6s wall, 990-995 self-compile gates = 87% of wall — the
content-keyed skip tier (T1) targets exactly that block. Baseline data:
.ai/testperf-baseline.md.
This commit is contained in:
2026-06-10 15:33:24 +09:00
parent 4ff79bff0f
commit f940072623

View File

@@ -32,10 +32,17 @@ if [ "$1" = "--one" ]; then
: > "$prefix.fail"
exit 0
fi
# Per-test wall-clock (task #10 baseline). Stamp around the binary run
# only; build cost lives in `make all`, not here. Duration lands in
# <prefix>.dur as "<sec>\t<name>" for the collector's timing section —
# kept out of <prefix>.status so the ok/FAIL log format is untouched.
t0=$(date +%s.%N)
if "$bin" > "$prefix.out" 2> "$prefix.err"; then
t1=$(date +%s.%N)
printf 'ok %s\n' "$name" > "$prefix.status"
else
rc=$?
t1=$(date +%s.%N)
{
printf 'FAIL %s (rc=%d)\n' "$name" "$rc"
echo '--- stdout ---'
@@ -45,6 +52,8 @@ if [ "$1" = "--one" ]; then
} > "$prefix.status"
: > "$prefix.fail"
fi
awk -v a="$t0" -v b="$t1" -v n="$name" 'BEGIN{printf "%.3f\t%s\n", b-a, n}' \
> "$prefix.dur"
exit 0
fi
@@ -55,6 +64,10 @@ trap 'rm -rf "$RESULTS"' EXIT
JOBS=${JOBS:-$(nproc 2>/dev/null || echo 4)}
# Phase wall-clock stamps (task #10 baseline). Each phase records start/end
# so the collector can report wall shares onto ken's three poles.
run_start=$(date +%s.%N)
# Phase 2 runs the wwstage byte-id gates (990-997) + 950_selfcheck.
# ww_ww writes intermediates next to every traversed source (task #15),
# so 991/992/994's reads of selfhost/cmd/<tool>/main.{s,o,combined.ww}
@@ -69,11 +82,13 @@ for t in test/wcc/*.c; do
name=${t##*/}; name=${name%.c}
printf '%s/%s\0%s\0' "$RESULTS" "$name" "$t"
done | xargs -0 -n2 -P "$JOBS" "$0" --one || true
p1_end=$(date +%s.%N)
# UNIT=1 (make test-unit) is the inner-loop short path: skip the wwstage
# byte-id gates (990-997) and 950_selfcheck entirely. Pre-push uses
# `make test` for the full suite.
if [ "${UNIT:-0}" != "1" ]; then
p2par_start=$(date +%s.%N)
# Phase 2 is partitioned (#3): the pure-reader byte-id gates run in
# parallel; the source-tree writers run in a serial tail afterward.
#
@@ -89,7 +104,9 @@ if [ "${UNIT:-0}" != "1" ]; then
name=${t##*/}; name=${name%.c}
printf '%s/%s\0%s\0' "$RESULTS" "$name" "$t"
done | xargs -0 -n2 -P "$JOBS" "$0" --one || true
p2par_end=$(date +%s.%N)
p2ser_start=$(date +%s.%N)
# SERIAL TAIL — 993/995/950, the only source-tree writers. 993 & 995
# both write cmd/wwdump/main.* (995 writes all 5 cmd/*/main.*), so they
# run sequentially w.r.t. each other AND after the parallel group, so
@@ -99,6 +116,7 @@ if [ "${UNIT:-0}" != "1" ]; then
name=${t##*/}; name=${name%.c}
"$0" --one "$RESULTS/$name" "$t" || true
done
p2ser_end=$(date +%s.%N)
# combined.ww freshness gate (#110): 990/995 above unconditionally
# regenerate every tracked combined.ww amalgamation, so a diff vs HEAD
@@ -138,6 +156,26 @@ if [ -d test/lang ]; then
done
fi
# ---- timing (task #10 baseline) -----------------------------------------
# Per-test durations + phase walls. Emitted after the per-test ok/FAIL dump
# but before the summary line's exit checks, so timing prints even on the
# failure path; the "all N tests passed" summary stays the last line. No log
# consumer is disturbed: the "---" delimiters and "<sec>\t<name>" rows match
# neither the "all N tests passed" nor the "FAIL" grep keys.
run_end=$(date +%s.%N)
echo '--- timing: per-test (sec, desc) ---'
cat "$RESULTS"/*.dur 2>/dev/null | sort -rn
echo '--- timing: phase walls (sec) ---'
awk -v rs="$run_start" -v p1e="$p1_end" \
-v ppar_s="$p2par_start" -v ppar_e="$p2par_end" \
-v pser_s="$p2ser_start" -v pser_e="$p2ser_end" \
-v re="$run_end" 'BEGIN{
printf "phase1_parallel\t%.3f\n", p1e - rs
if (ppar_e != "") printf "phase2_parallel\t%.3f\n", ppar_e - ppar_s
if (pser_e != "") printf "phase2_serial_tail\t%.3f\n", pser_e - pser_s
printf "total\t%.3f\n", re - rs
}'
if [ $ran -eq 0 ]; then
echo "no tests were run"
exit 1