Finding and fixing slow queries

Draft

An 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

-- 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;
querycallstotal_msmean_msblocks
SELECT id, name FROM products WHERE name ILIKE $1 ORDER BY name LIMIT $2201334.666.7315940
SELECT id, name, price_cents FROM products WHERE category = $1 ORDER BY id LIMIT $2 OFFSET $3200461.12.3121562
INSERT INTO products (name, category, price_cents) VALUES ($1, $2, $3)2001.30.01806
DELETE FROM products WHERE id = $11000.70.01400

Search: 20 calls, most of the total time. Timings are real, measured in your browser.

Slowest actual calls

-- The actual calls, with their real values.
SELECT endpoint, query, duration_ms
FROM request_log
ORDER BY duration_ms DESC
LIMIT 5;
endpointqueryduration_ms
searchSELECT id, name FROM products WHERE name ILIKE '%oak%' ORDER BY name LIMIT 2088.00
searchSELECT id, name FROM products WHERE name ILIKE '%oak%' ORDER BY name LIMIT 2087.00
searchSELECT id, name FROM products WHERE name ILIKE '%velvet%' ORDER BY name LIMIT 2079.00
searchSELECT id, name FROM products WHERE name ILIKE '%mirror 42%' ORDER BY name LIMIT 2076.00
searchSELECT id, name FROM products WHERE name ILIKE '%wooden bench%' ORDER BY name LIMIT 2075.00
-- 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;
queryduration_ms
SELECT id, name, price_cents FROM products WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 15204.00
SELECT id, name, price_cents FROM products WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 16204.00
SELECT id, name, price_cents FROM products WHERE category = 'kitchen' ORDER BY id LIMIT 20 OFFSET 16404.00

Why is search slow?

-- 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 ms

Fix 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);
-- 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 ms

Why are deep pages slow?

-- 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 ms

Fix 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;
-- 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 ms

Verify

Same traffic, before and after both fixes.

Before

querycallstotal_msmean_msblocks
SELECT id, name FROM products WHERE name ILIKE $1 ORDER BY name LIMIT $2201334.666.7315940
SELECT id, name, price_cents FROM products WHERE category = $1 ORDER BY id LIMIT $2 OFFSET $3200461.12.3121562
INSERT INTO products (name, category, price_cents) VALUES ($1, $2, $3)2001.30.01806
DELETE FROM products WHERE id = $11000.70.01400

After

querycallstotal_msmean_msblocks
SELECT id, name FROM products WHERE name ILIKE $1 ORDER BY name LIMIT $22053.52.677080
SELECT id, name, price_cents FROM products WHERE category = $1 AND id > $2 ORDER BY id LIMIT $32007.50.04868
INSERT INTO products (name, category, price_cents) VALUES ($1, $2, $3)2003.70.021206
DELETE FROM products WHERE id = $11000.50.01400

Search and list are fixed. INSERT now touches more blocks: every new row also updates the trigram index. Indexes aren't free.

Try Yourself

Loaded Database:slow-queries.database-init

The database for this lesson is already loaded. Write any query you want and run it directly in your browser.

Exercises

0 OF 2 DONE
1.Timings vary between runs, buffer blocks don't. From pg_stat_statements, return query, calls, and shared_blks_hit + shared_blks_read AS blocks for the app's queries (NOT toplevel), most blocks first.
2.With keyset pagination, return id, name, and price_cents of the 20 'office' products after id 50000, in id order.

What We Learned