Rapidly Locating Query Bottlenecks in a Django Codebase

Hunt down the lines of your Django application code which are responsible for executing the most queries.

In this article, we'll introduce a tool, django-queryhunter, which can rapidly locate which lines of your Django code are responsible for executing the most queries, the SQL those lines execute and from which user or URL the query originated.

The Never Ending Battle Against n+1 Queries

A scourge of any Django project is the continual battle of preventing, locating and fixing query bottlenecks. A particularly ubiquitous query bottleneck in Django projects are n+1 queries, most often caused by a missing call to select_related or prefetch_related.

There are already countless online resources which document how to avoid n+1 queries by using these methods. Despite the wealth of information and preventative tooling, it is still commonplace for Django developers to introduce such query bottlenecks into their codebase. This is especially true when working in a large codebase, where it may not be at all obvious from the immediate context which joins are required further down the call stack when writing our select_related code.

In a production level codebase, therefore, developers need a helping hand in knowing how to write efficient queries and in locating slow ones. A common approach to this problem is to use some sort of query profiling tool.

Query Profiling in a Django Codebase

Libraries such as django-silk are excellent for profiling the queries executed by your Django application, giving a detailed breakdown of the SQL emitted on a view by view basis. We have found, however, that they do not provide a completely straightforward way to identify the lines of your application code which are responsible for executing the most queries. In most cases, this is the data the application developer will understand and be able to use as a starting point to address the underlying issue.

django-queryhunter is a library which aims to fill this gap by providing a simple code-first approach to query profiling. Using its context manager or middleware for profiling Django views or function, it can provide a detailed report of the lines of your application code which are responsible for executing SQL queries, including data on:

• The module name and the line number of the code which executed the query.

• The executing code itself on that line.

• The number queries that line was responsible for invoking was and the total time the queries invoked by that line took to execute.

• The SQL query itself.

• Customisable metadata such as the URL and method of the request which caused the queries to be executed.

Let's see this tool in action with via its usage in a simple concrete example.

Using queryhunter in Practice

Let's suppose we have a Django application with the following models:

# queryhunter/tests/models.py

from django.db import models

class Author(models.Model):
    name = models.CharField(max_length=100)

class Post(models.Model):
    content = models.CharField(max_length=100)
    author = models.ForeignKey(Author, on_delete=models.CASCADE)

Now suppose we have another module my_module.py where we fetch our posts and collect their author's names in a list. We run this code under the queryhunter context manager, which will collect information on the lines of code responsible for executing SQL queries inside the context:

# queryhunter/tests/my_module.py
from queryhunter.tests.models import Post, Author
from queryhunter import queryhunter

def get_authors() -> list[Author]:
    with queryhunter():
        authors = []
        posts = Post.objects.all()  # suppose we have 5 posts
        for post in posts:
            authors.append(post.author.name)
    return authors

Let's now run the code

>>> from queryhunter.tests.my_module import get_authors
>>> get_authors()

and see what the output from the queryhunter is:

queryhunter/tests/my_module.py

====================================

Line no: 8 | Code: for post in posts: | Num. Queries: 1 | SQL: SELECT "tests_post"."id", "tests_post"."content", "tests_post"."author_id" FROM "tests_post" | Duration: 4.783299999999713e-05

Line no: 9 | Code: authors.append(post.author.name) | Num. Queries: 5 | SQL: SELECT "tests_author"."id", "tests_author"."name" FROM "tests_author" WHERE "tests_author"."id" = %s LIMIT 21 | Duration: 8.804199999801199e-05

What can we learn from this output?

• There are 2 distinct lines of code responsible for executing SQL in the get_authors function.

• The line authors.append(post.author.name) was responsible for executing 5 SQL queries, one for each post.

• This is a quick way to identify that we are missing a `select_related('author')` call in our Post.objects.all() query.

This may have been obvious in this contrived example, but in a large code base, flushing out these kinds of issues can be very useful.

Profiling Views with queryhunter's Middleware

django-queryhunter also ships with a middleware which, when installed, will profile all requests to your Django application.

To install the middleware, add `queryhunter.middleware.QueryHunterMiddleware` to your MIDDLEWARE setting:

# settings.py

MIDDLEWARE = [

    # ...

    'queryhunter.middleware.QueryHunterMiddleware',

]

As well as the usual query data reported by queryhunter, the middleware will also report the URL and the method of the request which caused the queries to be executed.

Here's some sample output:

queryhunter/tests/my_module.py

====================================

Line no: 8 | Code: for post in posts: | Num. Queries: 1 | Duration: 0.04 | url: /authors | method: GET | SQL: SELECT "tests_post"."id", "tests_post"."content", "tests_post"."author_id" FROM "tests_post"

Line no: 9 | Code: authors.append(post.author.name) | Num. Queries: 5 | Duration: 0.05 | url: /authors | method: GET | SQL: SELECT "tests_author"."id", "tests_author"."name" FROM "tests_author" WHERE "tests_author"."id" = %s LIMIT 21

Knowing not only the line of code which caused the bottleneck, but also the URL from which it originated, is an incredibly useful piece of information to have. It allows the developer connect the dots between the view code and the code underneath it in the call stack, thus informing them that perhaps the view code is missing some select_related call required by the previously unseen code underneath it.

Usage in Production

We have used this on a production code base and has outperformed similar libraries in diagnosing certain kinds of performance issues. queryhunter is lightweight enough to have enabled in production and its profiling will have negligible effect on performance. Having it continually enabled in production means wecan use it as a monitoring tool, quickly alerting the developer to any new bottlenecks accidentally introduced.

For some of my other work, see https://github.com/PaulGilmartin/