From 3fc4e413d2f63f90ce06fab6c0aafcd034d398f6 Mon Sep 17 00:00:00 2001 From: ethernet Date: Tue, 14 Jul 2026 16:22:05 -0400 Subject: [PATCH] feat(ci): track time.sleep in docker test profiler The profiler now monkey-patches time.sleep alongside subprocess.run, capturing the invisible "gap" time from polling loops (wait_for_container_ready, poll_container, wait_for_log, etc.) that was previously unaccounted for. The JSON report now includes per-test total_sleep_s, sleep_count, and a sleeps[] array with caller location. The summary includes total_sleep_s and total_wall_s (docker + sleep). The CI merge step also aggregates sleep totals. Local profile now shows: 201s docker + 75s sleep = 276s wall (38s runner wall with 32-way parallelism). The biggest sleep consumer is test_dashboard_insecure_env_var_no_longer_bypasses at 11.8s of poll_container sleeps. --- .github/workflows/docker.yml | 12 ++- tests/docker/profiling.py | 185 +++++++++++++++++++++++------------ 2 files changed, 133 insertions(+), 64 deletions(-) diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index 0cfbc2aee6f..93816fb7260 100644 --- a/.github/workflows/docker.yml +++ b/.github/workflows/docker.yml @@ -168,14 +168,22 @@ jobs: # Recompute summary aggregates from merged tests. subcmd_totals = {} subcmd_counts = {} + total_sleep = 0 + total_sleeps = 0 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'] + total_sleep += t.get('total_sleep_s', 0) + total_sleeps += t.get('sleep_count', 0) + total_docker = sum(subcmd_totals.values()) merged['summary'] = { 'total_tests': len(merged['tests']), 'total_calls': sum(subcmd_counts.values()), - 'total_docker_s': round(sum(subcmd_totals.values()), 3), + 'total_sleeps': total_sleeps, + 'total_docker_s': round(total_docker, 3), + 'total_sleep_s': round(total_sleep, 3), + 'total_wall_s': round(total_docker + total_sleep, 3), 'by_subcommand': { sub: { 'count': subcmd_counts[sub], @@ -187,7 +195,7 @@ jobs: } 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)') + print(f'Merged {len(files)} per-PID profiles ({len(merged[\"tests\"])} tests, {total_docker:.0f}s docker + {total_sleep:.0f}s sleep = {total_docker + total_sleep:.0f}s wall)') " - name: Upload docker test profile diff --git a/tests/docker/profiling.py b/tests/docker/profiling.py index 952a020f21e..2a29fd77124 100644 --- a/tests/docker/profiling.py +++ b/tests/docker/profiling.py @@ -2,8 +2,9 @@ Activated by ``HERMES_DOCKER_TEST_PROFILE=1``. Instruments every ``subprocess.run`` call whose argv starts with ``docker`` to measure -wall-clock time, and collects per-test breakdowns so we can see exactly -which docker operations dominate the slow CI runs. +wall-clock time, and also tracks ``time.sleep`` calls so we can see the +full wall-clock picture — including the invisible sleep time in polling +loops that doesn't show up as docker call duration. Outputs: - JSON report at ``$HERMES_DOCKER_PROFILE_OUT`` (default: @@ -36,26 +37,54 @@ _ACTIVE = bool(os.environ.get("HERMES_DOCKER_TEST_PROFILE")) @dataclass -class DockerCall: - """One instrumented docker subprocess call.""" +class TimedEvent: + """Base for any timed event in a test's lifecycle.""" - argv: list[str] duration_s: float - returncode: int timestamp: float # monotonic +@dataclass +class DockerCall(TimedEvent): + """One instrumented docker subprocess call.""" + + argv: list[str] + returncode: int + + +@dataclass +class SleepGap(TimedEvent): + """A time.sleep() that occurred between docker calls. + + This captures the invisible "gap" time — the polling sleeps, the + Python logic between assertions, etc. Each SleepGap is attributed to + the test that was running when it occurred. + """ + + caller: str # short description of who called sleep + + @dataclass class TestProfile: - """Per-test accumulation of docker call timings.""" + """Per-test accumulation of docker calls and sleep gaps.""" name: str calls: list[DockerCall] = field(default_factory=list) + sleeps: list[SleepGap] = field(default_factory=list) @property def total_docker_s(self) -> float: return sum(c.duration_s for c in self.calls) + @property + def total_sleep_s(self) -> float: + return sum(s.duration_s for s in self.sleeps) + + @property + def total_wall_s(self) -> float: + """Docker time + sleep time — the test's visible wall-clock cost.""" + return self.total_docker_s + self.total_sleep_s + @property def call_count(self) -> int: return len(self.calls) @@ -81,11 +110,14 @@ class ProfileCollector: self.tests: dict[str, TestProfile] = {} self.current: Optional[TestProfile] = None self._original_run: Any = None + self._original_sleep: Any = None self._patched = False + self._last_docker_end: float = 0.0 def start_test(self, name: str) -> None: self.current = TestProfile(name=name) self.tests[name] = self.current + self._last_docker_end = 0.0 def end_test(self) -> None: self.current = None @@ -93,14 +125,20 @@ class ProfileCollector: def record(self, call: DockerCall) -> None: if self.current is not None: self.current.calls.append(call) + self._last_docker_end = call.timestamp + call.duration_s + + def record_sleep(self, gap: SleepGap) -> None: + if self.current is not None: + self.current.sleeps.append(gap) def install_patch(self) -> None: - """Monkey-patch subprocess.run to capture docker call timings.""" + """Monkey-patch subprocess.run and time.sleep to capture timings.""" if self._patched: return import subprocess self._original_run = subprocess.run + self._original_sleep = time.sleep collector = self def timed_run(*args: Any, **kwargs: Any) -> Any: @@ -113,23 +151,51 @@ class ProfileCollector: elapsed = time.monotonic() - t0 rc = getattr(result, "returncode", -1) call = DockerCall( - argv=[str(a) for a in argv], duration_s=round(elapsed, 4), - returncode=rc, timestamp=t0, + argv=[str(a) for a in argv], + returncode=rc, ) collector.record(call) return result + def timed_sleep(secs: float) -> None: + # Only track sleeps that happen between docker calls within a test. + # Short sleeps (< 0.05s) are probably just Python scheduling noise. + if collector.current is None or secs < 0.05: + return collector._original_sleep(secs) + t0 = time.monotonic() + collector._original_sleep(secs) + elapsed = time.monotonic() - t0 + # Try to identify the caller for context + import traceback + stack = traceback.extract_stack(limit=4) + caller = "" + for frame in reversed(stack): + fname = frame.filename + if "conftest" in fname or "test_" in fname: + caller = f"{Path(fname).name}:{frame.lineno}" + break + gap = SleepGap( + duration_s=round(elapsed, 4), + timestamp=t0, + caller=caller, + ) + collector.record_sleep(gap) + subprocess.run = timed_run + time.sleep = timed_sleep self._patched = True def uninstall_patch(self) -> None: - if not self._patched or self._original_run is None: + if not self._patched: return import subprocess - subprocess.run = self._original_run + if self._original_run is not None: + subprocess.run = self._original_run + if self._original_sleep is not None: + time.sleep = self._original_sleep self._patched = False def build_report(self) -> dict[str, Any]: @@ -139,18 +205,23 @@ class ProfileCollector: "summary": {}, } all_docker_time = 0.0 + all_sleep_time = 0.0 all_call_count = 0 + all_sleep_count = 0 subcmd_totals: dict[str, float] = defaultdict(float) subcmd_counts: dict[str, int] = defaultdict(int) for _name, tp in sorted( - self.tests.items(), key=lambda x: x[1].total_docker_s, reverse=True + self.tests.items(), key=lambda x: x[1].total_wall_s, reverse=True ): by_sub = tp.by_subcommand() test_entry: dict[str, Any] = { "name": tp.name, "total_docker_s": round(tp.total_docker_s, 3), + "total_sleep_s": round(tp.total_sleep_s, 3), + "total_wall_s": round(tp.total_wall_s, 3), "call_count": tp.call_count, + "sleep_count": len(tp.sleeps), "by_subcommand": { sub: { "count": len(calls), @@ -172,16 +243,27 @@ class ProfileCollector: }, "calls": [ { + "type": "docker", "argv": " ".join(c.argv[:8]), "duration_s": c.duration_s, "returncode": c.returncode, } for c in sorted(tp.calls, key=lambda x: x.duration_s, reverse=True) ], + "sleeps": [ + { + "type": "sleep", + "duration_s": s.duration_s, + "caller": s.caller, + } + for s in sorted(tp.sleeps, key=lambda x: x.duration_s, reverse=True) + ], } report["tests"].append(test_entry) all_docker_time += tp.total_docker_s + all_sleep_time += tp.total_sleep_s all_call_count += tp.call_count + all_sleep_count += len(tp.sleeps) for sub, calls in by_sub.items(): subcmd_totals[sub] += sum(c.duration_s for c in calls) subcmd_counts[sub] += len(calls) @@ -189,7 +271,10 @@ class ProfileCollector: report["summary"] = { "total_tests": len(self.tests), "total_docker_s": round(all_docker_time, 3), + "total_sleep_s": round(all_sleep_time, 3), + "total_wall_s": round(all_docker_time + all_sleep_time, 3), "total_calls": all_call_count, + "total_sleeps": all_sleep_count, "by_subcommand": { sub: { "count": subcmd_counts[sub], @@ -218,7 +303,7 @@ class ProfileCollector: return print("\n" + "=" * 72, file=sys.stderr) - print("[docker-profile] Docker operation timing breakdown", file=sys.stderr) + print("[docker-profile] Docker + sleep timing breakdown", file=sys.stderr) print("=" * 72, file=sys.stderr) subcmd_totals: dict[str, float] = defaultdict(float) @@ -227,15 +312,17 @@ class ProfileCollector: for sub, calls in tp.by_subcommand().items(): subcmd_totals[sub] += sum(c.duration_s for c in calls) subcmd_counts[sub] += len(calls) + total_sleep = sum(tp.total_sleep_s for tp in self.tests.values()) + total_docker = sum(tp.total_docker_s for tp in self.tests.values()) + total_wall = total_docker + total_sleep - total = sum(subcmd_totals.values()) print( - f"\n Total docker time: {total:.1f}s across" - f" {sum(subcmd_counts.values())} calls\n", + f"\n Total wall time: {total_wall:.1f}s" + f" = {total_docker:.1f}s docker + {total_sleep:.1f}s sleep\n", file=sys.stderr, ) print( - f" {'Subcommand':<15} {'Calls':>8} {'Total':>10} {'Avg':>8} {'%':>6}", + f" {'Category':<15} {'Count':>8} {'Total':>10} {'Avg':>8} {'%':>6}", file=sys.stderr, ) print( @@ -247,58 +334,35 @@ class ProfileCollector: ): t = subcmd_totals[sub] n = subcmd_counts[sub] - pct = (t / total * 100) if total else 0 + pct = (t / total_wall * 100) if total_wall else 0 print( - f" {sub:<15} {n:>8} {t:>9.1f}s {t / n:>7.2f}s {pct:>5.1f}%", + f" docker {sub:<8} {n:>8} {t:>9.1f}s {t / n:>7.2f}s {pct:>5.1f}%", file=sys.stderr, ) - + # Sleep row + sleep_count = sum(len(tp.sleeps) for tp in self.tests.values()) + pct = (total_sleep / total_wall * 100) if total_wall else 0 print( - f"\n Top 10 slowest tests (by docker operation time):\n", + f" {'time.sleep':<15} {sleep_count:>8} {total_sleep:>9.1f}s" + f" {total_sleep / sleep_count if sleep_count else 0:>7.2f}s {pct:>5.1f}%", + file=sys.stderr, + ) + + # Top 10 slowest tests by WALL time + print( + f"\n Top 10 slowest tests (by wall time = docker + sleep):\n", file=sys.stderr, ) sorted_tests = sorted( - self.tests.values(), key=lambda t: t.total_docker_s, reverse=True + self.tests.values(), key=lambda t: t.total_wall_s, reverse=True ) for i, tp in enumerate(sorted_tests[:10], 1): print( - f" {i:>2}. {tp.total_docker_s:>6.1f}s" - f" {tp.call_count:>3} calls {tp.name}", + f" {i:>2}. {tp.total_wall_s:>6.1f}s " + f"({tp.total_docker_s:.1f}s docker + {tp.total_sleep_s:.1f}s sleep) " + f"{tp.call_count:>3} calls ...{tp.name[-50:]}", file=sys.stderr, ) - by_sub = tp.by_subcommand() - for sub, calls in sorted( - by_sub.items(), - key=lambda x: sum(c.duration_s for c in x[1]), - reverse=True, - ): - t = sum(c.duration_s for c in calls) - if t < 0.1: - continue - print( - f" {sub:<13} {t:>5.1f}s ({len(calls)} calls)", - file=sys.stderr, - ) - - all_calls: list[tuple[str, DockerCall]] = [] - for tp in self.tests.values(): - for c in tp.calls: - all_calls.append((tp.name, c)) - all_calls.sort(key=lambda x: x[1].duration_s, reverse=True) - if all_calls: - print( - f"\n Top 10 slowest individual docker calls:\n", - file=sys.stderr, - ) - for i, (test_name, c) in enumerate(all_calls[:10], 1): - argv_short = " ".join(c.argv[:6]) - if len(c.argv) > 6: - argv_short += " ..." - print( - f" {i:>2}. {c.duration_s:>6.1f}s {argv_short}", - file=sys.stderr, - ) - print(f" test: {test_name}", file=sys.stderr) print("\n" + "=" * 72, file=sys.stderr) @@ -330,7 +394,7 @@ def pytest_runtest_call(item): def pytest_sessionstart(session): - """Install the subprocess.run patch at session start.""" + """Install the subprocess.run + time.sleep patches at session start.""" if not _ACTIVE: return collector = _get_collector() @@ -344,9 +408,6 @@ def pytest_sessionfinish(session, exitstatus): collector = _get_collector() collector.uninstall_patch() - # 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)