Debugging, Logging & Profiling — Python Course

What you'll learn

When something breaks or runs slowly, guessing wastes hours. This lesson gives you the tools professionals use to find problems fast: tracebacks, the debugger, logging, and profilers.

By the end of this lesson you'll be able to:

Read a traceback and jump straight to the real cause
Step through code with breakpoint() and pdb
Configure logging with levels, handlers, and formatters
Measure code with timeit and find bottlenecks with cProfile

Reading tracebacks

A traceback is a map to the crash, not noise. Read it bottom-up: the last line is the error type and message; the frames above show the chain of calls that led there, most recent last.

shop.py

def parse_price(text):
    return float(text)

def checkout(items):
    return sum(parse_price(x) for x in items)

checkout(["9.99", "oops", "3.50"])

Key idea

Start at the bottom: ValueError: could not convert string to float: 'oops' tells youwhat and which value. Then read the frame just above it to see where — here, parse_price on line 2. That's usually all you need.

The debugger

Print-debugging works, but a debugger lets you pause and inspect a running program. Drop breakpoint() anywhere and Python opens an interactive pdb session at that line, with your variables live.

debug.py

def running_total(nums):
    total = 0
    for n in nums:
        breakpoint()        # drops into the debugger here (Python 3.7+)
        total += n
    return total

running_total([1, 2, 3])

pdb session

(Pdb) p n          # print an expression
1
(Pdb) l            # list the code around here
(Pdb) n            # execute the next line
(Pdb) c            # continue until the next breakpoint
(Pdb) q            # quit the debugger

Tip

Use the built-in breakpoint() (Python 3.7+) rather than import pdb; pdb.set_trace(). The key commands are n (next), s (step into), c (continue), p (print), l (list), and q (quit).

Logging done right

You met logging.basicConfig earlier. For real apps, get a named logger and attach handlers (where messages go — console, file, network) and formatters (how each line looks). Levels then let you dial verbosity up or down without touching the log calls.

setup_logging.py

import logging

logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)

# A handler decides WHERE logs go; a formatter decides how they LOOK
handler = logging.FileHandler("app.log")
handler.setFormatter(logging.Formatter(
    "%(asctime)s %(levelname)s %(name)s: %(message)s"
))
logger.addHandler(handler)

logger.debug("cache miss for key=42")
logger.error("payment failed for order %s", 1234)   # lazy %s formatting

app.log

2024-08-26 09:30:00,123 DEBUG myapp: cache miss for key=42
2024-08-26 09:30:00,124 ERROR myapp: payment failed for order 1234

Note

Pass values as arguments — logger.error("order %s", 1234) — not f-strings. The message is only formatted if that level is actually emitted, so suppressed logs cost almost nothing.

Profiling & timing

Before optimizing, measure. timeit times small snippets accurately (best of many runs, avoiding one-off noise):

bench.py

import timeit

# Compare two ways to build a string, best of many runs
loop = timeit.timeit("''.join(str(i) for i in range(100))", number=10000)
concat = timeit.timeit(
    "s=''\nfor i in range(100): s+=str(i)", number=10000
)
print(round(loop, 3), "vs", round(concat, 3))   # join is usually faster

For a whole program, cProfile shows where the time really goes — sort by cumulative time and the worst offender jumps out:

terminal

$ python -m cProfile -s cumtime app.py
   ncalls  tottime  cumtime  filename:lineno(function)
        1    0.000    2.013   app.py:8(main)
        3    0.001    2.010   app.py:1(fetch)      <- the bottleneck
     6003    0.004    0.004   app.py:5(parse)

Watch out

Don't optimize by intuition — programmers are famously bad at guessing bottlenecks. Profile first, fix the one function that dominates, then measure again. Most "slow" code is slow in a single, surprising place.

Recap & quick check

Key takeaways

Read tracebacks bottom-up: the last line is the error; the frames above are the call chain.
breakpoint() opens pdb at that line; use n (next), s (step), c (continue), p (print), q (quit).
Real logging uses a named logger with handlers (where) and formatters (how); levels control verbosity.
Pass log values as arguments (logger.error('%s', x)) so suppressed messages aren't formatted.
timeit accurately times small snippets; cProfile finds bottlenecks across a whole program.
Always measure before optimizing — intuition about bottlenecks is usually wrong.

Quick check

1. How should you read a Python traceback?

2. What does breakpoint() do?

3. In logging, what does a handler control?

4. Why pass values as logger.error('%s', x) instead of an f-string?

5. What's the right first step when code is slow?

Now that you can find slow code, let's understand why it's slow and how to make it fast. Next up: Module 34 — Performance, Memory & CPython Internals.