Skip to content

Commit 9a5bfec

Browse files
Jammy2211claude
authored andcommitted
feat: unit_test_timing leg — off-tick slow-test regression tracking (#63)
Phase 4a of the hygiene perf mode (first of three original-prompt capabilities the shipped perf mode didn't cover). Tracks library unit-test durations over time and flags slow-test regressions, mirroring the import_time leg (#62). - heart/checks/unit_test_timing.py: runs `pytest --durations=N` per library in a SUBPROCESS (rule 4: Heart never imports the test stack; runner injected so the stdlib-only tests use fixtures). Parses the slowest-durations report, rolling per-test baseline (~/.pyauto-heart/timings-unit/), ratio classify (1.5/3.0), writes ~/.pyauto-heart/unit_test_timing.json + colored summary. OFF-TICK (suites take minutes → daily cron / on demand, NOT tick.sh). - heart/state.py + heart/dashboard.py: aggregate + advisory "Unit-test timing" section (local-only family); NOT in the readiness gating set (test speed is not release-blocking). - tests/test_unit_test_timing.py: 6 stdlib-only tests (injected runner) incl. a parser test against real pytest --durations output. Parser validated live against real pytest output. Full suite 257 pass. Follow-on (PyAutoBrain): hygiene perf reads unit_test_timing.json when present. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Tw3EwV55k6VzxorYng3Kfn
1 parent 08d5e17 commit 9a5bfec

4 files changed

Lines changed: 329 additions & 0 deletions

File tree

heart/checks/unit_test_timing.py

Lines changed: 217 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,217 @@
1+
"""heart/checks/unit_test_timing.py — track library unit-test durations, flag
2+
slow-test regressions.
3+
4+
OFF-TICK by design. Running the library suites costs minutes (test_autofit is
5+
~1500 tests), which does not fit the <30s watch-loop budget (``docs/internals.md``
6+
rule 3). Run on a slower cadence — a daily/weekly cron or on demand — and do
7+
**not** wire it into ``heart/tick.sh``:
8+
9+
python -m heart.checks.unit_test_timing
10+
HYGIENE_PYTHON=~/venv/PyAuto/bin/python python -m heart.checks.unit_test_timing
11+
12+
The suites run in a SUBPROCESS (``pytest --durations``) — Heart's own process
13+
never imports the test/science stack (rule 4) — and the runner is injected so
14+
the stdlib-only tests feed fixtures and never run pytest-in-pytest. Advisory:
15+
surfaced on the board but never a release gate (test speed is not release-blocking).
16+
17+
State: ~/.pyauto-heart/timings-unit/<slug>.json — rolling window per tracked test.
18+
Output: ~/.pyauto-heart/unit_test_timing.json — the latest regression summary.
19+
Classification (mirrors script_timing): ratio = latest / median(prior window);
20+
green <= yellow_factor (1.5), yellow <= red_factor (3.0), else red.
21+
"""
22+
23+
from __future__ import annotations
24+
25+
import json
26+
import os
27+
import re
28+
import statistics
29+
import subprocess
30+
import sys
31+
from pathlib import Path
32+
from typing import Any, Callable
33+
34+
import yaml
35+
36+
HEART_STATE_DIR = Path(
37+
os.environ.get("HEART_STATE_DIR")
38+
or Path.home() / ".pyauto-heart"
39+
)
40+
HEART_UNIT_TIMINGS_DIR = HEART_STATE_DIR / "timings-unit"
41+
HEART_HOME = Path(__file__).resolve().parents[2]
42+
CONFIG_PATH = HEART_HOME / "config" / "repos.yaml"
43+
44+
# Each library's suite is discovered via its own pytest config (testpaths), so we
45+
# just invoke pytest from the repo root. Import-name maps to repo dir name.
46+
DEFAULT_REPOS = ["PyAutoConf", "PyAutoFit", "PyAutoArray", "PyAutoGalaxy", "PyAutoLens"]
47+
48+
# A runner maps a repo checkout dir to {test_nodeid: call_seconds} for the
49+
# slowest tests, or None when the suite could not be run. Injected in tests.
50+
Runner = Callable[[Path], "dict[str, float] | None"]
51+
52+
# pytest's "slowest durations" report lines: "1.23s call path::test_x"
53+
_DURATION_RE = re.compile(r"^\s*([0-9.]+)s\s+call\s+(\S+)\s*$")
54+
55+
56+
def load_thresholds() -> tuple[float, float, int, int]:
57+
"""Return (yellow_factor, red_factor, baseline_window, top_n) from config."""
58+
yellow, red, window, top_n = 1.5, 3.0, 7, 15
59+
if CONFIG_PATH.is_file():
60+
cfg = yaml.safe_load(CONFIG_PATH.read_text()) or {}
61+
t = cfg.get("thresholds", {}).get("unit_test_timing", {})
62+
yellow = float(t.get("yellow_factor", yellow))
63+
red = float(t.get("red_factor", red))
64+
window = int(t.get("baseline_window", window))
65+
top_n = int(t.get("top_n", top_n))
66+
return yellow, red, window, top_n
67+
68+
69+
def parse_durations(stdout: str) -> dict[str, float]:
70+
"""Extract {nodeid: call_seconds} from a pytest --durations report."""
71+
out: dict[str, float] = {}
72+
for line in stdout.splitlines():
73+
m = _DURATION_RE.match(line)
74+
if m:
75+
out[m.group(2)] = float(m.group(1))
76+
return out
77+
78+
79+
def default_runner(python: str, timeout: float, top_n: int) -> Runner:
80+
"""Run ``pytest --durations`` per repo in a subprocess; parse the slowest."""
81+
env = {
82+
**os.environ,
83+
"NUMBA_CACHE_DIR": os.environ.get("NUMBA_CACHE_DIR", "/tmp/numba_cache"),
84+
"MPLCONFIGDIR": os.environ.get("MPLCONFIGDIR", "/tmp/matplotlib"),
85+
}
86+
87+
def run_repo(repo_dir: Path) -> dict[str, float] | None:
88+
if not repo_dir.is_dir():
89+
return None
90+
cmd = [python, "-m", "pytest", "--durations", str(top_n),
91+
"-q", "-p", "no:cacheprovider"]
92+
try:
93+
proc = subprocess.run(
94+
cmd, cwd=str(repo_dir), capture_output=True, text=True,
95+
timeout=timeout, env=env,
96+
)
97+
except (subprocess.TimeoutExpired, FileNotFoundError):
98+
return None
99+
# A non-zero exit (test failures) still prints the durations report; parse
100+
# regardless. Only a total absence of parseable lines means "no data".
101+
parsed = parse_durations(proc.stdout)
102+
return parsed or None
103+
104+
return run_repo
105+
106+
107+
def _slug(repo: str, nodeid: str) -> str:
108+
safe = re.sub(r"[^A-Za-z0-9]+", "_", f"{repo}__{nodeid}").strip("_")
109+
return f"{safe}.json"
110+
111+
112+
def update_history(slug: str, duration: float, window: int) -> list[float]:
113+
HEART_UNIT_TIMINGS_DIR.mkdir(parents=True, exist_ok=True)
114+
history_path = HEART_UNIT_TIMINGS_DIR / slug
115+
if history_path.is_file():
116+
try:
117+
history = json.loads(history_path.read_text())
118+
except json.JSONDecodeError:
119+
history = []
120+
else:
121+
history = []
122+
history.append(duration)
123+
history = history[-window:]
124+
history_path.write_text(json.dumps(history))
125+
return history
126+
127+
128+
def classify(ratio: float, yellow: float, red: float) -> str:
129+
if ratio > red:
130+
return "red"
131+
if ratio > yellow:
132+
return "yellow"
133+
return "green"
134+
135+
136+
def run(runner: Runner | None = None, repos: list[str] | None = None) -> dict[str, Any]:
137+
"""Run each repo's suite, update rolling per-test baselines, classify."""
138+
yellow_factor, red_factor, window, top_n = load_thresholds()
139+
repos = repos if repos is not None else DEFAULT_REPOS
140+
python = os.environ.get("HYGIENE_PYTHON", "python3")
141+
timeout = float(os.environ.get("HEART_UNIT_TEST_TIMEOUT", "1800"))
142+
root = Path(os.environ.get("PYAUTO_ROOT", str(Path.home() / "Code" / "PyAutoLabs")))
143+
runner = runner or default_runner(python, timeout, top_n)
144+
145+
findings: dict[str, list[dict[str, Any]]] = {"red": [], "yellow": [], "green": []}
146+
repos_measured = 0
147+
unavailable: list[str] = []
148+
new_tests = 0
149+
150+
for repo in repos:
151+
durations = runner(root / repo)
152+
if durations is None:
153+
unavailable.append(repo)
154+
continue
155+
repos_measured += 1
156+
for nodeid, duration in durations.items():
157+
history = update_history(_slug(repo, nodeid), duration, window)
158+
if len(history) <= 1:
159+
new_tests += 1
160+
continue
161+
baseline = statistics.median(history[:-1])
162+
if baseline <= 0:
163+
continue
164+
ratio = duration / baseline
165+
findings[classify(ratio, yellow_factor, red_factor)].append({
166+
"repo": repo,
167+
"test": nodeid,
168+
"latest_seconds": round(duration, 3),
169+
"baseline_seconds": round(baseline, 3),
170+
"ratio": round(ratio, 2),
171+
"samples": len(history) - 1,
172+
})
173+
174+
summary = {
175+
"python": python,
176+
"repos_measured": repos_measured,
177+
"repos_unavailable": unavailable,
178+
"new_tests_no_baseline": new_tests,
179+
"red_count": len(findings["red"]),
180+
"yellow_count": len(findings["yellow"]),
181+
"green_count": len(findings["green"]),
182+
"red": sorted(findings["red"], key=lambda x: -x["ratio"]),
183+
"yellow": sorted(findings["yellow"], key=lambda x: -x["ratio"]),
184+
}
185+
186+
sys.path.insert(0, str(HEART_HOME))
187+
from heart import state
188+
189+
state.atomic_write_json(HEART_STATE_DIR / "unit_test_timing.json", summary)
190+
return summary
191+
192+
193+
def main(argv: list[str]) -> int:
194+
summary = run()
195+
196+
from heart_color import c_ok, c_warn, c_fail, c_info, c_meta, glyph_ok, glyph_warn, glyph_fail
197+
198+
if summary["red_count"]:
199+
glyph = glyph_fail()
200+
label = c_fail(f"{summary['red_count']} red") + " " + c_warn(f"{summary['yellow_count']} yellow")
201+
elif summary["yellow_count"]:
202+
glyph = glyph_warn()
203+
label = c_warn(f"{summary['yellow_count']} slower than baseline")
204+
elif not summary["repos_measured"]:
205+
glyph = glyph_warn()
206+
label = c_warn("no suite runnable (set HYGIENE_PYTHON / PYAUTO_ROOT)")
207+
else:
208+
glyph = glyph_ok()
209+
label = c_ok(f"{summary['green_count']} tracked tests within baseline")
210+
extra = c_meta(f" ({summary['new_tests_no_baseline']} new, no baseline)")
211+
print(f"{glyph} {c_info('unit_test_timing')} {label}{extra}")
212+
return 0
213+
214+
215+
if __name__ == "__main__":
216+
sys.path.insert(0, str(Path(__file__).resolve().parents[1]))
217+
sys.exit(main(sys.argv))

heart/dashboard.py

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,7 @@
5757
"worktree_drift",
5858
"script_timing",
5959
"import_time",
60+
"unit_test_timing",
6061
"profiling_drift",
6162
"test_run",
6263
"version_skew",
@@ -398,6 +399,30 @@ def build_board(
398399
]
399400
sections.append(Section("import_time", "Import timing", st, summary, details))
400401

402+
# Unit-test timing (advisory; off-tick) -----------------------------------
403+
if "unit_test_timing" in unobserved:
404+
sections.append(_unobs_section("unit_test_timing", "Unit-test timing"))
405+
else:
406+
ut = snapshot.get("unit_test_timing") or {}
407+
if ut:
408+
r = _as_int(ut.get("red_count"))
409+
y = _as_int(ut.get("yellow_count"))
410+
g = _as_int(ut.get("green_count"))
411+
if r:
412+
st, summary = FAIL, f"{r} test regressions (>3× baseline), {y} slow (>1.5×)"
413+
elif y:
414+
st, summary = WARN, f"{y} tests >1.5× baseline, {g} within"
415+
elif not _as_int(ut.get("repos_measured")):
416+
st, summary = WARN, "no suite runnable (set HYGIENE_PYTHON / PYAUTO_ROOT)"
417+
else:
418+
st, summary = OK, f"{g} tracked tests within baseline"
419+
details = [
420+
f"✗ {e['repo']} {e['test'].split('::')[-1]} "
421+
f"{e['latest_seconds']:.2f}s vs {e['baseline_seconds']:.2f}s ({e['ratio']}×)"
422+
for e in (ut.get("red") or [])[:5]
423+
]
424+
sections.append(Section("unit_test_timing", "Unit-test timing", st, summary, details))
425+
401426
# Profiling pinned-value drift -------------------------------------------
402427
if "profiling_drift" in unobserved:
403428
sections.append(_unobs_section("profiling_drift", "Profiling drift"))

heart/state.py

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -75,6 +75,7 @@ def aggregate() -> dict[str, Any]:
7575
"worktree_drift": _read_json_or_default(HEART_STATE_DIR / "worktree_drift.json", {}),
7676
"script_timing": _read_json_or_default(HEART_STATE_DIR / "script_timing.json", {}),
7777
"import_time": _read_json_or_default(HEART_STATE_DIR / "import_time.json", {}),
78+
"unit_test_timing": _read_json_or_default(HEART_STATE_DIR / "unit_test_timing.json", {}),
7879
"profiling_drift": _read_json_or_default(HEART_STATE_DIR / "profiling_drift.json", {}),
7980
"test_run": _read_json_or_default(HEART_STATE_DIR / "test_run.json", {}),
8081
"version_skew": _read_json_or_default(HEART_STATE_DIR / "version_skew.json", {}),

tests/test_unit_test_timing.py

Lines changed: 86 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,86 @@
1+
"""tests/test_unit_test_timing.py — slow-test regression classifier + parser.
2+
3+
Stdlib-only (internals rule 4): the pytest runner is injected, so the suite
4+
never runs pytest-in-pytest or imports the science stack.
5+
"""
6+
7+
from __future__ import annotations
8+
9+
import importlib
10+
import json
11+
12+
import pytest
13+
14+
15+
@pytest.fixture
16+
def tmp_state(tmp_path, monkeypatch):
17+
monkeypatch.setenv("HEART_STATE_DIR", str(tmp_path))
18+
import heart.state as state_mod
19+
importlib.reload(state_mod)
20+
import heart.checks.unit_test_timing as ut
21+
importlib.reload(ut)
22+
ut.HEART_STATE_DIR = tmp_path
23+
ut.HEART_UNIT_TIMINGS_DIR = tmp_path / "timings-unit"
24+
ut.HEART_UNIT_TIMINGS_DIR.mkdir(parents=True, exist_ok=True)
25+
return tmp_path, ut
26+
27+
28+
def _runner(mapping):
29+
"""A runner that returns `mapping` (or None) for any repo."""
30+
return lambda repo_dir: mapping
31+
32+
33+
def test_first_observation_has_no_baseline(tmp_state):
34+
_, ut = tmp_state
35+
s = ut.run(runner=_runner({"t.py::test_a": 5.0}), repos=["PyAutoFit"])
36+
assert s["new_tests_no_baseline"] == 1
37+
assert s["red_count"] == 0 and s["yellow_count"] == 0
38+
assert s["repos_measured"] == 1
39+
40+
41+
def test_within_baseline_green(tmp_state):
42+
_, ut = tmp_state
43+
ut.run(runner=_runner({"t.py::test_a": 5.0}), repos=["PyAutoFit"])
44+
s = ut.run(runner=_runner({"t.py::test_a": 5.0}), repos=["PyAutoFit"])
45+
assert s["green_count"] == 1 and s["red_count"] == 0 and s["yellow_count"] == 0
46+
47+
48+
def test_yellow_and_red_thresholds(tmp_state):
49+
_, ut = tmp_state
50+
ut.run(runner=_runner({"t.py::test_a": 5.0}), repos=["PyAutoFit"])
51+
s = ut.run(runner=_runner({"t.py::test_a": 10.0}), repos=["PyAutoFit"]) # 2.0×
52+
assert s["yellow_count"] == 1 and s["red_count"] == 0
53+
ut.run(runner=_runner({"t.py::test_b": 5.0}), repos=["PyAutoFit"])
54+
s = ut.run(runner=_runner({"t.py::test_b": 20.0}), repos=["PyAutoFit"]) # 4.0×
55+
assert s["red_count"] == 1
56+
57+
58+
def test_repo_unavailable(tmp_state):
59+
_, ut = tmp_state
60+
s = ut.run(runner=_runner(None), repos=["PyAutoFit"])
61+
assert s["repos_measured"] == 0 and s["repos_unavailable"] == ["PyAutoFit"]
62+
63+
64+
def test_rolling_window_caps_history(tmp_state):
65+
_, ut = tmp_state
66+
for d in [1.0, 1.1, 1.2, 1.3, 1.4, 1.5, 1.6, 1.7, 1.8, 1.9]:
67+
ut.run(runner=_runner({"t.py::test_a": d}), repos=["PyAutoFit"])
68+
files = list(ut.HEART_UNIT_TIMINGS_DIR.glob("*.json"))
69+
assert len(files) == 1
70+
assert len(json.loads(files[0].read_text())) == 7
71+
72+
73+
def test_parse_durations_reads_call_lines_only(tmp_state):
74+
_, ut = tmp_state
75+
stdout = (
76+
"===== slowest 3 durations =====\n"
77+
"12.34s call test_autofit/test_x.py::test_slow\n"
78+
"1.20s setup test_autofit/test_x.py::test_slow\n"
79+
"0.98s call test_autofit/test_y.py::test_other\n"
80+
"\n===== short test summary =====\n"
81+
)
82+
parsed = ut.parse_durations(stdout)
83+
assert parsed == {
84+
"test_autofit/test_x.py::test_slow": 12.34,
85+
"test_autofit/test_y.py::test_other": 0.98,
86+
}

0 commit comments

Comments
 (0)