Finding Slow Queries — pg_stat_statements and auto_explain

"The site is slow" cannot be worked on. "These three statements account for 61% of all execution time on the primary, and one of them runs 200,000 times an hour" can be worked on this afternoon. Two extensions produce that second sentence: pg_stat_statements aggregates every statement the server runs into one row per normalized query shape, and auto_explain writes the plan of individual slow executions into the log.

Nadia currently has neither. She knows which pages users complain about and nothing about which statements are behind them, so every performance conversation starts with a guess and ends with a new index. Both extensions ship with Postgres in the standard contrib packaging, one of them needs a restart, and together they cost a few percent of a core on a busy server.

Installing and Reading pg_stat_statements

pg_stat_statements hooks the executor, so it has to be loaded into the postmaster before any backend starts. That means a line in postgresql.conf and a restart, which is the one detail worth knowing in advance: the moment you want this extension is the middle of an incident, and a restart is a poor thing to propose then. The extension also needs query identifiers, which compute_query_id produces; its default of auto means loading the module is enough to switch them on.

# postgresql.conf — requires a restart
shared_preload_libraries = 'pg_stat_statements,auto_explain'
pg_stat_statements.max   = 10000   # default 5000 entries
pg_stat_statements.track = top     # the default; 'all' includes nested

-- then, once, in the database
CREATE EXTENSION pg_stat_statements;

What lands in the view is one row per normalized statement, and normalization is the mechanism the whole thing rests on: literal constants are replaced by $1, $2 and so on, so 200,000 checkout queries with 200,000 different customer ids collapse into a single row with calls = 200000. Each row carries calls, total, minimum, maximum, mean and standard deviation of execution time, rows returned, shared and temporary block counters, and WAL volume as wal_records, wal_fpi and wal_bytes. Planning-time columns exist too, but track_planning is off by default because it contends badly when many backends plan the same statement shape at once.

Total Time Beats Mean Time

The instinct is to sort by the slowest query, and the instinct is wrong nearly every time. A nightly report that takes 40 seconds and runs once costs the server 40 seconds a day. Cartwheel's checkout lookup takes 8 milliseconds and runs 200,000 times an hour, which is 1,600 seconds of execution every hour — forty times the report's daily cost, every hour, on the path that users are actually waiting on. Sorting by mean_exec_time finds the report. Sorting by total_exec_time finds the thing that is eating the machine.

SELECT calls,
       round(total_exec_time)::int                        AS total_ms,
       round(mean_exec_time::numeric, 2)                   AS mean_ms,
       round(100 * total_exec_time / sum(total_exec_time) OVER (), 1) AS pct,
       rows / nullif(calls, 0)                             AS rows_per_call,
       left(query, 48)                                     AS query
  FROM pg_stat_statements
 ORDER BY total_exec_time DESC LIMIT 4;

  calls   | total_ms | mean_ms | pct  | rows_per_call |              query
----------+----------+---------+------+---------------+----------------------------------
  4812339 | 41022914 |    8.52 | 38.1 |             1 | SELECT … FROM inventory WHERE pro
   190447 | 19883012 |  104.40 | 18.5 |           312 | SELECT … FROM orders o JOIN order
       31 |  4980221 |  160.6k |  4.6 |        412008 | REFRESH MATERIALIZED VIEW analyti
  8802116 |   803114 |    0.09 |  0.7 |             1 | SELECT 1 FROM customers WHERE id

Those four rows carry four different fixes. The top one is 38% of the server's time in 8.5-millisecond slices, so the win is either fewer calls or two milliseconds shaved, which is a caching question as much as a database one. The second returns 312 rows per call at 104 milliseconds, which is a query worth reading before it is worth indexing. The materialized view refresh has by far the worst mean time and is 4.6% of the total, which is where mean-time-first ranking would have sent you. And the fourth is doing nothing wrong at all: 8.8 million calls at 0.09 milliseconds is a healthy index lookup, and the only question it raises is why the application asks it that often.

I/O Timing

track_io_timing is off by default and is the single switch that turns "this query is slow" into "this query spends 91% of its time waiting for blocks". With it on, the view gains shared_blk_read_time and shared_blk_write_time alongside the block counts, and the same data appears in pg_stat_database, pg_stat_io, VACUUM VERBOSE and the buffer lines of a plan. The cost is repeated clock reads, which the documentation warns can be significant on some platforms; pg_test_timing ships with Postgres to measure exactly that on the hardware in front of you, and on a modern x86 server the answer is usually that it is cheap enough to leave on permanently.

The reason it earns its overhead is that it separates two problems that look identical from the outside. A statement with most of its time in shared_blk_read_time is waiting on storage, and the levers are caching, a narrower row, or an index that reads fewer pages. A statement with almost no read time and a large total is burning CPU on rows it fetched from memory, and the lever is doing less work: fewer rows, a cheaper expression, a better join order. Without the timings the view cannot separate them, and block counts alone do not, because a block counted as read may have come from the kernel's cache in microseconds.

Resetting and Windowing

Every number in the view is cumulative since the last reset or restart, which makes an unreset installation a six-month average that includes an incident, two deploys and a schema migration. Each row carries stats_since so you can see how long it has been accumulating, and pg_stat_statements_reset() clears everything or, given arguments, one user, one database or one queryid. The cheapest before-and-after measurement available is to reset, apply one change, wait a representative interval, and read the view again.

SELECT pg_stat_statements_reset();            -- baseline at 10:00
-- … one change applied, one hour of production traffic …

SELECT now() - stats_since AS window, calls, round(total_exec_time)::int AS total_ms
  FROM pg_stat_statements WHERE queryid = 8451209947712300111;

     window      |  calls  | total_ms
-----------------+---------+----------
 01:04:17.882301 |  204118 |  1731044

One statement, one hour, a number that means something because the window is known. A monitoring agent does the same thing continuously, sampling the view every minute and graphing the differences, which is the same arithmetic without anyone having to remember when the reset happened. The counters are shared, though: every dashboard in the team is built on them, and a reset taken as a debugging reflex zeroes all of them at once.

auto_explain for the Plan You Missed

The aggregate view never shows a plan. It tells you a statement got slower; it cannot tell you that the plan flipped from a hash join to a nested loop at 09:14 on the first Saturday of the month. auto_explain fills that gap by logging the plan of any statement that exceeds a duration threshold — and because it fires on the executions that actually happened, it catches the pathological ones that never reproduce when you run the query by hand with a parameter you chose yourself.

auto_explain.log_min_duration = '500ms'  # default -1 = off
auto_explain.log_analyze      = on        # actual rows and times
auto_explain.log_buffers      = on        # and the I/O behind them
auto_explain.log_timing       = off       # the expensive half of log_analyze
auto_explain.log_nested_statements = on   # plans from inside functions
auto_explain.sample_rate      = 1.0       # lower it on a very hot server

Of those settings, only the threshold is a judgement call: 500 milliseconds on Cartwheel's primary produces a handful of plans an hour, all of them worth reading, whereas zero produces a plan for every statement and turns the log itself into the outage. log_nested_statements matters because the default records only top-level statements, so anything executed inside a PL/pgSQL function is invisible without it. The module can also be loaded through session_preload_libraries, which takes effect for new sessions without a restart — useful when the cluster is already running and you do not have a maintenance window.

Their Cost, Honestly

pg_stat_statements costs a small constant per statement and a fixed shared-memory footprint set by pg_stat_statements.max, which defaults to 5,000 entries and is allocated at startup. When more distinct shapes arrive than that, the least-executed entries are evicted, and the least-executed entries are exactly the rare, ad-hoc, once-a-week statements you may be hunting. pg_stat_statements_info.dealloc counts how often that has happened. A figure that keeps climbing means the view is showing the hot path and dropping the tail, and the setting is allocated at startup, so raising it costs a restart.

auto_explain has a sharper edge, and it is the thing people get wrong. Turning on log_analyze does not instrument only the statements that will exceed the threshold. The server has no way to know which those are until they finish, so the per-node instrumentation runs for every statement, and the manual warns that the effect on performance can be significant. log_timing is the expensive part of it, since it takes clock readings around every node; leaving it off keeps actual row counts and loses actual times, which is often the better trade. sample_rate below 1.0 caps the exposure further by instrumenting only a fraction of executions.

Run both, permanently, with the aggregate view as the standing dashboard and the plan capture set to a threshold that fires occasionally. The pairing converts a support ticket into a query id, a query id into a plan, and a plan into a change. The next topic widens the view from statements to the rest of the counters the server has been keeping all along.