Django performance: profiling and optimising

nivas/profile_report.py

"""The dues report of tower B measured two ways: every query it sends, captured and grouped by its shape (the SQL with
its values taken out), and the time it takes. The slow report reads the bills one flat at a time; the other asks the
database to count and add them up.

The times change from run to run and from computer to computer; the queries do not.
"""

import re
import time
from collections import Counter

import seed

seed.fresh()

from django.db import connection  # noqa: E402
from django.test.utils import CaptureQueriesContext  # noqa: E402

from society.reports import dues_report, dues_report_slow  # noqa: E402

VALUES = re.compile(r"'[^']*'|\b\d+\b")


def measure(label, report):
    with CaptureQueriesContext(connection) as ctx:
        start = time.perf_counter()
        rows = report('B')
        took = time.perf_counter() - start
    shapes = Counter(VALUES.sub('?', q['sql']) for q in ctx.captured_queries)
    shape, repeats = shapes.most_common(1)[0]
    n = len(ctx.captured_queries)
    print(f'{label}: {n} {"query" if n == 1 else "queries"} in {took * 1000:.0f} ms, {len(rows)} flats')
    if repeats > 1:
        print(f'   {repeats} of them have the same shape: SELECT … FROM "society_bill"{shape[shape.find(" WHERE"):]}')
    return rows


slow = measure('dues_report_slow', dues_report_slow)
fast = measure('dues_report', dues_report)
print('the two reports agree:', slow == fast, '| first row:', fast[0])

dues_report_slow: 201 queries in 216 ms, 200 flats
   200 of them have the same shape: SELECT … FROM "society_bill" WHERE ("society_bill"."flat_id" = ? AND "society_bill"."paid_on" IS NULL)
dues_report: 1 query in 3 ms, 200 flats
the two reports agree: True | first row: ('B-1001', 3, 735000)

society/reports.py · nivas/society/reports.py

from django.db.models import Count, Q, Sum

from .models import Flat

UNPAID = Q(bills__paid_on__isnull=True)


def dues_report_slow(tower):
    """Each flat of the tower with its unpaid bills and what it owes, read one flat at a time."""
    rows = []
    for flat in Flat.objects.filter(tower=tower).order_by('code'):
        unpaid = list(flat.bills.filter(paid_on__isnull=True))
        rows.append((flat.code, len(unpaid), sum(bill.amount_paise for bill in unpaid)))
    return rows


def dues_report(tower):
    """The same report in one query: the database counts and adds up the unpaid bills of every flat."""
    flats = (Flat.objects.filter(tower=tower).order_by('code')
             .annotate(unpaid=Count('bills', filter=UNPAID), owed=Sum('bills__amount_paise', filter=UNPAID, default=0)))
    return [(flat.code, flat.unpaid, flat.owed) for flat in flats]

nivas/seed.py

"""The data the examples of this lesson start from: tower B with 200 flats and a year of monthly bills each, 2,400
bills of which the last three months are unpaid. fresh() builds the tables from nothing first.
"""

import os
from datetime import date

os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'config.settings')

import django  # noqa: E402

django.setup()

from django.core.management import call_command  # noqa: E402


def fresh(flats=200):
    from django.conf import settings

    db = settings.DATABASES['default']['NAME']
    if settings.DATABASES['default']['ENGINE'].endswith('sqlite3') and os.path.exists(db):
        os.remove(db)
    call_command('migrate', verbosity=0)
    from society.models import Bill, Flat

    homes = Flat.objects.bulk_create(Flat(tower='B', code=f'B-{1001 + i}') for i in range(flats))
    Bill.objects.bulk_create(
        Bill(flat=flat, month=date(2026, month, 1), amount_paise=245000 + 100 * (i % 7),
             paid_on=None if month > 9 else date(2026, month, 5))
        for i, flat in enumerate(homes) for month in range(1, 13)
    )

manage.py check · nivas/toolbar_check_session.py

"""django-debug-toolbar half installed, then installed: its own system check names what is missing."""

from session import run

run(
    """
    python manage.py check --settings config.settings_toolbar_half
    python manage.py check --settings config.settings_toolbar
    """
)

$ python manage.py check --settings config.settings_toolbar_half
System check identified some issues:

WARNINGS:
?: (debug_toolbar.W001) debug_toolbar.middleware.DebugToolbarMiddleware is missing from MIDDLEWARE.
	HINT: Add debug_toolbar.middleware.DebugToolbarMiddleware to MIDDLEWARE.

System check identified 1 issue (0 silenced).
$ python manage.py check --settings config.settings_toolbar
System check identified no issues (0 silenced).

config/settings_toolbar.py · nivas/config/settings_toolbar.py

"""Development settings with django-debug-toolbar: the app, its middleware as early as possible, and the addresses it
shows itself to. Never in production: the toolbar shows every query and setting of a page to whoever sees it."""

from .settings import *  # noqa: F403

INSTALLED_APPS = [*INSTALLED_APPS, 'debug_toolbar']  # noqa: F405
MIDDLEWARE = ['debug_toolbar.middleware.DebugToolbarMiddleware', *MIDDLEWARE]  # noqa: F405
INTERNAL_IPS = ['127.0.0.1']

nivas/toolbar_report.py

"""What django-debug-toolbar shows for the two reports, read through the test client instead of a browser: the toolbar
is added to every HTML page for an address in INTERNAL_IPS, and its SQL panel, which a browser loads when the panel is
opened, counts the page's queries and how many of them are similar (the same SQL with other values) or duplicates
(the same SQL with the same values).

The toolbar also shows how long each query took; those times change on every run, so they are left out here.
"""

import json
import os
import re

os.environ['DJANGO_SETTINGS_MODULE'] = 'config.settings_toolbar'

import seed  # noqa: E402

seed.fresh()

from django.test import Client  # noqa: E402

client = Client()  # its requests come from 127.0.0.1, which INTERNAL_IPS lists
for url in ['/reports/slow/B/', '/reports/B/']:
    page = client.get(url).content.decode()
    request_id = re.search(r'data-request-id="([^"]+)"', page).group(1)
    panels = [re.sub(r'\s+in [\d.]+ms', '', s) for s in re.findall(r'<small>([^<]*)</small>', page)]
    sql = client.get(f'/__debug__/render_panel/?request_id={request_id}&panel_id=SQLPanel')
    text = re.sub(r'\s+', ' ', re.sub(r'<[^>]+>', ' ', json.loads(sql.content)['content']))
    summary = re.search(r'\((\d+ quer[^)]*)\)', text).group(1).strip()
    print(f'{url}: the toolbar says "{panels[4]}"; SQL panel: {summary}')

/reports/slow/B/: the toolbar says "201 queries"; SQL panel: 201 queries including 200 similar
/reports/B/: the toolbar says "1 query"; SQL panel: 1 query

config/urls.py · nivas/config/urls.py

from django.conf import settings
from django.urls import include, path

urlpatterns = [
    path('', include('society.urls')),
]

if 'debug_toolbar' in settings.INSTALLED_APPS:
    from debug_toolbar.toolbar import debug_toolbar_urls

    urlpatterns += debug_toolbar_urls()