skip to content

A Django timing middleware stores its start time on self in __call__; why are its durations wrong under concurrent load, and how do you fix it?

level: seniorimportance: should knowfreq 30%

answer

  1. how many instances exist
  2. who else calls __call__ meanwhile
  3. locals and the request object
  4. what the header does not include

basics

~20 s

Django creates one middleware instance per process at startup and every request shares it, so a concurrent request overwrites self.start and durations come out too short. Keep per-request state in a local variable in call or on the request object.

solid answer

~50 s

The handler instantiates each `MIDDLEWARE` entry once, when it builds the chain, and that single instance's `__call__` serves every request the process handles, concurrently when the server uses threads or runs Django under ASGI. `self.start = time.perf_counter()` is shared state: request B overwrites it while A is still running, so A's duration is measured from B's start and comes out too short, and the figures look inconsistent only under load. Fix it by keeping the start time in a local variable in `__call__`, or on the `request` object if another hook such as `process_view` needs it. Everything on `self` should be read-only configuration set in `__init__`. It also helps to know what the number covers: only the layers below this middleware, not a streaming body, and with default settings a view's exception still arrives as a 500 response, so the header is set on errors too.

code

python · 18 lines
python
import time


class TimingMiddleware:
    def __init__(self, get_response):
        self.get_response = get_response  # configuration only

    def __call__(self, request):
        request.timing_start = time.perf_counter()  # per request, not per instance
        response = self.get_response(request)
        elapsed_ms = (time.perf_counter() - request.timing_start) * 1000
        view_name = getattr(request, "timing_view", "unresolved")
        response["Server-Timing"] = f'app;dur={elapsed_ms:.1f};desc="{view_name}"'
        return response

    def process_view(self, request, view_func, view_args, view_kwargs):
        request.timing_view = view_func.__qualname__
        return None

go deeper

for a junior

Recall that init runs once and call per request, so values that change per request must not be stored on self.

for a middle

Explain that one instance per MIDDLEWARE entry serves every request in the process, and show the local-variable or request-attribute fix.

for a senior

Diagnose load-only anomalies from shared instance state, state what a timing middleware does and does not measure, and design checks that reproduce overlapping requests.

for a principal

Set conventions for middleware state and observability layers, such as review rules against per-request data on self, so concurrency bugs are prevented rather than debugged.

## One instance, many requests Django's WSGI and ASGI handlers call `load_middleware()` once, when the handler is created. That method instantiates every entry in `MIDDLEWARE` a single time and links the instances into a chain. From then on, **the same instance** of your middleware handles every request that process serves: - under a threaded server, several threads call its `__call__` at the same time; - under ASGI, concurrent requests are interleaved in one process. So instance attributes behave like **globals shared by all in-flight requests**. ## How the bug shows up ```python import time class BrokenTimingMiddleware: def __init__(self, get_response): self.get_response = get_response def __call__(self, request): self.start = time.perf_counter() # shared by every request response = self.get_response(request) elapsed = time.perf_counter() - self.start response["Server-Timing"] = f"app;dur={elapsed * 1000:.1f}" return response ``` Trace two overlapping requests: 1. Request A enters and sets `self.start` to t0. 2. Request B enters and overwrites `self.start` with t1. 3. A finishes and computes `now - t1`, a figure that leaves out the time between t0 and t1. The result is durations that are **too short and inconsistent**, and only under concurrency, so the middleware looks fine in development and in tests that send one request at a time. The same trap applies to any per-request value stored on `self`: the current user, a request ID, a counter that is read and then written back. ## The fix - **Local variables** inside `__call__` are private to one call, so `start = time.perf_counter()` is correct as it stands. - If a second hook needs the value, for example a `process_view` that records the view name for the timing header, **attach it to the request** (`request.timing_start = start`); the request object belongs to one request. - Keep `self` for **configuration** computed once in `__init__`: settings values, compiled patterns, a thread-safe client. - If you truly need mutable shared state, such as an in-process counter, protect it with a lock, and remember it is still per process, not global across servers. ## What the number actually measures Even when correct, the header only covers what the middleware wraps: | Situation | Effect on the timing | |---|---| | Middleware listed below one that returns early (for example an HTTPS redirect from `SecurityMiddleware`) | those requests are never timed | | Layers listed above the timing middleware | their work is not included | | A `StreamingHttpResponse` | the header is set before the body streams, so streaming time is excluded | | The view raises and `DEBUG_PROPAGATE_EXCEPTIONS` is `False` (the default) | the exception becomes a 500 response inside the chain, so the header is still set | | `DEBUG_PROPAGATE_EXCEPTIONS` is `True` | uncaught exceptions propagate through `__call__`; use `try/finally` if you must record them | Time spent outside Django altogether, in the server and the network, is invisible to any middleware. ## Checking the fix A single-request test cannot catch this class of bug. Useful checks are: - review every assignment to `self.` inside `__call__` and the hook methods; there should be none for per-request data; - load-test with overlapping slow and fast requests and compare the header with client-side timings; - log the per-request value next to a request identifier, so mismatches between requests become visible.

  • Why does the header still appear on 500 responses when the view raises?
    Django wraps the innermost handler and every middleware layer with `convert_exception_to_response`. With `DEBUG_PROPAGATE_EXCEPTIONS` at its default `False`, the view's exception becomes a 500 response before it reaches the timing middleware, so `get_response` returns normally and the after-phase sets the header. With it set to `True`, uncaught exceptions propagate, and the middleware needs `try/finally` to record the time.
  • What is safe to keep on self in a Django middleware?
    Values computed once in `__init__` and never changed per request: settings, compiled regular expressions, feature flags, clients designed for concurrent use. Anything that differs between requests, or is read and then written back, belongs in local variables or on the request, or needs a lock if it truly must be shared.

saying these in an interview costs you the question

  • Django creates a new middleware instance for every request.
  • Attributes on self are private to the current request.
  • The bug would show up in a single-request unit test.
  • A middleware's timing header includes streaming the response body.
  • A view exception skips the timing middleware's after-phase under default settings.