feat(kvb-check-ansible): rank where an Ansible run spends its time

New skill with ansible_tasks.py: gaps, durations, kinds, kind and task rank a run's log by wall-clock gaps or profile_tasks lines; profile-report merges cProfile dumps of the controller and its forked workers (sitecustomize hook); bench-carrier and the bench playbook measure per-task overhead against variable size. kvb-code-tune hands its Ansible timing to it.

🎯 Fix: 92 %
💥 Break: 2 %
💸 Cost: new
⏱️ Time: new
🛡️ Security: 100 %
🏆 Score: 90
🚦 Gate: cost new, time new: cleared by the operator's commit word for kvb-check-ansible (2026-11-07)

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Kevin Veen-BirkenbachandClaude Opus 5.5 committed 2026-11-07 10:57:47 +00:00
1 parent 8b0c287ada
commit 05cc891998
17 files changed
+1212

No files matched your search

+125
View File
@@ -0,0 +1,125 @@
"""Shared paths, script modules, synthetic logs and the CLI test case of the kvb-check-ansible tests."""
from __future__ import annotations
import json
import subprocess
import sys
import tempfile
import unittest
from pathlib import Path
SKILL = Path(__file__).resolve().parents[1] / "skills" / "kvb-check-ansible"
sys.path.insert(0, str(SKILL / "scripts"))
import ansible_bench
import ansible_log
import ansible_tables
__all__ = [
"BENCH",
"MIDNIGHT_LOG",
"PROFILE_DIR",
"PROFILE_LOG",
"SCRIPT",
"WALL_KINDS",
"WALL_LOG",
"LogCase",
"ansible_bench",
"ansible_log",
"ansible_tables",
]
SCRIPT = SKILL / "scripts" / "ansible_tasks.py"
PROFILE_DIR = SKILL / "scripts" / "profile"
BENCH = SKILL / "bench"
STARS = " " + "*" * 40
WALL_LOG = "\n".join(
[
"2026-11-07T06:45:40.0000000Z PLAY [deploy]" + STARS,
"2026-11-07T06:45:40.5000000Z TASK [setup : install]" + STARS,
"2026-11-07T06:45:43.0000000Z \x1b[0;33mchanged: [host]\x1b[0m",
"2026-11-07T06:45:44.0000000Z TASK [setup : check]" + STARS,
"2026-11-07T06:45:44.1000000Z skipping: [host]",
"2026-11-07T06:45:44.2Z TASK [setup : install]" + STARS,
"2026-11-07T06:45:44.5000000Z skipping: [host] => (item=a)",
"2026-11-07T06:45:45.0000000Z ok: [host] => (item=b)",
"2026-11-07T06:45:45.700000000Z TASK [setup : include]" + STARS,
"2026-11-07T06:45:45.8000000Z included: /x/y.yml for host",
"2026-11-07T06:45:46.0 TASK [setup : flush]" + STARS,
"2026-11-07T06:45:46.5000000Z [WARNING]: nothing to flush",
"2026-11-07T06:45:46.8000000Z RUNNING HANDLER [setup : restart]" + STARS,
"2026-11-07T06:45:48.0000000Z fatal: [host]: FAILED! => {}",
"2026-11-07T06:45:48.0000000Z PLAY RECAP" + STARS,
"2026-11-07T06:45:48.0000000Z host : ok=2 changed=1 skipped=1 failed=1",
]
) + "\n"
PROFILE_LINE = "Saturday 07 November 2026 06:45:40 +0000 ({}) 0:00:00.020 " + "*" * 20
PROFILE_LOG = "\n".join(
[
"PLAY [deploy]" + STARS,
"",
"TASK [Gathering Facts]" + STARS,
PROFILE_LINE.format("0:00:00.020"),
"ok: [host]",
"TASK [setup : install]" + STARS,
PROFILE_LINE.format("0:00:02.000"),
"changed: [host]",
"TASK [setup : check]" + STARS,
PROFILE_LINE.format("0:00:03.500"),
"skipping: [host]",
"TASK [setup : install]" + STARS,
PROFILE_LINE.format("0:00:00.100"),
"included: /x/y.yml for host",
"RUNNING HANDLER [setup : restart]" + STARS,
PROFILE_LINE.format("0:01:01.500"),
"ok: [host]",
"PLAY RECAP" + STARS,
"host : ok=3 changed=1 skipped=1",
"TASKS RECAP" + STARS,
PROFILE_LINE.format("0:00:00.400"),
"=" * 40,
"setup : install ----------------------- 63.50s",
]
) + "\n"
MIDNIGHT_LOG = chr(0xFEFF) + "2026-11-07T23:59:59.5Z TASK [late]" + STARS + "\n2026-11-08T00:00:00.25Z PLAY RECAP" + STARS + "\n"
WALL_KINDS = [
"kind\tcount\tsum\tmean\t<0.25\t<0.5\t<1\t<2\t>=2",
"ran\t3\t6.2\t2.0667\t0\t0\t0\t2\t1",
"other\t1\t0.8\t0.8000\t0\t0\t1\t0\t0",
"included\t1\t0.3\t0.3000\t0\t1\t0\t0\t0",
"skipped\t1\t0.2\t0.2000\t1\t0\t0\t0\t0",
]
class LogCase(unittest.TestCase):
def setUp(self):
tmp = tempfile.TemporaryDirectory()
self.addCleanup(tmp.cleanup)
self.base = Path(tmp.name)
self.wall = self.write("wall.log", WALL_LOG)
self.profile = self.write("profile.log", PROFILE_LOG)
def write(self, name: str, text: str) -> Path:
path = self.base / name
path.write_text(text, encoding="utf-8")
return path
def run_script(self, *args: str, env: dict | None = None) -> subprocess.CompletedProcess:
return subprocess.run(
[sys.executable, str(SCRIPT), *args], capture_output=True, text=True, check=False, env=env
)
def lines(self, *args: str) -> list[str]:
result = self.run_script(*args)
self.assertEqual(result.returncode, 0, result.stderr)
return result.stdout.splitlines()
def report(self, *args: str) -> dict:
result = self.run_script(*args, "--json")
self.assertEqual(result.returncode, 0, result.stderr)
return json.loads(result.stdout)
+79
View File
@@ -0,0 +1,79 @@
"""Exercise kvb-check-ansible's bench: the synthetic carrier fact and a real run of the bench playbook."""
from __future__ import annotations
import json
import os
import shutil
import subprocess
import sys
import tempfile
import unittest
from pathlib import Path
from ansible_support import BENCH, SCRIPT, LogCase, ansible_bench, ansible_log
class TestBenchCarrier(LogCase):
def test_writes_exactly_the_asked_size(self):
out = self.base / "carrier.json"
result = self.run_script("bench-carrier", "--kb", "3", "--out", str(out))
self.assertEqual(result.returncode, 0, result.stderr)
self.assertEqual(out.stat().st_size, 3 * 1024)
fact = json.loads(out.read_text(encoding="ascii"))
self.assertEqual(result.stdout, f"{out}\t3072 bytes\t{len(fact) - 1} entries\n")
self.assertIn("pad", fact)
for size in (1024, 1500, 400 * 1024):
with self.subTest(size=size):
self.assertEqual(len(json.dumps(ansible_bench.carrier(size))), size)
self.assertGreater(len(ansible_bench.carrier(400 * 1024)), 100)
def test_bench_inventory_pins_no_interpreter_path(self):
self.assertNotRegex((BENCH / "hosts.yml").read_text(encoding="utf-8"), r"interpreter:\s*/")
@unittest.skipUnless(shutil.which("ansible-playbook"), "ansible-playbook not installed")
class TestBench(unittest.TestCase):
@classmethod
def setUpClass(cls):
tmp = tempfile.TemporaryDirectory()
cls.addClassCleanup(tmp.cleanup)
base = Path(tmp.name)
carrier = base / "carrier.json"
carrier.write_text(json.dumps(ansible_bench.carrier(8 * 1024)), encoding="ascii")
cls.log = base / "bench.log"
env = {
"PATH": os.environ["PATH"],
"HOME": str(base),
"ANSIBLE_LOCAL_TEMP": str(base / "tmp"),
"ANSIBLE_NOCOLOR": "1",
"ANSIBLE_CALLBACKS_ENABLED": "ansible.posix.profile_tasks",
}
cls.result = subprocess.run(
[
"ansible-playbook", "-i", str(BENCH / "hosts.yml"), str(BENCH / "bench.yml"),
"-e", "bench_count=3", "-e", f"bench_carrier_file={carrier}",
],
cwd=base, env=env, capture_output=True, text=True, check=False,
)
cls.log.write_text(cls.result.stdout, encoding="utf-8")
def test_runs_one_skipped_and_one_ran_task_per_item(self):
self.assertEqual(self.result.returncode, 0, self.result.stdout + self.result.stderr)
self.assertEqual(self.result.stdout.count("skipping: [bench]"), 3)
self.assertEqual(self.result.stdout.count("included: "), 3)
def test_profile_tasks_output_ranks_by_kind(self):
if ansible_log.ELAPSED.search(self.result.stdout) is None:
self.skipTest("ansible.posix.profile_tasks not installed")
result = subprocess.run(
[sys.executable, str(SCRIPT), "kinds", "--log", str(self.log), "--json"],
capture_output=True, text=True, check=False,
)
self.assertEqual(result.returncode, 0, result.stderr)
counts = {row["kind"]: row["count"] for row in json.loads(result.stdout)["kinds"]}
self.assertEqual(counts, {"ran": 4, "skipped": 3, "included": 1})
if __name__ == "__main__":
unittest.main()
+96
View File
@@ -0,0 +1,96 @@
"""Exercise kvb-check-ansible's log parsing: timestamps, sources, line ranges and the task boundaries."""
from __future__ import annotations
import calendar
import unittest
from ansible_support import MIDNIGHT_LOG, PROFILE_LOG, LogCase, ansible_log
class TestStamps(unittest.TestCase):
def test_fraction_digits_zone_and_missing_z(self):
base = calendar.timegm((2026, 11, 7, 6, 45, 47))
for text, fraction in (
("2026-11-07T06:45:47.1234567Z x", 0.1234567),
("2026-11-07T06:45:47.1Z x", 0.1),
("2026-11-07T06:45:47Z x", 0.0),
("2026-11-07T06:45:47.123456789 x", 0.123456789),
("2026-11-07T07:45:47.5+01:00 x", 0.5),
("2026-11-07T01:45:47.5-0500 x", 0.5),
("2026-11-07 06:45:47,25 x", 0.25),
):
with self.subTest(text=text):
stamp, content = ansible_log.split_stamp(text)
self.assertAlmostEqual(stamp, base + fraction, places=5)
self.assertEqual(content, "x")
self.assertEqual(ansible_log.split_stamp("TASK [x] ***"), (None, "TASK [x] ***"))
class TestWallParsing(LogCase):
def test_line_range_drops_the_task_its_end_cuts_off(self):
self.assertEqual(
self.lines("gaps", "--log", str(self.wall), "--from", "4", "--to", "13"),
[
"1.5\t1\tsetup : install",
"0.8\t1\tsetup : flush",
"0.3\t1\tsetup : include",
"0.2\t1\tsetup : check",
"2.8\t4\tTOTAL",
],
)
def test_midnight_bom_and_recap_close_the_last_task(self):
midnight = self.write("midnight.log", MIDNIGHT_LOG)
self.assertEqual(self.report("gaps", "--log", str(midnight))["rows"], [{"name": "late", "sum": 0.75, "count": 1}])
class TestProfileParsing(LogCase):
def test_durations_pair_each_header_with_the_next_elapsed_line(self):
self.assertEqual(
self.lines("durations", "--log", str(self.profile)),
[
"65.0\t2\tsetup : install",
"2.0\t1\tGathering Facts",
"0.4\t1\tsetup : restart",
"0.1\t1\tsetup : check",
"67.5\t5\tTOTAL",
],
)
def test_kinds_fall_back_to_the_profile_source(self):
self.assertEqual(
self.lines("kinds", "--log", str(self.profile)),
[
"kind\tcount\tsum\tmean\t<0.25\t<0.5\t<1\t<2\t>=2",
"included\t1\t61.5\t61.5000\t0\t0\t0\t0\t1",
"ran\t3\t5.9\t1.9667\t0\t1\t0\t0\t2",
"skipped\t1\t0.1\t0.1000\t1\t0\t0\t0\t0",
],
)
self.assertEqual(self.report("kinds", "--log", str(self.profile))["source"], "profile")
def test_profile_source_reads_a_timestamped_log_too(self):
stamped = self.write("stamped.log", "".join(f"2026-11-07T06:45:40.1234Z {line}\n" for line in PROFILE_LOG.splitlines()))
self.assertEqual(
self.lines("kind", "--log", str(stamped), "--source", "profile", "--kind", "skipped"),
["0.1\t1\tsetup : check", "0.1\t1\tTOTAL"],
)
class TestUnmeasurable(LogCase):
def assertFails(self, needle: str, *args: str):
result = self.run_script(*args)
self.assertEqual((result.returncode, result.stdout), (2, ""))
self.assertIn(needle, result.stderr)
def test_wrong_source_or_range_exits_2(self):
self.assertFails("ISO timestamp", "gaps", "--log", str(self.profile))
self.assertFails("ISO timestamp", "kinds", "--log", str(self.profile), "--source", "wall")
self.assertFails("profile_tasks", "durations", "--log", str(self.wall))
self.assertFails("no task closed", "gaps", "--log", str(self.wall), "--from", "2", "--to", "2")
self.assertFails("No such file", "gaps", "--log", str(self.base / "missing.log"))
if __name__ == "__main__":
unittest.main()
+98
View File
@@ -0,0 +1,98 @@
"""Exercise kvb-check-ansible's controller profiler and its profile-report subcommand."""
from __future__ import annotations
import cProfile
import os
import subprocess
import sys
import tempfile
import unittest
from pathlib import Path
from ansible_support import PROFILE_DIR, LogCase
FORKING = (
"import multiprocessing\n"
"def work():\n"
" return sum(range(1000))\n"
"if __name__ == '__main__':\n"
" child = multiprocessing.get_context('fork').Process(target=work)\n"
" child.start()\n"
" child.join()\n"
)
def busy() -> int:
return sum(number * number for number in range(20000))
class TestProfileReport(LogCase):
def setUp(self):
super().setUp()
self.profiles = self.base / "profiles"
self.profiles.mkdir()
for name in ("main-1.prof", "worker-2.prof", "worker-3.prof"):
profiler = cProfile.Profile()
profiler.enable()
busy()
profiler.disable()
profiler.dump_stats(self.profiles / name)
def test_merges_main_and_worker_profiles(self):
found = self.report("profile-report", "--dir", str(self.profiles), "--top", "3")
self.assertEqual((found["main"]["profiles"], found["worker"]["profiles"]), (1, 2))
for role, calls in (("main", 1), ("worker", 2)):
with self.subTest(role=role):
self.assertLessEqual(len(found[role]["cumulative"]), 3)
self.assertLessEqual(len(found[role]["tottime"]), 3)
rows = [row for row in found[role]["cumulative"] if row["function"].endswith("(busy)")]
self.assertEqual([row["calls"] for row in rows], [calls])
lines = self.lines("profile-report", "--dir", str(self.profiles), "--top", "2")
self.assertRegex(lines[0], r"^== main: 1 profiles, \d+\.\d{3} s ==$")
self.assertIn("-- tottime: cumtime, tottime, calls, function --", lines)
self.assertTrue(any(line.startswith("== worker: 2 profiles") for line in lines))
def test_dir_comes_from_the_environment_and_empty_exits_2(self):
env = {"PATH": os.environ["PATH"], "ANSIBLE_PROFILE_DIR": str(self.profiles)}
result = self.run_script("profile-report", "--top", "1", env=env)
self.assertEqual(result.returncode, 0, result.stderr)
self.assertTrue(result.stdout.startswith("== main: 1 profiles"))
empty = self.base / "empty"
empty.mkdir()
result = self.run_script("profile-report", "--dir", str(empty), "--top", "1")
self.assertEqual(result.returncode, 2)
self.assertIn("no main-*.prof or worker-*.prof", result.stderr)
class TestProfiler(unittest.TestCase):
def setUp(self):
tmp = tempfile.TemporaryDirectory()
self.addCleanup(tmp.cleanup)
self.base = Path(tmp.name)
def fork(self, program: str, **env: str) -> None:
script = self.base / program
script.write_text(FORKING, encoding="utf-8")
result = subprocess.run(
[sys.executable, str(script)],
env={"PATH": os.environ["PATH"], "PYTHONPATH": str(PROFILE_DIR), "TMPDIR": str(self.base), **env},
capture_output=True, text=True, check=False,
)
self.assertEqual(result.returncode, 0, result.stderr)
def test_ansible_playbook_and_its_workers_land_under_tmpdir(self):
self.fork("ansible-playbook")
out = self.base / "ansible-profile"
self.assertEqual(len(list(out.glob("main-*.prof"))), 1)
self.assertEqual(len(list(out.glob("worker-*.prof"))), 1)
def test_profile_dir_wins_and_other_programs_stay_unprofiled(self):
self.fork("ansible-playbook", ANSIBLE_PROFILE_DIR=str(self.base / "chosen"))
self.assertEqual(len(list((self.base / "chosen").glob("*.prof"))), 2)
self.fork("ansible", ANSIBLE_PROFILE_DIR=str(self.base / "other"))
self.assertFalse((self.base / "other").exists())
if __name__ == "__main__":
unittest.main()
+97
View File
@@ -0,0 +1,97 @@
"""Exercise kvb-check-ansible's reporting subcommands: name, kind and occurrence tables, JSON and usage errors."""
from __future__ import annotations
import unittest
from ansible_support import WALL_KINDS, LogCase, ansible_tables
class TestNameTables(LogCase):
def test_gaps_sum_per_name_biggest_first_with_total(self):
self.assertEqual(
self.lines("gaps", "--log", str(self.wall)),
[
"5.0\t2\tsetup : install",
"1.2\t1\tsetup : restart",
"0.8\t1\tsetup : flush",
"0.3\t1\tsetup : include",
"0.2\t1\tsetup : check",
"7.5\t6\tTOTAL",
],
)
def test_gaps_json_and_top_keep_the_full_total(self):
self.assertEqual(
self.report("gaps", "--log", str(self.wall), "--top", "2"),
{
"source": "wall",
"rows": [
{"name": "setup : install", "sum": 5.0, "count": 2},
{"name": "setup : restart", "sum": 1.2, "count": 1},
],
"total": {"sum": 7.5, "count": 6},
},
)
def test_kind_sums_one_kind_per_name(self):
self.assertEqual(
self.lines("kind", "--log", str(self.wall), "--kind", "ran"),
["5.0\t2\tsetup : install", "1.2\t1\tsetup : restart", "6.2\t3\tTOTAL"],
)
self.assertEqual(self.lines("kind", "--log", str(self.wall), "--kind", "other"), ["0.8\t1\tsetup : flush", "0.8\t1\tTOTAL"])
class TestKindTable(LogCase):
def test_kinds_detect_ran_before_skipped_and_fill_the_buckets(self):
self.assertEqual(self.lines("kinds", "--log", str(self.wall)), WALL_KINDS)
found = self.report("kinds", "--log", str(self.wall))
self.assertEqual(found["source"], "wall")
self.assertEqual(
found["kinds"][0],
{"kind": "ran", "count": 3, "sum": 6.2, "mean": 2.0667,
"buckets": {"<0.25": 0, "<0.5": 0, "<1": 0, "<2": 2, ">=2": 1}},
)
def test_bucket_edges(self):
for seconds, label in ((0.0, "<0.25"), (0.2499, "<0.25"), (0.25, "<0.5"), (0.5, "<1"), (1.0, "<2"), (1.999, "<2"), (2.0, ">=2")):
with self.subTest(seconds=seconds):
self.assertEqual(ansible_tables.bucket(seconds), label)
class TestOccurrences(LogCase):
def test_task_lists_every_occurrence_of_the_needle(self):
self.assertEqual(
self.lines("task", "--log", str(self.wall), "--needle", "install"),
["2\t3.500\tran\tsetup : install", "6\t1.500\tran\tsetup : install"],
)
found = self.report("task", "--log", str(self.wall), "--needle", "install", "--top", "1")
self.assertEqual(
found,
{
"source": "wall",
"needle": "install",
"count": 2,
"sum": 5.0,
"occurrences": [{"line": 2, "seconds": 3.5, "kind": "ran", "name": "setup : install"}],
},
)
class TestUsage(LogCase):
def test_usage_errors_exit_2(self):
for args in (
("gaps",),
("gaps", "--log", str(self.wall), "--from", "5", "--to", "4"),
("gaps", "--log", str(self.wall), "--top", "0"),
("kind", "--log", str(self.wall), "--kind", "slow"),
("task", "--log", str(self.wall)),
("profile-report", "--dir", str(self.base)),
("bench-carrier", "--kb", "0", "--out", str(self.base / "c.json")),
):
with self.subTest(args=args):
self.assertEqual(self.run_script(*args).returncode, 2)
if __name__ == "__main__":
unittest.main()