Lesson 25.35 · PostgreSQL Operations · 20 min read

Slow queries: the log and pg_stat_statements

Q: What is a normalized query?

pgstatstatements replaces constants with placeholders, so select from orders where id = 42 and where id = 43 count as one entry with $1. Each entry has a queryid, which you can use to refer to the same statement in monitoring, in discussions with the app team and when comparing before and after a fix.

Q: The database is slow overall and nothing shows up in the slow-query log. How do you find the responsible query?

pgstatstatements: it keeps calls, total and mean time, rows and buffers per normalized query. It needs sharedpreloadlibraries = 'pgstatstatements' (a restart) and CREATE EXTENSION. Sort by totalexectime to find what costs the server the most - often a query of a few milliseconds called thousands of times, which a logmindurationstatement threshold never catches. Then EXPLAIN the top query, fix it (usually an index), call pgstatstatementsreset() and compare the same load before and after.

In plain words

A restaurant is struggling and the manager asks which dish takes the kitchen's time. Watching only the dishes that take over half an hour misses the problem: a two-minute starter ordered by every single table.

pg_stat_statements is the kitchen's tally sheet: for every kind of order it counts how often it came in and how long it took in total. Sorting by total time shows the starter at the top.

Why this lesson exists

EXPLAIN answers "why is this query slow". On call you first have to answer "which query is making the database slow" - out of thousands of statements a minute from a dozen services. PostgreSQL has two tools for that, and every production server should have both on before the incident: the slow-query log (log_min_duration_statement) and the pg_stat_statements extension, which keeps running totals for every distinct query. This lesson sets both up on the lab server and uses them to find a query that eats the database.

What you need to know already: EXPLAIN (ANALYZE) and indexes (the last lesson), postmaster vs sighup settings and ALTER SYSTEM (lesson 2), the orders-api apps (lesson 5).

The words you need first

Slow-query log - with log_min_duration_statement = 250ms, every statement that takes longer is written to the server log with its duration and text.
pg_stat_statements - a contrib extension: for each normalized query (constants replaced by $1, $2) it counts calls, total / mean / max time, rows and buffer use, since the last reset. It needs to be loaded at server start (shared_preload_libraries).
Normalized query - select * from orders where id = 42 and ... id = 43 are the same entry: select * from orders where id = $1.
Total time vs mean time - a 2 ms query called 50,000 times a minute costs more than a 10 s report once an hour. Sort by total to find the load, by mean to find the individually slow ones.
auto_explain - another contrib module that logs the plan of every statement slower than a threshold.

The slow-query log

It is a superuser-context setting, so a reload is enough, and it can be set per role or database too:

$ sudo -u postgres psql -c "alter system set log_min_duration_statement = '20ms'"
ALTER SYSTEM
$ sudo -u postgres psql -c "select pg_reload_conf()"
 pg_reload_conf
----------------
 t
(1 row)
$ sudo -u postgres psql -d orders -qc "select count(*) from orders o join order_items i on i.order_id = o.id where o.status = 'paid'" > /dev/null
$ sudo grep 'duration:' /var/log/postgresql/postgresql-18-main.log | tail -n 2
2026-09-22 20:01:54.500 UTC [17417] postgres@orders LOG:  duration: 20.190 ms  statement: select count(*) from orders o join order_items i on i.order_id = o.id where o.status = 'paid'

duration: N ms statement: ... with user@database in the prefix - enough to know who ran what. In production 250ms to 1s is typical; 0 logs everything (only for a few minutes, it can produce gigabytes). Related switches: log_statement = 'ddl' (log every schema change

cheap, very useful), log_lock_waits = on, log_temp_files = 0 (sorts spilling to disk).

The log answers "what was slow at 14:02", but not "what costs the most overall": a query that takes 15 ms is never logged at a 250 ms threshold, even if it runs 2000 times a second.

pg_stat_statements

Two steps: load the library at start (a restart), then create the extension in the database you query it from.

$ sudo -u postgres psql -d orders -c "select * from pg_stat_statements limit 1"
ERROR:  relation "pg_stat_statements" does not exist
LINE 1: select * from pg_stat_statements limit 1
                      ^
$ sudo -u postgres psql -c "alter system set shared_preload_libraries = 'pg_stat_statements'"
ALTER SYSTEM
$ sudo systemctl restart postgresql@18-main
$ sudo -u postgres psql -d orders -c "create extension if not exists pg_stat_statements"
CREATE EXTENSION
$ sudo -u postgres psql -d orders -c "select * from pg_stat_statements limit 1"
 userid | dbid | toplevel | queryid | query | plans | total_plan_time | min_plan_time | max_plan_time | mean_plan_time | stddev_plan_time | calls | total_exec_time | min_exec_time | max_exec_time | mean_exec_time | stddev_exec_time | rows | shared_blks_hit | shared_blks_read | shared_blks_dirtied | shared_blks_written | local_blks_hit | local_blks_read | local_blks_dirtied | local_blks_written | temp_blks_read | temp_blks_written | shared_blk_read_time | shared_blk_write_time | local_blk_read_time | local_blk_write_time | temp_blk_read_time | temp_blk_write_time | wal_records | wal_fpi | wal_bytes | wal_buffers_full | jit_functions | jit_generation_time | jit_inlining_count | jit_inlining_time | jit_optimization_count | jit_optimization_time | jit_emission_count | jit_emission_time | jit_deform_count | jit_deform_time | parallel_workers_to_launch | parallel_workers_launched | stats_since | minmax_stats_since
--------+------+----------+---------+-------+-------+-----------------+---------------+---------------+----------------+------------------+-------+-----------------+---------------+---------------+----------------+------------------+------+-----------------+------------------+---------------------+---------------------+----------------+-----------------+--------------------+--------------------+----------------+-------------------+----------------------+-----------------------+---------------------+----------------------+--------------------+---------------------+-------------+---------+-----------+------------------+---------------+---------------------+--------------------+-------------------+------------------------+-----------------------+--------------------+-------------------+------------------+-----------------+----------------------------+---------------------------+-------------+--------------------
(0 rows)

The order of the errors is the order of the steps: first the view does not exist (no extension), and with the extension but without the library it says pg_stat_statements must be loaded via "shared_preload_libraries". On managed services the library is usually preloaded and you only CREATE EXTENSION. Careful with shared_preload_libraries: it is one list - if it already holds something (auto_explain, pg_cron, timescaledb), append, do not replace.

Now let the orders-api fleet run for a while, then ask the classic question:

$ sudo -u postgres psql -d orders -c "select left(query, 60) as query, calls, round(total_exec_time::numeric, 1) as total_ms, round(mean_exec_time::numeric, 2) as mean_ms, rows from pg_stat_statements order by total_exec_time desc limit 5"
 query | calls | total_ms | mean_ms | rows
-------+-------+----------+---------+------
(0 rows)

Read it like a profile:

The top row by total_ms is where the server spends its time - here the order history query, run over and over, each one a sequential scan of orders (the last lesson's query without its index).
calls and mean_ms say why it is on top: many calls of a moderately slow query, or a few calls of a very slow one. The fix differs (an index vs a different query or a cache).
rows / calls - a query returning thousands of rows per call is often an N+1 or a missing LIMIT in the app.

Other columns worth knowing: shared_blks_hit / shared_blks_read (cache vs disk), temp_blks_written (spilling sorts), stddev_exec_time (unstable plans), toplevel, stats_since. pg_stat_statements_reset() starts the counters from zero - do it before you measure a fix, so the before/after comparison is clean, and note the time.

From the query to the fix

The top query, with its plan:

$ sudo -u postgres psql -d orders -c "explain (analyze, buffers) select id, status, total_cents, created_at from orders where customer_id = 1234 order by created_at desc limit 20"
                                                     QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
 Limit  (cost=871.17..871.19 rows=10 width=26) (actual time=7.146..7.152 rows=10.00 loops=1)
   Buffers: shared hit=374 dirtied=371
   ->  Sort  (cost=871.17..871.19 rows=10 width=26) (actual time=7.143..7.145 rows=10.00 loops=1)
         Sort Key: created_at DESC
         Sort Method: quicksort  Memory: 17kB
         Buffers: shared hit=374 dirtied=371
         ->  Seq Scan on orders  (cost=0.00..871.00 rows=10 width=26) (actual time=0.406..6.975 rows=10.00 loops=1)
               Filter: (customer_id = 1234)
               Rows Removed by Filter: 39990
               Buffers: shared hit=371 dirtied=371
 Planning:
   Buffers: shared hit=44 read=1 dirtied=2
   I/O Timings: shared read=0.013
 Planning Time: 0.195 ms
 Execution Time: 7.165 ms
(15 rows)

A Seq Scan with tens of thousands of rows removed by the filter, run thousands of times. Build the index without blocking the app (lesson 10 explains CONCURRENTLY), reset the counters, let the load run again:

$ sudo -u postgres psql -d orders -c "create index concurrently orders_customer_created_idx on orders (customer_id, created_at desc)"
CREATE INDEX
$ sudo -u postgres psql -d orders -c "select pg_stat_statements_reset()"
 pg_stat_statements_reset
--------------------------
 2026-09-22 20:07:47+00
(1 row)
$ sudo -u postgres psql -d orders -c "select left(query, 60) as query, calls, round(total_exec_time::numeric, 1) as total_ms, round(mean_exec_time::numeric, 3) as mean_ms from pg_stat_statements order by total_exec_time desc limit 3"
                            query                             | calls | total_ms | mean_ms
--------------------------------------------------------------+-------+----------+---------
 SELECT id, status, total_cents, created_at FROM orders WHERE |   124 |     52.0 |   0.419
 SELECT o.id, o.status, o.total_cents FROM orders o WHERE o.i |    55 |     24.6 |   0.448
 UPDATE orders SET status = $1, updated_at = now() WHERE id = |    17 |      6.8 |   0.402
(3 rows)

Same calls, a fraction of the time per call. That before/after table is what goes into the incident timeline.

auto_explain, and where else to look

pg_stat_statements tells you which query; auto_explain logs the plan it actually used when it was slow - invaluable when a query is only slow sometimes (other parameters, other data, a plan flip after ANALYZE):

shared_preload_libraries = 'pg_stat_statements,auto_explain'
auto_explain.log_min_duration = '500ms'
auto_explain.log_analyze = on        # real row counts (adds overhead to every statement)
auto_explain.log_buffers = on

More places the "slow" can come from - check them before blaming a query:

symptom	look at
many queries slow at once, CPU idle	locks (lesson 6): `wait_event_type = 'Lock'`
slow after a big data change	stale statistics: `last_autoanalyze`, run `ANALYZE`
slowly worse over days	bloat (lesson 7): `n_dead_tup`, table size vs rows
slow at the same minute every hour	a cron job / report: `pg_stat_activity` at that minute, `application_name`
everything slow, high I/O wait	`pg_stat_io`, `shared_blks_read` in pg_stat_statements, the disk itself (`iostat`)
writes slow, reads fine	checkpoints (`log_checkpoints`, "checkpoints are occurring too frequently"), WAL disk, synchronous replicas

Quick check

$ sudo -u postgres psql -Atc "select context from pg_settings where name = 'shared_preload_libraries'"

You add pg_stat_statements to shared_preload_libraries and reload. What next?

CREATE EXTENSION is enough now; the reload loaded it
nothing works until a restart: shared_preload_libraries is read only when the server starts
the setting is per database, so you set it with ALTER DATABASE

Answer

nothing works until a restart: shared_preload_libraries is read only when the server starts - shared_preload_libraries has context postmaster; the library has to be loaded into the postmaster at start so every backend gets the shared memory it needs.

In an interview: "The database is slow - how do you find the query responsible?" - pg_stat_statements (preloaded via shared_preload_libraries, one restart, then CREATE EXTENSION): sort by total_exec_time for what costs the most overall, by mean for the individually slow ones; log_min_duration_statement for what was slow at a given minute; then EXPLAIN (ANALYZE, BUFFERS) on the top query and fix it (usually an index), resetting the counters to compare before and after.

Quick check

$ sudo -u postgres psql -Atc "show log_min_duration_statement"

Is the slow-query log on in a stock configuration?

yes, at 1 second
no: -1 = off
yes, everything is logged

Answer

no: -1 = off - -1 disables it; you choose the threshold (250 ms - 1 s is typical, 0 logs every statement).

What you can do now

Turn on and read the slow-query log, and choose a sensible threshold.
Install pg_stat_statements in the right order (preload + restart, then the extension).
Find the top queries by total and by mean time, and explain the difference.
Measure a fix cleanly with pg_stat_statements_reset().
Know when to reach for auto_explain, and the non-query causes of "slow".

Why it helps

On call, the question is rarely "why is this query slow" - it is "which query is making the database slow". The slow-query log shows outliers above a threshold; pg_stat_statements shows the whole profile, including cheap queries called thousands of times a minute.

Both must be on before the incident: pg_stat_statements needs shared_preload_libraries and a restart. Measuring a fix cleanly (reset, same load, compare) is also how you show the change worked.

Commands in this lesson

psql grep systemctl

FAQ

Why does pg_stat_statements need a restart?

It keeps its counters in shared memory, which only libraries loaded when the postmaster starts can allocate. shared_preload_libraries is a postmaster setting, so add pg_stat_statements there, restart once, then CREATE EXTENSION pg_stat_statements in the database you query it from. Managed services usually have it preloaded already.

Should I sort by total or by mean time?

Both, for different questions. Total execution time shows where the server spends its time overall - often a fast query called very often. Mean time shows the individually slow queries - reports, missing indexes on rare paths. Rows per call shows queries returning far more than the app needs.

What threshold should log_min_duration_statement have?

Typical production values are 250 milliseconds to one second: enough to catch real outliers without flooding the log. Setting it to 0 logs every statement, which is useful for a few minutes of investigation and dangerous for longer because the log can grow by gigabytes. It can also be set per role or database.

What is a normalized query?

pg_stat_statements replaces constants with placeholders, so select * from orders where id = 42 and where id = 43 count as one entry with $1. Each entry has a queryid, which you can use to refer to the same statement in monitoring, in discussions with the app team and when comparing before and after a fix.

When is auto_explain useful?

When a query is only sometimes slow: different parameters, a plan that flips after statistics change, or data that differs per customer. auto_explain logs the plan the server actually used for statements slower than its threshold, so you see the bad plan instead of the good one you get when you try it by hand later.

In an interview Mid

The database is slow overall and nothing shows up in the slow-query log. How do you find the responsible query?

pg_stat_statements: it keeps calls, total and mean time, rows and buffers per normalized query. It needs shared_preload_libraries = 'pg_stat_statements' (a restart) and CREATE EXTENSION. Sort by total_exec_time to find what costs the server the most - often a query of a few milliseconds called thousands of times, which a log_min_duration_statement threshold never catches. Then EXPLAIN the top query, fix it (usually an index), call pg_stat_statements_reset() and compare the same load before and after.

Also asked: What is the difference between total and mean execution time? · How do you set up slow-query logging in PostgreSQL? · What else besides a bad query can make a database slow?

Practise this lesson in the terminal Free, in your browser - a real Ubuntu terminal to try it in, with missions that check your work.