From f940072623e972dbac64a78d5493d17cea44c5ed Mon Sep 17 00:00:00 2001
From: Hojun-Cho <ghwns6743@gmail.com>
Date: Wed, 10 Jun 2026 15:33:24 +0900
Subject: [PATCH] test/run: per-test + per-phase wall-clock timing (test-perf
 step 0)
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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.
---
 test/run | 38 ++++++++++++++++++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/test/run b/test/run
index 208199d4..10713053 100755
--- a/test/run
+++ b/test/run
@@ -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