The tools: debugger, profiler, logs, bisect

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

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

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

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

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

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}

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.

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

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