PostgreSQL Slow Queries: What pg_stat_statements Misses

Add pg_stat_statements to shared_preload_libraries, restart PostgreSQL, run CREATE EXTENSION pg_stat_statements and sort the view by total_exec_time. That is how you find slow queries in PostgreSQL, and the restart is the step to plan for, because the pg_stat_statements documentation says plainly that adding or removing the module needs one.

Then read the list with suspicion. We ran six workloads at once against PostgreSQL 18.6, otherwise on stock settings, for two minutes: primary-key reads, a lookup on a column with no index, an ORM-style page making 51 queries, a report, and one session holding a row lock while three others tried to update the same row. The view found the missing index. It also put an UPDATE that runs in 0.145 ms at the top of the list, gave the session causing the trouble a 0.05 ms row, and filed the 51-query page's lookups among the cheapest statements on the server.

A slow query and index review is part of how CloudSpinx runs PostgreSQL for companies in Kenya, and it starts from this view.

How to find slow queries in PostgreSQL with pg_stat_statements

With the module loaded, this is the ranking, a simplified copy of the one we ran:

SELECT left(query, 72) AS query, calls,
       round(total_exec_time::numeric / 1000, 1) AS total_s,
       round(mean_exec_time::numeric, 3) AS mean_ms,
       temp_blks_written AS temp_w
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 8;

And what it returned after two minutes, trimmed to the workload rows:

 query                                                                   | calls  | total_s | mean_ms | temp_w
 UPDATE pgbench_branches SET bbalance = bbalance - $1 WHERE bid = $2     |   1083 |   142.5 | 131.588 |      0
 SELECT count(*), sum(amount) FROM orders WHERE customer_id = $1         |    570 |    52.3 |  91.791 |      0
 SELECT customer_id, sum(amount) AS total FROM orders WHERE created_at > |     30 |    19.4 | 645.597 |  49655
 SELECT abalance FROM pgbench_accounts WHERE aid = $1                    |  60061 |     3.3 |   0.056 |      0
 SELECT name, region FROM customers WHERE id = $1                        | 120300 |     2.7 |   0.022 |      0
 SELECT id, customer_id, amount FROM orders WHERE id BETWEEN $1 AND $2 + |   2406 |     0.2 |   0.092 |      0
 UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2     |     24 |     0.0 |   0.050 |      0

The second row is the honest one. 570 lookups on orders.customer_id at 91.8 ms each, and EXPLAIN (ANALYZE, BUFFERS) on one of them shows a parallel sequential scan discarding an average of 666,659 rows in each of three processes to find 22. One CREATE INDEX and a rerun on its own took the mean to 0.29 ms. If every row behaved like that one, the job would end there.

Sort by total, not mean. Ranked by mean, ranks four to eight in our run were one-off queries from our monitoring and the benchmark tool, because a statement run once at 0.15 to 0.4 ms outranks one run 120,000 times at 0.02. Add WHERE calls > 10 if you want the mean view at all. And check SELECT dealloc FROM pg_stat_statements_info first: the view keeps 5,000 statements by default and drops the least-executed ones when more turn up, and dealloc counts each time it does, so a climbing number means the list has been forgetting.

Why is a fast UPDATE at the top of pg_stat_statements?

That first row accounts for 142.5 seconds, 64.7% of all the execution time the server recorded in the run. Run alone it takes 0.145 ms. It is not slow. It was waiting.

Another session had updated the same row, then held its transaction open for two seconds while the client did something else before sending COMMIT. In the lab that was a sleep on the client side. In an application the same shape comes from an HTTP call or a payment request made between the UPDATE and the COMMIT. Every other session that touched the row queued, and the time a statement spends waiting for a lock lands in its own execution time. The holder's UPDATE shows 24 calls at 0.05 ms. Its two idle seconds appear in no row at all, because an idle session is not running a statement, and statements are all this view times.

pg_stat_activity sees what the ranking cannot. Sixty seconds into the run:

 state               | wait_event_type | wait_event    | query
 active              | Lock            | tuple         | UPDATE pgbench_branches SET bbalance = bbalance - 74 WHERE b
 active              | Lock            | tuple         | UPDATE pgbench_branches SET bbalance = bbalance - 4 WHERE bi
 active              | Lock            | transactionid | UPDATE pgbench_branches SET bbalance = bbalance - 30 WHERE b
 idle in transaction | Client          | ClientRead    | UPDATE pgbench_branches SET bbalance = bbalance + 1 WHERE bi

The idle in transaction row is the culprit, and its query column shows the last statement it ran, which narrows down the code path. pg_blocking_pids(pid) on the waiting sessions draws the chain: the first waiter blocked by the idle session, the other two queued behind the first.

That snapshot only helps while the lock is held. For the record afterwards, turn on log_lock_waits, which is off by default in PostgreSQL 18 and takes a reload, not a restart. Once a wait passes deadlock_timeout (one second by default) the server logs it:

LOG:  process 2708850 still waiting for ShareLock on transaction 1934 after 1000.068 ms
DETAIL:  Process holding the lock: 2708849. Wait queue: 2708850.

It names the holder by process ID and not by query, so pair it with pg_stat_activity. The fix was in the application: we moved the two-second wait in front of BEGIN, and in the same 60-second test the waiting UPDATE went from a 132.9 ms mean to 0.104 ms, with 900 calls instead of 540. PostgreSQL also offers idle_in_transaction_session_timeout, off by default, which terminates a session left idle inside a transaction; the documentation says it can be used to ensure that idle sessions do not hold locks "for an unreasonable amount of time". It ends the session, so the application gets an error. Treat it as the backstop, not the repair.

Why does an N+1 page look fast?

The 51-query page's 50 lookups are the fifth row: 120,300 primary-key reads at 0.022 ms, 1.2% of the recorded execution time. First by calls and near the bottom by mean, and nobody fixes a query that cheap.

Look at the arithmetic instead. 120,300 is exactly 50 times 2,406, the call count on the orders query that opens each page. A cheap row whose calls are a round multiple of another row's points to a loop in the application, and the view will never show what that loop costs, because it times work on the server and the wait between the application and the database happens on the network.

So we measured the wait. One client ran the page directly and then through a small proxy that adds a fixed delay in each direction, against the same page written as one JOIN. The round trip is a bare SELECT 1 timed the same way:

Across all four runs pg_stat_statements recorded about 1.3 ms of execution per 51-query page, on average. At 81.7 ms nearly all the rest is 51 round trips: 51 times 81.7 ms is about 4,167 ms, within a few milliseconds of what we measured.

That last row is close to a real Kenyan path. From a Nairobi connection we measured about 84 ms to AWS in Cape Town, so an application in Nairobi talking to a database in Cape Town, or one left in Cape Town after the database moved home for residency, pays about that on every statement. The database looks idle and a 51-query page like ours would take over four seconds. If that split is where you are, tell us where each half runs through the scoping form and we will say which side should move.

The work_mem fix that made a report slower

temp_blks_written flagged one row, the report: 49,655 blocks over 30 runs, about 13 MB of temporary files each time, because the sorts did not fit in the default 4 MB of work_mem. The textbook answer is more work_mem. We gave that one session 64 MB. The temporary files went to zero, and the mean went from 628 ms to 1,073 ms.

EXPLAIN (ANALYZE, BUFFERS) showed why. At 4 MB the planner split the scan across the leader and two parallel workers and sorted and grouped in pieces, spilling as it went. With 64 MB it chose one hash table in memory on a single process, with no workers, and on our 8-vCPU machine that plan was slower. At 256 MB it picked the same plan again.

That is one query on one machine, and our temporary files sat on a RAM-backed filesystem, so it does not measure what the spill costs on a disk. What it does show is that a spill flag is a reason to test, not a setting to change. Change work_mem for the one role or query that needs it, compare the plans before and after, and never raise it server-wide on a guess: the setting applies to each sort and hash operation in each session, several at a time.

Before you add an index

The order we would run on a database we had never seen:

1. Check dealloc in pg_stat_statements_info. If it is climbing, raise pg_stat_statements.max at the next restart and let it collect again.
2. Rank by total_exec_time, with calls > 10 on any view by mean.
3. Run each top statement alone under EXPLAIN (ANALYZE, BUFFERS), inside BEGIN and ROLLBACK for anything that writes, because ANALYZE executes it. If it is fast alone with typical values, suspect a wait before the plan: look for a lock wait in pg_stat_activity, and in the server log with log_lock_waits on, before you reach for an index.
4. Compare call counts. A cheap row at a round multiple of another row points to a loop in the application.
5. For any row with temp_blks_written, test work_mem on that query before setting it anywhere.
6. Then the indexes.

The view keeps totals, averages and extremes, never the one slow run with the values it ran with. That is log_min_duration_statement's job, and its output has a trap of its own: a direct statement logs as statement:, a prepared one as execute <name>:. The first parser in the slow-query alert we built across 137 PostgreSQL databases for an AWS platform team read the execute lines and missed every statement: line, which is the kind of failure that reports success.

A team with one database and someone who reads query plans does not need us for any of this. The six steps above are the whole job. Where it pays to bring us in is the database nobody owns, behind an application whose developers have moved on. Send us that ranking query's output with LIMIT 20, the PostgreSQL version and where the application and the database each run: describe it in the managed database scoping form, choosing "Performance and slow queries", and send the export as a file on WhatsApp at +254 713 403 044. The view shows most constants as $1, $2, so the export is mostly the shape of your queries, but read it before you send it. You get back each row marked index, lock, loop, memory or rewrite, in the order we would fix them, free and with no commitment. If you want us to keep it that way afterwards, running the database is one monthly figure.