feat(plans): VI-B1 per-page per-stage exclusive timings in sidecar, manifest and CLI - #594
feat(plans): VI-B1 per-page per-stage exclusive timings in sidecar, manifest and CLI#594r-uben wants to merge 4 commits into
Conversation
VI-B1's reindent of the routing branch pushed the pinned line past the formatter's width, so it now wraps across three lines. The behaviour pin beside it (test_probe_is_consulted_only_after_a_timeout) is unchanged and green; only the spelling pin needed to stop depending on line layout. Outside TICKET-B1's Files list; consequence of the reindent, recorded here.
|
ⓘ Qodo reviews are paused because your trial has ended. Ask your workspace admin to add credits to resume reviews. Manage billing |
|
Important
This repository does not receive automatic reviews because it has fewer than 10 stars. ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Team Run ID: Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
r-uben
left a comment
r-uben
left a comment
There was a problem hiding this comment.
Verdict: REQUEST_CHANGES
Measurement-only VI-B1 is the right shape (sidecar / restore / fingerprint / .md byte-identity look sound; try/finally + exception finalize is real). Three holes before merge.
1. Ticket Done-when (a) silently rewritten; STATUS claim is false
docs/plans/verifier-independence/TICKETS.md Done-when (a) still requires exclusive keys to sum to timings_s.total within 1 ms. The build correctly makes total an independent page wall so the remainder is visible — good for the 8 min/page owner. But this PR does not change TICKETS.md or STATUS.md (board still says B1 TODO / "Nothing dispatched"). The PR body says the decision was "recorded as a decision in the wave-1 STATUS update" — that update is not in the tree. Record it in-tree (amend Done-when (a) + STATUS board), or the ticket gate and the code disagree.
2. Process tests still pin the obsolete Done-when
tests/test_timings.py docstring and _assert_exclusive_sum still require Σ exclusive ≈ total. test_process_sidecar_exclusive_keys_sum_to_total / test_native_page_records_extract_not_route use that pin, while test_total_is_independent_page_wall_not_the_stage_sum requires a measurable gap. Under the new semantics the process pin is wrong (inter-span gaps are exactly what independent total is for) and is a flake risk when those gaps exceed 1 ms. Drop _assert_exclusive_sum from process paths; assert remainder / independent wall instead.
3. CLI summary always prints zero timings
rollup_page_timings() always returns a fully-keyed zero dict. _print_summary feeds that straight into format_timings_summary_line, whose only empty check is if not timings_s — so non-agentic runs and all-resumed pre-B1 sidecars get route=0.0s … total=0.0s on the Success line. build_manifest already gates on has_page_timings; the CLI path must do the same (or treat all-zero as empty). No test covers the empty case.
Otherwise solid
- Sparse sidecar + restore round-trip + fingerprint / fragment / audit_events exclusion tested.
- Nested exclusive spans + OCR
extractunderroutevia_timed_route_provideris coherent; escalation stays untimed under tables as intended. - Escaping-exception finalize / clear (
8b13e18) is the right fix. 31bebd5gh222 whitespace pin is disclosed; fine as reindent fallout.
Nits (non-blocking): manual _route_span.__enter__/__exit__ (prefer with); unused add_exclusive.
Do not merge until 1–3 are fixed. Did not merge.
![cubic-dev-ai[bot]](https://avatars.githubusercontent.com/in/1082092?s=60&v=4){kind=small}
There was a problem hiding this comment.
4 issues found across 6 files
Prompt for AI agents (unresolved issues)
Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.
<file name="tests/test_timings.py">
<violation number="1" location="tests/test_timings.py:149">
P2: In the real-pipeline tests, `_assert_exclusive_sum` requires the sum of exclusive stage spans to equal the page `total` within 1 ms. `_PageStageClock.total` is the full wall from construction to `finalize()` and includes any time outside the named `span()` blocks (decision handling between stages, sidecar writes, overhead), which is exactly the unattributed remainder this PR makes visible. On a slower or loaded CI runner that remainder can exceed 1 ms, making these two tests flaky. Consider asserting `sum <= total` with a larger/relative epsilon (e.g. 0.01s) or only asserting the invariant on the fake-clock tests where the gap is exactly controlled.</violation>
<violation number="2" location="tests/test_timings.py:298">
P3: `test_native_page_records_extract_not_route` never checks the property it is named for: that a native page records extract and not route. It only asserts `extract >= 0.0`, which a mis-routed page would also satisfy. Add `assert meta['timings_s']['route'] == 0.0` (and ideally that `figures`/`tables` are 0.0) so the test actually pins the 'extract, not route' contract it claims to cover.</violation>
</file>
<file name="src/socr/core/manifest.py">
<violation number="1" location="src/socr/core/manifest.py:109">
P2: When no page has recorded timings, `rollup_page_timings` returns a truthy all-zero mapping, so the CLI prints fake `route=0.0s ... total=0.0s` timings on timing-disabled and non-agentic runs. Track whether a valid page timing mapping was seen and return `{}` when none was recorded.</violation>
</file>
<file name="src/socr/pipeline/orchestrator.py">
<violation number="1" location="src/socr/pipeline/orchestrator.py:6789">
P2: On every normal page, `clock.finalize()` runs before the `flush` span exits, so the span has not added its elapsed wall yet. Move finalization after the span closes so `flush` reports its I/O time while the later sidecar write remains excluded.</violation>
</file>
Reply with feedback, questions, or to request a fix.
Re-trigger cubic
|
|
||
|
|
||
| def _assert_exclusive_sum(timings: dict) -> None: | ||
| assert abs(exclusive_timings_sum(timings) - float(timings["total"])) <= 0.001 |
There was a problem hiding this comment.
P2: In the real-pipeline tests, _assert_exclusive_sum requires the sum of exclusive stage spans to equal the page total within 1 ms. _PageStageClock.total is the full wall from construction to finalize() and includes any time outside the named span() blocks (decision handling between stages, sidecar writes, overhead), which is exactly the unattributed remainder this PR makes visible. On a slower or loaded CI runner that remainder can exceed 1 ms, making these two tests flaky. Consider asserting sum <= total with a larger/relative epsilon (e.g. 0.01s) or only asserting the invariant on the fake-clock tests where the gap is exactly controlled.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At tests/test_timings.py, line 149:
<comment>In the real-pipeline tests, `_assert_exclusive_sum` requires the sum of exclusive stage spans to equal the page `total` within 1 ms. `_PageStageClock.total` is the full wall from construction to `finalize()` and includes any time outside the named `span()` blocks (decision handling between stages, sidecar writes, overhead), which is exactly the unattributed remainder this PR makes visible. On a slower or loaded CI runner that remainder can exceed 1 ms, making these two tests flaky. Consider asserting `sum <= total` with a larger/relative epsilon (e.g. 0.01s) or only asserting the invariant on the fake-clock tests where the gap is exactly controlled.</comment>
<file context>
@@ -0,0 +1,535 @@
+
+
+def _assert_exclusive_sum(timings: dict) -> None:
+ assert abs(exclusive_timings_sum(timings) - float(timings["total"])) <= 0.001
+ for key in PAGE_TIMING_EXCLUSIVE_KEYS:
+ assert key in timings
</file context>
| acc = {key: 0.0 for key in PAGE_TIMING_EXCLUSIVE_KEYS} | ||
| acc["total"] = 0.0 | ||
| for ps in state.pages.values(): | ||
| timings = coerce_page_timings(getattr(ps, "timings_s", None) or {}) | ||
| if not timings: | ||
| continue | ||
| for key in PAGE_TIMING_EXCLUSIVE_KEYS: | ||
| acc[key] += float(timings.get(key, 0.0) or 0.0) | ||
| acc["total"] += float(timings.get("total", 0.0) or 0.0) | ||
| return acc |
There was a problem hiding this comment.
P2: When no page has recorded timings, rollup_page_timings returns a truthy all-zero mapping, so the CLI prints fake route=0.0s ... total=0.0s timings on timing-disabled and non-agentic runs. Track whether a valid page timing mapping was seen and return {} when none was recorded.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At src/socr/core/manifest.py, line 109:
<comment>When no page has recorded timings, `rollup_page_timings` returns a truthy all-zero mapping, so the CLI prints fake `route=0.0s ... total=0.0s` timings on timing-disabled and non-agentic runs. Track whether a valid page timing mapping was seen and return `{}` when none was recorded.</comment>
<file context>
@@ -67,6 +68,56 @@
+
+def rollup_page_timings(state: DocumentState) -> dict[str, float]:
+ """Sum per-page ``timings_s`` into one document dict."""
+ acc = {key: 0.0 for key in PAGE_TIMING_EXCLUSIVE_KEYS}
+ acc["total"] = 0.0
+ for ps in state.pages.values():
</file context>
| acc = {key: 0.0 for key in PAGE_TIMING_EXCLUSIVE_KEYS} | |
| acc["total"] = 0.0 | |
| for ps in state.pages.values(): | |
| timings = coerce_page_timings(getattr(ps, "timings_s", None) or {}) | |
| if not timings: | |
| continue | |
| for key in PAGE_TIMING_EXCLUSIVE_KEYS: | |
| acc[key] += float(timings.get(key, 0.0) or 0.0) | |
| acc["total"] += float(timings.get("total", 0.0) or 0.0) | |
| return acc | |
| acc = {key: 0.0 for key in PAGE_TIMING_EXCLUSIVE_KEYS} | |
| seen = False | |
| for ps in state.pages.values(): | |
| timings = coerce_page_timings(getattr(ps, "timings_s", None) or {}) | |
| if not timings: | |
| continue | |
| seen = True | |
| for key in PAGE_TIMING_EXCLUSIVE_KEYS: | |
| acc[key] += float(timings.get(key, 0.0) or 0.0) | |
| acc["total"] += float(timings.get("total", 0.0) or 0.0) | |
| return acc if seen else {} |
| exc, | ||
| ) | ||
| self._flush_page_fragment(state, page_num, _body, output_dir) | ||
| ps.timings_s = clock.finalize() |
There was a problem hiding this comment.
P2: On every normal page, clock.finalize() runs before the flush span exits, so the span has not added its elapsed wall yet. Move finalization after the span closes so flush reports its I/O time while the later sidecar write remains excluded.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At src/socr/pipeline/orchestrator.py, line 6789:
<comment>On every normal page, `clock.finalize()` runs before the `flush` span exits, so the span has not added its elapsed wall yet. Move finalization after the span closes so `flush` reports its I/O time while the later sidecar write remains excluded.</comment>
<file context>
@@ -6229,466 +6292,516 @@ def _get_table_extractor():
- exc,
- )
+ self._flush_page_fragment(state, page_num, _body, output_dir)
+ ps.timings_s = clock.finalize()
+ self._flush_page_sidecar(
+ state, page_num, output_dir, terminal=False, record=_record
</file context>
|
|
||
| meta = _sidecar(out_dir) | ||
| _assert_exclusive_sum(meta["timings_s"]) | ||
| # Trusted native copies already-extracted text; it is not an OCR route. |
There was a problem hiding this comment.
P3: test_native_page_records_extract_not_route never checks the property it is named for: that a native page records extract and not route. It only asserts extract >= 0.0, which a mis-routed page would also satisfy. Add assert meta['timings_s']['route'] == 0.0 (and ideally that figures/tables are 0.0) so the test actually pins the 'extract, not route' contract it claims to cover.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At tests/test_timings.py, line 298:
<comment>`test_native_page_records_extract_not_route` never checks the property it is named for: that a native page records extract and not route. It only asserts `extract >= 0.0`, which a mis-routed page would also satisfy. Add `assert meta['timings_s']['route'] == 0.0` (and ideally that `figures`/`tables` are 0.0) so the test actually pins the 'extract, not route' contract it claims to cover.</comment>
<file context>
@@ -0,0 +1,535 @@
+
+ meta = _sidecar(out_dir)
+ _assert_exclusive_sum(meta["timings_s"])
+ # Trusted native copies already-extracted text; it is not an OCR route.
+ assert meta["timings_s"]["extract"] >= 0.0
+
</file context>
| # Trusted native copies already-extracted text; it is not an OCR route. | |
| assert meta["timings_s"]["extract"] >= 0.0 | |
| assert meta["timings_s"]["route"] == 0.0 |
1 participant
Summary
TICKET-B1 of
docs/plans/verifier-independence/. Measurement only — no threshold, no new status, no optimisation._PageStageClock(orchestrator.py): nested spans, children subtracted from parents, soroute / extract / tables / ladder / adjudication / figures / equations / flushare exclusive.totalis the independently measured page wall-clock from clock construction to finalize;total − Σ exclusiveis the unattributed remainder and is visible, not absorbed into a stage.timings_sin the page sidecar (absent when nothing was measured — existing byte-shape pins unchanged); restored in_restore_terminal_page_state; rolled up inManifest.timings_s; one summary line insocr process.audit_events.detail,canonical_page_texts, or_run_fingerprint. Final.mdbyte-identical with timings on/off (tested).try/finally: partial timings preserved and the clock cleared on an escaping exception (tested)._available_engines_for_agentic,_resolve_judge_modelpatched); pin-a-difference throughout, incl. a test that a constructedtotalwould erase a 50 ms gap.Provenance:
/curia— codex vs grok in worktrees, plus a Sonnet seat. All three initially definedtotal := Σ stages(tautological invariant); one relay, both conceded; grok's build chosen. Sonnet reviewer ACCEPT; Codex brain seat found the escaping-exception hole, fixed in8b13e18, then APPROVE-FOR-PR.31bebd5whitespace-normalises a pre-existing line-layout pin intest_gh222_probe_host.pythat the reindent tripped (behaviour pin beside it unchanged).Ticket text note: Done-when (a) said "exclusive keys sum to total"; the build deliberately reports the remainder instead. Recorded as a decision in the wave-1 STATUS update, not silently.
Test plan
PYTHONPATH=src ~/venvs/socr/bin/pytest tests -q→ 4108 passed, 4 xfailed, 0 failed (ollama absent fortests/test_timings.py).uvx ruff@0.16.0 format --check .clean.Summary by cubic
Adds per-page stage wall-clock timings to sidecars, manifest, and CLI summary. Previously pages had no timing data; now each page records exclusive stage timings (route, extract, tables, ladder, adjudication, figures, equations, flush) plus an independent page wall-clock total. Measurement only — no threshold, status, or optimization changes; output
.mdremains byte-identical.Written for commit 31bebd5. Summary will update on new commits.