mirror of
https://github.com/NousResearch/hermes-agent.git
synced 2026-07-31 19:16:29 +00:00
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.
This commit is contained in:
ethernet
parent
ca6ede33e1
commit
3fc4e413d2
2 changed files with 133 additions and 64 deletions
|
|
@ -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)
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue