feat(telemetry): a read surface over retrieval_logs — the tuning loop had no read half (#2975)
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 7s
CI & Build / integration (push) Successful in 25s
CI & Build / TypeScript typecheck (push) Successful in 33s
CI & Build / Python tests (push) Successful in 1m3s
CI & Build / Build & push image (push) Successful in 20s
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 7s
CI & Build / integration (push) Successful in 25s
CI & Build / TypeScript typecheck (push) Successful in 33s
CI & Build / Python tests (push) Successful in 1m3s
CI & Build / Build & push image (push) Successful in 20s
`retrieval_logs` was write-only. `record_retrieval` inserted rows and nothing in the tree ever selected from them: the only `select()` over RetrievalLog lived in a test. So #1038's gate — "build the reranker once telemetry shows precision is the bottleneck" — was unsatisfiable by construction, and the one real tuning decision on record (the 0.68 write-path threshold, #2223) had to be reached by hand-probing the live instance with eight payloads. This adds the half that was missing. `retrieval_summary(user_id, days=30)` returns two aggregates side by side, each read from the table built for it — NOT a join. NoteUsageEvent's docstring is explicit that the two are complements ("RetrievalLog tunes the threshold, this tunes the corpus") and that RetrievalLog's JSONB `result_ids` cannot be indexed at the per-note grain, so correlating through it would be both slower and less honest than reading each source directly. That corrects the approach sketched on the task. - `sources`, per surface: calls, zero_result_calls, cleared_threshold (how often the best hit beat the threshold in force for THAT call), the top_score spread as p10/p50/p90/min/max, avg_result_count, p90 duration. Zero-result calls are counted apart from low-scoring ones — they are a different failure and averaging them together would hide both. - `usage`, from note_usage_events: ranked surfacings, ambient surfacings, and pulls split into `pulled_by_agent` / `pulled_by_human`. That split is not decoration. NoteUsageEvent's own comment says the mcp_/rest_ prefix is load-bearing and names #1038 while saying so: "is this dead weight?" is answered by any pull, "was that injected line useful?" only by an agent pull. `pull_through` exists to answer the second, so it counts agent pulls over ranked surfacings; both halves ship so the first stays answerable. Two things the code made me get right rather than guess: - Distinct-note counts get their own queries. `count(distinct note_id)` per (event, source) group cannot be summed across groups — a note surfaced by two sources is one distinct note and would be counted twice. A wrong number labelled "distinct" is worse than no number. - No CASE in the GROUP BY. #2663 is the bug where a second case() rendered its own expanding bind names, Postgres rejected the query, a broad except swallowed it, and every counter read zero in production while mocked tests passed. Grouping on raw `source` and classifying in Python cannot fail that way. For the same reason the readout distinguishes `read_failed` from an empty window, and its tests are integration against real Postgres — percentile_cont ... WITHIN GROUP only proves it parses against a database. Exposed as the `retrieval_telemetry` MCP tool, added to `_READ_ONLY_TOOLS`: it mutates nothing, but its name carries no read prefix, so the completeness test cannot derive it and it would otherwise have failed closed for read-only keys in silence — the same reason `enter_project` is spelled out there. Docs updated to name both exceptions rather than leave the rule looking derivable. Scoped to the caller's own telemetry: a retrieval log records what one user's agent asked for, query text included, and is not a shared record kind — the owner filter is the whole access rule, not a shortcut past access.py. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
@@ -112,6 +112,11 @@ _READ_ONLY_TOOLS = frozenset({
|
||||
# The shape ledger's todo query (#2789). Reads only — classify_shapes is
|
||||
# the write, and it is deliberately NOT here.
|
||||
"list_shapes", "shape_history",
|
||||
# The retrieval telemetry readout (#2975). Aggregates two log tables and
|
||||
# writes nothing. Listed explicitly because its name carries no read
|
||||
# prefix, so the completeness test below cannot derive it — the same
|
||||
# reason `enter_project` is spelled out above.
|
||||
"retrieval_telemetry",
|
||||
})
|
||||
|
||||
# Read-SHAPED tools that must NOT be reachable with a read key — a getter that
|
||||
|
||||
@@ -12,7 +12,7 @@ import time
|
||||
from scribe.mcp._context import current_user_id
|
||||
from scribe.services.access import owner_names_for
|
||||
from scribe.services.embeddings import DEFAULT_SIMILARITY_THRESHOLD, semantic_search_notes
|
||||
from scribe.services.retrieval_telemetry import record_retrieval
|
||||
from scribe.services.retrieval_telemetry import record_retrieval, retrieval_summary
|
||||
|
||||
|
||||
async def search(
|
||||
@@ -95,5 +95,52 @@ async def search(
|
||||
}
|
||||
|
||||
|
||||
async def retrieval_telemetry(days: int = 30) -> dict:
|
||||
"""What the retrieval telemetry says about YOUR surfaces, over a window.
|
||||
|
||||
The read half of the loop the ranker's thresholds are meant to be tuned
|
||||
from (#2975). Reach for it before changing a similarity threshold, a top-k,
|
||||
or deciding whether a reranker is worth building — the alternative is
|
||||
hand-probing the live instance, which is how the last such decision had to
|
||||
be made.
|
||||
|
||||
Two readouts, from the two tables built for them:
|
||||
|
||||
`sources` — per retrieval surface (`auto_inject`, `write_path`,
|
||||
`mcp_search`, …), from `retrieval_logs`: `calls`, `zero_result_calls`,
|
||||
`cleared_threshold` (how often the best hit beat the threshold in force for
|
||||
that call), the `top_score` spread (p10/p50/p90/min/max), `avg_result_count`
|
||||
and `p90_duration_ms`. THE number to read first is `cleared_threshold`
|
||||
against `calls`, with the spread beside it: a surface that clears its bar
|
||||
on nearly every call is either well-tuned or too loose, and p10 says which.
|
||||
|
||||
`usage` — from `note_usage_events`, at the per-note grain
|
||||
`retrieval_logs` cannot be indexed at: `surfaced` (ranked surfacings — a
|
||||
scored surface CHOSE the record), `ambient` (the rest), `pulled` split into
|
||||
`pulled_by_agent` / `pulled_by_human`, the distinct-note counts, and
|
||||
`pull_through`. That ratio is the corpus-side precision signal: records
|
||||
surfaced often and opened never are dead weight competing for the injection
|
||||
budget every turn.
|
||||
|
||||
`pull_through` is AGENT pulls over RANKED surfacings, and both halves of
|
||||
that matter. "Is this record dead weight?" is answered by any pull; "was
|
||||
that injected line useful?" — the question a threshold or a reranker is
|
||||
tuned against — only by a pull the agent made. Aggregating across the
|
||||
mcp_/rest_ prefix would silently answer the wrong one.
|
||||
|
||||
Scoped to your own telemetry — a retrieval log records what your agent
|
||||
asked for, query text included, and is not a shared record kind.
|
||||
|
||||
`read_failed: true` means the query itself failed — deliberately distinct
|
||||
from an empty window, because those two looked identical for weeks once
|
||||
(#2663) and every counter silently read zero.
|
||||
|
||||
Args:
|
||||
days: window size, default 30. Clamped to at least 1.
|
||||
"""
|
||||
return await retrieval_summary(current_user_id(), days=days)
|
||||
|
||||
|
||||
def register(mcp) -> None:
|
||||
mcp.tool(name="search")(search)
|
||||
mcp.tool(name="retrieval_telemetry")(retrieval_telemetry)
|
||||
|
||||
@@ -18,8 +18,14 @@ from __future__ import annotations
|
||||
import asyncio
|
||||
import logging
|
||||
|
||||
from datetime import datetime, timedelta, timezone
|
||||
|
||||
from sqlalchemy import case, func, select
|
||||
|
||||
from scribe.models import async_session
|
||||
from scribe.models.base import iso
|
||||
from scribe.models.note import Note
|
||||
from scribe.models.note_usage import PULLED, SURFACED, NoteUsageEvent
|
||||
from scribe.models.retrieval_log import RetrievalLog
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
@@ -135,3 +141,205 @@ def record_retrieval(
|
||||
return
|
||||
_pending.add(task)
|
||||
task.add_done_callback(_pending.discard)
|
||||
|
||||
|
||||
# --- The read half (#2975) ---------------------------------------------------
|
||||
# Until this existed, `retrieval_logs` was WRITE-ONLY: rows accrued and the only
|
||||
# `select()` over them in the whole tree lived in a test. That made #1038's gate
|
||||
# — "build the reranker once telemetry shows precision is the bottleneck" —
|
||||
# unsatisfiable by construction, and it is why the one real tuning decision on
|
||||
# record (the 0.68 write-path threshold, #2223) was reached by hand-probing the
|
||||
# live instance with eight payloads instead of by reading what was collected.
|
||||
|
||||
def _bucket(rows: list) -> dict:
|
||||
"""A score readout a human can act on, from one aggregate row."""
|
||||
calls, zero, cleared, p10, p50, p90, lo, hi, avg_n, dur = rows
|
||||
return {
|
||||
"calls": int(calls or 0),
|
||||
# A call that returned nothing is not a low-scoring call — it is a
|
||||
# different failure (nothing indexed, filter too narrow), and averaging
|
||||
# it into the score distribution would hide both.
|
||||
"zero_result_calls": int(zero or 0),
|
||||
# How often the best hit actually cleared the threshold in force for
|
||||
# that call. THE precision-adjacent number: a surface that clears its
|
||||
# bar on almost every call is either well-tuned or too loose, and the
|
||||
# score spread below says which.
|
||||
"cleared_threshold": int(cleared or 0),
|
||||
"top_score": {
|
||||
"p10": _round(p10), "p50": _round(p50), "p90": _round(p90),
|
||||
"min": _round(lo), "max": _round(hi),
|
||||
},
|
||||
"avg_result_count": _round(avg_n),
|
||||
"p90_duration_ms": _round(dur, 1),
|
||||
}
|
||||
|
||||
|
||||
def _round(v, places: int = 4):
|
||||
return None if v is None else round(float(v), places)
|
||||
|
||||
|
||||
async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
"""What the retrieval telemetry says, per surface, over a window.
|
||||
|
||||
Two aggregates side by side, each read from the table built for it — NOT a
|
||||
join. `NoteUsageEvent`'s own docstring is explicit that the two are
|
||||
complements ("RetrievalLog tunes the threshold, this tunes the corpus") and
|
||||
that RetrievalLog's JSONB `result_ids` "can't be indexed at" the per-note
|
||||
grain. So the score distribution comes from `retrieval_logs` on its indexed
|
||||
columns, and surfaced-vs-pulled comes from `note_usage_events` at the grain
|
||||
it was built for. Reading each from its own table is both cheaper and more
|
||||
honest than correlating them through JSONB.
|
||||
|
||||
Scoped to one user's own telemetry. There is no sharing model for a
|
||||
retrieval log — it records what THIS user's agent asked for, including the
|
||||
query text — so an owner filter is the whole access rule here rather than a
|
||||
shortcut around `services/access.py` (P#78 governs shared record kinds).
|
||||
|
||||
Never raises: a telemetry readout that can break its caller is worse than
|
||||
no readout. It does distinguish "no rows" from "the read failed", because
|
||||
#2663 is exactly the bug where those two looked identical for weeks.
|
||||
"""
|
||||
since = datetime.now(timezone.utc) - timedelta(days=max(1, int(days)))
|
||||
out: dict = {
|
||||
"window_days": int(days),
|
||||
"since": iso(since),
|
||||
"sources": {},
|
||||
"usage": {},
|
||||
"read_failed": False,
|
||||
}
|
||||
|
||||
cleared = case(
|
||||
(
|
||||
(RetrievalLog.threshold.isnot(None))
|
||||
& (RetrievalLog.top_score.isnot(None))
|
||||
& (RetrievalLog.top_score >= RetrievalLog.threshold),
|
||||
1,
|
||||
),
|
||||
else_=0,
|
||||
)
|
||||
zero = case((RetrievalLog.result_count == 0, 1), else_=0)
|
||||
|
||||
def pct(p: float):
|
||||
return func.percentile_cont(p).within_group(RetrievalLog.top_score.asc())
|
||||
|
||||
try:
|
||||
async with async_session() as session:
|
||||
rows = (
|
||||
await session.execute(
|
||||
select(
|
||||
RetrievalLog.source,
|
||||
func.count().label("calls"),
|
||||
func.sum(zero).label("zero"),
|
||||
func.sum(cleared).label("cleared"),
|
||||
pct(0.1), pct(0.5), pct(0.9),
|
||||
func.min(RetrievalLog.top_score),
|
||||
func.max(RetrievalLog.top_score),
|
||||
func.avg(RetrievalLog.result_count),
|
||||
func.percentile_cont(0.9).within_group(
|
||||
RetrievalLog.duration_ms.asc()
|
||||
),
|
||||
)
|
||||
.where(
|
||||
RetrievalLog.created_at >= since,
|
||||
RetrievalLog.user_id == user_id,
|
||||
)
|
||||
.group_by(RetrievalLog.source)
|
||||
)
|
||||
).all()
|
||||
for row in rows:
|
||||
out["sources"][row[0]] = _bucket(list(row[1:]))
|
||||
|
||||
# The corpus side, at its own grain. `ambient` mirrors
|
||||
# note_usage.usage_for_notes: an ambient surfacing was not a scored
|
||||
# CHOICE, so folding it into pull-through would understate it.
|
||||
# Grouped by RAW source, then classified in Python. The
|
||||
# alternative — CASE expressions in the GROUP BY — is the shape
|
||||
# that produced #2663: a second case() renders its own expanding
|
||||
# bind names, the database sees two different expressions and
|
||||
# rejects the query, and the broad except swallows it. One CASE is
|
||||
# provably fine (usage_for_notes does it); two is where it broke.
|
||||
# `source` has a handful of distinct values, so grouping on it
|
||||
# directly is cheap and cannot fail that way at all.
|
||||
urows = (
|
||||
await session.execute(
|
||||
select(
|
||||
NoteUsageEvent.event,
|
||||
NoteUsageEvent.source,
|
||||
func.count().label("n"),
|
||||
)
|
||||
.where(
|
||||
NoteUsageEvent.created_at >= since,
|
||||
NoteUsageEvent.user_id == user_id,
|
||||
)
|
||||
.group_by(NoteUsageEvent.event, NoteUsageEvent.source)
|
||||
)
|
||||
).all()
|
||||
|
||||
# Distinct-note counts need their OWN queries, and this is not
|
||||
# fussiness: count(distinct note_id) per (event, source) group
|
||||
# cannot be summed across groups — a note surfaced by two sources
|
||||
# is one distinct note and would be counted twice. A wrong number
|
||||
# labelled "distinct" is worse than no number.
|
||||
from scribe.services.note_usage import AMBIENT_SOURCES as _AMB
|
||||
|
||||
distinct_surfaced = (
|
||||
await session.execute(
|
||||
select(func.count(func.distinct(NoteUsageEvent.note_id))).where(
|
||||
NoteUsageEvent.created_at >= since,
|
||||
NoteUsageEvent.user_id == user_id,
|
||||
NoteUsageEvent.event == SURFACED,
|
||||
NoteUsageEvent.source.notin_(_AMB),
|
||||
)
|
||||
)
|
||||
).scalar_one()
|
||||
distinct_pulled = (
|
||||
await session.execute(
|
||||
select(func.count(func.distinct(NoteUsageEvent.note_id))).where(
|
||||
NoteUsageEvent.created_at >= since,
|
||||
NoteUsageEvent.user_id == user_id,
|
||||
NoteUsageEvent.event == PULLED,
|
||||
)
|
||||
)
|
||||
).scalar_one()
|
||||
except Exception:
|
||||
logger.warning("retrieval summary read failed", exc_info=True)
|
||||
out["read_failed"] = True
|
||||
return out
|
||||
|
||||
from scribe.services.note_usage import AMBIENT_SOURCES
|
||||
|
||||
usage = {
|
||||
"surfaced": 0, "ambient": 0,
|
||||
"pulled": 0, "pulled_by_agent": 0, "pulled_by_human": 0,
|
||||
"distinct_notes_surfaced": int(distinct_surfaced or 0),
|
||||
"distinct_notes_pulled": int(distinct_pulled or 0),
|
||||
}
|
||||
for event, source, n in urows:
|
||||
n = int(n)
|
||||
if event == SURFACED:
|
||||
if source in AMBIENT_SOURCES:
|
||||
usage["ambient"] += n
|
||||
else:
|
||||
usage["surfaced"] += n
|
||||
elif event == PULLED:
|
||||
usage["pulled"] += n
|
||||
# The mcp_/rest_ split is load-bearing (see NoteUsageEvent's own
|
||||
# comment, which names #1038 — this readout's whole purpose). "Is
|
||||
# this record dead weight?" is answered by ANY pull; "was that
|
||||
# injected line useful to the agent?" only by an AGENT pull. So
|
||||
# pull-through, which exists to answer the second, counts mcp_*
|
||||
# only. Both halves are reported so the first question is still
|
||||
# answerable from the same payload.
|
||||
if source.startswith("mcp_"):
|
||||
usage["pulled_by_agent"] += n
|
||||
else:
|
||||
usage["pulled_by_human"] += n
|
||||
# Ranked surfacings in the denominator, agent pulls in the numerator: the
|
||||
# "surfaced often, opened never" reading is only valid where a scored
|
||||
# surface CHOSE the record and an agent was the one who declined it.
|
||||
usage["pull_through"] = (
|
||||
round(usage["pulled_by_agent"] / usage["surfaced"], 4)
|
||||
if usage["surfaced"] else None
|
||||
)
|
||||
out["usage"] = usage
|
||||
return out
|
||||
|
||||
Reference in New Issue
Block a user