RE:NODE
Обзор хостинга

Базы данных13 мин чтения

EXPLAIN ANALYZE: reading a Postgres query plan

How to read a PostgreSQL query plan: EXPLAIN ANALYZE options, node types, bad row estimates, and the indexes that turn a seq scan into a 0.1 ms lookup.

Эта статья пока на английском. Мы её переводим.

0 прочтений

Put EXPLAIN (ANALYZE, BUFFERS) in front of the query, run it, and read the output from the bottom up. You are looking for three things: the node where most of the time is actually spent, a node whose estimated row count differs from its actual row count by an order of magnitude, and a sequential scan over a large table that returns a handful of rows. Almost every slow query on a small or medium database is one of those three, and the fix is an index, fresher statistics, or a rewritten WHERE clause. The rest of this post is how to tell which one you are looking at.

The plan is not a mystery document. It is a tree of nodes, each one taking rows from its children and handing rows to its parent, with the planner's guess and the executor's reality printed side by side. Once you know what six or seven node types mean and which numbers to compare, a plan takes about thirty seconds to read.

EXPLAIN, EXPLAIN ANALYZE, and the options worth using#

EXPLAIN alone shows the plan the planner has chosen without running the query. It is instant and safe, and it gives you estimates only. EXPLAIN ANALYZE actually executes the query and prints what really happened next to what was predicted. That difference is the whole point, so use ANALYZE unless you have a reason not to.

Two warnings before you do. EXPLAIN ANALYZE on an UPDATE, DELETE or INSERT performs the write. Wrap it if you do not want that:

sql
BEGIN;EXPLAIN (ANALYZE, BUFFERS)DELETE FROM sessions WHERE expires_at < now() - interval '30 days';ROLLBACK;

And ANALYZE adds timing overhead. On most machines it is a few percent; on a system with a slow clock source it can double a short query's measured time. If the numbers look impossible, re-run with TIMING OFF, which keeps the row counts and drops the per-node timings.

The options that earn their place:

  • BUFFERS - how many 8 kB blocks each node read from shared buffers (shared hit), from disk or the operating system cache (shared read), and wrote (shared written). This is the closest thing to a physical I/O count you will get, and it is far more stable than wall-clock time on a shared machine. From PostgreSQL 18 it is included with ANALYZE by default; on earlier versions you ask for it.
  • VERBOSE - prints the output column list and schema-qualified names. Useful on plans with several joins and repeated column names.
  • SETTINGS - prints any planner setting that is not at its default. Worth adding once when a plan on one server differs from the same plan on another.
  • WAL - write-ahead log records and bytes generated. Only meaningful with a write statement.
  • FORMAT JSON - machine-readable output, which is what the plan visualisers on the web consume.
  • GENERIC_PLAN (PostgreSQL 16 and later) - lets you EXPLAIN a statement containing $1 placeholders without supplying values, which is how you inspect what a prepared statement or an ORM is really sending.
sql
EXPLAIN (ANALYZE, BUFFERS, VERBOSE, SETTINGS)SELECT ...;

Run the query twice and read the second plan. The first run pays for reading blocks off disk into the cache, and you rarely want to tune against a cold cache unless coldness is the actual complaint.

How to read the tree#

Every line that starts with -> is a node. Indentation is nesting: a node's children are indented under it, and execution flows from the innermost node outwards. Read from the deepest indentation upwards and you are following the rows.

A node line looks like this:

code
->  Index Scan using orders_pkey on orders  (cost=0.43..8.45 rows=1 width=36)                                            (actual time=0.021..0.023 rows=1 loops=1)

Six numbers, and each of them means something specific:

  • cost=0.43..8.45 - the estimated startup cost and total cost, in arbitrary units where 1.0 is roughly the cost of reading one sequential page. The first number is what it takes before the first row can be returned, which is why a sort has a large startup cost and an index scan has almost none. The numbers only matter relative to each other.
  • rows=1 - the estimated number of rows this node will produce, per execution.
  • width=36 - the estimated average row width in bytes. Useful when a plan is moving far more data than you expected.
  • actual time=0.021..0.023 - real milliseconds to the first row and to the last row, averaged over the loops.
  • loops=1 - how many times this node ran. This is the number people forget: on the inner side of a nested loop, actual time and rows are per loop. A node showing actual time=0.4..0.5 rows=3 loops=9000 cost roughly 4.5 seconds and produced 27,000 rows, not half a millisecond and three rows.

Times are inclusive of children, so a node's own cost is its actual time minus the time of everything under it. The two lines at the bottom, Planning Time and Execution Time, are separate: planning time that is a large fraction of the total usually means a partitioned table with hundreds of partitions, or an enormous number of joins.

Extra lines under a node are where the detail lives. Filter with Rows Removed by Filter, Index Cond, Heap Fetches, Sort Method, Buckets, and Buffers all tell you something the headline numbers do not.

The nodes you will actually see#

NodeWhat it doesWhen it is a problem
Seq ScanReads every row in the tableBig table, small result, selective filter
Index ScanWalks an index, fetches matching rowsRarely, unless it loops thousands of times
Index Only ScanAnswers from the index aloneWhen Heap Fetches is high
Bitmap Heap ScanCollects row locations, then reads pages in orderRecheck Cond with lossy blocks
Nested LoopFor each outer row, probe the inner sideOuter row count much larger than estimated
Hash JoinBuilds a hash of one side, probes with the otherBatches greater than 1 means it spilled
Merge JoinJoins two sorted inputsWhen the sorts feeding it are the real cost
SortOrders rowsSort Method: external merge Disk:
HashAggregateGroups rows in memorySpills to disk on a bad estimate
GatherCollects rows from parallel workersWorkers launched fewer than planned
MemoizeCaches inner results in a nested loopLow hit rate wastes memory

A sequential scan is not automatically bad. Reading a 500-row lookup table end to end is cheaper than any index, and the planner knows it. A sequential scan becomes the problem when the table is large, the filter is selective, and Rows Removed by Filter is a number with six digits in it.

Two lines are worth learning to spot immediately. Sort Method: external merge Disk: 48312kB means the sort did not fit in work_mem and went to temporary files, which is usually the single biggest win available: raising work_mem for that session or that query turns it into Sort Method: quicksort Memory: 51000kB. And Buckets: 65536 Batches: 8 Memory Usage: 3841kB on a hash join means the hash table was split into eight passes over the data for the same reason. PostgreSQL tuning for small servers covers what those settings should be on a 1 to 8 GB machine, and why raising work_mem globally is a way to run out of memory.

A slow query, fixed#

Here is a plan from a table of 2.4 million orders, answering "the last twenty orders for one customer".

sql
EXPLAIN (ANALYZE, BUFFERS)SELECT id, created_at, totalFROM ordersWHERE customer_id = 4821  AND created_at >= now() - interval '90 days'ORDER BY created_at DESCLIMIT 20;
code
Limit  (cost=48231.44..48231.49 rows=20 width=20)       (actual time=812.334..812.339 rows=20 loops=1)  Buffers: shared hit=1204 read=41988  ->  Sort  (cost=48231.44..48232.07 rows=252 width=20)            (actual time=812.332..812.334 rows=20 loops=1)        Sort Key: created_at DESC        Sort Method: top-N heapsort  Memory: 27kB        ->  Seq Scan on orders  (cost=0.00..48224.72 rows=252 width=20)                                (actual time=0.412..811.903 rows=238 loops=1)              Filter: ((customer_id = 4821) AND (created_at >= (now() - '90 days'::interval)))              Rows Removed by Filter: 2399762              Buffers: shared hit=1204 read=41988Planning Time: 0.214 msExecution Time: 812.381 ms

Everything you need is in there. The scan read 43,192 blocks, about 337 MB, to return 238 rows and then throw away 2.4 million. The estimate of 252 rows was close to the actual 238, so the statistics are fine. There is simply no index that matches the filter.

sql
CREATE INDEX CONCURRENTLY orders_customer_created_idx    ON orders (customer_id, created_at DESC);
code
Limit  (cost=0.43..38.72 rows=20 width=20) (actual time=0.041..0.088 rows=20 loops=1)  Buffers: shared hit=23  ->  Index Scan using orders_customer_created_idx on orders        (cost=0.43..482.90 rows=252 width=20) (actual time=0.039..0.084 rows=20 loops=1)        Index Cond: ((customer_id = 4821) AND (created_at >= (now() - '90 days'::interval)))        Buffers: shared hit=23Planning Time: 0.302 msExecution Time: 0.114 ms

Twenty-three blocks instead of forty-three thousand, and the Sort node has vanished entirely: because the index stores created_at descending within each customer_id, the rows arrive in the order the query asked for and the LIMIT stops after twenty. Column order in that index is not arbitrary, and neither is the DESC. PostgreSQL indexes explained goes through why equality columns come first and range columns last.

The five things that make a plan slow#

A bad row estimate. Compare rows= with actual ... rows= on every node. A factor of two is nothing. A factor of a hundred means the planner chose its strategy on bad information, and the node above it is probably a nested loop that should have been a hash join. Causes: the table has not been analysed since a bulk load, the default_statistics_target of 100 is too coarse for a skewed column, or two columns are correlated and the planner is multiplying their selectivities as if they were independent. The fixes, in order of effort:

sql
ANALYZE orders;ALTER TABLE orders ALTER COLUMN status SET STATISTICS 1000;CREATE STATISTICS orders_city_region (dependencies, ndistinct)    ON city, region FROM orders;ANALYZE orders;

A missing or unusable index. The index exists but the query cannot use it: a function on the column (WHERE lower(email) = ... needs an expression index on lower(email)), a type mismatch that forces a cast, a leading wildcard in LIKE, or an OR across two columns that no single index covers.

Sorting or hashing on disk. Covered above. Look for Disk: anywhere in the plan.

Too many loops. A nested loop with 40,000 iterations of a 0.2 ms index scan is eight seconds that no single node admits to. Multiply actual time by loops before you believe a node is cheap.

Work the query does not need. SELECT of every column when three are wanted, an ORDER BY with no LIMIT, DISTINCT compensating for a duplicating join, a COUNT over a whole table on every page load. The cheapest query is the one you delete.

Dead rows are the sixth cause and they hide well: a table that has bloated because autovacuum cannot keep up reads like a much larger table, and an Index Only Scan with thousands of Heap Fetches is the same story from the other side. Postgres vacuum and bloat is the one to read if a query got slower without the data growing.

Finding the slow queries in the first place#

Reading a plan assumes you know which query to read. Three tools, in increasing order of setup:

  1. pg_stat_activity for right now. SELECT pid, now() - query_start AS runtime, state, left(query, 80) FROM pg_stat_activity WHERE state <> 'idle' ORDER BY runtime DESC; shows what is running and for how long. pg_cancel_backend(pid) stops one politely, pg_terminate_backend(pid) stops it rudely.
  2. log_min_duration_statement for the log. Set it to 500 and every statement taking longer than half a second is written to the server log with its duration and parameters. It costs nothing when nothing is slow.
  3. pg_stat_statements for the pattern. This is the one that changes how you work. It needs to be listed in shared_preload_libraries and needs a restart, then CREATE EXTENSION pg_stat_statements;.
sql
SELECT calls,       round(total_exec_time::numeric, 1) AS total_ms,       round(mean_exec_time::numeric, 2)  AS mean_ms,       rows,       left(query, 70) AS queryFROM pg_stat_statementsORDER BY total_exec_time DESCLIMIT 15;

Sort by total_exec_time, not by mean_exec_time. The query that takes 4 ms and runs two million times a day is costing you more than the nightly report that takes nine seconds, and it is usually the easier fix. pg_stat_statements_reset() clears the counters so you can measure a window.

The fourth option, auto_explain, logs the full plan of any statement over a threshold, which catches the plan that only goes wrong at 3 a.m. with particular parameters. Loading it costs a little on every query, so turn it on to catch something specific and turn it off again.

All four need a superuser or a suitably privileged role, plus the ability to edit postgresql.conf and restart. On RE:NODE the PostgreSQL line hands you the superuser password generated for that server, the file manager and SFTP for the configuration files, and the console for the restart, so shared_preload_libraries is a setting you can actually change rather than a support ticket. The panel guides cover where those credentials appear.

What the plan does not tell you#

A plan describes the work the server did on that statement. It says nothing about:

  • Waiting for a lock. A query blocked behind an ALTER TABLE shows a perfectly healthy plan and takes ninety seconds. Check pg_locks joined to pg_stat_activity, or the wait_event_type column.
  • Connection overhead. Opening a new PostgreSQL connection forks a process and costs a few milliseconds plus several megabytes. An application opening one per request spends more time connecting than querying. That is a pooler's job, not the planner's - see connection pools and limits.
  • Network round trips. Two hundred small queries in a loop, each fast, is an N+1 problem, and every ORM produces them by accident. The plans all look perfect.
  • Client-side time. Fetching 400,000 rows into an application that needed a count is slow in a place EXPLAIN cannot see.
  • The rest of the machine. A plan that reads 40,000 blocks is fine on an idle server and terrible when six other connections are doing the same thing. The panel's memory, CPU and disk graphs are the check that the plan and the machine agree.

One more honest limit: EXPLAIN without ANALYZE shows what the planner intends with current statistics and current settings, and prepared statements can switch to a generic plan after five executions, so what your driver runs is not always what you tested by hand. EXPLAIN (GENERIC_PLAN) on PostgreSQL 16 and later exists precisely because of that gap.

FAQ#

Why does Postgres ignore my index?

Usually because it believes the query returns a large fraction of the table, in which case a sequential scan genuinely is cheaper. Check the estimate against reality first. If the estimate is right and you still expect an index scan, the cause is often random_page_cost, which defaults to 4 and assumes spinning disks. On NVMe, 1.1 reflects the hardware and shifts the planner towards index scans across the board.

Is a Seq Scan always bad?

No. On a small table it is the fastest option, and the planner will pick it deliberately. It is bad when the table is large and the filter throws away most of what it read, which the Rows Removed by Filter line tells you exactly.

What is the difference between cost and actual time?

Cost is a unit-less estimate the planner uses to compare candidate plans, anchored so that reading one sequential page costs 1.0. Actual time is milliseconds measured during execution. You cannot convert one into the other, and you should not try - the only useful comparison is between the estimated and actual row counts.

Should I just add an index to every column?

No. Every index has to be updated on every insert, update and delete of the indexed columns, takes disk space, and adds work for vacuum. Three well-chosen composite indexes usually beat fifteen single-column ones. Look at pg_stat_user_indexes for idx_scan = 0 to find the indexes nothing has used since the last restart.

My query is fast in psql and slow from the application. Why?

Most often the application is not running the same query: different parameters, a generic plan, a wrapping transaction with a different isolation level, or an ORM adding a LIMIT and an ORDER BY you did not write. Turn on log_min_duration_statement, capture the exact statement the server received, and explain that.

How often should I run ANALYZE manually?

Autovacuum handles the routine case. Run it by hand after a bulk load, after a restore, and after a migration that changes the distribution of a column, because until it runs the planner is working from statistics that describe a table that no longer exists. A dump does not carry statistics with it, which is why a freshly restored database is often mysteriously slow - pg_dump and pg_restore has the rest of that story.


Комментарии

Полностью анонимно: без аккаунта, без почты, без cookie. Мы храним имя, которое вы ввели, текст и время - больше ничего. Количество ссылок ограничено, разметка не отображается.

0/2000