Türker Yıldırım

The N+1 that does not appear in the query log

Deep dive10 min read

The orders page took four seconds and the slow query log was empty. Not almost empty — empty, for the whole day, because every query the page ran completed in under a millisecond. There were three hundred and forty of them.

The symptom

$ curl -s -o /dev/null -w '%{time_total}n' https://shop.internal/orders
3.914

$ mysql -e "SELECT COUNT(*) FROM mysql.slow_log WHERE start_time > NOW() - INTERVAL 1 DAY"
0

$ mysql -e "SHOW GLOBAL STATUS LIKE 'Questions'"; sleep 10; 
  mysql -e "SHOW GLOBAL STATUS LIKE 'Questions'"
Questions   84120211
Questions   84147918          # 2,770 queries/sec on a quiet afternoon

A four-second page with no slow query is the signature. The database is not the bottleneck by any measure it reports about itself — it is answering thousands of trivial questions very quickly, and the cost is entirely in the round trips.

Why it happens

Lazy loading is invisible at the call site. $order->customer->name in a template looks like a property access and is a query, and it runs once per row of whatever loop it is in. The number of queries is therefore proportional to the result set, which is why a page that is fine with twelve rows of seed data is unusable with real ones.

// the controller: one query
$orders = Order::where('status', 'processing')->paginate(20);

// the template: twenty more, and then some
@foreach ($orders as $order)
    {{ $order->customer->name }}          {{-- +1 per row --}}
    {{ $order->customer->country->code }}  {{-- +1 per row --}}
    {{ $order->lines->count() }}           {{-- +1 per row --}}
    {{ $order->lines->sum('total') }}      {{-- already loaded, free --}}
@endforeach

Sixty-one queries from four lines of template, and the fourth line is free because the third already loaded the collection. That asymmetry is the reason this is hard to reason about by reading: whether a line costs a query depends on what ran before it.

The fix

Eager loading, and the nested case

// 61 queries → 4
$orders = Order::with(['customer.country', 'lines'])
    ->where('status', 'processing')
    ->paginate(20);

// the count without the rows — one more query, no hydration
$orders = Order::withCount('lines')
    ->with('customer.country')
    ->paginate(20);

// {{ $order->lines_count }}   — an integer from the query

Dot notation loads a relation of a relation, which is the case people miss — eager loading customer and then reading customer.country in the template solves half the problem and leaves the other half looking identical. withCount is the one worth reaching for whenever a template only needs the number: it adds a subselect to the existing query rather than hydrating twenty collections of model objects.

Constraining the eager load

Eager loading the wrong relation is a slower page, not a faster one. A customer with four thousand orders loaded to display three is worse than the N+1 it replaced.

// loads every line of every order
$orders = Order::with('lines')->get();

// loads the three that are shown
$orders = Order::with(['lines' => function ($query) {
    $query->orderBy('total', 'desc')->limit(3);
}])->get();

// and the one that catches people: this does NOT limit per parent.
// the limit applies to the whole eager-load query, so nineteen of
// the twenty orders get nothing.

That last comment is the trap and it is not documented anywhere prominent. The eager load is a single WHERE order_id IN (...) query, so a limit inside the constraint limits the total rather than the rows per parent. Getting three lines per order requires either a window function or a separate query per order, and at that point the N+1 was probably fine.

Finding them without reading every template

The reliable way to find these is to count queries per request and look at the outliers, rather than to audit code.

final class CountQueries
{
    public function handle($request, Closure $next)
    {
        $count = 0;
        DB::listen(function () use (&$count) { $count++; });

        $response = $next($request);

        if ($count > 25) {
            Log::warning('request.query_count', [
                'route' => optional($request->route())->getName(),
                'count' => $count,
                'uri'   => $request->getRequestUri(),
            ]);
        }

        return $response;
    }
}

Twenty-five is arbitrary and the number does not matter — what matters is that the log now contains a ranked list of the worst routes, which is a work queue rather than a suspicion. On that codebase it found eleven routes above the threshold, of which two were above two hundred and nobody had reported either of them as slow.

The middleware costs a closure invocation per query, which is measurable and small. Running it in production behind a sampling rate — one request in a hundred — gives the same ranking at a fraction of the cost, and catches the routes that are only slow with real data.

A test that fails when it regresses

Fixing an N+1 without a test means fixing it again in four months, because nothing about adding a field to a template announces that it costs a query.

public function testOrderIndexDoesNotNPlusOne(): void
{
    factory(Order::class, 20)->create();

    $count = 0;
    DB::listen(function () use (&$count) { $count++; });

    $this->get('/orders')->assertOk();

    $this->assertLessThan(
        10, $count, "query count regressed to {$count}"
    );
}

An upper bound rather than an exact number is what makes it survivable — an exact assertion fails on every unrelated change and gets deleted within a month. Twenty rows in the factory is the part that makes it meaningful, since an N+1 across three rows is four queries and passes any threshold. The failure message carrying the actual count saves the next person a debugging session.

Verifying it worked

$ curl -s -o /dev/null -w '%{time_total}n' https://shop.internal/orders
0.212                                    # was 3.914

$ grep 'request.query_count' /var/log/app/app.json | jq -r .context.route 
  | sort | uniq -c | sort -rn
     0

$ mysql -e "SHOW GLOBAL STATUS LIKE 'Questions'"; sleep 10; 
  mysql -e "SHOW GLOBAL STATUS LIKE 'Questions'"
# 2,770/sec → 410/sec

$ vendor/bin/phpunit --filter NPlusOne
OK (11 tests, 11 assertions)

The global query rate dropping by a factor of six is the number worth reporting, because it is the one that shows up as headroom on the database rather than as a faster page. The eleven tests are the part that keeps it fixed, and they were written after the fix rather than before — which is the wrong order and is what actually happens.

What this costs

Eager loading is a decision that has to be made per query rather than once, and the default is the dangerous one. A relation eager-loaded on a route that does not use it is wasted work on every request, and there is nothing that reports it — the mirror image of the original problem, and considerably harder to find because the page is fast enough that nobody looks.

The deeper cost is that this is a permanent tax on writing templates. Every property access on a model is potentially a query and the syntax gives no hint either way, which is the price of the abstraction and is not going to change. The query-count test is the only mechanism I have found that makes it self-correcting, because it puts the feedback in front of the person who wrote the line rather than in front of a customer four months later.