From 8cfbced3167305235d9d97bdd2f21236962f01bc Mon Sep 17 00:00:00 2001 From: "songtianyi.theo" Date: Sat, 27 Jun 2026 01:26:25 +0800 Subject: [PATCH] =?UTF-8?q?=E8=A1=A5=E5=85=85=20SVGlide=20=E8=B0=83?= =?UTF-8?q?=E8=AF=95=E8=80=97=E6=97=B6=E5=AE=A1=E8=AE=A1?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 新增 debug-time-audit.json，分离 runner 执行时间、事件间 gap、显式 debug bucket 与未归属耗时。 保持 timing receipt 语义不变，避免再用 runner stage time 误代表完整人工调试耗时。 --- .../svglide-node-debug-time-audit.md | 5 +- .../scripts/svglide_project_runner.py | 62 +++++++++++++++++++ .../scripts/svglide_project_runner_test.py | 42 +++++++++++++ 3 files changed, 107 insertions(+), 2 deletions(-) diff --git a/skills/lark-slides/references/svglide-node-debug-time-audit.md b/skills/lark-slides/references/svglide-node-debug-time-audit.md index ed9210fef..794fcc072 100644 --- a/skills/lark-slides/references/svglide-node-debug-time-audit.md +++ b/skills/lark-slides/references/svglide-node-debug-time-audit.md @@ -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: diff --git a/skills/lark-slides/scripts/svglide_project_runner.py b/skills/lark-slides/scripts/svglide_project_runner.py index 6a5e4ab07..35a7e0434 100644 --- a/skills/lark-slides/scripts/svglide_project_runner.py +++ b/skills/lark-slides/scripts/svglide_project_runner.py @@ -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 diff --git a/skills/lark-slides/scripts/svglide_project_runner_test.py b/skills/lark-slides/scripts/svglide_project_runner_test.py index d49ab3446..2b61207fa 100644 --- a/skills/lark-slides/scripts/svglide_project_runner_test.py +++ b/skills/lark-slides/scripts/svglide_project_runner_test.py @@ -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: