Detecting N+1 with pg_stat_statements #

The database is at 80% CPU and no single query is slow. The slowest statement in the log takes 9 ms. Ranking by total time instead of mean time changes the picture completely: a statement averaging 0.04 ms runs 12 million times an hour and consumes more CPU than every reporting query combined.

Framework-specific detection is covered in detecting N+1 in Django ORM. This page finds the same pattern from the database side, which works for any stack and needs no application changes.

The Condition #

An N+1 pattern has a fingerprint in pg_stat_statements:

That last point is what distinguishes an N+1 from a legitimately frequent query. A point lookup called once per web request is normal; one called fifty times per request, matching the page size of a list endpoint, is a loop.

pg_stat_statements normalises literals into $1, so all iterations of a loop collapse into one row, which is exactly what makes the pattern visible. Two settings matter: pg_stat_statements.max (default 5000) so entries are not evicted, and pg_stat_statements.track = 'top' (the default) which tracks statements as the client issues them.

The four numbers to look at Four columns are annotated. A very high calls count identifies the loop. A low mean execution time shows each query is trivial. A high total execution time shows the aggregate cost. A call ratio matching another statement's rows confirms which parent drives the loop. calls = 12,040,110 the loop, not a slow query mean_exec_time = 0.041 ms each call is trivial total_exec_time = 493 s/hour the real cost calls ÷ parent calls ≈ 50 page size: confirms the loop rank by total_exec_time, never by mean_exec_time

Annotated Evidence #

Rank by total time:

SELECT calls,
       round(mean_exec_time::numeric, 3) AS mean_ms,
       round(total_exec_time::numeric)   AS total_ms,
       rows / nullif(calls, 0)           AS avg_rows,
       left(query, 70)                   AS query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 5;
  calls    | mean_ms | total_ms | avg_rows |                        query
-----------+---------+----------+----------+-----------------------------------------------
 12040110  |   0.041 |   493644 |        1 | SELECT … FROM customers WHERE id = $1
  8204110  |   0.038 |   311756 |        1 | SELECT … FROM addresses WHERE customer_id = $1
   240802  |   1.902 |   457805 |       50 | SELECT … FROM orders WHERE account_id = $1 …
      412  | 892.400 |   367669 |    12044 | SELECT … FROM order_lines l JOIN … (report)
-- orders runs 240,802 times returning 50 rows each → 12,040,100 order rows
-- customers calls = 12,040,110 ≈ one per order row: an N+1
-- addresses calls ≈ 0.68 per order row: a second lazy load, partly cached

Confirm with auto_explain that the child query is a trivial lookup:

LOG:  duration: 0.041 ms  plan:
  Index Scan using customers_pkey on customers  (cost=0.43..8.45 rows=1 width=84)
    Index Cond: (id = $1)
-- nothing to tune in this plan; the fix is to stop calling it

And check how the load is distributed over time:

SELECT now(), calls, total_exec_time FROM pg_stat_statements WHERE queryid = 8123456789012345678;
-- sample twice, a minute apart, and take the difference for a per-minute rate
Where the CPU actually goes Per hour, the customers-by-id loop consumes 494 seconds of execution time, the addresses loop 312 seconds, the orders list query 458 seconds, and the heaviest report 368 seconds. The two loops together exceed every deliberate query. customers by id (loop) 494 s/hour addresses by customer 312 s/hour orders list query 458 s/hour heaviest report 368 s/hour neither loop appears in a slow-query log with a 100 ms threshold

Step-by-Step Resolution #

  1. Reset the statistics before a representative window, so rates are meaningful:

    SELECT pg_stat_statements_reset();

  2. Rank by total_exec_time and note statements whose calls are orders of magnitude above the rest.

  3. Find the parent. Look for a statement whose calls × avg_rows matches the suspect’s calls. That is the query producing the rows the loop iterates over.

  4. Map the statement to code. Use the table and predicate to locate the association in the ORM. Where that is ambiguous, enabling application-level query tagging — a comment with the endpoint name, which pg_stat_statements preserves — removes the guesswork:

    /* endpoint=orders#index */ SELECT …

  5. Confirm the plan is trivial with auto_explain so you do not tune a query that needs no tuning.

  6. Fix in the application with eager loading or batching, then re-measure: the child statement’s calls should drop to roughly the parent’s calls.

  7. Add a monitoring check on the ratio between the two statements’ call counts so the regression is caught automatically.

Four steps from statistics to cause Four steps. Reset statistics and collect a window. Rank statements by total execution time. Match a high-call statement to a parent by comparing calls with rows. Confirm with auto_explain that the child plan is a trivial lookup, then fix it in the application. reset + collect one traffic window rank by total time not by mean match call ratio child calls vs rows confirm + fix auto_explain, eager load the database identifies the pattern; the fix is always in the application

Before and After #

-- BEFORE
customers by id:  calls 12,040,110/hour   total 494 s/hour
orders list:      calls    240,802/hour   avg_rows 50

-- AFTER eager loading
customers by id = ANY(array):  calls 240,802/hour   total 41 s/hour

Why total time is the only useful ranking #

Slow-query logging with a threshold — 100 ms, 1 s — is designed to catch individual expensive statements and is structurally blind to this pattern, because no individual call is slow. Ranking pg_stat_statements by mean_exec_time has the same blind spot. Only total_exec_time exposes the aggregate, and it also correctly ranks the genuinely heavy reports alongside the loops, which is what you want when deciding where to spend effort.

A second useful ranking is by rows ÷ calls combined with calls: statements returning exactly one row, millions of times, are almost always loops or cache-miss patterns. Statements returning tens of thousands of rows a few hundred times are reports. The two need completely different fixes, and the columns distinguish them without looking at the SQL.

Where pg_stat_statements is unavailable — a managed service that does not expose it, or a version without it — the same analysis is possible from auto_explain logs aggregated by normalised query text, though at higher logging cost. The reasoning is identical: group by statement shape, rank by summed duration, compare call counts between shapes.

Turning the check into monitoring #

Once the pattern is understood, it is worth watching continuously rather than rediscovering it during an incident. A simple recurring job samples pg_stat_statements twice a few minutes apart, computes per-statement call rates from the differences, and records the top statements by call rate and by total time growth. Alerting on a sudden jump in the call rate of any statement catches a newly deployed N+1 within minutes of the deploy, while it is still obviously connected to the change that caused it.

The same sampling supports a useful dashboard: calls per second and total time per second for the ten heaviest statements. Loops stand out immediately as tall bars in the calls chart with almost nothing in the time-per-call chart, and the shape of the two charts together tells you whether a regression is “more queries” or “slower queries” — which are different problems with different owners.

Common Pitfalls #

Ranking by mean time. The loop never appears. Diagnostic signal: a top-N list of reports while CPU is spent elsewhere. Fix: rank by total time.

Statistics evicted. With pg_stat_statements.max too low, rare statements push out common ones. Diagnostic signal: statements disappearing between samples. Fix: raise the limit.

Assuming one loop. Applications often have several. Diagnostic signal: fixing one and seeing modest improvement. Fix: repeat the ranking after each fix.

Tuning the child query. Its plan is already optimal. Diagnostic signal: an index scan of four buffers. Fix: reduce the number of calls instead.

Frequently Asked Questions #

How do I find N+1 queries without access to the application? #

Rank pg_stat_statements by total execution time and look for statements with very high call counts and sub-millisecond mean times. Match their call counts against another statement’s calls times rows to identify the parent query driving the loop.

Why does the slow query log not show N+1 patterns? #

Each individual query is fast — often well under a millisecond — so it never crosses a duration threshold. The problem is the number of executions, which only aggregate statistics reveal.

What ratio confirms an N+1? #

When a child statement’s call count is approximately the parent statement’s call count multiplied by the average rows the parent returns. That means one child query per parent row.

Up: N+1 Query Detection