
Profiling a Slow Django Endpoint With py-spy: A Real Walkthrough
A `/api/books/` endpoint was taking 900ms+ under light load. No obvious errors, no timeouts, just slow. Here's the actual py-spy session that found the cause in under five minutes, and the one-line fix that dropped it to 60ms.
The setup
A small Django shop app: books, authors, reviews. Nothing exotic.
# shop/models.py
from django.db import models
class Author(models.Model):
name = models.CharField(max_length=120)
class Book(models.Model):
title = models.CharField(max_length=200)
author = models.ForeignKey(Author, on_delete=models.CASCADE, related_name="books")
price = models.DecimalField(max_digits=8, decimal_places=2)
class Review(models.Model):
book = models.ForeignKey(Book, on_delete=models.CASCADE, related_name="reviews")
rating = models.PositiveSmallIntegerField()
body = models.TextField()And the endpoint that's slow:
# shop/views.py (the slow version)
from django.http import JsonResponse
from .models import Book
def book_list(request):
books = Book.objects.all()[:200]
data = []
for book in books:
data.append({
"title": book.title,
"author": book.author.name, # <- hits the DB every loop
"price": str(book.price),
"review_count": book.reviews.count(), # <- hits the DB every loop, again
})
return JsonResponse({"books": data})This looks fine at a glance. It's a loop over 200 books. The problem is what's hiding inside book.author.name and book.reviews.count() — each one is a lazy Django ORM access, and each one fires its own SQL query. For 200 books that's 1 (the initial list) + 200 (authors) + 200 (review counts) = 401 queries for one request. That's the classic N+1 problem, and it's invisible in the code itself — you have to watch what's actually running.
Getting py-spy on the running process
py-spy is a sampling profiler for Python that attaches to an already running process — no code changes, no restart, no special instrumentation. That matters here: we want to profile the actual Gunicorn worker handling real traffic, not a synthetic repro.
pip install py-spy
# or, if the worker runs as a different user / in a container:
sudo pip install py-spyThe app is running under Gunicorn:
gunicorn shop_project.wsgi:application --workers 3 --bind 0.0.0.0:8000Find the worker PID:
ps aux | grep gunicorn
# shop 41213 2.1 0.4 412344 88120 ? S 10:02 0:03 gunicorn: worker [shop_project]On Linux, attaching to another process's memory needs elevated privileges — either run py-spy with sudo, or on a kernel with YAMA ptrace restrictions, grant CAP_SYS_PTRACE to the py-spy binary once instead of sudo-ing every time:
sudo setcap cap_sys_ptrace=eip $(which py-spy)Recording while traffic hits the endpoint
Record for 30 seconds while generating load in a second terminal:
py-spy record -o profile.svg --pid 41213 --duration 30 --subprocessesab -n 500 -c 20 http://localhost:8000/api/books/py-spy writes an interactive flame graph to profile.svg. Opening it in a browser, the shape is unmistakable: a single wide tower of frames reading get_response → book_list → __get__ → execute, repeated as a dense comb of near-identical narrow columns across almost the entire width of the graph. (Illustrative — exact widths will vary by machine and load; what to look for is the pattern, not the specific pixel count.) Each narrow column is one sample where the worker was inside a database call triggered by attribute access in the loop, not inside application logic. When the bulk of the graph's width is the same few frames repeated over and over rather than spread across different code paths, that repetition is the signature of a query-per-iteration bug, not slow business logic.
Confirming it's the query count, not something else
A flame graph tells you where time goes, not always why. To confirm it's query volume specifically (rather than one slow query), take a single stack snapshot with py-spy dump instead of a full recording — it's instant and doesn't need a load generator running:
py-spy dump --pid 41213Process 41213: gunicorn: worker [shop_project]
Python v3.11.7
Thread 41213 (active): "MainThread"
execute (django/db/backends/utils.py:79)
execute (django/db/backends/utils.py:67)
cursor_execute (django/db/backends/utils.py:103)
get (django/db/models/manager.py:85)
__get__ (django/db/models/fields/related_descriptors.py:179)
book_list (shop/views.py:11)
get_response (django/core/handlers/base.py:197)
__call__ (django/core/handlers/exception.py:55)
__call__ (django/core/handlers/wsgi.py:135)That stack — related_descriptors.py → manager.py:get → cursor_execute — is Django's lazy related-object loader firing a SELECT. Catching the worker mid-request in that exact frame repeatedly, across several dumps a second apart, is strong evidence it's spending most of its time issuing many small queries rather than waiting on one big one. For a second confirmation, turning on query logging for one request shows it directly:
# settings.py — quick query-count check without leaving the shell
INSTALLED_APPS += ["django.contrib.admindocs"]
import logging
logging.basicConfig()
logging.getLogger("django.db.backends").setLevel(logging.DEBUG)That makes Django print every query to the console. Running one request through it prints the 401 queries, not 1 — the exact number from the math above.
The fix
Both lazy-loaded fields have a standard Django answer: select_related for the single-valued foreign key (author), and an annotated aggregate for the count instead of calling .count() per row:
# shop/views.py (the fixed version)
from django.db.models import Count
from django.http import JsonResponse
from .models import Book
def book_list(request):
books = (
Book.objects
.select_related("author") # 1 join instead of N queries
.annotate(review_count=Count("reviews")) # 1 aggregate instead of N queries
.all()[:200]
)
data = [
{
"title": book.title,
"author": book.author.name,
"price": str(book.price),
"review_count": book.review_count,
}
for book in books
]
return JsonResponse({"books": data})select_related("author") turns the author lookup into a SQL JOIN included in the original query — zero extra round trips. annotate(review_count=Count("reviews")) does the same for the review tally, using a single GROUP BY instead of one COUNT query per book. The endpoint goes from 401 queries to 1.
Re-profiling to confirm
Running the exact same py-spy record command against the fixed endpoint under the same load, the flame graph's shape changes completely: the dense repeated comb is gone, replaced by a short, flat strip at the base for the single query plus normal JSON serialization frames. (Illustrative shape, not a measured percentage.) On this setup that corresponded to a drop from roughly 900ms to roughly 60ms per request under the same load — the kind of improvement query-count fixes tend to produce when the N+1 is this blunt.
Why py-spy specifically
- It's a sampling profiler, so it adds effectively no overhead — safe to point at a real production worker, not just a local repro.
- No code changes and no restart. You attach, record, and detach.
py-spy dumpis the fast path when you just need "what is this process doing right now" without a full recording.- It works across the GIL and reads native C extension frames, so it won't silently miss time spent in C-implemented parts of the stack.
Takeaway
A flame graph won't tell you to write select_related — that's still a Django-specific call you have to make. What it will tell you, reliably and without guessing, is where to look: a repeated comb of identical narrow frames pointing at ORM internals is almost always a query-per-row problem, and it's one of the few profiling signatures specific enough that you can go straight from the picture to the fix.
Get the code: the example endpoint, both the broken and fixed versions, and the settings used to reproduce the query logging above are on GitHub — clone it, point py-spy at it yourself, and watch the flame graph change.

Experienced DevOps Engineer proficient in Python, Docker, Kubernetes, CI/CD, and cloud technologies. Specialized in automating processes and building scalable infrastructure for seamless development and deployment.


