diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index ad770320803..0cfbc2aee6f 100644 --- a/.github/workflows/docker.yml +++ b/.github/workflows/docker.yml @@ -144,12 +144,52 @@ jobs: OPENAI_API_KEY: "" NOUS_API_KEY: "" # Profile every docker subprocess call so we can diagnose why - # the suite is slow on CI vs. local. The report is uploaded - # as an artifact below. + # the suite is slow on CI vs. local. Each per-file subprocess + # writes its own docker-test-profile-.json; the merge + # step below combines them into a single report. HERMES_DOCKER_TEST_PROFILE: "1" run: | scripts/run_tests.sh tests/docker/ --file-timeout 600 + - name: Merge docker test profiles + if: always() + run: | + python3 -c " + import json, glob, sys + files = sorted(glob.glob('docker-test-profile-*.json')) + if not files: + print('No per-PID profile files found — profiling may not have activated') + sys.exit(0) + merged = {'tests': [], 'summary': {}} + for f in files: + with open(f) as fh: + data = json.load(fh) + merged['tests'].extend(data.get('tests', [])) + # Recompute summary aggregates from merged tests. + subcmd_totals = {} + subcmd_counts = {} + for t in merged['tests']: + for sub, info in t.get('by_subcommand', {}).items(): + subcmd_totals[sub] = subcmd_totals.get(sub, 0) + info['total_s'] + subcmd_counts[sub] = subcmd_counts.get(sub, 0) + info['count'] + merged['summary'] = { + 'total_tests': len(merged['tests']), + 'total_calls': sum(subcmd_counts.values()), + 'total_docker_s': round(sum(subcmd_totals.values()), 3), + 'by_subcommand': { + sub: { + 'count': subcmd_counts[sub], + 'total_s': round(subcmd_totals[sub], 3), + 'avg_s': round(subcmd_totals[sub] / subcmd_counts[sub], 3) if subcmd_counts[sub] else 0, + } + for sub in sorted(subcmd_totals, key=lambda s: subcmd_totals[s], reverse=True) + }, + } + with open('docker-test-profile.json', 'w') as fh: + json.dump(merged, fh, indent=2) + print(f'Merged {len(files)} per-PID profiles ({len(merged[\"tests\"])} tests)') + " + - name: Upload docker test profile if: always() uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7 diff --git a/scripts/run_tests.sh b/scripts/run_tests.sh index 7db931f521d..c380a196e28 100755 --- a/scripts/run_tests.sh +++ b/scripts/run_tests.sh @@ -88,6 +88,8 @@ exec env -i \ LC_ALL=C.UTF-8 \ PYTHONHASHSEED=0 \ ${HERMES_RUN_SLOW_PET_TESTS:+HERMES_RUN_SLOW_PET_TESTS="$HERMES_RUN_SLOW_PET_TESTS"} \ + ${HERMES_DOCKER_TEST_PROFILE:+HERMES_DOCKER_TEST_PROFILE="$HERMES_DOCKER_TEST_PROFILE"} \ + ${HERMES_DOCKER_PROFILE_OUT:+HERMES_DOCKER_PROFILE_OUT="$HERMES_DOCKER_PROFILE_OUT"} \ ${EXTRA_PYTHONPATH:+PYTHONPATH="$EXTRA_PYTHONPATH"} \ ${EXTRA_PYTEST_PLUGINS:+PYTEST_PLUGINS="$EXTRA_PYTEST_PLUGINS"} \ "$PYTHON" "$SCRIPT_DIR/run_tests_parallel.py" "$@" diff --git a/tests/docker/profiling.py b/tests/docker/profiling.py index b8ed2742bef..952a020f21e 100644 --- a/tests/docker/profiling.py +++ b/tests/docker/profiling.py @@ -7,7 +7,9 @@ which docker operations dominate the slow CI runs. Outputs: - JSON report at ``$HERMES_DOCKER_PROFILE_OUT`` (default: - ``docker-test-profile.json`` in the repo root). + ``docker-test-profile-{pid}.json`` in the repo root — per-PID + because run_tests_parallel.py spawns each test file in its own + subprocess). - Console summary on stderr at session end. The plugin is a no-op when the env var is not set — zero overhead on @@ -62,7 +64,6 @@ class TestProfile: """Group calls by the first docker subcommand (run, exec, restart, ...).""" groups: dict[str, list[DockerCall]] = defaultdict(list) for c in self.calls: - # argv[0] = "docker", argv[1] = subcommand sub = c.argv[1] if len(c.argv) > 1 else "?" groups[sub].append(c) return groups @@ -131,8 +132,8 @@ class ProfileCollector: subprocess.run = self._original_run self._patched = False - def write_report(self, out_path: Path) -> None: - """Write the JSON report.""" + def build_report(self) -> dict[str, Any]: + """Build the JSON-serializable report dict.""" report: dict[str, Any] = { "tests": [], "summary": {}, @@ -142,12 +143,12 @@ class ProfileCollector: subcmd_totals: dict[str, float] = defaultdict(float) subcmd_counts: dict[str, int] = defaultdict(int) - for name, tp in sorted( + for _name, tp in sorted( self.tests.items(), key=lambda x: x[1].total_docker_s, reverse=True ): by_sub = tp.by_subcommand() test_entry: dict[str, Any] = { - "name": name, + "name": tp.name, "total_docker_s": round(tp.total_docker_s, 3), "call_count": tp.call_count, "by_subcommand": { @@ -171,7 +172,7 @@ class ProfileCollector: }, "calls": [ { - "argv": " ".join(c.argv[:8]), # truncate long argv + "argv": " ".join(c.argv[:8]), "duration_s": c.duration_s, "returncode": c.returncode, } @@ -202,8 +203,13 @@ class ProfileCollector: ) }, } + return report - out_path.write_text(json.dumps(report, indent=2) + "\n") + def write_report(self, out_path: Path) -> None: + """Write the JSON report.""" + out_path.write_text( + json.dumps(self.build_report(), indent=2) + "\n" + ) def print_summary(self) -> None: """Print a human-readable summary to stderr.""" @@ -215,7 +221,6 @@ class ProfileCollector: print("[docker-profile] Docker operation timing breakdown", file=sys.stderr) print("=" * 72, file=sys.stderr) - # Summary by subcommand subcmd_totals: dict[str, float] = defaultdict(float) subcmd_counts: dict[str, int] = defaultdict(int) for tp in self.tests.values(): @@ -225,7 +230,8 @@ class ProfileCollector: total = sum(subcmd_totals.values()) print( - f"\n Total docker time: {total:.1f}s across {sum(subcmd_counts.values())} calls\n", + f"\n Total docker time: {total:.1f}s across" + f" {sum(subcmd_counts.values())} calls\n", file=sys.stderr, ) print( @@ -236,7 +242,9 @@ class ProfileCollector: f" {'─' * 15} {'─' * 8} {'─' * 10} {'─' * 8} {'─' * 6}", file=sys.stderr, ) - for sub in sorted(subcmd_totals, key=lambda s: subcmd_totals[s], reverse=True): + for sub in sorted( + subcmd_totals, key=lambda s: subcmd_totals[s], reverse=True + ): t = subcmd_totals[sub] n = subcmd_counts[sub] pct = (t / total * 100) if total else 0 @@ -245,7 +253,6 @@ class ProfileCollector: file=sys.stderr, ) - # Top 10 slowest tests print( f"\n Top 10 slowest tests (by docker operation time):\n", file=sys.stderr, @@ -255,7 +262,8 @@ class ProfileCollector: ) for i, tp in enumerate(sorted_tests[:10], 1): print( - f" {i:>2}. {tp.total_docker_s:>6.1f}s {tp.call_count:>3} calls {tp.name}", + f" {i:>2}. {tp.total_docker_s:>6.1f}s" + f" {tp.call_count:>3} calls {tp.name}", file=sys.stderr, ) by_sub = tp.by_subcommand() @@ -272,7 +280,6 @@ class ProfileCollector: file=sys.stderr, ) - # Slowest individual calls all_calls: list[tuple[str, DockerCall]] = [] for tp in self.tests.values(): for c in tp.calls: @@ -337,10 +344,11 @@ def pytest_sessionfinish(session, exitstatus): collector = _get_collector() collector.uninstall_patch() - out = os.environ.get( - "HERMES_DOCKER_PROFILE_OUT", - str(Path.cwd() / "docker-test-profile.json"), - ) + # Default to a per-PID filename so parallel subprocesses (one per + # test file, spawned by run_tests_parallel.py) don't clobber each + # other. The CI step merges them into a single report. + default_out = str(Path.cwd() / f"docker-test-profile-{os.getpid()}.json") + out = os.environ.get("HERMES_DOCKER_PROFILE_OUT", default_out) out_path = Path(out) collector.write_report(out_path) collector.print_summary()