Debugging

Most debugging is guessing, and it works often enough to pass for a method. It stops working on the failures that matter in AI systems: no exception, no stack trace, just an answer that is quietly wrong. This section is a procedure instead — reproduce it, form a hypothesis you could disprove, then halve the search space until one explanation is left standing. It covers reading someone else's stack trace, chasing intermittent failures, and the particular problem of debugging something that never errors.

The loop#

1. 1.Reproduce it reliably. Everything else is guesswork until you can.
2. 2.Form one hypothesis about the cause.
3. 3.Design the cheapest experiment that could prove it wrong.
4. 4.Run it. Update. Repeat.

The discipline is trying to falsify rather than confirm. Looking for evidence that supports your hypothesis will always find some, and you will fix the wrong thing.

One hypothesis at a time is the part people drop under pressure. Change three things and watch the symptom go away, and all you have learnt is that one of the three mattered; you now have to keep all three forever, because you do not know which. Change one and you learn something either way. If the symptom persists you have ruled a cause out, and ruling causes out is most of what debugging is.

Reproduce it first#

Everything after this step is cheap and everything before it is guesswork, so reproduction deserves more effort than it usually gets. A reproduction is not the bug report. It is a command you can run that fails, in under a minute, on your machine. Three things make one: the exact input, saved to a file rather than described; the exact versions, pinned, including the model, because a provider updating a default is invisible from your side; and the exact state, because a bug that only appears on a warm cache is a different bug from the one you are about to chase.

When you have it, write it down as a test that fails. It costs two minutes, it stops the reproduction quietly rotting, and it is the only evidence anyone will accept later that you actually fixed the thing.

Reading a stack trace#

Read it bottom upwards. The last line is the exception type and its message, and the message is usually precise about what went wrong. The lines above are the call path with the innermost frame last. The frame you want is the last one that is your own code, because the library beneath it is almost always doing exactly what it was asked to do.

import os, traceback

def load_config(raw):                 # library code, doing what it was asked
    return {k: v for k, v in (line.split("=") for line in raw.splitlines() if line)}

def read_settings(raw):               # yours
    return load_config(raw)

def start(raw):                       # yours
    return read_settings(raw)["model"]

try:
    start("model=haiku\nretries=3\nnote=written by an = sign")
except Exception:
    here = os.path.dirname(os.path.abspath(__file__)) + "/"
    print(traceback.format_exc().replace(here, ""))

# Traceback (most recent call last):
#   File "settings.py", line 13, in <module>
#     start("model=haiku\nretries=3\nnote=written by an = sign")
#     ~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
#   File "settings.py", line 10, in start
#     return read_settings(raw)["model"]
#            ~~~~~~~~~~~~~^^^^^
#   File "settings.py", line 7, in read_settings
#     return load_config(raw)
#   File "settings.py", line 4, in load_config
#     return {k: v for k, v in (line.split("=") for line in raw.splitlines() if line)}
#                      ^^^^
# ValueError: too many values to unpack (expected 2, got 3)

Work it from the bottom. The exception is a ValueError and the message says three values where two were expected, which is a complete description of the bug before you have looked at any code. The innermost frame is load_config, and it is where the fix goes: split on the first equals sign only. The two frames above it, both yours, are innocent — they passed the string along. And the input that triggered it is right there in the top frame: a value with an equals sign inside it. Reading the message carefully was faster than any debugger would have been.

Two habits follow. Read the whole message, numbers included, before scrolling anywhere. And when every frame is library code, you are almost certainly handing something the wrong shape, so find the last frame that is yours and print what it passed.

Halve the space#

Rather than inspecting from the start, test the midpoint. Is the data correct halfway through the pipeline? That one question eliminates half the system, and repeating it finds the cause in a handful of steps regardless of size.

parse -> chunk -> embed -> index -> retrieve -> rerank -> generate

Check the retrieved chunks first. Correct means the problem is
downstream, in generation. Wrong means it is upstream, and you
have removed four stages with one check.

Three things are worth halving and they are the same move applied to different axes: the pipeline, as above; the commit history, when it worked last week and does not now; and the input, when one document in forty thousand brings the run down. Each turns a linear search into a logarithmic one, which is the difference between an afternoon and ten minutes.

Bisecting the commit history#

git bisect does this for you. Its value is entirely in the logarithm: a thousand commits is ten tests rather than five hundred. What people get wrong is the test itself. Write a script that exits zero when the commit is good and non-zero when it is bad, check it by hand against the known-good and known-bad ends before starting, and then let bisect run unattended with git bisect run.

import math

commits = [f"c{i:03d}" for i in range(1000)]
BROKE_AT = 617                       # the answer, which you do not know

def test(i):
    """Stands in for git bisect run: true if this commit is good."""
    return i < BROKE_AT

lo, hi, steps = 0, len(commits) - 1, 0     # lo known good, hi known bad
assert test(lo) and not test(hi)
while hi - lo > 1:
    mid = (lo + hi) // 2
    steps += 1
    good = test(mid)
    print(f"  step {steps:>2}: {hi - lo:>4} commits left, testing {commits[mid]} -> "
          f"{'good' if good else 'bad'}")
    if good:
        lo = mid
    else:
        hi = mid

print(f"\nfirst bad commit: {commits[hi]}")
print(f"{steps} tests over {len(commits)} commits (log2 is {math.log2(len(commits)):.1f})")
print(f"reading them one at a time would have been up to {BROKE_AT + 1}")

#   step  1:  999 commits left, testing c499 -> good
#   step  2:  500 commits left, testing c749 -> bad
#   step  3:  250 commits left, testing c624 -> bad
#   step  4:  125 commits left, testing c561 -> good
#   step  5:   63 commits left, testing c592 -> good
#   step  6:   32 commits left, testing c608 -> good
#   step  7:   16 commits left, testing c616 -> good
#   step  8:    8 commits left, testing c620 -> bad
#   step  9:    4 commits left, testing c618 -> bad
#   step 10:    2 commits left, testing c617 -> bad
#
# first bad commit: c617
# 10 tests over 1000 commits (log2 is 10.0)
# reading them one at a time would have been up to 618

Bisecting the input#

The same halving works on data, and almost nobody does it. A batch of forty thousand documents fails somewhere. You do not need to know where; you need the smallest input that still fails. Halve it, keep the half that still fails, repeat, then take one item away at a time until nothing more can go. What you are left with is a test case.

calls = 0

def fails(rows):
    """The real check is running your pipeline. Here: a heading row with no
    text makes the chunker emit an empty chunk, which crashes embedding."""
    global calls
    calls += 1
    return any(r.startswith("## ") and r.strip() == "##" for r in rows)

def shrink(rows, fails):
    """Halve, keep the half that still fails, then drop one row at a time."""
    while len(rows) > 1:
        half = len(rows) // 2
        for candidate in (rows[:half], rows[half:]):
            if fails(candidate):
                rows = candidate
                break
        else:
            break
    changed = True
    while changed:
        changed = False
        for i in range(len(rows)):
            candidate = rows[:i] + rows[i + 1:]
            if fails(candidate):
                rows, changed = candidate, True
                break
    return rows

document = [f"line {i}" for i in range(400)]
document[137] = "## "
document[300] = "## also empty but not needed to reproduce"

print(f"input that fails: {len(document)} lines")
minimal = shrink(document, fails)
print(f"minimal input that still fails: {len(minimal)} lines -> {minimal}")
print(f"{calls} runs of the pipeline to get there")

# input that fails: 400 lines
# minimal input that still fails: 1 lines -> ['## ']
# 12 runs of the pipeline to get there

Four hundred lines down to one, and the one is a heading with nothing under it. The bug report changes from the ingest job crashes to a heading with no body produces an empty chunk, and that sentence contains its own fix.

When nothing errors#

AI systems fail by producing wrong output with no exception. The stack trace you would normally start from does not exist, so you need a different entry point.

• Read the rendered prompt. Not the template, the exact text that was sent. Most surprising behaviour is obvious once you see it.
• Check the retrieved context before blaming the model. The answer usually was not there.
• Compare a failing case against a similar passing one and find the difference.
• Check the model and its version. A provider changing a default is invisible from your side.
• Look at temperature. Intermittent failures with identical input are often sampling variance rather than a bug.

Systems you cannot reproduce by re-running#

A model call at a non-zero temperature, a race between two workers, a cache that expires after five minutes: none of these fail on demand. Running it again and watching it pass is the commonest way people convince themselves a bug is fixed, and the arithmetic says a clean run means very little.

import math, random

def runs_needed(p, confidence=0.95):
    """How many attempts before you have seen a p-probability failure at least once."""
    return math.ceil(math.log(1 - confidence) / math.log(1 - p))

print("failure rate   runs to see it once (95%)   runs to see it five times (expected)")
for p in (0.30, 0.10, 0.05, 0.02, 0.005):
    print(f"{p:>10.1%}   {runs_needed(p):>25}   {math.ceil(5/p):>36}")

random.seed(0)
p = 0.05
clean = sum(1 for _ in range(10_000) if all(random.random() > p for _ in range(3)))
print(f"\nA 5% failure passes three runs in a row {clean/10_000:.1%} of the time.")
print("Three clean runs is not evidence that you fixed it.")

# failure rate   runs to see it once (95%)   runs to see it five times (expected)
#      30.0%                           9                                     17
#      10.0%                          29                                     50
#       5.0%                          59                                    100
#       2.0%                         149                                    250
#       0.5%                         598                                   1000
#
# A 5% failure passes three runs in a row 85.4% of the time.
# Three clean runs is not evidence that you fixed it.

So the first move on an intermittent failure is not to hunt but to measure. Run it enough times to get a rate. A rate converts is it broken, which nobody can answer, into is it broken less often than before, which anybody can. Then remove one source of variance at a time: fix the seed, set temperature to zero, run a single worker, freeze the clock. If the failure survives all of that it was never variance. If it disappears, you have found the knob it hangs from.

The other half is capture. A system that fails one time in fifty cannot be debugged from a log line saying the answer was wrong. It can be debugged from the rendered prompt, the retrieved chunks, the model and version, the sampling settings and the request id, written down for every request an automated check flagged. Build that before you need it; you cannot go back and collect it for a failure that already happened.

Intermittent failures#

• Something concurrent: a race, a shared mutable object, an unbounded pool.
• Something time-dependent: a cache expiring, a token, a date boundary.
• Something external: rate limits, a slow dependency, another team deploying.
• Sampling: with a non-zero temperature, identical input genuinely produces different output.

What to skip#

Skip reading code looking for the bug. Reading finds the bugs you already suspect and walks past the one that is actually there, which is why the loop starts with reproduction rather than inspection. Skip the clever theory until the boring ones are gone: the wrong environment variable, the stale build, two copies of the file, a cache. And skip the second tool when the first one answered the question — a debugger session for something a log line already shows is a quarter of an hour you did not need to spend.

Most of the time lost to bugs is lost to guessing. This section is the four tools that replace guessing with looking: a debugger to stop inside running code and read the values that are actually there, a profiler to find where the time goes, py-spy to see what a hung process is waiting on, and git bisect to make history find the commit that broke things. Structured logs with a request id sit underneath all of them, because they are the only way to pull one request's story out of millions of lines.

Stop and look#

def build_prompt(docs, question):
    breakpoint()        # execution pauses here; inspect docs, step with n, continue with c
    ...

A debugger shows you the actual values instead of what you assume they are. In an editor such as VS Code, click in the margin to set a breakpoint and run with the debugger. For code running in a container or on a server, the debugpy package lets your editor attach remotely.

Six commands cover almost everything, and knowing them is the difference between a debugger being faster than print statements and slower. They are worth memorising because you will be typing them in a terminal on a server at some point, with no editor to help.

n    next line, stepping over any call
s    step into the call on this line
c    continue until the next breakpoint
u    up one frame, towards the caller
p x  print the expression x in this frame
l    list the source around where you are stopped

python -m pdb -c continue script.py    run it, and drop into pdb at the exception
import pdb; pdb.post_mortem()          inspect the frame a caught exception came from

Where does the time go?#

python -m cProfile -s cumtime pipeline.py | head -30

A profiler reports time spent per function. The answer is almost always a surprise, which is the point of measuring. In AI pipelines it is often not the model call at all, but PDF parsing, a slow regex, or repeated tokenisation.

Read the call counts before the timings. Timings move between runs and tempt you into optimising whatever happened to be slow this time; a call count is exact, and an absurd call count is a bug rather than a slow function.

import cProfile, pstats, re

PAGES = ["word " * 400 + "\n## heading\n" for _ in range(200)]

def clean(page):
    for _ in range(40):                   # forty passes, one regex each
        page = re.sub(r"\s+", " ", page)
    return page

def chunk(page):
    return [page[i:i + 500] for i in range(0, len(page), 500)]

def run():
    return [chunk(clean(p)) for p in PAGES]

pr = cProfile.Profile()
pr.enable(); run(); pr.disable()

stats = pstats.Stats(pr).stats
rows = sorted(stats.items(), key=lambda kv: (-kv[1][0], kv[0][2]))[:5]
print(f"{'function':<40}{'calls':>10}{'per page':>10}")
for (path, _line, name), (calls, *_rest) in rows:
    label = f"{name} ({path.rsplit('/', 1)[-1]})"
    print(f"{label[:39]:<40}{calls:>10,}{calls/len(PAGES):>10.0f}")

# function                                     calls  per page
# <built-in method builtins.isinstance> (      8,013        40
# <method 'sub' of 're.Pattern' objects>       8,000        40
# _compile (__init__.py)                       8,000        40
# sub (__init__.py)                            8,000        40
# <built-in method builtins.len> (~)             219         1

Forty regex substitutions per page, and a pattern cache lookup for each of them, on two hundred pages. Nobody wrote that deliberately; it accumulated as one cleanup rule after another. The fix is not a faster regex, it is one pass instead of forty, and no amount of staring at the timings would have said so as plainly as the number 8,000.

A process that is stuck#

py-spy dump --pid 12345     # what every thread is doing right now
py-spy top  --pid 12345     # live view of where time goes

py-spy attaches to a running Python process without restarting it. When a job has hung for an hour, one dump usually shows the line it is waiting on.

The reason it matters is that restarting the process destroys the only copy of the evidence. A batch job that hangs once a week is unreproducible by definition, so the rule is: dump first, restart second. Two dumps thirty seconds apart also tell you the difference between stuck and slow, since a stuck process shows the same stack twice.

Logs you can search#

import logging, json, sys

logging.basicConfig(level=logging.INFO, format="%(message)s", stream=sys.stdout)
log = logging.getLogger("rag")

request_id, scores, elapsed_ms = "r0042", [0.768, 0.61, 0.55], 182

log.info(json.dumps({
    "event": "retrieval",
    "request_id": request_id,
    "k": 5,
    "top_score": round(scores[0], 3),
    "ms": elapsed_ms,
}))

# {"event": "retrieval", "request_id": "r0042", "k": 5, "top_score": 0.768, "ms": 182}

Structured logs with a request id on every line let you pull the full story of one request out of millions of lines. Print statements do not.

The test for whether a log line is worth writing is simple: name a question it answers. Retrieval done answers none. Got 5 chunks answers none either, because you cannot tell which request it belonged to or whether the chunks were any good. A line carrying the request id, the scores and the timing answers several, including ones you have not thought of yet.

import json, random

# Logging that answers nothing:
#   log.info("retrieval done")
#   log.info(f"got {len(chunks)} chunks")
# Both true. Neither says which request, which query, or how good the hits were.

def record(**fields):
    return json.dumps(fields, separators=(",", ":"))

random.seed(7)
lines = []
for i in range(500):
    rid = f"r{i:04d}"
    lines.append(record(event="retrieval", request_id=rid, k=5,
                        top_score=round(random.uniform(0.18, 0.86), 3),
                        ms=random.randint(40, 400)))
    lines.append(record(event="generation", request_id=rid, model="small-v2",
                        input_tokens=random.randint(900, 4000), stop="end_turn"))

# The question you actually have at 2am: the answer was wrong for r0042. Why?
for line in lines:
    step = json.loads(line)
    if step["request_id"] == "r0042":
        print(step)

weak = [json.loads(l) for l in lines
        if json.loads(l)["event"] == "retrieval" and json.loads(l)["top_score"] < 0.35]
print(f"\n{len(weak)} of 500 requests retrieved nothing above 0.35.")
print("That is a number you can alert on. 'retrieval done' is not.")

# {'event': 'retrieval', 'request_id': 'r0042', 'k': 5, 'top_score': 0.768, 'ms': 182}
# {'event': 'generation', 'request_id': 'r0042', 'model': 'small-v2', 'input_tokens': 3793, 'stop': 'end_turn'}
#
# 118 of 500 requests retrieved nothing above 0.35.
# That is a number you can alert on. 'retrieval done' is not.

Let git search history for you#

git bisect start
git bisect bad                 # current commit is broken
git bisect good v1.4.0         # this release was fine
git bisect run pytest tests/test_parser.py   # git tests each step automatically

Bisect halves the range of commits each step, so even a thousand commits take about ten tests. With a script that exits non-zero on failure, it runs unattended.

Two things make it fail in practice. A commit in the middle that does not build at all, which you mark with git bisect skip rather than guessing. And a test that is itself flaky, which will confidently name an innocent commit; if the failure is intermittent, make the bisect script run it several times and call the commit bad only if it fails at least once.

Which tool, and what to skip#

you can reproduce it locally        debugger
it is slow and you do not know why  profiler, call counts first
it is hung right now in production  py-spy dump, before you restart it
it worked in last week's release    git bisect run
it happens to one user in a thousand  structured logs with a request id
it happens inside a model call      log the rendered prompt; none of the above helps

Skip the profiler when you have not established that the thing is slow for a reason you care about; a p99 that is bad once an hour is a queueing problem and a profile will not show it. Skip the debugger for anything you can only reproduce in production. And skip adding a fifth log line to the same function: if four were not enough, the missing thing is a field on one of them, usually the id that lets you join it to everything else.