Finding Slow Queries and Reading Plans in PostgreSQL: pg_stat_statements, EXPLAIN ANALYZE and Where the Planner Goes Wrong

When an application slows down, the usual reflex is to add an index to whichever query looks guilty. An index added without knowing which query actually costs the most raises write overhead and leaves the real bottleneck untouched. PostgreSQL already ships the tools for this job: pg_stat_statements for aggregate load, EXPLAIN (ANALYZE, BUFFERS) for looking inside a single query, and auto_explain for capturing slow plans in production. This post covers the order to use them in and what to read in a plan.

Measure the load before the query

The slow query log (log_min_duration_statement) catches individual long statements. What usually wears a database down, though, is not the 3 second report that runs once, but the 8 millisecond query that runs hundreds of times per second. You only see that by looking at totals.

pg_stat_statements strips constants and folds queries with the same shape into one row. It has to be loaded at server start, so it needs a restart:

# postgresql.conf
shared_preload_libraries = 'pg_stat_statements'
track_io_timing = on

After the restart, in the database you want to observe:

CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

SELECT calls,
       round(total_exec_time::numeric, 0) AS total_ms,
       round(mean_exec_time::numeric, 2)  AS mean_ms,
       rows,
       shared_blks_hit,
       shared_blks_read,
       left(query, 120) AS query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 20;

Sort by total_exec_time, not mean_exec_time. Sorting by the mean puts the nightly maintenance job on top; sorting by the total shows where the database is actually spending its time. The calls column deserves its own look: a small query executed thousands of times per request is the clearest sign of an N+1 pattern in the application, and no index fixes that.

If you reset the counters with SELECT pg_stat_statements_reset(); before a change, you get a clean window to measure its effect.

With track_io_timing on, time spent reading from disk shows up in both the statistics and plan output. On some virtual machines where reading the clock is expensive it adds overhead, so measuring with pg_test_timing first is a good habit.

Reading a plan with EXPLAIN ANALYZE

Once you have a target, look at its plan:

EXPLAIN (ANALYZE, BUFFERS)
SELECT o.id, o.total
FROM orders o
WHERE o.customer_id = 4211
  AND o.status = 'open'
ORDER BY o.created_at DESC
LIMIT 50;

Plain EXPLAIN shows only the estimated plan. ANALYZE actually runs the statement and adds real row counts and timings to every node. So when examining an UPDATE or DELETE, wrap it in a transaction and roll back:

BEGIN;
EXPLAIN (ANALYZE, BUFFERS) UPDATE orders SET status = 'closed' WHERE id = 10;
ROLLBACK;

These are the places to look.

Estimated versus actual rows. Each node shows rows= twice: the planner's estimate and the real figure in the actual part. If they differ by a factor of ten or more, the planner decided with bad information, and every later choice (join type, index use, memory) is built on that error. In slow plans the problem is usually not the slowest node but the node where the first bad estimate was made.

loops. In nested loop joins the inner node's time and row count are per iteration; multiply by loops for the real cost. A 0.05 ms index scan that runs 200,000 times is the most expensive line in the plan.

Rows Removed by Filter. When an index was used but part of the condition is not in it, rows are fetched and then discarded. A large number here means the index columns or their order do not match the query.

Buffers. shared hit counts pages found in memory, read counts pages from disk. If a second run of the same query is much faster, what slowed the first one may have been a cold cache rather than the plan. Judging an optimization by pages touched is more reliable than by time, because time moves with machine load and page counts do not.

Sort Method. external merge Disk: ... means the sort did not fit in work_mem and spilled to a temporary file. Rather than raising work_mem globally, use SET LOCAL work_mem for the problematic transaction; the value is spent per sort or hash operation, not per connection.

Why the planner gets it wrong

Most bad estimates come from a few familiar causes.

Stale statistics. After a bulk load or a large delete, if autovacuum has not run ANALYZE yet, the planner reasons about the old table. Ending batch jobs with an explicit ANALYZE table_name; closes this whole class.

Correlated columns. By default the planner treats each condition's selectivity as independent and multiplies them. For columns where one implies the other, such as city = 'Ankara' AND country = 'TR', that badly underestimates the row count. Extended statistics teach it the relationship:

CREATE STATISTICS orders_city_country (dependencies) ON city, country FROM orders;
ANALYZE orders;

Skewed distributions. When most rows share a handful of values, the default sample can be too small. ALTER TABLE orders ALTER COLUMN status SET STATISTICS 1000; followed by ANALYZE collects a finer histogram for that column.

Expressions that disable an index. WHERE lower(email) = $1 cannot use a plain index on email; it needs an expression index (CREATE INDEX ON users (lower(email));). Comparisons that cast the column to another type cause the same thing.

ORDER BY with LIMIT. The planner may assume that scanning the sort column's index backwards will hit 50 matching rows quickly. If the matching rows sit at the other end of the table, it reads millions. If you see Index Scan Backward with a large Rows Removed by Filter, the fix is usually an index covering both the filter and the sort, for example (customer_id, created_at).

Pitfalls

Reading plans on a development database. Planner decisions depend on table size and data distribution. A sequential scan is the right choice on a few thousand rows; the same query gets a different plan in production. Read plans in production, or on a copy with the same size and distribution.

Generic plans for prepared statements. Drivers usually send queries as prepared statements. PostgreSQL builds parameter specific plans for the first few executions and may then switch to a generic plan if its cost looks similar. On skewed data that generic plan can be terrible for some parameters, and you cannot reproduce it with a hand typed EXPLAIN, because a literal query gets a custom plan. If you suspect this, try plan_cache_mode = force_custom_plan at session level and measure the difference.

Turning on ANALYZE everywhere in production. auto_explain logs plans for statements above a duration threshold and is the most honest way to see production plans. With auto_explain.log_analyze enabled, though, timing is collected for every statement, including those under the threshold. Start with auto_explain.log_min_duration and estimated plans only, and enable log_analyze briefly when you need real numbers.

Fixing one query and forgetting the load. Halving a query that ranks tenth in pg_stat_statements barely moves the total. Compare totals before and after.

When this is the wrong path

If the query is fast but calls per request is in the hundreds, the problem is in the application, not the database: you need batching or a join. If the time goes to lock waits instead of execution, EXPLAIN shows nothing; look at wait_event_type in pg_stat_activity and at pg_locks. Connection setup and pool queueing are not part of query time either. EXPLAIN tells you why a query is slow; for it to tell you why the application is slow, you first have to have measured that this query is the culprit.