Eine langsame Shop-Verwaltung: N+1-Abfragen und ein fehlender Index

Das Lager arbeitet in der Verwaltung mit der Bestellliste: 50 pro Seite, gefiltert nach Status, die neuesten oben. Zu jeder Bestellung stehen Kundenname, Versandart und Anzahl der Positionen. Nach einigen Jahren hat die Bestelltabelle Hunderttausende Zeilen.

Das Template durchläuft die Bestellungen in einer Schleife und liest bei jeder order.customer.name, order.shipping_method.name und order.items.count.

Die Liste wurde allmählich langsamer, deshalb fiel es lange niemandem auf. Im Weihnachtsgeschäft endete die Seite mit einem 502: Gunicorn beendet einen Worker, der nicht innerhalb der standardmäßigen 30 Sekunden antwortet, und Nginx liefert dann 502. Das Lager konnte Bestellungen nur noch über einen Export bearbeiten.

Gleichzeitig stieg die Datenbanklast und auch der Shop selbst wurde langsamer, weil Kunden und Verwaltung dieselbe Datenbank nutzen.

Die erste Ursache ist das N+1-Muster. Die Bestellabfrage lädt nur die Bestelltabelle. Jedes order.customer und order.shipping_method im Template schickt dann eine eigene Abfrage, order.items.count eine weitere. Bei 50 Bestellungen sind das 1 + 50 × 3 = 151 Abfragen pro Seitenaufruf. Jede ist schnell, aber 151 Wege zur Datenbank und zurück summieren sich.

Die zweite Ursache ist ein fehlender Index. Für den Filter nach Status und die Sortierung nach Erstellungsdatum gab es keinen passenden Index, also las PostgreSQL bei jedem Aufruf die ganze Tabelle und sortierte das Ergebnis, nur um die ersten 50 Zeilen zu liefern.

Auf einem Entwicklerrechner mit ein paar Dutzend Testbestellungen war beides nicht zu sehen.

Lokal, mit einer Kopie der Produktionsdaten, in der personenbezogene Daten durch erfundene ersetzt waren: django-debug-toolbar zeigte 151 Abfragen, die meisten Wiederholungen mit anderer ID.

In der Produktion die Erweiterung pg_stat_statements, die Statistiken zu Abfragen sammelt. Sie muss in shared_preload_libraries stehen, was einen Neustart von PostgreSQL erfordert, deshalb wurde sie nachts aktiviert. Die Abfrage der Bestellliste stand nach Gesamtzeit ganz oben.

EXPLAIN (ANALYZE, BUFFERS) zu dieser Abfrage zeigte einen sequenziellen Durchlauf der ganzen Tabelle (Seq Scan) und das Sortieren aller Zeilen mit dem gewählten Status.

Zugehörige Daten werden auf einmal geladen. select_related holt Kunde und Versandart per JOIN in dieselbe Abfrage, prefetch_related lädt die Positionen für alle 50 Bestellungen mit einer einzigen weiteren Abfrage.

orders = (
    Order.objects
    .filter(status=status)
    .select_related("customer", "shipping_method")  # joined into the same query
    .prefetch_related("items")                       # one extra query for the whole page
    .order_by("-created_at")
)
page = Paginator(orders, 50).get_page(request.GET.get("page"))

# template: {{ order.customer.name }}, {{ order.items.all|length }}
# both now read what is already loaded instead of asking the database again

Ein Index auf Status und Erstellungsdatum in absteigender Reihenfolge. Die Tabelle ist groß und der Shop läuft, deshalb wird der Index mit CONCURRENTLY angelegt, das Schreibzugriffe nicht blockiert. Das darf aber nicht in einer Transaktion laufen, daher atomic = False in der Migration.

from django.contrib.postgres.operations import AddIndexConcurrently
from django.db import migrations, models


class Migration(migrations.Migration):
    # CREATE INDEX CONCURRENTLY cannot run inside a transaction
    atomic = False

    dependencies = [("shop", "0042_order_note")]

    operations = [
        AddIndexConcurrently(
            "order",
            models.Index(fields=["status", "-created_at"], name="order_status_created_idx"),
        ),
    ]

Ein Test, der darüber wacht, dass die Zahl der Abfragen nicht mit der Zahl der Bestellungen wächst. Er prüft keine genaue Zahl, die sich legitim ändern kann, sondern ob 5 und 50 Bestellungen gleich viel kosten.

from django.db import connection
from django.test import TestCase
from django.test.utils import CaptureQueriesContext
from django.urls import reverse


def count_queries(client, url):
    with CaptureQueriesContext(connection) as ctx:
        client.get(url)
    return len(ctx.captured_queries)


class OrderListTests(TestCase):
    def test_query_count_does_not_grow_with_orders(self):
        self.client.force_login(make_staff())
        url = reverse("admin_orders")

        make_orders(5)
        few = count_queries(self.client, url)
        make_orders(45)
        many = count_queries(self.client, url)

        self.assertEqual(few, many)

Die Zahl der Abfragen ist jetzt konstant, egal wie viele Bestellungen auf der Seite stehen. Die Daten, die das Template liest, sind schon im Speicher, es fragt nicht erneut.

Der Index ist genau so sortiert, wie wir fragen: erst Status, dann Datum ab dem neuesten. PostgreSQL findet die ersten 50 Zeilen dieses Status direkt im Index und liest nicht weiter. Kein Durchlauf der ganzen Tabelle, kein Sortieren.

Der Test schlägt beim ersten neuen Feld im Template fehl, das N+1 zurückbringen würde, also bevor das Lager es merkt.

Was das nicht löst: Die Seitennavigation braucht die Gesamtzahl der Bestellungen im Status, und dieses COUNT(*) wächst weiter mit ihrer Zahl, wenn auch mit Index günstiger. Andere Seiten der Verwaltung wurden nicht geprüft.