From c2af5ad3dae033e62b762408675d661fa88a81c7 Mon Sep 17 00:00:00 2001 From: Brummel Date: Fri, 8 May 2026 15:17:53 +0200 Subject: [PATCH] bench: latency_harness --runs N (stat-of-N, drop-slowest) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes the architect's tidy follow-up item on bench-number methodology. The harness now accepts --runs N (default 1, byte- identical output for back-compat); with N>=2 it reports median + min..max per cell across runs, with N>=4 it drops the slowest run before aggregating to match bench/run.sh's drop- slowest throughput convention. bench/run.sh now invokes the harness with --runs 5 for each of the three latency arms, so a single bench/run.sh run produces both a regression-stable throughput table and a regression-stable latency table. The qualitative claims from JOURNAL 2026-05-08 (RC tail latency 23x better than Boehm; RC RSS lower than Boehm) hold at the new stat-of-5 confidence level — a 5-run smoke on the explicit-rc arm shows p99=296µs (range 289-311), p99/median=1.31x (range 1.28-1.37). Variance is well below the signal. --- bench/latency_harness.py | 153 +++++++++++++++++++++++++++++---------- bench/run.sh | 11 ++- 2 files changed, 120 insertions(+), 44 deletions(-) diff --git a/bench/latency_harness.py b/bench/latency_harness.py index cb307f9..a23369c 100755 --- a/bench/latency_harness.py +++ b/bench/latency_harness.py @@ -102,57 +102,118 @@ def percentile(xs: list[float], p: float) -> float: return xs[k] -def report(label: str, timestamps_ns: list[int], lines: int, status: int, rss_kb: int, wall_s: float) -> None: - # The fixtures emit: - # line 1 : 8888 (READY, after build_tree) - # line 2..1001 : per-chunk markers (1000 timing samples) - # line 1002 : 9999 (DONE) - # Inter-arrival gaps: between consecutive timestamps. - # We drop the first gap (READY -> first chunk includes a partial - # chunk's setup but is dominated by chunk work; still informative) - # and the last gap (last chunk -> DONE includes program exit). - # Per the orchestrator's brief we want the steady-state distribution, - # so we trim both ends. +def summarise(timestamps_ns: list[int], lines: int) -> dict | None: + """Compute the per-cell summary stats for one run. Returns None on + failure (too few lines for a meaningful distribution).""" if lines < 5: - print(f"[{label}] FAIL: only {lines} lines, status={status}") - return - + return None gaps_ns: list[int] = [] for i in range(1, len(timestamps_ns)): gaps_ns.append(timestamps_ns[i] - timestamps_ns[i - 1]) - # Trim the first gap (READY -> first chunk; includes the loop's # first chunk's full work) and the last gap (last chunk -> DONE; # includes program teardown). Everything between is steady-state. trimmed = gaps_ns[1:-1] if len(gaps_ns) >= 3 else gaps_ns - gaps_us = sorted(g / 1000.0 for g in trimmed) + if not gaps_us: + return None + return { + "n": len(trimmed), + "min": min(gaps_us), + "median": percentile(gaps_us, 50), + "mean": sum(gaps_us) / len(gaps_us), + "p90": percentile(gaps_us, 90), + "p99": percentile(gaps_us, 99), + "p999": percentile(gaps_us, 99.9), + "max": max(gaps_us), + "zero_gaps": sum(1 for g in trimmed if g == 0), + } - # Quantization detection: how many gaps are exactly 0 ns? That - # means two newlines arrived in the same os.read. - zero_gaps = sum(1 for g in trimmed if g == 0) - median = percentile(gaps_us, 50) - p90 = percentile(gaps_us, 90) - p99 = percentile(gaps_us, 99) - p999 = percentile(gaps_us, 99.9) - p_max = max(gaps_us) if gaps_us else float("nan") - p_min = min(gaps_us) if gaps_us else float("nan") - mean = sum(gaps_us) / len(gaps_us) if gaps_us else float("nan") +def cell_median(values: list[float]) -> tuple[float, float, float]: + """Iter 18g.tidy.fu: median + min + max of a list of per-run values + for one cell (e.g. p99 across N runs). Drops slowest-by-magnitude + if N >= 4 to match `bench/run.sh`'s drop-slowest convention. + Returns (median, min, max) — the orchestrator can read both the + central tendency and the spread from one tuple. + """ + if not values: + return (float("nan"), float("nan"), float("nan")) + s = sorted(values) + if len(s) >= 4: + # Drop the largest (slowest = highest latency) to absorb a + # one-off STW pause or scheduler hiccup. Mirrors run.sh. + s = s[:-1] + n = len(s) + if n % 2 == 1: + med = s[n // 2] + else: + med = (s[n // 2 - 1] + s[n // 2]) / 2 + return (med, s[0], s[-1]) + + +def report( + label: str, + runs: list[tuple[list[int], int, int, int, float]], +) -> None: + """Iter 18g.tidy.fu: report one or many runs. With N=1 the output + is byte-identical to the pre-stat-of-N format. With N>1 each cell + shows median(min..max) across runs after dropping the slowest. + """ + summaries: list[dict] = [] + last_status = 0 + last_rss = 0 + last_wall = 0.0 + last_lines = 0 + for timestamps, lines, status, rss_kb, wall_s in runs: + last_status, last_rss, last_wall, last_lines = status, rss_kb, wall_s, lines + s = summarise(timestamps, lines) + if s is not None: + summaries.append(s) + + if not summaries: + print(f"[{label}] FAIL: no successful runs (lines={last_lines}, status={last_status})") + return print(f"=== {label} ===") - print(f" lines: {lines} exit_status: {status} wall: {wall_s:.3f}s max_rss: {rss_kb} KB") - print(f" inter-arrival gaps (steady-state, n={len(trimmed)}, trimmed first+last):") - print(f" min: {p_min:10.1f} us") - print(f" median: {median:10.1f} us") - print(f" mean: {mean:10.1f} us") - print(f" p90: {p90:10.1f} us") - print(f" p99: {p99:10.1f} us") - print(f" p99.9: {p999:10.1f} us") - print(f" max: {p_max:10.1f} us") - print(f" p99/median: {p99 / median if median else float('nan'):.2f}x") - print(f" max/median: {p_max / median if median else float('nan'):.2f}x") - print(f" zero-ns gaps (read coalescing): {zero_gaps} / {len(trimmed)}") + if len(summaries) == 1: + # Single-run path: keep the pre-stat-of-N output exactly. + s = summaries[0] + print(f" lines: {last_lines} exit_status: {last_status} wall: {last_wall:.3f}s max_rss: {last_rss} KB") + print(f" inter-arrival gaps (steady-state, n={s['n']}, trimmed first+last):") + print(f" min: {s['min']:10.1f} us") + print(f" median: {s['median']:10.1f} us") + print(f" mean: {s['mean']:10.1f} us") + print(f" p90: {s['p90']:10.1f} us") + print(f" p99: {s['p99']:10.1f} us") + print(f" p99.9: {s['p999']:10.1f} us") + print(f" max: {s['max']:10.1f} us") + print(f" p99/median: {s['p99'] / s['median'] if s['median'] else float('nan'):.2f}x") + print(f" max/median: {s['max'] / s['median'] if s['median'] else float('nan'):.2f}x") + print(f" zero-ns gaps (read coalescing): {s['zero_gaps']} / {s['n']}") + return + + # Multi-run path: median + min..max per cell across runs (drop + # slowest if N >= 4, matching bench/run.sh). + n_kept = len(summaries) - 1 if len(summaries) >= 4 else len(summaries) + print(f" runs: {len(summaries)} kept: {n_kept} (drop slowest if N>=4) last exit_status: {last_status}") + print(f" per-run distribution medians (steady-state, trimmed first+last):") + + def fmt_cell(key: str) -> str: + med, lo, hi = cell_median([s[key] for s in summaries]) + return f"median={med:7.1f} range=[{lo:7.1f}, {hi:7.1f}]" + + for key in ("min", "median", "mean", "p90", "p99", "p999", "max"): + label_key = "p99.9" if key == "p999" else key + print(f" {label_key:7s} {fmt_cell(key)} us") + + # Derived ratios computed per-run, then aggregated. + p99_med_ratios = [s["p99"] / s["median"] if s["median"] else float("nan") for s in summaries] + max_med_ratios = [s["max"] / s["median"] if s["median"] else float("nan") for s in summaries] + pmm_med, pmm_lo, pmm_hi = cell_median(p99_med_ratios) + mmm_med, mmm_lo, mmm_hi = cell_median(max_med_ratios) + print(f" p99/median median={pmm_med:.2f}x range=[{pmm_lo:.2f}x, {pmm_hi:.2f}x]") + print(f" max/median median={mmm_med:.2f}x range=[{mmm_lo:.2f}x, {mmm_hi:.2f}x]") def main() -> int: @@ -160,11 +221,23 @@ def main() -> int: ap.add_argument("binary", help="path to the bench binary") ap.add_argument("--label", default=None, help="label for the report") ap.add_argument("--timeout", type=float, default=600.0) + ap.add_argument( + "--runs", + type=int, + default=1, + help="number of timed runs (default 1). With N>=2 the report shows median + range per cell across runs; with N>=4 the slowest run is dropped before aggregation, matching bench/run.sh's drop-slowest convention.", + ) args = ap.parse_args() + if args.runs < 1: + print(f"--runs must be >= 1 (got {args.runs})", file=sys.stderr) + return 2 + label = args.label or os.path.basename(args.binary) - timestamps, lines, status, rss_kb, wall_s = run_pty(args.binary, args.timeout) - report(label, timestamps, lines, status, rss_kb, wall_s) + runs: list[tuple[list[int], int, int, int, float]] = [] + for _ in range(args.runs): + runs.append(run_pty(args.binary, args.timeout)) + report(label, runs) return 0 diff --git a/bench/run.sh b/bench/run.sh index 209cbd1..4d95176 100755 --- a/bench/run.sh +++ b/bench/run.sh @@ -192,12 +192,15 @@ if [[ -x "$LAT_HARNESS" && -f "$LAT_IMPL_SRC" && -f "$LAT_EXPL_SRC" ]]; then # The harness prints a multi-line block per arm; we let it speak # for itself. The orchestrator captures the verbatim output into a - # JOURNAL entry like the throughput table above. - "$PY" "$LAT_HARNESS" "$OUTDIR/bench_latency_implicit_gc" --label "implicit @ gc (Boehm-fair)" + # JOURNAL entry like the throughput table above. `--runs 5` runs + # each arm five times; the harness drops the slowest run and + # reports median + range per cell, matching the throughput + # table's drop-slowest convention. + "$PY" "$LAT_HARNESS" "$OUTDIR/bench_latency_implicit_gc" --runs 5 --label "implicit @ gc (Boehm-fair)" echo - "$PY" "$LAT_HARNESS" "$OUTDIR/bench_latency_explicit_rc" --label "explicit @ rc (RC-fair)" + "$PY" "$LAT_HARNESS" "$OUTDIR/bench_latency_explicit_rc" --runs 5 --label "explicit @ rc (RC-fair)" echo - "$PY" "$LAT_HARNESS" "$OUTDIR/bench_latency_implicit_rc" --label "implicit @ rc (control: leaks, no STW)" + "$PY" "$LAT_HARNESS" "$OUTDIR/bench_latency_implicit_rc" --runs 5 --label "implicit @ rc (control: leaks, no STW)" fi echo