From d2ac3312277a297daca25e972323974fd9c8ed57 Mon Sep 17 00:00:00 2001 From: ZhuchkaTriplesix Date: Fri, 9 Oct 2026 17:01:51 +0300 Subject: [PATCH] ci(bench): compare the Dart build time over three interleaved runs per side (#1132) The grid benchmark compared one run per side on FrameTiming.totalSpan, which includes vsync wait and software rasterising on a shared VM, so the base itself moved by 40% between runs and PRs that did not touch the grid got regression comments. - Three runs per side, interleaved (base, PR, ...); medians are compared. - Only build p50 / p90 flag a regression: worse by more than 10% and 0.2 ms, and slower in every pair. Raster, total and stutters stay in the table as information. - Stutters count gaps over 25 ms (a missed vsync at 60 Hz under xvfb). - Unit tests for the comparator run in CI. --- .github/workflows/benchmark.yml | 50 ++++++---- .github/workflows/ci.yml | 3 + benchmark/grid_perf_bench.dart | 6 +- scripts/ci/bench_compare.py | 160 +++++++++++++++++++++++-------- scripts/ci/test_bench_compare.py | 128 +++++++++++++++++++++++++ 5 files changed, 285 insertions(+), 62 deletions(-) create mode 100644 scripts/ci/test_bench_compare.py diff --git a/.github/workflows/benchmark.yml b/.github/workflows/benchmark.yml index e9347379..176d43bc 100644 --- a/.github/workflows/benchmark.yml +++ b/.github/workflows/benchmark.yml @@ -1,8 +1,9 @@ name: Benchmark # Informational: compares frame timings of benchmark/grid_perf_bench.dart on the -# PR against its base branch and comments when the PR is >5% slower. Never -# blocks a merge. +# PR against its base branch, three interleaved runs per side, and comments when +# the Dart build time is slower in every pair (scripts/ci/bench_compare.py). +# Never blocks a merge. on: pull_request: @@ -30,7 +31,7 @@ jobs: # Forks get no write token and must never reach any self-hosted runner. if: github.event_name != 'pull_request' || github.event.pull_request.head.repo.full_name == github.repository runs-on: ubuntu-latest - timeout-minutes: 45 + timeout-minutes: 75 continue-on-error: true steps: - uses: actions/checkout@v4 @@ -49,31 +50,40 @@ jobs: channel: 'stable' cache: true - - name: Run benchmark on PR head - timeout-minutes: 15 + - name: Prepare the PR and the base checkouts run: | flutter pub get - xvfb-run -a -s '-screen 0 1920x1080x24' flutter run --profile -d linux \ - -t benchmark/grid_perf_bench.dart --dart-define=MODE=scroll \ - 2>&1 | tee "$RUNNER_TEMP/head.log" || true + if [ "${{ github.event_name }}" = "pull_request" ]; then + git worktree add "$RUNNER_TEMP/base" "origin/${{ github.base_ref }}" + # The base runs the PR's benchmark, so both sides measure the same thing. + rm -rf "$RUNNER_TEMP/base/benchmark" + cp -r benchmark "$RUNNER_TEMP/base/benchmark" + (cd "$RUNNER_TEMP/base" && flutter pub get) + fi - - name: Run benchmark on base - if: github.event_name == 'pull_request' - timeout-minutes: 15 + # Base and PR alternate (base, PR, base, PR, base, PR), so a slow + # stretch of the shared runner lands on both sides. + - name: Run the benchmark, 3 interleaved runs per side + timeout-minutes: 40 run: | - git worktree add "$RUNNER_TEMP/base" "origin/${{ github.base_ref }}" - rm -rf "$RUNNER_TEMP/base/benchmark" - cp -r benchmark "$RUNNER_TEMP/base/benchmark" - cd "$RUNNER_TEMP/base" - flutter pub get - xvfb-run -a -s '-screen 0 1920x1080x24' flutter run --profile -d linux \ - -t benchmark/grid_perf_bench.dart --dart-define=MODE=scroll \ - 2>&1 | tee "$RUNNER_TEMP/base.log" || true + bench() { + (cd "$1" && xvfb-run -a -s '-screen 0 1920x1080x24' flutter run --profile -d linux \ + -t benchmark/grid_perf_bench.dart --dart-define=MODE=scroll \ + 2>&1 | tee "$2") || true + } + for i in 1 2 3; do + if [ "${{ github.event_name }}" = "pull_request" ]; then + bench "$RUNNER_TEMP/base" "$RUNNER_TEMP/base$i.log" + fi + bench "$GITHUB_WORKSPACE" "$RUNNER_TEMP/head$i.log" + done - name: Compare id: compare run: | - python3 scripts/ci/bench_compare.py "$RUNNER_TEMP/base.log" "$RUNNER_TEMP/head.log" 5 > "$RUNNER_TEMP/report.txt" + python3 scripts/ci/bench_compare.py \ + --base "$RUNNER_TEMP"/base*.log --head "$RUNNER_TEMP"/head*.log \ + > "$RUNNER_TEMP/report.txt" cat "$RUNNER_TEMP/report.txt" echo "regression=$(head -1 "$RUNNER_TEMP/report.txt" | cut -d= -f2)" >> "$GITHUB_OUTPUT" tail -n +2 "$RUNNER_TEMP/report.txt" > "$RUNNER_TEMP/report.md" diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index eb7ae37d..022c66ee 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -137,6 +137,9 @@ jobs: - name: Analyze code run: flutter analyze + - name: Test the benchmark comparison script + run: python3 scripts/ci/test_bench_compare.py + # packages/ is excluded above: the bridge is its own dependency-free # package and must keep compiling to a single static binary. - name: Analyze and build querya-mcp diff --git a/benchmark/grid_perf_bench.dart b/benchmark/grid_perf_bench.dart index fd85490a..0bd3c3c0 100644 --- a/benchmark/grid_perf_bench.dart +++ b/benchmark/grid_perf_bench.dart @@ -248,15 +248,17 @@ void _report() { stdout.writeln('BENCH ${row('raster', raster)}'); stdout.writeln('BENCH ${row('total ', total)}'); // Real smoothness: gap between consecutive presented frames. At 120 Hz a gap - // above ~12.5 ms means at least one vsync was missed (a visible stutter). + // above ~12.5 ms means at least one vsync was missed (a visible stutter); at + // 60 Hz (xvfb in CI) the same holds above 25 ms. final starts = [for (final t in timings) t.timestampInMicroseconds(FramePhase.vsyncStart)]..sort(); final gaps = [for (var i = 1; i < starts.length; i++) (starts[i] - starts[i - 1]) / 1000.0]; if (gaps.isNotEmpty) { final missed = gaps.where((g) => g > 12.5).length; + final missed60 = gaps.where((g) => g > 25).length; final secs = (starts.last - starts.first) / 1e6; stdout.writeln('BENCH frames: ${timings.length} in ${secs.toStringAsFixed(1)} s = ${(timings.length / secs).toStringAsFixed(0)} fps, ' 'gap p50=${pct(gaps, .5).toStringAsFixed(2)} p99=${pct(gaps, .99).toStringAsFixed(2)} max=${pct(gaps, 1).toStringAsFixed(1)} ms, ' - 'stutters(>12.5ms)=$missed'); + 'stutters(>12.5ms)=$missed stutters(>25ms)=$missed60'); } } diff --git a/scripts/ci/bench_compare.py b/scripts/ci/bench_compare.py index 17522511..ddcfd039 100644 --- a/scripts/ci/bench_compare.py +++ b/scripts/ci/bench_compare.py @@ -1,57 +1,137 @@ #!/usr/bin/env python3 -"""Compare two grid_perf_bench logs and print a Markdown report. +"""Compare grid_perf_bench logs of the base branch and of a PR. -usage: bench_compare.py BASE.log HEAD.log [threshold_percent] +usage: bench_compare.py --base B1.log [B2.log ...] --head H1.log [H2.log ...] + [--threshold PERCENT] [--min-ms MS] -Reads the `BENCH total p50=.. p90=.. p99=..` line of each log. Always exits 0: -the report is informational. The first output line is `REGRESSION=1` or -`REGRESSION=0` so a workflow can decide whether to comment. +Each log holds the `BENCH build|raster|total p50=.. p90=.. p99=..` lines of one +run. Runs are paired in order (base 1 with PR 1, ...), as the workflow runs +them interleaved, so a runner spike hits both sides. + +Only the Dart side decides: `build` p50 and p90. A metric regresses when the +median of the PR runs is worse than the median of the base runs by more than +--threshold percent (default 10) and --min-ms (default 0.2), and the PR is +slower in every pair. raster and total (software rendering, vsync wait) and +the stutter count stay in the table as information. + +Always exits 0: the report is informational. The first output line is +`REGRESSION=1` or `REGRESSION=0` so a workflow can decide whether to comment. """ +import argparse import re -import sys +import statistics + +_ROW = re.compile( + r"BENCH (build|raster|total)\s+p50=([\d.]+)\s+p90=([\d.]+)\s+p99=([\d.]+)") +_STUTTERS = re.compile(r"stutters\(>25ms\)=(\d+)") + +# (metric, flagged): flagged metrics can raise a regression. +METRICS = [ + ("build p50", True), + ("build p90", True), + ("build p99", False), + ("raster p50", False), + ("total p50", False), + ("total p99", False), + ("stutters", False), +] + +FLAGGED = {key for key, flagged in METRICS if flagged} -def parse(path): + +def parse(text): + """Metrics of one run, e.g. {'build p50': 0.45, 'stutters': 3.0}.""" metrics = {} - try: - text = open(path, encoding="utf-8", errors="replace").read() - except OSError: - return metrics - m = re.search(r"BENCH total\s+p50=([\d.]+)\s+p90=([\d.]+)\s+p99=([\d.]+)", text) - if m: - metrics = {"p50": float(m[1]), "p90": float(m[2]), "p99": float(m[3])} - s = re.search(r"stutters\(>12\.5ms\)=(\d+)", text) + for kind, p50, p90, p99 in _ROW.findall(text): + metrics[f"{kind} p50"] = float(p50) + metrics[f"{kind} p90"] = float(p90) + metrics[f"{kind} p99"] = float(p99) + s = _STUTTERS.search(text) if s: metrics["stutters"] = float(s[1]) return metrics -def main(): - base, head = parse(sys.argv[1]), parse(sys.argv[2]) - threshold = float(sys.argv[3]) if len(sys.argv) > 3 else 5.0 - if not base or not head: - print("REGRESSION=0") - print("Benchmark produced no comparable output (base or head log has no `BENCH total` line).") - return +def read(path): + try: + with open(path, encoding="utf-8", errors="replace") as f: + return parse(f.read()) + except OSError: + return {} + + +def compare(base_runs, head_runs, threshold=10.0, min_ms=0.2): + """Rows (metric, base median, PR median, change %, regressed) and the verdict. + + Runs without output are dropped; pairs are kept in order up to the shorter + side. + """ + base_runs = [r for r in base_runs if r] + head_runs = [r for r in head_runs if r] + if not base_runs or not head_runs: + return [], False + pairs = list(zip(base_runs, head_runs)) rows, regressed = [], False - for key in ("p50", "p90", "p99", "stutters"): - if key not in base or key not in head: + for key, flagged in METRICS: + b_vals = [r[key] for r in base_runs if key in r] + h_vals = [r[key] for r in head_runs if key in r] + if not b_vals or not h_vals: continue - b, h = base[key], head[key] - delta = (h - b) / b * 100 if b else (0.0 if h == 0 else 100.0) - # Tiny absolute differences are noise on a shared runner. - worse = delta > threshold and (h - b) > (0.3 if key != "stutters" else 2) + b, h = statistics.median(b_vals), statistics.median(h_vals) + change = (h - b) / b * 100 if b else (0.0 if h == 0 else 100.0) + worse = False + if flagged: + slower_everywhere = all( + hr[key] > br[key] for br, hr in pairs if key in br and key in hr) + worse = change > threshold and (h - b) > min_ms and slower_everywhere regressed = regressed or worse + rows.append((key, b, h, change, worse)) + return rows, regressed + + +def report(rows, regressed, runs, threshold, min_ms): + lines = [f"REGRESSION={1 if regressed else 0}"] + if not rows: + lines.append("Benchmark produced no comparable output " + "(no `BENCH build` line in the base or the PR logs).") + return "\n".join(lines) + lines += [ + "### Grid scroll benchmark", + "", + f"Median of {runs} interleaved runs per side.", + "", + "| metric | base | PR | change |", + "|---|---|---|---|", + ] + for key, b, h, change, worse in rows: unit = "" if key == "stutters" else " ms" - rows.append(f"| {key} | {b:.2f}{unit} | {h:.2f}{unit} | {delta:+.1f}% {'⚠️' if worse else ''} |") - print(f"REGRESSION={1 if regressed else 0}") - print("### Grid scroll benchmark") - print() - print("| metric | base | PR | change |") - print("|---|---|---|---|") - print("\n".join(rows)) - print() - print(f"Informational only (threshold {threshold:g}%). Shared CI runners are noisy; re-run before trusting a single result.") - - -main() + mark = " ⚠️" if worse else "" + info = "" if key in FLAGGED else " (info)" + lines.append(f"| {key}{info} | {b:.2f}{unit} | {h:.2f}{unit} | {change:+.1f}%{mark} |") + lines += [ + "", + f"Only `build` p50 / p90 can flag a regression: worse by more than " + f"{threshold:g}% and {min_ms:g} ms, and slower in every pair. Raster " + f"is software rendering on a shared runner; stutters count gaps over " + f"25 ms (a missed vsync at 60 Hz). Informational, never blocks a merge.", + ] + return "\n".join(lines) + + +def main(argv=None): + ap = argparse.ArgumentParser() + ap.add_argument("--base", nargs="+", required=True) + ap.add_argument("--head", nargs="+", required=True) + ap.add_argument("--threshold", type=float, default=10.0) + ap.add_argument("--min-ms", type=float, default=0.2) + args = ap.parse_args(argv) + base = [read(p) for p in args.base] + head = [read(p) for p in args.head] + rows, regressed = compare(base, head, args.threshold, args.min_ms) + runs = min(len([r for r in base if r]), len([r for r in head if r])) + print(report(rows, regressed, runs, args.threshold, args.min_ms)) + + +if __name__ == "__main__": + main() diff --git a/scripts/ci/test_bench_compare.py b/scripts/ci/test_bench_compare.py new file mode 100644 index 00000000..c6bc6a7d --- /dev/null +++ b/scripts/ci/test_bench_compare.py @@ -0,0 +1,128 @@ +#!/usr/bin/env python3 +"""Tests for bench_compare.py (#1132). Run: python3 scripts/ci/test_bench_compare.py""" +import io +import os +import sys +import tempfile +import unittest +from contextlib import redirect_stdout + +sys.path.insert(0, os.path.dirname(__file__)) +import bench_compare as bc # noqa: E402 + + +def log(build=(0.45, 0.60, 1.2), raster=(6.0, 9.0, 14.0), total=(11.0, 16.0, 30.0), + stutters=3): + lines = [ + "BENCH mode=scroll rows=50000 cols=12 frames=300", + f"BENCH build p50={build[0]:.2f} p90={build[1]:.2f} p99={build[2]:.2f} max=2.00 over8.33ms=0/300", + f"BENCH raster p50={raster[0]:.2f} p90={raster[1]:.2f} p99={raster[2]:.2f} max=20.00 over8.33ms=9/300", + f"BENCH total p50={total[0]:.2f} p90={total[1]:.2f} p99={total[2]:.2f} max=40.00 over8.33ms=290/300", + ] + if stutters is not None: + lines.append( + "BENCH frames: 300 in 5.0 s = 60 fps, gap p50=16.67 p99=33.00 max=40.0 ms, " + f"stutters(>12.5ms)=290 stutters(>25ms)={stutters}") + return "\n".join(lines) + + +def runs(*texts): + return [bc.parse(t) for t in texts] + + +class ParseTest(unittest.TestCase): + def test_reads_build_raster_total_and_60hz_stutters(self): + m = bc.parse(log()) + self.assertEqual(m["build p50"], 0.45) + self.assertEqual(m["build p90"], 0.60) + self.assertEqual(m["raster p50"], 6.0) + self.assertEqual(m["total p99"], 30.0) + self.assertEqual(m["stutters"], 3) + + def test_120hz_stutter_count_is_not_used(self): + self.assertNotIn("stutters", bc.parse(log(stutters=None))) + + def test_no_bench_lines_gives_nothing(self): + self.assertEqual(bc.parse("flutter crashed"), {}) + + +class CompareTest(unittest.TestCase): + def verdict(self, base, head, **kw): + return bc.compare(runs(*base), runs(*head), **kw)[1] + + def test_slower_build_in_every_pair_is_a_regression(self): + base = [log(build=(0.45, 0.60, 1.0))] * 3 + head = [log(build=(0.80, 1.00, 1.5))] * 3 + self.assertTrue(self.verdict(base, head)) + + def test_one_slow_pair_out_of_three_is_noise(self): + base = [log(build=(0.45, 0.60, 1.0))] * 3 + head = [log(build=(0.80, 1.00, 1.5)), + log(build=(0.80, 1.00, 1.5)), + log(build=(0.40, 0.55, 1.0))] + self.assertFalse(self.verdict(base, head)) + + def test_raster_and_total_never_flag(self): + # The #1131 case: total p50 and p99 moved, build did not. + base = [log(total=(15.75, 20.0, 30.0))] * 3 + head = [log(total=(16.78, 22.0, 35.4))] * 3 + rows, regressed = bc.compare(runs(*base), runs(*head)) + self.assertFalse(regressed) + total = [r for r in rows if r[0] == "total p50"][0] + self.assertFalse(total[4]) + + def test_small_absolute_change_is_not_a_regression(self): + # +20% but only +0.09 ms. + base = [log(build=(0.45, 0.60, 1.0))] * 3 + head = [log(build=(0.54, 0.70, 1.0))] * 3 + self.assertFalse(self.verdict(base, head)) + + def test_under_threshold_is_not_a_regression(self): + base = [log(build=(4.0, 5.0, 6.0))] * 3 + head = [log(build=(4.3, 5.4, 6.0))] * 3 # +7.5%, +8% + self.assertFalse(self.verdict(base, head)) + + def test_medians_ignore_one_outlier_run(self): + base = [log(build=(0.45, 0.60, 1.0)), log(build=(5.0, 6.0, 9.0)), + log(build=(0.46, 0.61, 1.0))] + head = [log(build=(0.47, 0.62, 1.0))] * 3 + rows, _ = bc.compare(runs(*base), runs(*head)) + b50 = [r for r in rows if r[0] == "build p50"][0] + self.assertEqual(b50[1], 0.46) + + def test_a_missing_side_gives_no_rows(self): + rows, regressed = bc.compare(runs(log()), [{}]) + self.assertEqual(rows, []) + self.assertFalse(regressed) + + +class ReportTest(unittest.TestCase): + def test_first_line_is_the_verdict_and_info_rows_are_marked(self): + rows, regressed = bc.compare(runs(log()), runs(log())) + text = bc.report(rows, regressed, 1, 10, 0.2) + self.assertTrue(text.startswith("REGRESSION=0\n")) + self.assertIn("| build p50 |", text) + self.assertIn("| raster p50 (info) |", text) + self.assertIn("| stutters (info) |", text) + + def test_main_reads_log_files(self): + with tempfile.TemporaryDirectory() as d: + paths = {} + for name, text in {"b": log(), "h": log(build=(0.9, 1.2, 2.0))}.items(): + paths[name] = os.path.join(d, name + ".log") + with open(paths[name], "w", encoding="utf-8") as f: + f.write(text) + out = io.StringIO() + with redirect_stdout(out): + bc.main(["--base", paths["b"], "--head", paths["h"]]) + self.assertTrue(out.getvalue().startswith("REGRESSION=1")) + + def test_missing_logs_report_no_output(self): + out = io.StringIO() + with redirect_stdout(out): + bc.main(["--base", "/nonexistent/a.log", "--head", "/nonexistent/b.log"]) + self.assertIn("no comparable output", out.getvalue()) + + +if __name__ == "__main__": + unittest.main()