The N+1 that only appeared in production

An endpoint that returned in forty milliseconds locally and took two point one seconds in production, on the same code, with a database of the same schema. The test suite asserted three queries; production was doing nine hundred.

The symptom

the same request, two environments:

  local     3 queries      41ms
  staging   7 queries      88ms
  prod    902 queries   2,140ms

and the difference is the data:

  local     each customer has 1 order
  staging   each customer has 2-3
  prod      the top 40 customers have 200-900

// the endpoint
$customers = Customer::with('orders')->paginate(20);

return CustomerResource::collection($customers);

// the resource
public function toArray($request): array
{
    return [
        'id' => $this->id,
        'latest_order' => $this->orders->isEmpty()
            ? null
            : $this->orders()->latest()->first(),   // ← a query
    ];
}

The eager load is there and it is not being used. $this->orders reads the loaded relation, and $this->orders() starts a fresh query — one character apart, and the difference between three queries and nine hundred.

Why it happens

Seed data has the shape somebody typed rather than the shape production has. A relationship with one row behaves identically whether it is loaded or queried, so an N+1 with N equal to one is invisible in every environment except the one that matters.

The fix

Finding it: sampled query logging

// enabled for 1 request in 200, in production
if (random_int(1, 200) === 1) {
    DB::listen(function (QueryExecuted $q) {
        app(QuerySampler::class)->record($q->sql, $q->time);
    });

    app()->terminating(function (QuerySampler $sampler) {
        if ($sampler->count() > 50) {
            Log::warning('high query count', $sampler->summary());
        }
    });
}

what the summary looked like:

  route:    GET /api/customers
  count:    902
  total:    1,840ms
  distinct: 4
  top:
    881×  select * from orders where customer_id = ?
           order by created_at desc limit 1
     20×  select * from customers ...

881 executions of one statement is not a slow query.
it is the same query, 881 times.

Grouping by normalised statement rather than listing every query is what makes the output readable — nine hundred lines is noise and “881 executions of this one” is a diagnosis. The threshold of fifty is arbitrary and low enough to catch this class without firing on a legitimately complex page.

The fix, which is two lines

// eager load the specific thing the resource needs
$customers = Customer::with(['orders' => fn ($q) =>
    $q->latest()->limit(1)
])->paginate(20);

// and the resource stops re-querying
'latest_order' => $this->orders->first(),

// note: a constrained eager load with a limit needs
// care — a plain limit applies to the whole loaded set,
// not per parent. this uses the lateral-join helper.

The limit-per-parent problem is the trap in the fix: naively adding limit(1) to an eager load returns one row across all parents, not one per parent. Getting that wrong replaces a slow endpoint with a wrong one, which is worse.

The lazy-loading guard

// AppServiceProvider::boot()
Model::preventLazyLoading(! app()->isProduction());

Model::handleLazyLoadingViolationUsing(
    function (Model $model, string $relation): void {
        $message = sprintf('lazy load: %s::%s', $model::class, $relation);

        if (app()->isProduction()) {
            Log::warning($message);
            return;
        }

        throw new LazyLoadingViolationException($model, $relation);
    }
);

Throwing in development and logging in production is the right split: a violation in production is a performance problem and not worth a 500, and a violation locally should stop the developer immediately. Turning this on found eleven more, of which four were real.

Seed data that resembles production

// before: uniform
Customer::factory(100)->has(Order::factory())->create();

// after: the shape production has
Customer::factory(60)->has(Order::factory()->count(1))->create();
Customer::factory(35)->has(Order::factory()->count(rand(2, 20)))->create();
Customer::factory(5)->has(Order::factory()->count(rand(200, 900)))->create();

// the last line is the one that matters, and it makes
// the seed take 40 seconds instead of 2.

The distribution matters more than the volume. Five customers with several hundred orders each reproduces this class of bug reliably, and a hundred thousand customers with one order each does not — which is why “seed more data” is the wrong instinct.

The query count assertion, and its brittleness

public function testCustomerIndexDoesNotScaleWithOrders(): void
{
    $this->seedRealisticDistribution();

    DB::enableQueryLog();
    $this->getJson('/api/customers')->assertOk();

    // not an exact count — a bound. the point is that it
    // does not grow with the data.
    self::assertLessThan(10, count(DB::getQueryLog()));
}

Asserting a bound rather than an exact number is what stops this test failing every time somebody adds a legitimate query. An exact assertion is more precise and produces a test that gets updated without being read, which is worse than a loose one that only fires on a real regression.

Verifying it worked

$ ./bin/query-count /api/customers
  local (realistic seed)     4 queries    48ms
  production (sampled)       4 queries    61ms

# p95 on the endpoint, one week
  before  2,140ms
  after      88ms

# and the guard, over a month in production
$ grep -c 'lazy load:' /var/log/app/*.log
11
$ grep -oP 'lazy load: KS+' /var/log/app/*.log | sort -u | wc -l
7        # 7 distinct, 4 of which were fixed

The seven distinct violations found by the guard are the real return on this work — one of them was on the checkout path and had been adding two hundred milliseconds to every order for eighteen months.

What this costs

Seed data that must now resemble production shapes, which makes the seed slower and gives it a maintenance burden — the distribution is a guess that will drift from reality unless somebody periodically checks it against the real thing.

The lazy-loading guard is also a behaviour change that will surprise somebody. A relation accessed in a Blade template that was fine for three years now throws in development, and the correct fix is usually to eager load it — but the pressure under a deadline is to disable the guard for that request, which is available and is how this protection gets eroded.