Python

Python Profiling with cProfile and py-spy: Finding Performance Bottlenecks

HelpMeTest

HelpMeTest

— 7 min read
Python Profiling with cProfile and py-spy: Finding Performance Bottlenecks

Python profiling uses cProfile for deterministic function-level profiling, py-spy for low-overhead sampling profiling in production, and line_profiler for line-by-line analysis. This guide covers running each tool, reading pstats output, generating flame graphs, and profiling Django and FastAPI applications.

Python's GIL (Global Interpreter Lock) means only one thread executes Python bytecode at a time. CPU-bound tasks don't parallelize within one process. This makes profiling especially important: a slow function in Python doesn't just slow one request—it blocks all concurrent requests being handled by that thread. Finding and fixing hotspots has outsized impact.

cProfile: Standard Library Deterministic Profiler

cProfile is included in Python's standard library. It instruments every function call and measures exact call counts and cumulative time. Overhead: 2-10x slowdown (use for development/staging, not production).

Command-Line Usage

# Profile a script
python -m cProfile -s cumulative myapp.py

# Save to file and analyze later
python -m cProfile -o profile.stats myapp.py

Programmatic Usage

import cProfile
import pstats
import io

# Profile a specific function
profiler = cProfile.Profile()
profiler.enable()

# Code to profile
result = process_large_dataset(data)

profiler.disable()

# Print sorted stats
stream = io.StringIO()
stats = pstats.Stats(profiler, stream=stream)
stats.sort_stats('cumulative')  # Sort by cumulative time
stats.print_stats(20)           # Show top 20 functions
print(stream.getvalue())

Understanding cProfile Output

         12345 function calls (12000 primitive calls) in 3.456 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    3.456    3.456 myapp.py:1(<module>)
        1    0.002    0.002    3.455    3.455 myapp.py:45(process_data)
     1000    0.123    0.000    3.120    0.003 myapp.py:67(transform_record)
     1000    2.980    0.003    2.980    0.003 myapp.py:82(validate_schema)  ← HOTSPOT
     5000    0.150    0.000    0.150    0.000 {method 'match' of 're.Pattern'}

Columns:

  • ncalls: Number of calls
  • tottime: Time IN the function (excluding called functions)
  • cumtime: Cumulative time (including all callees)
  • percall: Average time per call

validate_schema has tottime=2.980 — it's spending 86% of total time inside its own code, called 1000 times. percall=0.003s (3ms) × 1000 calls = 3 seconds.

Context Manager Profiling

from contextlib import contextmanager
import cProfile, pstats

@contextmanager
def profile_block(sort_by='cumulative', lines=20):
    pr = cProfile.Profile()
    pr.enable()
    yield
    pr.disable()
    stats = pstats.Stats(pr)
    stats.sort_stats(sort_by)
    stats.print_stats(lines)

# Usage
with profile_block():
    result = expensive_function(data)

Profiling Django Views

# middleware.py — profile specific requests
import cProfile, pstats, io

class ProfilingMiddleware:
    def __init__(self, get_response):
        self.get_response = get_response

    def __call__(self, request):
        if 'HTTP_X_PROFILE' not in request.META:
            return self.get_response(request)

        # Profile this request
        profiler = cProfile.Profile()
        profiler.enable()
        response = self.get_response(request)
        profiler.disable()

        # Add profile to response headers (truncated)
        stream = io.StringIO()
        pstats.Stats(profiler, stream=stream).sort_stats('cumulative').print_stats(15)
        response['X-Profile'] = stream.getvalue()[:2000]

        return response

Trigger profiling with: curl -H "X-Profile: true" http://localhost:8000/api/products

py-spy: Production-Safe Sampling Profiler

py-spy attaches to a running Python process without code changes. Overhead: < 1%.

Installation

pip install py-spy
# or
cargo install py-spy  # from source

Basic Usage

# Find the process
ps aux | grep python
# PID: 12345

# Record a profile for 30 seconds
py-spy record -o profile.svg --pid 12345

# Live top-like view
py-spy top --pid 12345

# Dump current stack (instant snapshot)
py-spy dump --pid 12345

Flame Graph Generation

# Record and generate SVG flame graph
py-spy record \
  --output profile.svg \
  --format speedscope \
  --duration 30 \
  --pid 12345

# Open in browser
open profile.svg
# Speedscope format (richer visualization)
py-spy record \
  --output profile.speedscope.json \
  --format speedscope \
  --duration 30 \
  --pid 12345

# Upload to speedscope.app for interactive exploration

Profiling Without a PID (Subprocess)

py-spy record -o profile.svg -- python myapp.py

Kubernetes/Docker Profiling

# Profile inside a Docker container
docker exec my-container py-spy record \
  --output /tmp/profile.svg \
  --pid $(pgrep -f "python myapp.py") \
  --duration 30

docker cp my-container:/tmp/profile.svg ./profile.svg
# Kubernetes pod profiling
kubectl exec my-pod -- py-spy record \
  --output /tmp/profile.svg \
  --pid $(kubectl exec my-pod -- pgrep -f gunicorn) \
  --duration 30

kubectl cp my-pod:/tmp/profile.svg ./profile.svg

line_profiler: Line-by-Line Analysis

When cProfile points to a slow function, line_profiler shows which specific lines are slow:

pip install line-profiler
from line_profiler import LineProfiler

def slow_function(data):
    results = []
    for item in data:               # ← line_profiler shows how often
        cleaned = item.strip()      #   each line executes and how long
        validated = validate(cleaned)
        if validated:
            results.append(transform(cleaned))
    return results

# Profile it
profiler = LineProfiler()
profiler.add_function(slow_function)
profiler.run('slow_function(large_dataset)')
profiler.print_stats()

Output:

Function: slow_function at line 1

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     3      1000      1234.5      1.2      0.1%   for item in data:
     4      1000      2345.6      2.3      0.2%       cleaned = item.strip()
     5      1000    987654.3    987.7     98.5%       validated = validate(cleaned)  ← HOTSPOT
     6       800      3456.7      4.3      0.3%       if validated:
     7       800      5678.9      7.1      0.6%           results.append(transform(cleaned))

Line 5 (validate(cleaned)) takes 98.5% of function time. Fix the validator, not the loop.

@profile Decorator

# Use @profile decorator (provided by line_profiler)
@profile
def process_batch(batch):
    results = []
    for item in batch:
        # ... processing
        results.append(item)
    return results
kernprof -l -v myapp.py

memory_profiler: Memory Usage Analysis

pip install memory-profiler
from memory_profiler import profile

@profile
def load_data():
    data = []
    with open('large_file.csv') as f:
        for line in f:
            data.append(line.split(','))
    return data
python -m memory_profiler myapp.py

Output:

Line #    Mem usage    Increment   Line Contents
================================================
     4   45.2 MiB     45.2 MiB   def load_data():
     5   45.2 MiB      0.0 MiB       data = []
     6   45.2 MiB      0.0 MiB       with open('large_file.csv') as f:
     7  523.1 MiB    477.9 MiB           for line in f:
     8  523.1 MiB      0.0 MiB               data.append(line.split(','))

The list comprehension grows from 45MB to 523MB. Fix: use a generator to process lines without loading everything into memory.

Finding GIL Contention

Python's GIL prevents true parallelism for CPU-bound tasks. Even with threading, only one thread runs Python at a time. Use py-spy to check if GIL is causing bottlenecks:

# Show threads and GIL status
py-spy top --pid 12345 --threads

# Dump all thread stacks
py-spy dump --pid 12345 --threads

If multiple threads show identical call stacks waiting on CPU-bound operations, your workload needs multiprocessing (not threading) or needs to offload CPU work to C extensions or asyncio.

FastAPI Profiling

# middleware for FastAPI
from fastapi import Request
import cProfile, pstats, io
import time

@app.middleware("http")
async def profiling_middleware(request: Request, call_next):
    if request.headers.get("X-Profile") == "true":
        profiler = cProfile.Profile()
        profiler.enable()

    start = time.time()
    response = await call_next(request)
    duration = time.time() - start

    if request.headers.get("X-Profile") == "true":
        profiler.disable()
        stream = io.StringIO()
        pstats.Stats(profiler, stream=stream).sort_stats('cumulative').print_stats(20)
        print(f"\n=== Profile for {request.url} ===\n{stream.getvalue()}")

    response.headers["X-Process-Time"] = str(duration)
    return response

Note: cProfile doesn't track await time well (it sees await as near-zero time). For async profiling in FastAPI, use py-spy which tracks wall-clock time across coroutines.

Continuous Python Profiling with Pyroscope

pip install pyroscope-io
import pyroscope

pyroscope.configure(
    application_name="my-django-app",
    server_address="http://pyroscope:4040",
    tags={"environment": "production"}
)

Pyroscope samples Python stacks at 100Hz continuously. Query historical profiles in the Pyroscope UI when investigating production slowdowns.

Profiling Async Python (asyncio)

cProfile works poorly with asyncio—it sees each await as near-zero time and misses the actual wait duration. For async Python, use py-spy (wall-clock mode captures suspend time) or specialized tools:

# py-spy wall-clock captures async wait time
py-spy record \
  --output async-profile.svg \
  --format speedscope \
  --duration 30 \
  --subprocesses \
  --pid 12345

Or use yappi (yet another Python profiler) which is asyncio-aware:

pip install yappi
import yappi
import asyncio

async def process_requests():
    # ... your async code

# Profile with coroutine time attribution
yappi.set_clock_type("wall")  # Include I/O wait time
yappi.start()

asyncio.run(process_requests())

yappi.stop()

# Print coroutine-level stats
stats = yappi.get_func_stats()
stats.sort("ttot")  # Total time including async wait
stats.print_all(out=open("yappi_stats.txt", "w"))

yappi's key advantage: it correctly attributes time to coroutines, showing that fetch_user_data() spent 200ms waiting on a database even though the coroutine was suspended (not running) for most of that time.

Common Python Performance Patterns

Beyond profiling tools, these patterns consistently appear as hotspots:

String building in loops:

# BAD: Creates new string object per iteration — O(N²) memory
result = ""
for item in items:
    result += format(item)  # String concatenation

# GOOD: Single join
result = "".join(format(item) for item in items)

Repeated attribute lookup:

# BAD: Looks up `re.compile` in module on every iteration
for text in texts:
    match = re.compile(r'\d+').search(text)

# GOOD: Compile once outside loop
DIGIT_PATTERN = re.compile(r'\d+')
for text in texts:
    match = DIGIT_PATTERN.search(text)

Unnecessary list materialization:

# BAD: Creates full list then iterates once
total = sum([calculate(x) for x in large_dataset])

# GOOD: Generator — no intermediate list
total = sum(calculate(x) for x in large_dataset)

These patterns are invisible in cProfile until they appear as re.compile or str.__add__ calls consuming unexpected percentages of runtime.

Profiling Django ORM Queries

Django's ORM can generate surprising query patterns. Add query logging to find N+1 in development:

# settings.py (development only)
LOGGING = {
    'loggers': {
        'django.db.backends': {
            'level': 'DEBUG',
            'handlers': ['console'],
        }
    }
}

Then use django-silk or django-debug-toolbar in staging to see query counts per view:

# pip install django-silk
MIDDLEWARE = ['silk.middleware.SilkyMiddleware', ...]
SILKY_PYTHON_PROFILER = True  # Also runs cProfile per request

Access /silk/ to see: request timing, SQL queries, query time, and the cProfile breakdown for each request. When a view shows 147 queries (N+1 for 146 related objects), fix with select_related() or prefetch_related().

Profiling Strategy

  1. Start with py-spy: Attach to the production process for 30 seconds, no code changes, minimal overhead
  2. If CPU > 80%: Use cProfile in staging with representative load to get exact function times
  3. When cProfile shows a hotspot: Use line_profiler on that function to get line-by-line data
  4. If memory grows: Use memory_profiler to find allocation sites
  5. For production visibility: Add Pyroscope agent for continuous profiles

Summary

Python profiling starts with py-spy for production-safe sampling—attach to any process, get a flame graph, no restarts required. For detailed analysis, cProfile gives exact call counts and cumulative times; line_profiler shows which specific lines within a slow function are the actual cost. Memory leaks need memory_profiler's per-line allocation tracking. For Django and FastAPI, a profiling middleware enables on-demand profiling in staging environments by adding an HTTP header. The most common finding: O(N²) loops, N+1 database queries (findable as many small calls in cProfile), and synchronous blocking operations inside async code.

Read more

Start now free