Tracing and Logging LLM Calls

You cannot debug what you cannot see

An LLM request is a pipeline, so a trace is a tree of spans: handle request, retrieve, rerank, model call, validate, each with start time, duration and attributes (model, token counts, number of chunks, validation result, release ID). With traces you can answer "why was this slow?" (the model call took 1.2 of 1.6 seconds), "why was it wrong?" (retrieval returned the wrong chunk), and "what did it cost?". Log enough to reproduce a problem: the release ID, the final prompt (or a reference to it), retrieved document IDs, tool calls and results, the raw output and the parsed output, plus user feedback. Balance this against privacy: redact personal data, restrict access, and set retention limits. Standard tools (OpenTelemetry-compatible tracing and LLM-specific observability platforms) provide spans, dashboards and search; the concept is the same as in the example.

See it, bound it, recover

Traces show what happened, drift detection shows what changed, and layered failure handling keeps users served.

A request trace as a tree, run

I ran this with plain Python 3 (standard library only). The trace shows a 1.62 s request whose child steps are retrieve (0.18 s), rerank (0.11 s), the model call (1.20 s, with token counts) and output validation (0.01 s). The slowest child step is the model call. The timings are made up to illustrate the structure.

class Tracer:
    def __init__(self): self.t = 0.0; self.events = []; self.depth = 0
    def span(self, name, duration, attrs=None):
        start = self.t
        self.events.append((self.depth, name, start, duration, attrs or {}))
        return self
    def advance(self, d): self.t += d

tr = Tracer()
tr.span("handle_request", 1.62); tr.depth = 1
tr.span("retrieve", 0.18, {"chunks": 5}); tr.advance(0.18)
tr.span("rerank", 0.11, {"kept": 3}); tr.advance(0.11)
tr.span("llm_call", 1.20, {"in_tokens": 1450, "out_tokens": 210, "model": "model-a"}); tr.advance(1.20)
tr.span("validate_output", 0.01, {"valid": True}); tr.advance(0.01)
for depth, name, start, dur, attrs in tr.events:
    print("  " * depth + f"{name:16} start {start:5.2f}s  took {dur:4.2f}s  {attrs if attrs else ''}")
slowest = max((e for e in tr.events if e[0] == 1), key=lambda e: e[3])
print("slowest step:", slowest[1])

Output:

handle_request   start  0.00s  took 1.62s  
  retrieve         start  0.00s  took 0.18s  {'chunks': 5}
  rerank           start  0.18s  took 0.11s  {'kept': 3}
  llm_call         start  0.29s  took 1.20s  {'in_tokens': 1450, 'out_tokens': 210, 'model': 'model-a'}
  validate_output  start  1.49s  took 0.01s  {'valid': True}
slowest step: llm_call

Log the release ID

Every trace should say which prompt and model bundle produced it.

Quick check: What does a trace let you do that an aggregate metric does not?

• Hide failures
• Make the model smarter
• Remove the need for tests
• See where time and errors occurred inside one specific request