Finding and fixing slow queries
DraftAn app is slow. Find which queries are to blame, understand why, fix them, and check that the fix worked.
The migration
CREATE TABLE products (
id SERIAL PRIMARY KEY,
name TEXT NOT NULL,
category TEXT NOT NULL,
price_cents INTEGER NOT NULL
);The seed
-- 100,000 products like 'blue lamp 41', in 10 categories.
INSERT INTO products (name, category, price_cents)
SELECT
(ARRAY['red', 'blue', 'green', 'black', 'white',
'small', 'large', 'vintage', 'modern', 'wooden'])[n % 10 + 1]
|| ' ' ||
(ARRAY['lamp', 'chair', 'table', 'sofa', 'desk', 'shelf', 'rug',
'mirror', 'clock', 'vase', 'bed', 'stool', 'bench', 'cabinet',
'frame', 'pillow', 'blanket', 'curtain', 'basket', 'candle'])[n % 20 + 1]
|| ' ' || n,
(ARRAY['living', 'bedroom', 'kitchen', 'office', 'garden',
'kids', 'bath', 'outdoor', 'decor', 'storage'])[n / 10 % 10 + 1],
500 + n * 7919 % 50000
FROM generate_series(1, 100000) AS n;
-- ANALYZE samples 300 rows per statistics target: 400 covers every row,
-- so the planner's estimates are the same on every run.
SET default_statistics_target = 400;
ANALYZE products;The app
Four endpoints: create, list, delete, search. First, turn on tracking:
CREATE EXTENSION pg_stat_statements;
-- Also track statements run inside functions: the app's queries run in timed().
SET pg_stat_statements.track = 'all';
-- Every request is logged with its real query and duration,
-- like an APM tool or log_min_duration_statement would.
CREATE TABLE request_log (
id SERIAL PRIMARY KEY,
endpoint TEXT NOT NULL,
query TEXT NOT NULL,
duration_ms NUMERIC NOT NULL
);
-- Runs a query, returns how long it took in milliseconds.
CREATE FUNCTION timed(query TEXT) RETURNS NUMERIC AS $$
DECLARE
started TIMESTAMPTZ := clock_timestamp();
BEGIN
EXECUTE query;
RETURN round(extract(epoch FROM clock_timestamp() - started)::numeric * 1000, 2);
END;
$$ LANGUAGE plpgsql;
SELECT pg_stat_statements_reset();Then send the app's traffic, each endpoint many times:
-- POST /products, 200 times
INSERT INTO request_log (endpoint, query, duration_ms)
SELECT 'create', q, timed(q)
FROM generate_series(1, 200) AS n,
format(
'INSERT INTO products (name, category, price_cents) VALUES (%L, %L, %s)',
'new lamp ' || n, 'garden', 1000 + n) AS q;
-- GET /products?category=kitchen&page=..., 200 times, pages 0 to 99
INSERT INTO request_log (endpoint, query, duration_ms)
SELECT 'list', q, timed(q)
FROM generate_series(1, 200) AS n,
LATERAL (SELECT n % 100 AS page) AS p,
format(
'SELECT id, name, price_cents FROM products WHERE category = %L ORDER BY id LIMIT 20 OFFSET %s',
'kitchen', page * 20) AS q;
-- DELETE /products/:id, 100 times
INSERT INTO request_log (endpoint, query, duration_ms)
SELECT 'delete', q, timed(q)
FROM generate_series(1, 100) AS n,
format('DELETE FROM products WHERE id = %s', n * 97) AS q;
-- GET /products/search?q=..., 10 search terms, twice each
INSERT INTO request_log (endpoint, query, duration_ms)
SELECT 'search', q, timed(q)
FROM unnest(ARRAY['lamp', 'oak', 'blue sofa', 'mirror 42', 'candle',
'rug', 'velvet', 'desk 7', 'wooden bench', 'clock']) AS term,
generate_series(1, 2),
format(
'SELECT id, name FROM products WHERE name ILIKE %L ORDER BY name LIMIT 20',
'%' || term || '%') AS q;Slowest query types
Loaded Database:slow-queries.database-init
-- One row per query shape: constants become $1, $2...
-- NOT toplevel: only the app's queries, the ones run inside timed().
SELECT
query,
calls,
round(total_exec_time::numeric, 1) AS total_ms,
round(mean_exec_time::numeric, 2) AS mean_ms,
shared_blks_hit + shared_blks_read AS blocks
FROM pg_stat_statements
WHERE NOT toplevel
ORDER BY total_exec_time DESC;| query | calls | total_ms | mean_ms | blocks |
|---|---|---|---|---|
| SELECT id, name FROM products WHERE name ILIKE $1 ORDER BY name LIMIT $2 | 20 | 1334.6 | 66.73 | 15940 |
| SELECT id, name, price_cents FROM products WHERE category = $1 ORDER BY id LIMIT $2 OFFSET $3 | 200 | 461.1 | 2.31 | 21562 |
| INSERT INTO products (name, category, price_cents) VALUES ($1, $2, $3) | 200 | 1.3 | 0.01 | 806 |
| DELETE FROM products WHERE id = $1 | 100 | 0.7 | 0.01 | 400 |
Search: 20 calls, most of the total time. Timings are real, measured in your browser.
Slowest actual calls
Loaded Database:slow-queries.database-init
-- The actual calls, with their real values.
SELECT endpoint, query, duration_ms
FROM request_log
ORDER BY duration_ms DESC
LIMIT 5;| endpoint | query | duration_ms |
|---|---|---|
| search | SELECT id, name FROM products WHERE name ILIKE '%oak%' ORDER BY name LIMIT 20 | 88.00 |
| search | SELECT id, name FROM products WHERE name ILIKE '%oak%' ORDER BY name LIMIT 20 | 87.00 |
| search | SELECT id, name FROM products WHERE name ILIKE '%velvet%' ORDER BY name LIMIT 20 | 79.00 |
| search | SELECT id, name FROM products WHERE name ILIKE '%mirror 42%' ORDER BY name LIMIT 20 | 76.00 |
| search | SELECT id, name FROM products WHERE name ILIKE '%wooden bench%' ORDER BY name LIMIT 20 | 75.00 |
Loaded Database:slow-queries.database-init
-- Same query shape, very different cost: it depends on the page.
SELECT query, duration_ms
FROM request_log
WHERE endpoint = 'list'
ORDER BY duration_ms DESC
LIMIT 3;| query | duration_ms |
|---|---|
| SELECT id, name, price_cents FROM products WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 1520 | 4.00 |
| SELECT id, name, price_cents FROM products WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 1620 | 4.00 |
| SELECT id, name, price_cents FROM products WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 1640 | 4.00 |
Why is search slow?
Loaded Database:slow-queries.database-init
-- ANALYZE runs the query for real. BUFFERS counts the 8 kB blocks it touched.
--
-- Seq Scan: every row is read and tested.
-- Rows Removed by Filter: ~100,000 rows thrown away to keep a handful.
-- A B-tree index on name wouldn't help: '%mirror 42%' can start anywhere.
EXPLAIN (ANALYZE, BUFFERS)
SELECT id, name FROM products WHERE name ILIKE '%mirror 42%' ORDER BY name LIMIT 20;Limit (cost=2048.74..2048.77 rows=10 width=22) (actual time=67.638..67.658 rows=20.00 loops=1)
Buffers: shared hit=797
-> Sort (cost=2048.74..2048.77 rows=10 width=22) (actual time=67.634..67.642 rows=20.00 loops=1)
Sort Key: name
Sort Method: top-N heapsort Memory: 18kB
Buffers: shared hit=797
-> Seq Scan on products (cost=0.00..2048.57 rows=10 width=22) (actual time=0.352..67.554 rows=56.00 loops=1)
Filter: (name ~~* '%mirror 42%'::text)
Rows Removed by Filter: 100044
Buffers: shared hit=797
Planning:
Buffers: shared hit=24
Planning Time: 0.529 ms
Execution Time: 67.739 msFix 1: a trigram index
-- pg_trgm splits text into 3-letter chunks: 'lamp' -> ' la', 'lam', 'amp'...
-- A GIN index on them can answer ILIKE '%...%', which a B-tree can't.
CREATE EXTENSION pg_trgm;
CREATE INDEX products_name_trgm_idx ON products USING gin (name gin_trgm_ops);Loaded Database:slow-queries.fixed-database-init
-- Bitmap Index Scan on products_name_trgm_idx: the index knows which rows
-- contain 'mir', 'irr', 'rro'..., so only those are read.
-- Compare Buffers and Execution Time with the plan above.
EXPLAIN (ANALYZE, BUFFERS)
SELECT id, name FROM products WHERE name ILIKE '%mirror 42%' ORDER BY name LIMIT 20;Limit (cost=135.76..135.79 rows=10 width=22) (actual time=0.525..0.545 rows=20.00 loops=1)
Buffers: shared hit=41
-> Sort (cost=135.76..135.79 rows=10 width=22) (actual time=0.523..0.531 rows=20.00 loops=1)
Sort Key: name
Sort Method: top-N heapsort Memory: 18kB
Buffers: shared hit=41
-> Bitmap Heap Scan on products (cost=98.83..135.59 rows=10 width=22) (actual time=0.387..0.483 rows=56.00 loops=1)
Recheck Cond: (name ~~* '%mirror 42%'::text)
Heap Blocks: exact=12
Buffers: shared hit=41
-> Bitmap Index Scan on products_name_trgm_idx (cost=0.00..98.83 rows=10 width=0) (actual time=0.327..0.328 rows=56.00 loops=1)
Index Cond: (name ~~* '%mirror 42%'::text)
Index Searches: 1
Buffers: shared hit=29
Planning:
Buffers: shared hit=65
Planning Time: 0.542 ms
Execution Time: 0.595 msWhy are deep pages slow?
Loaded Database:slow-queries.database-init
-- Page 99. Postgres walks the primary key in id order, drops the other
-- categories (Rows Removed by Filter), produces 2,000 kitchen rows,
-- then throws the first 1,980 away. OFFSET never skips work.
EXPLAIN (ANALYZE, BUFFERS)
SELECT id, name, price_cents FROM products
WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 1980;Limit (cost=723.28..730.58 rows=20 width=26) (actual time=5.709..5.744 rows=20.00 loops=1)
Buffers: shared hit=241
-> Index Scan using products_pkey on products (cost=0.29..3656.50 rows=10013 width=26) (actual time=0.030..5.032 rows=2000.00 loops=1)
Filter: (category = 'kitchen'::text)
Rows Removed by Filter: 17929
Index Searches: 1
Buffers: shared hit=241
Planning:
Buffers: shared hit=32
Planning Time: 0.291 ms
Execution Time: 5.793 msFix 2: keyset pagination
No index this time: change the query.
-- Before: skip 1,980 rows to show page 99.
SELECT id, name, price_cents FROM products
WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 1980;
-- After: the app remembers the last id it showed and continues from there.
SELECT id, name, price_cents FROM products
WHERE category = 'kitchen' AND id > 19800 ORDER BY id LIMIT 20;Loaded Database:slow-queries.fixed-database-init
-- Index Cond: (id > 19800): the primary key index starts right after the
-- last id seen. About 130 rows read instead of 20,000, on any page.
EXPLAIN (ANALYZE, BUFFERS)
SELECT id, name, price_cents FROM products
WHERE category = 'kitchen' AND id > 19800 ORDER BY id LIMIT 20;Limit (cost=0.29..8.11 rows=20 width=26) (actual time=0.026..0.081 rows=20.00 loops=1)
Buffers: shared hit=4
-> Index Scan using products_pkey on products (cost=0.29..3137.31 rows=8030 width=26) (actual time=0.024..0.064 rows=20.00 loops=1)
Index Cond: (id > 19800)
Filter: (category = 'kitchen'::text)
Rows Removed by Filter: 109
Index Searches: 1
Buffers: shared hit=4
Planning:
Buffers: shared hit=62
Planning Time: 0.291 ms
Execution Time: 0.114 msVerify
Same traffic, before and after both fixes.
Before
| query | calls | total_ms | mean_ms | blocks |
|---|---|---|---|---|
| SELECT id, name FROM products WHERE name ILIKE $1 ORDER BY name LIMIT $2 | 20 | 1334.6 | 66.73 | 15940 |
| SELECT id, name, price_cents FROM products WHERE category = $1 ORDER BY id LIMIT $2 OFFSET $3 | 200 | 461.1 | 2.31 | 21562 |
| INSERT INTO products (name, category, price_cents) VALUES ($1, $2, $3) | 200 | 1.3 | 0.01 | 806 |
| DELETE FROM products WHERE id = $1 | 100 | 0.7 | 0.01 | 400 |
After
| query | calls | total_ms | mean_ms | blocks |
|---|---|---|---|---|
| SELECT id, name FROM products WHERE name ILIKE $1 ORDER BY name LIMIT $2 | 20 | 53.5 | 2.67 | 7080 |
| SELECT id, name, price_cents FROM products WHERE category = $1 AND id > $2 ORDER BY id LIMIT $3 | 200 | 7.5 | 0.04 | 868 |
| INSERT INTO products (name, category, price_cents) VALUES ($1, $2, $3) | 200 | 3.7 | 0.02 | 1206 |
| DELETE FROM products WHERE id = $1 | 100 | 0.5 | 0.01 | 400 |
Search and list are fixed. INSERT now touches more blocks: every new row also updates the trigram index. Indexes aren't free.
What We Learned
- pg_stat_statementsGroups every statement by its shape and keeps running totals: calls, time, rows, buffer blocks.
- EXPLAIN (ANALYZE, BUFFERS)Runs the query and shows what each step of the plan really did.
- pg_trgmTrigram indexes: make
ILIKE '%...%'use an index. - Keyset pagination
WHERE id > last_idinstead ofOFFSET: every page costs the same.