engineering/arborist
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

add per-phase timings to query/ask output

Browse source 
Cache speedup was previously only visible by running 'time' externally.
Now every query/ask result includes a timings dict so the breakdown
shows up in the JSON itself:

  search_ms        FTS5 + title-LIKE across shards
  context_ms       load doc text into context window
  cache_lookup_ms  primary-key hit on providence_cache
  llm_ms           Hermes-3 round-trip (null on cache hit)
  persist_ms       insert record + chain audit event (null on cache hit)
  total_ms         end-to-end wall

Demo against the live shard cluster:

  Q "What is photosynthesis?" (cache miss):
    search 84.5  context 0.9  cache 0.1  llm 3983.3  persist 36.4
    total 4106.1 ms

  Q "What is photosynthesis?" (cache hit, same key):
    search 78.5  context 0.9  cache 0.1
    llm null     persist null
    total 85.7 ms      → 48x speedup

The cache lookup itself is 0.1 ms (PK on cache_key). The 85 ms hit
baseline is the cost of re-computing the 8-dim cache_key — context_root
depends on retrieval results, so search runs even on hits. A secondary
question-only cache could collapse this if needed, but the v9.8
admissibility model wants context_root in the key.

Same shape for ask (per-doc Q&A).

66 tests still passing.
This commit is contained in:
russell@unturf.com 2026-04-27 12:36:30 -04:00
parent c6182ae54e
commit 641a4c8bde
No known key found for this signature in database
2 changed files with 68 additions and 5 deletions
Download patch file Download diff file Expand all files Collapse all files

54
aborist/qa/query.py
View file

@ -309,16 +309,25 @@ def query(
) -> dict:
"""Answer `question` using the corpus. Cache to qa_db. Returns a result dict."""
policy = policy or DEFAULT_QUERY_POLICY
t_start = time.monotonic()
# 1. Search.
t_phase = time.monotonic()
hits = _search_corpus(shards_dir, single_db, question, over_fetch)
if not hits:
return {"status": "no_sources", "msg": "FTS5 search returned no hits"}
# 1b. Rerank — title-boost gives topically-named docs priority over
# body-only matches like Tell_(poker) for "tell me about ...".
return {
"status": "no_sources",
"msg": "FTS5 search returned no hits",
"timings": {
"search_ms": _ms_since(t_phase),
"total_ms": _ms_since(t_start),
},
}
hits = _rerank(hits, question)
search_ms = _ms_since(t_phase)
# 2. Pull doc texts within budget.
t_phase = time.monotonic()
chosen: list[_Hit] = []
context_parts: list[str] = []
char_budget = max_context_chars
@ -337,9 +346,17 @@ def query(
break
if not chosen:
return {"status": "no_sources", "msg": "top-k hits had cold or empty content"}
return {
"status": "no_sources",
"msg": "top-k hits had cold or empty content",
"timings": {
"search_ms": search_ms,
"context_ms": _ms_since(t_phase),
"total_ms": _ms_since(t_start),
},
}
context = "\n\n".join(context_parts)
context_ms = _ms_since(t_phase)
# 3. Build messages + hashes.
messages = [
@ -368,11 +385,13 @@ def query(
qa_conn = connect(qa_db)
try:
# 4. Cache lookup.
t_phase = time.monotonic()
cached = qa_conn.execute(
"SELECT * FROM providence_cache "
"WHERE cache_key = ? AND falsification_state = 'live'",
(ckey,),
).fetchone()
cache_lookup_ms = _ms_since(t_phase)
if cached is not None:
now = int(time.time())
with transaction(qa_conn):
@ -389,9 +408,18 @@ def query(
"context_root": context_root,
"answer_text": cached["answer_text"],
"sources": json.loads(cached["merkle_proof"])["sources"],
"timings": {
"search_ms": search_ms,
"context_ms": context_ms,
"cache_lookup_ms": cache_lookup_ms,
"llm_ms": None,
"persist_ms": None,
"total_ms": _ms_since(t_start),
},
}
# 5. Cache miss — call LLM.
t_phase = time.monotonic()
answer_text = chat_client.chat_completion(
messages,
model=model_id,
@ -399,8 +427,10 @@ def query(
max_tokens=policy["max_tokens"],
top_p=policy.get("top_p", 1.0),
)
llm_ms = _ms_since(t_phase)
# 6. Persist record + audit event.
t_phase = time.monotonic()
proof_obj = {
"context_root": context_root,
"sources": [
@ -463,6 +493,7 @@ def query(
finally:
qa_conn.close()
persist_ms = _ms_since(t_phase)
return {
"status": "cache_miss_then_written",
"audit_mode": "STRICT",
@ -470,4 +501,17 @@ def query(
"context_root": context_root,
"answer_text": answer_text,
"sources": proof_obj["sources"],
"timings": {
"search_ms": search_ms,
"context_ms": context_ms,
"cache_lookup_ms": cache_lookup_ms,
"llm_ms": llm_ms,
"persist_ms": persist_ms,
"total_ms": _ms_since(t_start),
},
}
def _ms_since(t: float) -> float:
"""Wall-time elapsed in milliseconds, rounded to 1 decimal."""
return round((time.monotonic() - t) * 1000, 1)

19
aborist/qa/runner.py
View file

@ -42,6 +42,10 @@ DEFAULT_POLICY = {
}
def _ms_since(t: float) -> float:
return round((time.monotonic() - t) * 1000, 1)
def ask(
conn: sqlite3.Connection,
*,
@ -56,6 +60,7 @@ def ask(
) -> dict:
"""Look up cached answer or run inference. Returns a result dict."""
policy = policy or DEFAULT_POLICY
t_start = time.monotonic()
doc = conn.execute(
"SELECT document_uri, chunking_version FROM documents "
@ -103,11 +108,13 @@ def ask(
doc["chunking_version"],
)
t_lookup = time.monotonic()
cached = conn.execute(
"SELECT * FROM providence_cache "
"WHERE cache_key = ? AND falsification_state = 'live'",
(ckey,),
).fetchone()
cache_lookup_ms = _ms_since(t_lookup)
if cached is not None:
with transaction(conn):
now = int(time.time())
@ -124,8 +131,14 @@ def ask(
"source_root": document_root,
"answer_text": cached["answer_text"],
"merkle_proof": json.loads(cached["merkle_proof"]),
"timings": {
"cache_lookup_ms": cache_lookup_ms,
"llm_ms": None,
"total_ms": _ms_since(t_start),
},
}
t_llm = time.monotonic()
answer_text = client.chat_completion(
messages,
model=model_id,
@ -133,6 +146,7 @@ def ask(
max_tokens=policy["max_tokens"],
top_p=policy.get("top_p", 1.0),
)
llm_ms = _ms_since(t_llm)
leaves = [bytes.fromhex(r["leaf_hash"]) for r in chunk_rows]
tree = MerkleTree.build(leaves)
@ -193,4 +207,9 @@ def ask(
"source_root": document_root,
"answer_text": answer_text,
"merkle_proof": proof_obj,
"timings": {
"cache_lookup_ms": cache_lookup_ms,
"llm_ms": llm_ms,
"total_ms": _ms_since(t_start),
},
}