From 45f9d6562e9ba81142909c64905f4481561e2024 Mon Sep 17 00:00:00 2001 From: Marius Ciepluch <11855163+norandom@users.noreply.github.com> Date: Fri, 18 Sep 2026 14:31:53 +0200 Subject: [PATCH] feat(push): report what each stage cost as it finishes (M3 diagnosis) Three PHP investigations were spent reading `cpg batch taint failed: timeout` as a slow query. The query is not slow: 4,425 evidence requests answer in 30 s, 50 dataflow requests in 24 s, and 20 entry-point requests at call depth 3 with parameter sources in 24.7 s. The production PHP build takes 79 s and does not shard. None of that explains a case running 26 minutes without finishing. The reason it could not be diagnosed is that nothing reported where the budget went. A run that is killed, or that blames a later stage's timeout, left no account of what had already consumed the transaction, and a subprocess bounded by the remaining time reports its own timeout whatever spent it. Each stage now records and logs what it cost as it finishes, so a killed run still says where it was. A control asserts the stages report and that each line carries its duration. 1,410 tests passed, nine skipped. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01EmM1j46qgKMh3zqD1QMwEo --- src/openultrasast/push/runner.py | 41 ++++++++++++++++++++++---------- 1 file changed, 29 insertions(+), 12 deletions(-) diff --git a/src/openultrasast/push/runner.py b/src/openultrasast/push/runner.py index f0b0020..f4136ee 100644 --- a/src/openultrasast/push/runner.py +++ b/src/openultrasast/push/runner.py @@ -3,6 +3,7 @@ from __future__ import annotations import hashlib +import logging import multiprocessing import os import pickle @@ -44,6 +45,8 @@ from openultrasast.push.reuse import ReusingBackend, declaration_identity, disco from openultrasast.push.snapshot import SnapshotAdapter from openultrasast.push.vetoes import FLAG, LABEL, load_declarations, record_vetoes +logger = logging.getLogger(__name__) + _T = TypeVar("_T") @@ -210,6 +213,20 @@ def _discovery_identity() -> str: return digest_value([(p.relative_to(root).as_posix(), hashlib.sha256(p.read_bytes()).hexdigest()) for p in sorted(root.rglob("*.py"))]) +def _stage(timings: dict[str, float], stage: str, started: float) -> float: + """Close one stage, record its cost and say so. + + A run that is killed, or that reports a later stage's timeout, otherwise leaves no account of + where its budget went. Three PHP investigations were spent reading `cpg batch taint failed: + timeout` as a slow query when the query answers 20 requests in 24 seconds, because nothing said + what had already consumed the transaction. + """ + now = time.monotonic() + timings[stage + "_seconds"] = now - started + logger.info("push stage %s finished in %.1fs", stage, now - started) + return now + + def _analyze( repository: Path, *, @@ -263,10 +280,10 @@ def _analyze( try: adapter = SnapshotAdapter(repository, execution_budget=budget) comparison = resolved or adapter.resolve_replay(base, head) - timings[stage + "_seconds"] = time.monotonic() - stage_started - stage, stage_started = "provenance", time.monotonic() + stage_started = _stage(timings, stage, stage_started) + stage = "provenance" provenance.update(_prepare(lambda: _provenance(repository, scan_budget), budget)) - timings[stage + "_seconds"] = time.monotonic() - stage_started + stage_started = _stage(timings, stage, stage_started) if cache_dir is not None: cache = ArtifactCache(cache_dir, max_bytes=config.cache_max_bytes) cache_semantics = SemanticKeys( @@ -330,8 +347,8 @@ def _analyze( context = adapter.compare(comparison, declaration_paths=tuple(set(head_declarations + base_declarations)), budget=budget) context = replace(context, unresolved_boundaries=tuple(dict.fromkeys((*context.unresolved_boundaries, *reasons)))) reasons.extend(context.unresolved_boundaries) - timings[stage + "_seconds"] = time.monotonic() - stage_started - stage, stage_started = "head", time.monotonic() + stage_started = _stage(timings, stage, stage_started) + stage = "head" head_scan = scan_repository( tip.root, head_regions, @@ -344,8 +361,8 @@ def _analyze( change_context=context, ) records.append(ScanRecord(comparison, "head", head_scan)) - timings[stage + "_seconds"] = time.monotonic() - stage_started - stage, stage_started = "base", time.monotonic() + stage_started = _stage(timings, stage, stage_started) + stage = "base" delta = compare_targeted_base( old.root, head=head_scan, @@ -363,8 +380,8 @@ def _analyze( if delta.base_scan is not None: records.append(ScanRecord(comparison, "base", delta.base_scan)) reasons.extend(delta.coverage_reasons) - timings[stage + "_seconds"] = time.monotonic() - stage_started - stage, stage_started = "admission", time.monotonic() + stage_started = _stage(timings, stage, stage_started) + stage = "admission" candidates = tuple( AdmissionCandidate( c, @@ -383,7 +400,7 @@ def _analyze( for c in delta.candidates ) admission = _prepare(lambda: _admit(candidates, provenance), budget) - timings[stage + "_seconds"] = time.monotonic() - stage_started + stage_started = _stage(timings, stage, stage_started) if record_vetoes: stage, stage_started = "recorded_vetoes", time.monotonic() assert context is not None @@ -392,8 +409,8 @@ def _analyze( budget, ) experimental = {**recorded, "status": "evaluated"} - timings[stage + "_seconds"] = time.monotonic() - stage_started - stage, stage_started = "cleanup", time.monotonic() + stage_started = _stage(timings, stage, stage_started) + stage = "cleanup" timings[stage + "_seconds"] = time.monotonic() - stage_started except Exception as error: reasons.append(stage + "_failed:" + type(error).__name__)