Locating the time in a slow request
coreadvancedStart by splitting one number into four. A request takes 2,400 ms; how much of that was the database, how much was waiting on other services, how much was your own Python, and how much happened before your view was even called? Middleware is the part people forget: every entry in `MIDDLEWARE` runs on every request, in order, on the way in and on the way out — so one middleware doing a database lookup per request adds its cost to every endpoint, including the health check. Until the 2,400 is broken up, any fix is a guess.
Think of it as
A request is a stack of nested spans, and debugging is narrowing down which span holds the time. The outermost span is the whole request; inside it, middleware on the way in, the view, and middleware on the way out. Inside the view sit database time, outbound call time, and your own computation. The useful discipline is to refuse to look at code until you know which span is guilty, because the layers look identical from a single duration and lead to completely different files. Two subtleties are worth internalising. First, database time is not the sum of your view's queries alone — session middleware, authentication middleware and any custom middleware also query, and their cost is attributed to the request but lives outside the view. An endpoint that is "slow for no reason" with three trivial queries is often paying for a session read, a user lookup, and a feature-flag fetch before the view runs. Second, a percentile hides shape. A p95 of 2 s can mean every request takes about 2 s, or that 95% take 50 ms and a tail takes 30 s — and those are unrelated investigations. Always look at the distribution, and always attach the four numbers to individual slow requests, so that a bad one can be read directly instead of inferred from an aggregate.
What we're doing: Time each middleware and the view separately, so "the request is slow" becomes "this layer is slow".
- 8
- A dict on the request is the simplest span carrier. Anything deeper — a database wrapper, an HTTP client hook — writes into it, so the log line is assembled in one place.
- 11
- Everything below this middleware in `MIDDLEWARE` happens inside this call, which is what makes an outermost middleware the right place to measure the whole request.
- 20
- The number that finds the problem nobody looks for: total minus view time is everything the middleware stack spent. A session backend on a slow store shows up here and nowhere else.
- 22–23
- Both database numbers, because they disagree usefully — high time with a high count is a different fix from high time with a low count.
- 27–29
- `process_view` fires after routing and just before the view, giving a clean boundary between "the framework got here" and "your code ran".
Why this works: One log line per request turns a duration into a location. The middleware span in particular is invisible to view-level profiling, and it is the layer whose cost is paid by every endpoint you own.
Profiling the view when the time is in middleware
Wrong
Better
What you see: Every endpoint has an unexplained floor — even a static response takes hundreds of milliseconds — and per-view optimisation never moves it, because no view is responsible.
Why: Middleware runs outside the view, so a profiler started inside the view cannot see it, and per-endpoint dashboards attribute its cost to whichever endpoint was called. The tell is the floor: a request that does nothing should be near zero, and when it is not, the cost is in the stack around it. This is also why middleware is the most expensive place to put a database query in the whole codebase — the cost is multiplied by your total request rate rather than by one endpoint's.
- 0 ms: Request accepted by the worker — anything before this is server queueing, not your code
- 0–40 ms: Middleware, inbound — session read + user lookup + feature flags = 3 queries before the view
- 40–2,250 ms: The view — db 2,210 ms across 431 queries — the count says N+1, not a slow query
- 2,250–2,380 ms: Serialization — invisible in the SQL log; shows up as cpu_ms
- 2,380–2,400 ms: Middleware, outbound — compression, headers — runs on every response too
- after: What a single duration told you — nothing: the same 2,400 ms could have been any one of these spans
Reading the four numbers
Together
Remember: Refuse to open a file until one duration is four numbers: database, external, CPU and — the one people forget — middleware. Every entry in `MIDDLEWARE` runs on every request in both directions, so a query in there is the most expensive query in the codebase; the tell is a floor under every endpoint, including ones that do nothing. And always read p50 next to p95 and p99, because uniform slowness and a bad tail look identical in a single percentile and need opposite investigations.
See also: database symptoms n plus 1 connections and locks · dependencies and the tool for each symptom · the request response lifecycle

