With modern distributed systems performance issues can surface in unexpected ways. When it comes to database servers like PostgreSQL issues can surface as slow pages, API calls timing out, jobs not completing, or users saying that the application is "slow". These issues usually occur at 4AM, so having a good debugging methodology (and lots of coffee) baked into your brain can help with speedy remediation.
The hard part is that these problems often look the same from the outside: the site is slow and nobody knows why yet. This post walks through some steps I personally take to tackle database issues. This process usually starts with identifying the source of the "slow" request, finding the SQL behind it, and reaching for a psql prompt to see what PostgreSQL is up to.
Sample Table to illustrate concepts
To illustrate some basic troubleshooting concepts, I am going to create an
orders table and populate it with random data. This table will be used
to show how to debug a common query performance issue.
CREATE TABLE orders (
order_id bigint,
customer_id int,
order_status text,
order_total numeric(10,2),
created_at timestamp
);
INSERT INTO orders (
order_id,
customer_id,
order_status,
order_total,
created_at
)
SELECT
gs,
(random() * 1000000)::int + 1,
(ARRAY[
'pending',
'paid',
'shipped',
'cancelled',
'refunded'
])[floor(random() * 5)::int + 1],
round((random() * 5000)::numeric, 2),
now() - (random() * interval '365 days')
FROM generate_series(1, 20000000) AS gs;
After loading the data, we can use \dt+ to view its size and
confirm that it exists:
db1=# \dt+ orders
List of tables
Schema | Name | Type | Owner | Persistence | Access method | Size | Description
--------+--------+-------+----------+-------------+---------------+---------+-------------
public | orders | table | postgres | permanent | heap | 1276 MB |
(1 row)
If you haven't run \dt+ before here is a summary of the output it
produces:
+---------------+--------------------------------------------------+
| Column | Meaning |
+---------------+--------------------------------------------------+
| Schema | Namespace that owns the table. |
| Name | Table name. |
| Type | Relation type, such as table. |
| Owner | Database role that owns the table. |
| Persistence | permanent, temporary, or unlogged. |
| Access method | Storage access method; heap is the default. |
| Size | Approximate disk space used by the table. |
| Description | Optional comment on the table. |
+---------------+--------------------------------------------------+
Understanding query execution plans with EXPLAIN
A database execution plan is the set of steps the database engine will use to answer a SQL query. SQL describes the result you want, but the database decides how to execute it. For a single query, PostgreSQL may choose between sequential scans, index scans, bitmap scans, joins, filters, sorts, aggregates, parallel workers, and other operations. It makes that choice from table statistics, available indexes, estimated row counts, query predicates, planner settings, and the structure of the SQL query.
These plans are useful because slow queries are often slow for concrete reasons:
PostgreSQL may be scanning a large table, filtering too many rows after reading
them, sorting data that could have been read in order, choosing a join strategy
that does not fit the row counts, or working from stale statistics. EXPLAIN
turns those hidden choices into something you can inspect before changing code
or adding an index.
Now suppose you get a notification from your monitoring tool that API latency
for get_customer_order_by_id() is well above normal ranges. Once you find
the SQL behind that method, the next step is to see how PostgreSQL plans to
run it. We can view the steps PostgreSQL will take by prefixing EXPLAIN to
the query:
EXPLAIN
SELECT
order_id,
customer_id,
order_status,
order_total,
created_at
FROM orders
WHERE customer_id = 123456
AND created_at >= now() - interval '90 days'
ORDER BY created_at DESC;
EXPLAIN shows the plan PostgreSQL expects to use. It does not run the query.
The output is a tree of plan nodes, and it is usually easiest to read from the
bottom up because lower nodes produce rows for the nodes above them. Here is
the plan returned from the EXPLAIN listed above:
QUERY PLAN
--------------------------------------------------------------------------------------------------
Sort (cost=330904.84..330904.85 rows=5 width=33)
Sort Key: created_at DESC
-> Gather (cost=1000.00..330904.78 rows=5 width=33)
Workers Planned: 2
-> Parallel Seq Scan on orders (cost=0.00..329904.28 rows=2 width=33)
Filter: ((customer_id = 123456) AND (created_at >= (now() - '90 days'::interval)))
JIT:
Functions: 2
Options: Inlining false, Optimization false, Expressions true, Deforming true
(9 rows)
Let's break this down one line at a time:
+-- Sort
| cost: 330904.84..330904.85
| rows: 5 estimated
| width: 33 bytes
| key: created_at DESC
| meaning: sort the estimated five matching rows newest-first.
|
+-- Gather
| workers: 2 planned
| cost: 1000.00..330904.78
| rows: 5 estimated
| meaning: collect estimated rows produced by parallel workers.
|
+-- Parallel Seq Scan on orders
cost: 0.00..329904.28
rows: 2 estimated per worker
access: scan orders, not an index
filter: customer_id and created_at are checked after rows are read
meaning: scan the table in parallel and keep rows matching both filters.
JIT
functions: 2
meaning: PostgreSQL may compile expression evaluation for this plan.
The key issue is the scan. PostgreSQL expects to read a large table first and filter afterward, which can be expensive.
Running an EXPLAIN can help answer a number of questions:
- Which table or index will PostgreSQL read first?
- Will the query use an index, a sequential scan, or a bitmap scan?
- Are rows filtered after being read?
- Does PostgreSQL expect to sort, join, aggregate, or gather worker results?
- Are estimated row counts larger or smaller than expected?
Those answers narrow the troubleshooting path. If the plan shows a sequential scan over a large table for a highly selective predicate, an index may be missing, unusable, or less attractive than expected. If the plan shows a sort, the query may benefit from an index that matches the filter and order. If row estimates look wrong, statistics may need to be refreshed or improved.
Using EXPLAIN ANALYZE to see how a query actually performs
Plain EXPLAIN shows the plan PostgreSQL expects to use, but
EXPLAIN ANALYZE actually runs the query and reports what happened. That makes
it better for troubleshooting because you can compare estimates with real row
counts, timing, loops, and buffer usage. Before measuring, refresh planner
statistics with ANALYZE TABLE_NAME so PostgreSQL has current table samples for
row-count estimates and plan selection. Use EXPLAIN ANALYZE carefully with
writes, expensive queries, and production systems because the statement really
executes.
ANALYZE orders
EXPLAIN (ANALYZE, BUFFERS)
SELECT
order_id,
customer_id,
order_status,
order_total,
created_at
FROM orders
WHERE customer_id = 123456
AND created_at >= now() - interval '90 days'
ORDER BY created_at DESC;
After the EXPLAIN ANALYZE runs you will get output similar to the following:
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
Sort (cost=330906.66..330906.67 rows=5 width=34) (actual time=452.302..458.081 rows=4.00 loops=1)
Sort Key: created_at DESC
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=1942 read=161293
-> Gather (cost=1000.00..330906.60 rows=5 width=34) (actual time=209.042..458.066 rows=4.00 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=1942 read=161293
-> Parallel Seq Scan on orders (cost=0.00..329906.10 rows=2 width=34) (actual time=250.180..440.200 rows=1.33 loops=3)
Filter: ((customer_id = 123456) AND (created_at >= (now() - '90 days'::interval)))
Rows Removed by Filter: 6666665
Buffers: shared hit=1942 read=161293
Planning:
Buffers: shared hit=17
Planning Time: 0.126 ms
JIT:
Functions: 6
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 0.894 ms (Deform 0.273 ms), Inlining 0.000 ms, Optimization 0.573 ms, Emission 9.499 ms, Total 10.966 ms
Execution Time: 458.444 ms
(20 rows)
Let's break this down one line at a time:
+-- Sort
| cost: 330906.66..330906.67
| time: 452.302..458.081 ms
| rows: 4.00
| key: created_at DESC
| method: quicksort, 25kB memory
| buffers: 1,942 hit / 161,293 read
| meaning: sort the four surviving rows newest-first in memory.
|
+-- Gather
| cost: 1000.00..330906.60
| time: 209.042..458.066 ms
| workers: 2 planned / 2 launched
| rows: 4.00
| buffers: 1,942 hit / 161,293 read
| meaning: merge four rows produced by the parallel table scan.
|
+-- Parallel Seq Scan on orders
cost: 0.00..329906.10
time: 250.180..440.200 ms
loops: 3
rows: 1.33 per loop
removed: 6,666,665 per loop
buffers: 1,942 hit / 161,293 read
meaning: read orders in parallel, apply both filters, and keep about four rows.
Planning
buffers: 17 hit
time: 0.126 ms
meaning: PostgreSQL spent almost no time choosing this plan.
JIT
functions: 6
time: 10.966 ms
meaning: PostgreSQL compiled expression work used by this execution.
Execution Time: 458.444 ms
In the EXPLAIN output the scan is the problem because PostgreSQL has to read rows before it can apply the customer and date filters. It read 161,293 buffers and discarded about 6.6 million rows per scan loop to return only four rows. Ouch! That is the structure of a query that would likely benefit from a targeted index.
When a query is slow, look for the lines that show where PostgreSQL spent time or read the most data:
- Large scans: a sequential scan on a big table means PostgreSQL may read far more data than the query returns.
- Rows removed: high
Rows Removed by Filtermeans PostgreSQL is spending work reading rows the query will not use. - Buffer reads: high
shared readcounts show how many pages PostgreSQL had to pull into memory. - Estimates: large gaps between estimated and actual rows can point to stale statistics or misleading data distribution.
- Sorts: sort nodes are fine for small result sets, but large or I/O intensive sorts can dominate runtime.
What Cost Means
The cost values in
the plans above are PostgreSQL's estimate of how much work each step will take.
In the slow plan above, Parallel Seq Scan on orders has most of the cost
because PostgreSQL expects the table scan to do most of the work.
cost=startup..total
startup cost = work before the first row can be returned
total cost = work to return all rows
The planner builds those numbers from estimated page reads, CPU work, row
counts, filters, sorts, joins, and parallel workers. Cost is useful for comparing
possible plans for the same query, but EXPLAIN ANALYZE is what shows what
actually happened.
Deciding if indexes will help a slow query
The plan above scanned millions of rows to return four because PostgreSQL had no
useful path for the predicate. The SQL asks for one customer_id, narrows that
customer's rows to the last 90 days, then sorts them newest-first. An index on
(customer_id, created_at DESC) matches how the query searches the table:
PostgreSQL can jump to one customer's orders, walk the recent rows in sort order,
and avoid reading most of the table. An index is less useful when most rows
match, the table is small, or the extra write and storage cost outweighs the
read benefit.
To address the slow query we can build an index from the part of the query doing the filtering and sorting:
WHERE customer_id = 123456
AND created_at >= now() - interval '90 days'
ORDER BY created_at DESC;
Put customer_id first because it is an equality filter. That gets PostgreSQL
to one customer's orders. Put created_at DESC next because the query needs a
date range and wants the newest rows first. Together, those columns let
PostgreSQL read the useful part of the table in the order the query already
requested.
customer_id equality filter
created_at DESC range filter and sort order
The slow plan read the table first, filtered by customer_id and created_at,
then sorted the four surviving rows. The following B-Tree index lets
PostgreSQL start at the matching customer_id entries and read the recent
rows in created_at DESC order:
CREATE INDEX CONCURRENTLY orders_customerid_createdat_idx
ON orders (customer_id, created_at DESC);
Creating an index can be resource-heavy because PostgreSQL has to read the table
and build a separate data structure to store the data. By default,
CREATE INDEX blocks writes while the index is being built. CONCURRENTLY
avoids that write lock, but it takes longer, uses more I/O, and cannot run
inside a transaction block. There are tradeoffs to both.
Once the index is built you can use the psql \di+ option to verify it was
created:
\di+ orders_customerid_createdat_idx
List of indexes
Schema | Name | Type | Owner | Table | Persistence | Access method | Size | Description
--------+---------------------------------+-------+----------+--------+-------------+---------------+--------+-------------
public | orders_customerid_createdat_idx | index | postgres | orders | permanent | btree | 602 MB |
(1 row)
We can see in the example above that a B-Tree index with the name orders_customerid_createdat_idx was created. It is 602MB in size.
Verifying that the index helped
Even with an index we can't assume the index helped just because it exists.
The next step is to update the statistics and run the same
EXPLAIN (ANALYZE, BUFFERS) query to see if the plan and
execution time changed:
ANALYZE orders;
EXPLAIN (ANALYZE, BUFFERS)
SELECT
order_id,
customer_id,
order_status,
order_total,
created_at
FROM orders
WHERE customer_id = 123456
AND created_at >= now() - interval '90 days'
ORDER BY created_at DESC;
Here is the new plan that was emitted after the EXPLAIN ANALYZE ran:
Index Scan using orders_customerid_createdat_idx on orders
actual time=0.031..0.039 rows=4 loops=1
Index Cond:
customer_id = 123456
created_at >= now() - interval '90 days'
Buffers: shared hit=8
Execution Time: 0.057 ms
If you have been following along you will notice that the query dropped from 458ms to .057ms:
Before
Parallel Seq Scan -> Gather -> Sort
Rows removed by filter: about 20 million across workers
Buffers: shared hit=1942 read=161293
Execution time: 458.444 ms
After
Index Scan
Rows found directly through the index
Buffers: shared hit=8
Execution time: 0.057 ms
This is a substantial gain and shows why indexes can be worth their weight in bits!
Find Active Slow Queries
The example above started with a known SQL statement. In a real incident you may
only know that the app is slow. I usually start my investigative work by reviewing
dashboard metrics, viewing system utilization data, and eventually digging into
pg_stat_activity to see what's running:
SELECT
pid,
usename,
application_name,
state,
wait_event_type,
wait_event,
now() - query_start AS runtime,
query
FROM pg_stat_activity
WHERE state <> 'idle'
ORDER BY runtime DESC;
+------------------+--------------------------------------------------+
| Column | Use |
+------------------+--------------------------------------------------+
| pid | Backend process ID. |
| usename | Database user. |
| application_name | Client or service name, if set. |
| state | active, idle, idle in transaction, etc. |
| wait_event_type | Broad reason the query is waiting. |
| wait_event | Specific wait event. |
| runtime | How long the current query has been running. |
| query | Current SQL text. |
+------------------+--------------------------------------------------+
pg_stat_activity can tell you what's running, if it's waiting on something,
how long the query has been running, etc. To find queries that are expensive
over time you can query the pg_stat_statements view.
pg_stat_statements isn't available by default. To enable it you will need
to preload pg_stat_statements in your server's postgresql.conf:
shared_preload_libraries = 'pg_stat_statements'
And then create an extension using CREATE EXTENSION. Once the extension
is working you can query pg_stat_statements to view execution
information for all queries that have been run:
SELECT
calls,
total_exec_time,
mean_exec_time,
rows,
query
FROM pg_stat_statements
WHERE query ILIKE '%orders%'
ORDER BY total_exec_time DESC
LIMIT 10;
+-----------------+------------------------------------------------+
| Column | Use |
+-----------------+------------------------------------------------+
| calls | Number of times the statement ran. |
| total_exec_time | Total time spent executing it. |
| mean_exec_time | Average execution time. |
| rows | Rows returned or affected. |
| query | Normalized SQL text. |
+-----------------+------------------------------------------------+
The total_exec_time can be a DBAs best friend, as can calls and
mean_exec_time. This is a view to commit to memory.
Check Index Usage
Once an index is added you want to verify it's actively being used.
pg_stat_user_indexes can help with this. This view shows a number
of useful for counters for each index:
SELECT
relname AS table_name,
indexrelname AS index_name,
idx_scan,
idx_tup_read,
idx_tup_fetch
FROM pg_stat_user_indexes
WHERE relname = 'orders'
ORDER BY idx_scan DESC;
+---------------+--------------------------------------------------+
| Column | Use |
+---------------+--------------------------------------------------+
| idx_scan | Number of index scans started. |
| idx_tup_read | Index entries returned by scans. |
| idx_tup_fetch | Live table rows fetched by simple index scans. |
+---------------+--------------------------------------------------+
These counters help you spot indexes that are large, duplicated, or rarely used. I have jobs set up to alert me to unused indexes. Unused indexes consume space and are still updated when changes are made to the underlying table. That consumes system resources which I always treat as a premium. But I am extremely careful about dropping indexes. An index may support a constraint, a rare report, or a maintenance job that has not run since statistics were reset.
Summary
I covered a lot in this post. Tuning PostgreSQL is an art in some ways, and to truly get the best bang for your buck you need to know your data and how it is accessed. There is no magic "fix me" button, and there is no substitute for having a clearly defined query baseline and testing plan.
Successful query tuning depends on the data, the workload, and how often the query runs. An index that makes one query fast can slow writes or duplicate an index you already have. Measure before and after, and test database changes in a non-production environment that is as close to production as practical.
Resources: