Profiling Python Web Apps: Finding Where the Time Actually Goes

Most engineers' intuition about performance is wrong. Engineers look at a slow endpoint, see a loop that serializes 500 objects, and spend an afternoon rewriting it with a comprehension and orjson. The endpoint only gets 4% faster. The actual problem, that one unindexed query burning 800ms, never gets touched, because nobody measured.

Profiling replaces that guessing with measurement. This post walks through profiling a Flask app end to end. We start with a deliberately broken demo app, the concepts you need to read any profile, three tools (Werkzeug's built-in profiler, SQLAlchemy query logging, py-spy in production), and the workflow that ties them together. By the end you'll have found and fixed four planted performance problems, and you'll know which tool to reach for the next time an endpoint "feels slow."

Our deliberately slow demo app

Clone the demo repo and start it:

git clone https://github.com/paulnasdaq/flask-profiling-demo
cd flask-profiling-demo
docker compose up -d postgres
pip install -r requirements.txt
flask --app app seed   # loads ~50k rows
flask --app app run

It's a stripped-down property listings API. It is made up of three endpoints, PostgreSQL, SQLAlchemy 2.0:

# app.py
from flask import Flask, jsonify, request
from models import db, Property, Unit, Tenant
from analytics import occupancy_score

app = Flask(__name__)
app.config["SQLALCHEMY_DATABASE_URI"] = "postgresql://demo:demo@localhost/demo"
db.init_app(app)

@app.get("/properties")
def list_properties():
    properties = db.session.scalars(db.select(Property).limit(100)).all()
    return jsonify([
        {
            "name": p.name,
            "units": len(p.units),                      # suspicious
            "occupied": sum(1 for u in p.units if u.tenant),  # very suspicious
        }
        for p in properties
    ])

@app.get("/properties/<int:pid>/score")
def property_score(pid):
    prop = db.get_or_404(Property, pid)
    return jsonify({"score": occupancy_score(prop)})    # CPU-bound

@app.get("/tenants/search")
def search_tenants():
    q = request.args.get("q", "")
    tenants = db.session.scalars(
        db.select(Tenant).where(Tenant.phone.like(f"%{q}%"))  # no index will save this
    ).all()
    return jsonify([t.name for t in tenants])

Four problems are planted in here: an N+1 query, a CPU-bound hot loop, an unindexed (and unindexable) query, and a memory leak we'll get to at the end. Time all three endpoints now so you have a baseline:

for path in "/properties" "/properties/17/score" "/tenants/search?q=254"; do
  curl -s -o /dev/null -w "$path -> %{time_total}s\n" "localhost:5000$path"
done

On my machine: 2.1s, 1.4s, and 0.9s. All three are unacceptable. All three are slow for completely different reasons, and the fix for each one starts with knowing which kind of slow you're dealing with.

The four concepts that let you read any profile

Every profiling tool, in every language, reports variations of the same four ideas. If you understand these four, you should be able to read any profile.

Deterministic vs. sampling. A deterministic profiler (cProfile) hooks every function call and return. You get exact call counts and complete coverage, but the instrumentation itself costs time, often 30–50% overhead, and it distorts results toward code that makes many small calls, because every call pays the tracing tax. A sampling profiler (py-spy) instead interrupts the process ~100 times a second and records the call stack. It misses functions that are fast and rare, but its overhead is close to zero, which is the property that makes it safe to point at production. Rule: cProfile in development, sampling in production.

Wall time vs. CPU time. Wall time is elapsed clock time in millisecond spent waiting on PostgreSQL, the network, a lock, or time.sleep. CPU time counts only instructions actually executing. The gap between them is your diagnosis: high wall, low CPU means the code is waiting, and no algorithmic cleverness will fix waiting. You may you need an index, a cache, batching, or fewer round trips. Web apps are wall-time-dominated almost by definition. That single fact explains why the database section below matters more than the cProfile section.

Cumulative time vs. self time. In profiler output, cumtime is time spent in a function plus everything it called; tottime is time in the function's own body alone. Read them in that order. Sort by cumtime to find which code path is slow; sort by tottime to find the function doing the actual work. A function with huge cumtime and negligible tottime is a middleman. Its cost lives in its callees.

The call stack is the context. Profilers record who-called-whom, not just flat timings, because the same function can be harmless from one call site and catastrophic from another (called once vs. called inside a loop, 10,000 times). Flame graphs are the standard rendering of this: width is share of time, vertical depth is stack depth. You read a flame graph by scanning for wide plateaus, then reading downward to see how execution got there.

First pass: Werkzeug's ProfilerMiddleware

Flask ships with a profiler already installed as part of Werkzeug. Two lines wrap your WSGI app and dump a cProfile capture for every request:

from werkzeug.middleware.profiler import ProfilerMiddleware

app.wsgi_app = ProfilerMiddleware(
    app.wsgi_app,
    profile_dir="./profiles",
    sort_by=("cumtime",),
    restrictions=[30],
)

Hit the score endpoint, then open the resulting file:

curl -s localhost:5000/properties/17/score > /dev/null
pip install snakeviz
snakeviz profiles/GET.properties.17.score.*.prof

Snakeviz renders the profile as an icicle chart. The picture for this endpoint is unambiguous: one enormous plateau under occupancy_score, and beneath it, _pairwise_distance occupying nearly the full width. The numbers table confirms it:

   ncalls  tottime  cumtime  function
        1    0.002    1.380  analytics.py:12(occupancy_score)
   124750    1.301    1.352  analytics.py:31(_pairwise_distance)

This is cumtime vs tottime in action. occupancy_score has the cumtime — it's the slow path — but almost no tottime. The work is in _pairwise_distance: 124,750 calls, which is exactly 500 choose 2. Someone is computing pairwise distances between every unit in the property in pure Python:

# analytics.py — the crime scene
def occupancy_score(prop):
    coords = [(u.lat, u.lng) for u in prop.units]
    total = 0.0
    for i in range(len(coords)):
        for j in range(i + 1, len(coords)):
            total += _pairwise_distance(coords[i], coords[j])
    ...

This is genuinely CPU-bound. tThe profile shows tottime ≈ cumtime at the leaf, no waiting anywhere. The fix for CPU-bound Python numerics is always the same: stop doing it in Python. Vectorize with NumPy:

def occupancy_score(prop):
    coords = np.array([(u.lat, u.lng) for u in prop.units])
    diffs = coords[:, None, :] - coords[None, :, :]
    total = np.sqrt((diffs ** 2).sum(-1)).sum() / 2
    ...

Re-profile: 1.4s → 40ms. The plateau is gone. That's the profiling loop in miniature — measure, identify the widest plateau, fix, re-measure. The re-measure should not be optional. It's how you know the fix worked and didn't just move the cost somewhere else.

One warning before moving on: ProfilerMiddleware profiles every request with full cProfile overhead. It's a development tool. Leaving it on under real traffic will roughly double your latency and fill a disk with .prof files.

The problem the profiler can't see

Now profile /properties the same way. The snakeviz output looks completely different. There is no single dominant function. Instead the time is smeared across dozens of SQLAlchemy and psycopg frames: _execute_internal, execute, socket reads. cProfile is faithfully telling you the truth: your Python code is fast, and the process spends its life waiting on the database. High wall time, low CPU time. The profiler has taken you as far as it can. It can tell you that you're waiting on PostgreSQL, but not why.

For why, log the queries. SQLAlchemy records them per request if you ask:

app.config["SQLALCHEMY_RECORD_QUERIES"] = True

from flask_sqlalchemy.record_queries import get_recorded_queries

@app.after_request
def query_report(response):
    queries = get_recorded_queries()
    if len(queries) > 10:
        app.logger.warning("%d queries in one request!", len(queries))
        for q in queries[:5]:
            app.logger.warning("%.1fms  %s", q.duration * 1000, q.statement[:120])
    return response

Hit /properties:

WARNING: 201 queries in one request!
WARNING: 3.2ms  SELECT property.id, property.name FROM property LIMIT 100
WARNING: 8.9ms  SELECT unit.id, unit.tenant_id FROM unit WHERE unit.property_id = %(pid)s
WARNING: 9.1ms  SELECT unit.id, unit.tenant_id FROM unit WHERE unit.property_id = %(pid)s
...

Two hundred and one queries: one for the properties, then p.units lazily fires a query per property, and u.tenant fires more. This is the N+1 pattern, and it's the single most common performance bug in ORM-backed applications. Each query is fast (around 9ms) which is exactly why it hides: nothing is individually slow, there's just 200× too much of it, and each one pays a full network round trip.

The fix is to tell SQLAlchemy to fetch the graph you actually need in one pass:

properties = db.session.scalars(
    db.select(Property)
    .options(selectinload(Property.units).joinedload(Unit.tenant))
    .limit(100)
).all()

201 queries become 3. The endpoint drops from 2.1s to 90ms. No profiler pointed at the fix, the query log did. Better still, the loop with len(p.units) and the occupancy sum shouldn't load units at all; a single aggregate query with func.count does it in one statement. That's the deeper lesson of DB-bound endpoints: the winning move is usually asking the database a better question, not making Python faster.

The third endpoint, /tenants/search, is the same species of problem one level down. The query log shows a single query taking 850ms. EXPLAIN ANALYZE in psql shows a sequential scan over 50k rows . LIKE '%254%' with a leading wildcard can't use a B-tree index at all. The fix is a trigram index:

CREATE EXTENSION IF NOT EXISTS pg_trgm;
CREATE INDEX idx_tenant_phone_trgm ON tenant USING gin (phone gin_trgm_ops);

850ms → 6ms. Postgres query planning is its own article. The point here is the diagnostic chain: profiler says "waiting" → query log says which query → EXPLAIN says why.

Production: py-spy against gunicorn

Everything so far ran on the dev server with an instrumented process. Production is different in ways that change the profile itself: gunicorn's worker model, real concurrency, production data volumes, connection pool contention. The dev profile is a hypothesis; the production profile is the fact.

py-spy is the tool for this because it attaches to a running process from outside. There is no code changes, no restart and the overhead is negligible:

pip install py-spy

gunicorn -w 4 -b 0.0.0.0:8000 app:app &
hey -z 30s -c 20 http://localhost:8000/properties &   # generate load

py-spy top --pid $(pgrep -f "gunicorn: worker" | head -1)

py-spy top is htop for your Python stack. It provides a live, self-updating view of which functions the sampler keeps catching. For a shareable artifact, record a flame graph instead:

sudo py-spy record -o flame.svg --duration 30 --pid <worker_pid>

Open flame.svg in a browser and read it the way the concepts section taught you: find the wide plateaus, read down the stack. If you fixed the earlier problems, the graph should now be dominated by genuine request handling with no single monster, which is what "fast" looks like: boring.

Two py-spy flags earn their keep in production. --subprocesses on the gunicorn master profiles all workers at once. And --gil shows what fraction of samples hold the GIL — the tell for threaded apps where threads look idle in wall time but are actually queued for the interpreter, a failure mode ordinary profilers render invisibly.

The deployment-realism rule generalizes beyond py-spy: whatever you measure, measure it under the process model and data scale you actually run. A profile of the single-threaded dev server against a 500-row dev database describes a program your users never touch.

When the symptom is memory, not latency

Time profilers are completely blind to the fourth planted bug. Run the load test for five minutes and watch the worker's RSS climb. A leak. The tool for allocations is tracemalloc, in the standard library:

import tracemalloc
tracemalloc.start(10)

@app.get("/_debug/memory")
def memory_snapshot():
    snapshot = tracemalloc.take_snapshot()
    top = snapshot.statistics("lineno")[:10]
    return jsonify([str(stat) for stat in top])

Take a snapshot, run load, take another, and diff them (snapshot2.compare_to(snapshot1, "lineno")). The demo app's leak shows up immediately: a module-level _cache = {} in analytics.py that's keyed by request args and never evicted. Grep for module-level mutable state; that's where Flask memory leaks live, because module globals survive across requests while everything request-scoped is freed. For deeper hunts — leaks in C extensions, native allocations — memray is the heavier tool, but tracemalloc plus a diff catches the common cases.

The workflow, distilled

Four problems, four different tools, one repeatable procedure:

1. Locate cheaply. Request timing, APM metrics, or py-spy — identify which endpoint and whether the time is CPU or waiting.
2. Classify. tottime ≈ cumtime at a leaf → CPU-bound. Time smeared across driver/socket frames → wall-bound, go to the query log.
3. Zoom with the matching tool. CPU-bound → cProfile/snakeviz, then line_profiler if you need line-level resolution. DB-bound → SQLALCHEMY_RECORD_QUERIES, then EXPLAIN ANALYZE. Memory → tracemalloc diff.
4. Fix and re-measure. A fix without a before/after profile is a hypothesis.

Profiling finds the problem once. To watch for it continuously, you want tracing — the OpenTelemetry instrumentation from the previous post gives you per-request spans, including every DB call, in production all the time. Profiling and tracing aren't competitors; tracing tells you a deploy made p95 worse, profiling tells you which function to blame.

Exercises

The demo repo has an exercises branch with all four problems unfixed plus two more I haven't mentioned. For each one: produce the profile or query log that proves the diagnosis, fix it, and produce the after-profile showing the improvement. Solutions, with the profiles as the answer key, are on main.