PHASE 11Advanced ~24 min· topic 6 of 11

Topic 11.6

Observing Retrieval

In one line

When an answer is wrong, you need to know what retrieval did: which passages came back, with what scores, and how long each stage took. Structured log lines and trace spans record that, and a few metrics tell you when to look.

Think of it like this

A delivery company that records nothing can only say "your parcel is late". One that scans the parcel at every depot can say "it sat at depot 3 for two days". Scans are logs and traces. Without them, every complaint about a wrong RAG answer becomes a guessing game about which stage failed.

Words you'll meet

New words in this topic, in plain English. Come back here whenever one feels fuzzy.

Structured log: A log line made of named fields (key=value or JSON) so it can be searched and counted.
Request id: A unique label added to every log line and span of one request, so they can be gathered later.
Trace: The record of one request across all its stages.
Span: One stage in a trace: a name, start, end, parent and attributes.
Attribute: A small named value attached to a span or log line, such as index=8.
Metric: A number computed over many requests, such as a rate or a percentile.
Weak evidence: A request whose best retrieval score is low, so the answer rests on little.
Sampling: Keeping only a fraction of detailed records, to limit cost and data exposure.

Step by step

01Step 1: give every request an id

Create it at the edge (the API gateway or the first line of the handler) and pass it to every stage and every log line. Without it, lines from two requests mix and cannot be pulled apart.

02Step 2: log retrieval as one structured line

ts=1 event=retrieve req=r1 q_words=6 index=8 hits=D8:3,D10:2 top=3. Ids and scores let you replay the ranking. The index version says which contents it saw. No passage text is needed to debug a bad ranking.

log.pywhole filepython

log("retrieve", ["req=" + req, "index=" + str(INDEX_VERSION),
                  "hits=" + ",".join(d + ":" + str(s) for d, s in hits), "top=" + str(top)])

03Step 3: log the outcome

event=answer outcome=refused or outcome=answered prompt_words=47. Outcomes are what you count. A refusal is not an error, but a sudden rise in them is the clearest sign that retrieval broke.

04Step 4: parse and aggregate

Split each line into fields, then count. Refusal rate, mean top score, and the share of weak-evidence requests come out of a few lines of code. In production a log system does this for you; the example shows that the lines are enough.

05Step 5: wrap each stage in a span

Open a span before the stage, close it after, and give it the root span as parent. Attributes carry the facts that explain the timing: cache hit or miss, candidate count, prompt size.

Step 5: wrap each stage in a spandiagram

Rendering diagram…

06Step 6: alert on a few numbers

Pick metrics that change before users complain: refusal rate, weak-evidence share, empty results, index lag and p95 per stage. Alert on a change from the normal level, not on a magic number copied from a blog.

Try it yourself

1
Make a silent failure loud
In the log example change INDEX_VERSION to 9 for the last three questions only (set it inside the loop). Which log field shows the change? How would you alert on "the index version changed"?
2
Find the hidden time
In the span example add work(40) after the search span closes and before the work(5) line. What does the "not covered" line show? Which stage would you wrap next?
3
Lower the alert line
Change the refusal alert threshold from 25 to 30 percent. Does the alert still fire? What is a good way to choose the line for your own traffic?

Code & diagrams

Structured logs, then metrics read back from them New tab

The clock is a counter. Scores are the shared-word counts of the toy retriever used throughout the course.

Expected output

ts=1 event=retrieve req=r1 q_words=6 index=8 hits=D8:3,D10:2 top=3
ts=2 event=answer req=r1 outcome=answered prompt_words=47
ts=3 event=retrieve req=r2 q_words=7 index=8 hits=D2:5 top=5
ts=4 event=answer req=r2 outcome=answered prompt_words=27
ts=5 event=retrieve req=r3 q_words=10 index=8 hits=D1:2,D10:2 top=2
ts=6 event=answer req=r3 outcome=answered prompt_words=57
...
requests: 7
refusal rate: 28.6 percent
mean top score: 2.00
weak evidence (top <= 2): 5 of 7
ALERT: refusal rate above 25 percent

Trace spans as plain data New tab

A real tracing library stores the same fields. Here the clock advances only when work() is called.

Expected output

ask 0-510 (510 ms) req=r7 index=8
  embed 0-30 (30 ms) model=toy-v1 cache=miss
  search 30-75 (45 ms) hits=3 top=0.71
  rerank 80-200 (120 ms) candidates=20
  generate 200-510 (310 ms) prompt_tokens=1750 finish=stop
slowest child: generate (310 ms)
time not covered by any child span: 5 ms

Break it on purpose

Errors are the best teachers. Make each change, read the error, guess what went wrong, then reveal the answer.

Break #1

Forget to close a span

In the Python tab of the second example, delete the close_span(step) line that follows the rerank stage (the one after work(120)) and run.

terminal

$ Run

── what you'll see ──

ask 0-510 (510 ms) req=r7 index=8

embed 0-30 (30 ms) model=toy-v1 cache=miss

search 30-75 (45 ms) hits=3 top=0.71

rerank 80-80 (0 ms) candidates=20

generate 200-510 (310 ms) prompt_tokens=1750 finish=stop

slowest child: generate (310 ms)

time not covered by any child span: 125 ms

Myth vs fact

Myth

If there are no errors in the logs, retrieval is working.

Fact

A bad retrieval raises no error. Only scores, outcomes and sampled reviews can show it.

Myth

Log the full prompt and answer of every request, just in case.

Fact

That stores personal data and costs money. Log ids and scores for all requests, and sample full text for a small share with a short retention.

Myth

Tracing is only for microservices.

Fact

A RAG request is a pipeline of five or six stages, even in one process. Spans show where the time and the quality loss happen.

Pro corner

Extra depth for experienced readers. New to this? Skip it for now and come back later.

▸
Attach the index version and embedding model name to every trace. Many mysteries ("it worked yesterday") are explained by a version change (Topic 11.8).
▸
Log the retrieved ids even when the answer is refused, and the near misses just below the threshold. They show whether the threshold is cutting good passages (Topic 8.4).
▸
Sample full requests into a review queue and into the golden set (Topic 9.8). Production traffic is the best source of real questions.
▸
Keep cardinality in mind: a metric labelled with the question text creates a new time series for every question and can overwhelm a metrics system. Put high-cardinality values (ids, text) in logs and traces, and low-cardinality values (stage, outcome, model) in metrics.
▸
LLM Engineering Topics 11.3 and 11.4 cover tracing and metrics for model calls; the Observability course (/observability) covers collection, dashboards and alert design in general. This topic is the retrieval-specific part.

Remember this

1
Why retrieval needs its own observability. A normal service either works or throws an error. RAG fails quietly: the model still writes a fluent answer from the wrong passages. Nothing crashes, nothing is logged, and the first sign is a user saying "that is not what the policy says". To debug it you must be able to replay what retrieval returned for that question.
2
Structured logs. A structured log line is written as key=value pairs (or JSON) instead of a sentence, so machines can filter and count it. The example logs one retrieve line per question with a request id, the number of words in the question, the index version, the ids and scores of the hits (hits=D8:3,D10:2) and the top score, then one answer line with the outcome. The request id ties the lines together, so you can pull every line for one question.
3
What to log, what not to. Log ids, scores, versions, sizes, timings and outcomes: small, safe and enough to replay. Be careful with the text of questions and passages: they may hold personal data or secrets (Topic 10.5 and LLM Engineering Topic 11.2). Log a hash or a redacted form by default and keep full text only for a short time, behind access control, for sampled requests.
4
Metrics worth alerting on. Counts built from those lines: refusal rate (answers that said "not found"), the distribution of the top score, share of requests with weak evidence (a best score of 2 or less in the example), empty-result rate, prompt size, cache hit rate per stage, index lag (Topic 11.2), p95 latency per stage (Topic 11.4), cost per answered question (Topic 11.5). The example computes three from its own log: a 28.6 percent refusal rate (above the 25 percent alert line), a mean top score of 2.00 and 5 of 7 requests with weak evidence.
5
Traces. A trace follows one request through the stages. Each stage is a span: a name, a start, an end, a parent and a few attributes. The spans are plain data, as in the second example: ask is the parent of embed, search, rerank and generate, and each carries attributes like index=8 or prompt_tokens=1750. Read in order they show where time went. Tracing tools such as OpenTelemetry store exactly this shape, and the Observability course (/observability) shows how to collect and view it.
6
Look for the gaps. In the example, ask took 510 ms, but its children add up to 505. The missing 5 ms is code nobody wrapped in a span. A small gap is fine; a large one means a stage is hidden. The same view shows the slowest child (generation, 310 ms), and an attribute such as cache=miss explains why a request was slow. Spans plus attributes answer "which stage, and under what conditions".

Explain it without notes

Why does a RAG system need more than error logs?

What would you log for each retrieval, and what would you be careful not to log?

What is a span, and what do the gaps in a trace tell you?

Name four metrics you would alert on for a RAG service and what each can reveal.

Practice

Write parse_logfmt(line) that splits a line of key=value pairs separated by spaces into a dict (the value may contain =). Print the outcome of ts=2 event=answer req=r3 outcome=refused.

Write slowest(spans) taking a list of (name, start, end) tuples and returning the name of the one that took longest (the first, on a tie). Try it on three spans.

Trade-offs

↔
Logging more fields: easier debugging, more storage and a bigger privacy surface.
↔
Tracing every request: complete data, higher cost; sampling lowers cost and can miss rare failures (sample all errors and slow requests).
↔
Alerting on many metrics: early warnings, and alert fatigue when they are noisy.

Done when you can

Done when you can write a structured log line for one retrieval with ids, scores, versions and an outcome.
Done when you can explain why a request id is needed and where it is created.
Done when you can compute refusal rate and weak-evidence share from log lines.
Done when you can read a trace, find the slowest stage and the time no span covers.
Done when you can say what not to log and how to keep sampled full text safe.

Command Palette

Words you'll meet

Step by step

01Step 1: give every request an id

02Step 2: log retrieval as one structured line

03Step 3: log the outcome

04Step 4: parse and aggregate

05Step 5: wrap each stage in a span

06Step 6: alert on a few numbers

Try it yourself

Make a silent failure loud

Find the hidden time

Lower the alert line

Code & diagrams

Break it on purpose

Forget to close a span

Myth vs fact

Pro corner

Remember this

Explain it without notes

Practice

Trade-offs

Done when you can