CodeOath
← All posts
Python65 min total · 18 parts

Django Fundamentals: The ORM, Migrations, and Shipping a Real App

Part 15 of 18 · ~2 min

Middleware, and Catching the Slow Page Before a Neighbor Does

MIDDLEWARE = [
    "django.middleware.security.SecurityMiddleware",
    "django.contrib.sessions.middleware.SessionMiddleware",
    "django.middleware.common.CommonMiddleware",
    "django.middleware.csrf.CsrfViewMiddleware",
    "django.contrib.auth.middleware.AuthenticationMiddleware",
]

Think of this list as a stack of layers, outermost first: whichever middleware sits at the top gets first crack at an incoming request, then hands it down to the next one, and so on until a view finally produces a response — which then climbs back up through those same layers in reverse before it reaches the browser. That ordering isn't arbitrary. AuthenticationMiddleware works by pulling whoever's currently signed in out of session data that only exists because SessionMiddleware set it up first — so it has to sit below SessionMiddleware in this list, not above it. Get that backwards, or slot a new middleware in above something it silently leans on, and there's no line of code anywhere that looks wrong; the failure only shows up as a feature quietly not working, with the actual cause sitting one file away from where anyone would think to look.

The middleware that actually caught the three-second page

Priya never noticed the browse page had degraded from a stopwatch — she noticed it from a middleware she'd added months earlier for an unrelated reason, which happened to be exactly the right tool for the job:

import logging
import time

logger = logging.getLogger("toolshed.slow_requests")

class SlowRequestLoggingMiddleware:
    def __init__(self, get_response):
        self.get_response = get_response   # runs once, at process startup

    def __call__(self, request):
        start = time.perf_counter()
        response = self.get_response(request)     # everything below this middleware runs here
        elapsed_ms = (time.perf_counter() - start) * 1000
        if elapsed_ms > 300:
            logger.warning("%s took %.0fms", request.path, elapsed_ms)
        return response

Django constructs this class exactly once, at process startup, which is why self.get_response gets stashed away inside __init__ rather than looked up fresh on each request — __call__ is the part that fires per request, so that's the only place any per-request work is allowed to live. start = time.perf_counter() captures a timestamp before the view or any middleware beneath this one has done a thing; elapsed_ms isn't computed until control comes back up through this same layer, response already assembled, everything downstream having already run. This is what actually put a number in front of Priya: a warning line reading /tools/ took 2840ms, sitting quietly in the logs for weeks before anyone thought to go looking for it.