补充 SVGlide 调试耗时审计

新增 debug-time-audit.json,分离 runner 执行时间、事件间 gap、显式 debug bucket 与未归属耗时。

保持 timing receipt 语义不变,避免再用 runner stage time 误代表完整人工调试耗时。
This commit is contained in:
songtianyi.theo
2026-06-27 01:26:25 +08:00
parent 02559cc0d4
commit 8cfbced316
3 changed files with 107 additions and 2 deletions

View File

@@ -114,7 +114,7 @@ Status conventions:
| `preflight` bbox / text backing false positives | Partially fixed | Bbox extraction and light-text backing checks were adjusted. Needs broader fixture coverage for path, clip, mask, and backing cases. | `svg_preflight.py`; current deck preflight passed. |
| `readback business_claims` checked unsubmitted metadata | Fixed in code | When prepared SVG exists, business claims are filtered to claims visible in submitted SVG text. `core_visible_text` remains the main visible-text guard. | `svglide_readback.py`; test in `svglide_readback_test.py`. |
| PPE route and live create | Evidence passed; optimization open | `live_create` used `--ppe-profile ppe_pure_svg` and injected proxy env. Long-term optimization: cache successful capability probe by proof and probe-file hash. | `live-create.json`, `ppe-proof.input.json`; `create_svg_capability_probe` passed. |
| Agent/debug time invisibility | Open | Add agent-side timing buckets for code inspection, patching, unit tests, state cleanup, approval wait, and rerun time. Runner timing alone underreports real time. | New instrumentation needed outside `state.json`. |
| Agent/debug time invisibility | Partially fixed in code | Runner now writes `06-check/debug-time-audit.json` beside `timing-report.json`, separating runner execution time, between-event gaps, instrumented debug buckets, and still-uninstrumented gap time. Full automatic agent bucket capture remains open. | `svglide_project_runner.py`; `svglide_project_runner_test.py` covers gap separation. |
## Resolved vs Remaining
@@ -131,7 +131,7 @@ Status conventions:
- Composite gate child stale ownership is less risky after stale-child rerun support, but richer diagnostics and child-output ownership tests are still needed.
- `generate_svg` has a clearer input boundary now; full cache reuse and renderer/template dependency hashing remain open.
- Preflight needs a broader false-positive fixture suite.
- Agent/debug time is not directly instrumented.
- Debug-time audit now separates runner time from between-event gaps; automatic agent bucket capture is still open.
- Template promotion fidelity and current deck publish fidelity now have separate receipts for the warning path; remaining work is naming/docs cleanup and any UI/report surfacing.
## Recommended TDD Follow-Up
@@ -207,6 +207,7 @@ Green:
- `approval_wait`
- `rerun_wait`
- Write them to a separate `debug-time-audit.json` so runtime receipts remain clean.
- Completed first slice: `debug-time-audit.json` is generated from timing events and optional `debug_time_events`, with explicit uninstrumented gap accounting.
Validation:

View File

@@ -636,6 +636,10 @@ def timing_receipt_path(project_root: Path) -> Path:
return project_root / "receipts" / "timing.json"
def debug_time_audit_path(project_root: Path) -> Path:
return project_root / "06-check" / "debug-time-audit.json"
def stage_attempt(events: list[dict[str, Any]], stage: str) -> int:
return sum(1 for event in events if event.get("stage") == stage) + 1
@@ -697,6 +701,63 @@ def build_script_hashes(command: list[str] | None) -> dict[str, str]:
return hashes
def write_debug_time_audit(project_root: Path, state: dict[str, Any], timing_report: dict[str, Any]) -> dict[str, Any]:
events = [event for event in state.get("timing_events", []) if isinstance(event, dict)]
parsed_events: list[tuple[datetime, datetime, dict[str, Any]]] = []
for event in events:
started = parse_iso_seconds(event.get("started_at") if isinstance(event.get("started_at"), str) else None)
ended = parse_iso_seconds(event.get("ended_at") if isinstance(event.get("ended_at"), str) else None)
if started and ended:
parsed_events.append((started, ended, event))
parsed_events.sort(key=lambda item: item[0])
gap_threshold = 10.0
material_gaps: list[dict[str, Any]] = []
total_gap = 0.0
observed_span = 0.0
if parsed_events:
observed_span = max(0.0, (max(item[1] for item in parsed_events) - min(item[0] for item in parsed_events)).total_seconds())
previous_end = parsed_events[0][1]
previous_stage = parsed_events[0][2].get("stage")
for started, ended, event in parsed_events[1:]:
gap = max(0.0, (started - previous_end).total_seconds())
total_gap += gap
if gap >= gap_threshold:
material_gaps.append(
{
"after_stage": previous_stage,
"before_stage": event.get("stage"),
"gap_seconds": round(gap, 3),
"classification": "uninstrumented_between_runner_events",
}
)
if ended > previous_end:
previous_end = ended
previous_stage = event.get("stage")
debug_events = [event for event in state.get("debug_time_events", []) if isinstance(event, dict)]
debug_buckets: dict[str, float] = {}
for event in debug_events:
bucket = event.get("bucket")
seconds = event.get("wall_time_seconds")
if isinstance(bucket, str) and isinstance(seconds, (int, float)):
debug_buckets[bucket] = round(debug_buckets.get(bucket, 0.0) + float(seconds), 3)
debug_total = round(sum(debug_buckets.values()), 3)
runner_total = float(timing_report.get("total_wall_time_seconds") or 0.0)
payload = {
"schema_version": "svglide-debug-time-audit/v1",
"runner_total_wall_time_seconds": round(runner_total, 3),
"observed_runner_span_seconds": round(observed_span, 3),
"between_runner_event_gap_seconds": round(total_gap, 3),
"instrumented_debug_time_seconds": debug_total,
"uninstrumented_gap_seconds": round(max(0.0, total_gap - debug_total), 3),
"gap_threshold_seconds": gap_threshold,
"debug_bucket_runtime_seconds": debug_buckets,
"material_gaps": material_gaps,
"claim_boundary": "runner timing is execution-only; between-event gaps may include agent inspection, patching, tests, approval wait, idle time, or context switching",
}
write_json(debug_time_audit_path(project_root), payload)
return payload
def write_timing_report(project_root: Path, state: dict[str, Any]) -> dict[str, Any]:
events = state.get("timing_events") if isinstance(state.get("timing_events"), list) else []
stage_runtime: dict[str, float] = {}
@@ -740,6 +801,7 @@ def write_timing_report(project_root: Path, state: dict[str, Any]) -> dict[str,
payload["cache"] = cache
write_json(timing_report_path(project_root), payload)
write_json(timing_receipt_path(project_root), payload)
write_debug_time_audit(project_root, state, payload)
return payload

View File

@@ -1375,6 +1375,48 @@ class SVGlideProjectRunnerTest(unittest.TestCase):
self.assertEqual(report["schema_version"], "svglide-timing-report/v1")
self.assertEqual(report["stage_attempts"]["plan"], 1)
self.assertEqual(report["sla"]["profile"], "preview_only")
debug_audit = json.loads((project_root / "06-check/debug-time-audit.json").read_text(encoding="utf-8"))
self.assertEqual(debug_audit["schema_version"], "svglide-debug-time-audit/v1")
self.assertEqual(debug_audit["runner_total_wall_time_seconds"], report["total_wall_time_seconds"])
self.assertIn("runner timing is execution-only", debug_audit["claim_boundary"])
def test_debug_time_audit_separates_runner_time_from_between_event_gaps(self) -> None:
with tempfile.TemporaryDirectory() as tmpdir:
plan_root = Path(tmpdir) / ".lark-slides/plan"
result = runner.init_project("smoke", "Smoke", plan_root=plan_root)
project_root = Path(result["project_root"])
state = runner.load_state(project_root)
state["profile"] = "preview_only"
state["timing_events"] = [
{
"stage": "plan",
"attempt": 1,
"status": "passed",
"started_at": "2026-06-27T10:00:00+08:00",
"ended_at": "2026-06-27T10:00:02+08:00",
"wall_time_seconds": 2.0,
},
{
"stage": "quality_gate",
"attempt": 1,
"status": "passed",
"started_at": "2026-06-27T10:00:32+08:00",
"ended_at": "2026-06-27T10:00:35+08:00",
"wall_time_seconds": 3.0,
},
]
state["debug_time_events"] = [{"bucket": "patch", "wall_time_seconds": 5.0}]
report = runner.write_timing_report(project_root, state)
audit = json.loads((project_root / "06-check/debug-time-audit.json").read_text(encoding="utf-8"))
self.assertEqual(report["total_wall_time_seconds"], 5.0)
self.assertEqual(audit["observed_runner_span_seconds"], 35.0)
self.assertEqual(audit["between_runner_event_gap_seconds"], 30.0)
self.assertEqual(audit["instrumented_debug_time_seconds"], 5.0)
self.assertEqual(audit["uninstrumented_gap_seconds"], 25.0)
self.assertEqual(audit["material_gaps"][0]["after_stage"], "plan")
self.assertEqual(audit["material_gaps"][0]["before_stage"], "quality_gate")
def test_collect_errors_stops_before_render_and_writes_structured_report(self) -> None:
with tempfile.TemporaryDirectory() as tmpdir: