From 0177c2d2786b893bf825f5489508a63d353a4750 Mon Sep 17 00:00:00 2001 From: "russell@unturf.com" Date: Sat, 2 May 2026 11:49:36 -0400 Subject: [PATCH] cli(query): per-phase timings line in human-readable render MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Surfaces where the per-call cost lands. The audit-line `7.5s` already shows total_ms but it's hidden inline with the verdict & cache_status. The new `timings:` line (after `capacity:`) breaks total wall-clock into its components so an operator can see at a glance whether a slow query was Hermes-bound, search-bound, or something else. Format: timings: cache 0.00s · search 0.30s · context 0.16s · llm 6.50s · persist 0.20s · **total 7.16s** Skipped phases (cache=0 on cache-miss; persist=0 on cache-hit; context=0 when retrieval pre-loaded) are filtered so the line stays compact. **total** stays bold to match the audit-line elapsed value already on screen. JSON mode (`--json`) already exposes `timings` — this just lifts the same data into the human render. Tests pass (641 / -n auto / 11s). --- aborist/cli.py | 26 ++++++++++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/aborist/cli.py b/aborist/cli.py index c97fb9c..2d6b142 100644 --- a/aborist/cli.py +++ b/aborist/cli.py @@ -794,6 +794,32 @@ def _render_query_human(result: dict, question: str) -> str: f"answer {result.get('answer_chars', 0):,} chars" ) + # Per-phase timings — surfaces where the per-call cost lands. + # Hermes-bound queries should show `llm_ms` dominating; if + # search_ms or persist_ms creeps up that's a retrieval / WAL + # signal the operator wants visible. Cache-hit rows skip llm + # entirely so the breakdown also tells you which path you're + # paying for. + timings = result.get("timings") or {} + if timings: + parts: list[str] = [] + order = ( + ("cache_lookup_ms", "cache"), + ("search_ms", "search"), + ("context_ms", "context"), + ("llm_ms", "llm"), + ("persist_ms", "persist"), + ) + for key, label in order: + v = timings.get(key) + if isinstance(v, (int, float)) and v > 0: + parts.append(f"{label} {v / 1000:.2f}s") + total = timings.get("total_ms") + if isinstance(total, (int, float)): + parts.append(f"**total {total / 1000:.2f}s**") + if parts: + lines.append("timings: " + " · ".join(parts)) + # Reference-frame notes (Ticket #000002). When detect_frame # classified the query as `reference`, surface the named work # so an operator knows the substrate routed to a fictional