Đọc EXPLAIN và EXPLAIN ANALYZE trong PostgreSQL Cơ bản

Vấn đề

Một endpoint trả về sau 2 giây. Bạn mở code, đọc câu SQL, và nó trông hoàn toàn bình thường:

SELECT count(*) FROM orders WHERE status = 'refunded';

Không có gì để đoán ở đây. Bảng có bao nhiêu dòng? PostgreSQL đọc cả bảng hay dùng index? Nó đọc bao nhiêu dữ liệu từ disk để trả về đúng một con số? Nhìn câu SQL không trả lời được câu nào trong số đó.

EXPLAIN in ra kế hoạch mà PostgreSQL định dùng để chạy query. EXPLAIN ANALYZE chạy query thật rồi in kèm số đo thực tế. Đây là cách duy nhất để biết chắc chuyện gì đang xảy ra, thay vì đoán rồi thêm index cầu may.

Bài này đọc plan thật, chạy trên PostgreSQL 17 với bảng 500.000 dòng. Mọi output bên dưới là kết quả copy từ lần chạy thật, không phải ví dụ minh hoạ.

Đọc nhanh: dấu hiệu xấu trong plan

Thấy gì trong plan	Nghĩa là gì	Xem tiếp cái gì
Rows Removed by Filter lớn	Đọc nhiều dòng rồi loại gần hết	Có index nào phục vụ được điều kiện đó không
actual rows lệch rows nhiều lần	Planner ước lượng sai	Statistics: thống kê cũ, cột tương quan
Sort Method: external merge	Sort phải ghi ra file tạm	Giảm số dòng cần sort, hoặc work_mem
loops lớn ở node trong	Node chạy lặp lại nhiều lần	Nhân actual time với loops ra công thật
Heap Fetches lớn ở Index Only Scan	Vẫn phải đọc bảng	Lần VACUUM gần nhất
Batches lớn hơn 1 ở Hash	Bảng băm không vừa work_mem	Kích thước đầu vào, work_mem, hash_mem_multiplier
Buffers lớn so với số dòng trả về	Đọc nhiều page cho ít kết quả	Bước 3 bên dưới

Bốn bước đọc một plan lạ:

Đang tải diagram…

Khái niệm cốt lõi

Một plan là cây các node. Mỗi node nhận dữ liệu từ node con bên dưới, làm một việc, rồi đưa kết quả lên node cha. Node thụt lề sâu hơn và có mũi tên -> là node con.

Quy tắc đọc quan trọng nhất: đọc từ trong ra ngoài, từ dưới lên trên. Node thụt sâu nhất chạy trước.

Bắt đầu bằng plan đơn giản nhất có thể — tìm một dòng theo primary key:

Index Scan using orders_pkey on orders  (cost=0.42..8.44 rows=1 width=10) (actual time=0.011..0.011 rows=1 loops=1)
  Index Cond: (id = 420000)
  Buffers: local hit=1 read=3
Planning Time: 0.047 ms
Execution Time: 0.020 ms

Từng phần có nghĩa gì:

Thành phần	Giá trị ở đây	Nghĩa
Tên node	Index Scan using orders_pkey	Cách node này lấy dữ liệu: đi qua index orders_pkey
cost=0.42..8.44	0.42 và 8.44	Chi phí ước lượng: số đầu là chi phí để trả row đầu tiên, số sau là để trả hết
rows=1	1	Số dòng planner đoán node này sẽ trả ra
width=10	10	Kích thước trung bình ước lượng của mỗi dòng, tính bằng byte
actual time=0.011..0.011	0.011 ms	Thời gian thật: tới dòng đầu tiên, và tới dòng cuối cùng
actual ... rows=1	1	Số dòng node thật sự trả ra
loops=1	1	Node này chạy 1 lần
Index Cond	id = 420000	Điều kiện được dùng để định vị entry trong index
Buffers: local hit=1 read=3	4 page	1 page có sẵn trong buffer cache, 3 page không có sẵn nên phải nạp vào (xem ghi chú local bên dưới)
Planning Time	0.047 ms	Thời gian lập plan, không gồm parse/rewrite. Với query ngắn có thể ngang Execution Time
Execution Time	0.020 ms	Thời gian chạy, gồm cả trigger nhưng không gồm planning

Hai nhóm số quan trọng nhất và hay bị lẫn:

• cost và rows (nhóm đầu) là ước lượng trước khi chạy. EXPLAIN không chạy query vẫn in được nhóm này.
• actual time, actual rows, loops, Buffers là số đo của lần chạy thật. Chỉ có khi thêm ANALYZE.

Việc so hai nhóm này với nhau là kỹ thuật chẩn đoán chính, và phần lớn bài này xoay quanh nó.

local hay shared trong Buffers?

Mọi output trong bài chạy trên bảng TEMP, nên Buffers hiện local. Bảng thường hiện shared, và temp là file tạm của sort/hash.

Tiền tố	Dữ liệu của
shared	Bảng và index thường
local	Bảng và index tạm (TEMP)
temp	Sort, hash, Materialize tràn ra file tạm

hit là block tìm thấy sẵn trong buffer cache. read là không có sẵn trong buffer cache của PostgreSQL; block đó có thể đến từ page cache của OS chứ không nhất thiết từ đĩa. Dùng track_io_timing = on để thấy I/O Timings thật.

PostgreSQL 18: EXPLAIN ANALYZE tự động in BUFFERS, và mỗi index scan báo thêm số lần tra index. Trên PG17 phải viết EXPLAIN (ANALYZE, BUFFERS).

cost không phải mili giây

cost là đơn vị nội bộ để planner so sánh các phương án với nhau, không quy đổi ra thời gian. Hai plan thật trong cùng bài này chứng minh điều đó:

Query	cost	Thời gian thật
Hash join 500.000 dòng	13.885	85 ms
Sort 500.000 dòng tràn disk	90.193	169 ms

cost chênh nhau gần 6,5 lần nhưng thời gian chỉ chênh 2 lần (hai query khác nhau, chỉ để minh hoạ). Dùng cost để hiểu planner đang cân nhắc gì, dùng actual time khi cần biết query chạy bao lâu.

Cách hoạt động

Khi mở một plan lạ, đọc theo bốn bước sau thay vì đọc tuần tự từ trên xuống.

Bước 1 — Tìm node tốn thời gian thật

Execution Time ở cuối cho tổng. Sau đó tìm node có actual time kết thúc gần sát tổng đó và có con số nhảy vọt so với node con của nó. Đó là nơi thời gian bị tiêu.

Lưu ý: actual time của node cha đã bao gồm thời gian của các node con. Đừng cộng thời gian của mọi dòng lại.

Bước 2 — So rows ước lượng với actual rows

Đây là plan thật của một query lọc theo hai điều kiện:

Aggregate  (cost=11177.12..11177.13 rows=1 width=8) (actual time=14.333..14.334 rows=1 loops=1)
  Buffers: local read=3677
  ->  Seq Scan on orders  (cost=0.00..11177.00 rows=49 width=0) (actual time=0.027..14.309 rows=500 loops=1)
        Filter: ((amount < 1.00) AND (status = 'paid'::text))
        Rows Removed by Filter: 499500
        Buffers: local read=3677

Node Seq Scan ước lượng rows=49 nhưng thực tế trả rows=500 — lệch hơn 10 lần.

Nguyên nhân ở đây: PostgreSQL mặc định coi hai điều kiện amount < 1.00 và status = 'paid' là độc lập, rồi nhân hai tỷ lệ chọn lọc với nhau. Trong dữ liệu này chúng lại tương quan, nên ước lượng thấp hơn thực tế.

Với một query đơn giản như trên, lệch 10 lần không gây hại. Nhưng nếu node này nằm dưới một join, planner có thể chọn nhầm thuật toán join vì tưởng đầu vào chỉ có 49 dòng. Estimate lệch là nguyên nhân gốc rất phổ biến của plan tệ.

Bước 3 — Xem node đọc bao nhiêu dữ liệu so với số dòng trả về

Buffers đếm số page 8kB mà node chạm vào. So sánh hai plan cùng trả về ít dòng:

-- Lọc theo status, không có index dùng được
Seq Scan on orders  (... rows=400 ...) (actual time=0.046..11.547 rows=500 loops=1)
      Filter: (status = 'refunded'::text)
      Rows Removed by Filter: 499500
      Buffers: local read=3677

-- Lọc theo primary key
Index Scan using orders_pkey on orders  (... rows=1 ...) (actual time=0.011..0.011 rows=1 loops=1)
  Index Cond: (id = 420000)
  Buffers: local hit=1 read=3

Plan đầu đọc 3.677 page (khoảng 29 MB) và vứt bỏ 499.500 dòng để giữ lại 500 dòng. Plan sau đọc 4 page. Chênh lệch gần 900 lần, và Rows Removed by Filter: 499500 là dấu hiệu rõ nhất: node đang đọc rất nhiều rồi loại gần hết.

Phân biệt Index Cond với Filter:

• Index Cond — điều kiện dùng để nhảy thẳng tới vùng dữ liệu cần trong index. Không tốn công cho dòng không khớp.
• Filter — điều kiện kiểm tra sau khi đã đọc dòng lên. Mỗi dòng bị loại vẫn đã tốn công đọc.

Thấy Filter kèm Rows Removed lớn là tín hiệu nên xét index cho điều kiện đó.

Bước 4 — Kiểm tra loops

Nested Loop  (cost=0.71..831.55 rows=190 width=10) (actual time=0.009..0.058 rows=200 loops=1)
  ->  Index Only Scan using customers_pkey on customers c  (... rows=19 ...) (actual time=0.004..0.005 rows=20 loops=1)
        Index Cond: ((id >= 1) AND (id <= 20))
        Heap Fetches: 0
  ->  Index Scan using orders_customer_id_idx on orders o  (... rows=10 ...) (actual time=0.001..0.002 rows=10 loops=20)
        Index Cond: (customer_id = c.id)

Node Index Scan trong cùng có loops=20: nó chạy lại 20 lần, một lần cho mỗi dòng của node bên trên.

Điều quan trọng: với loops > 1, actual time và actual rows là trung bình mỗi lần chạy, không phải tổng. Ở đây 10 dòng × 20 lần = 200 dòng, khớp với rows=200 của node Nested Loop cha. Tương tự, 0.002 ms × 20 ≈ 0.04 ms mới là công thật sự.

Con số 20 vô hại. Nhưng khi thấy loops=50000, một node “chỉ 0.1 ms” thực tế đang tốn 5 giây.

Bẫy với plan song song. Dưới node Gather, loops bằng số process đã chạy node đó: leader cộng các worker (Workers Launched), với điều kiện leader tham gia (parallel_leader_participation = on, mặc định).

Ví dụ Parallel Seq Scan ... rows=33333 loops=3 nghĩa là khoảng 100.000 dòng tổng, không phải 33.333.

Workers Launched nhỏ hơn Workers Planned nghĩa là hết slot worker lúc chạy (giới hạn bởi max_worker_processes và max_parallel_workers).

Các dạng node hay gặp

Node	Khi nào thấy	Con số cần nhìn
Index Only Scan	Query chỉ cần cột nằm trong index	Heap Fetches (cao khi VACUUM chưa chạy)
Bitmap Heap Scan	Nhiều dòng khớp, nằm rải rác	Heap Blocks, Rows Removed by Index Recheck
Hash Join	Equality join, một bên vừa bộ nhớ	Batches, Memory Usage
Sort	ORDER BY, merge join	Sort Method: quicksort hay external merge

Dòng cốt lõi từ các plan thật cùng script:

Index Only Scan using orders_customer_id_idx on orders  (cost=0.42..6.44 rows=101 width=4) (actual time=0.005..0.008 rows=110 loops=1)
  Heap Fetches: 0

Heap Fetches: 0 xác nhận không phải quay lại bảng. Số lớn nghĩa là tên “index only” không còn đúng trên thực tế.

Bitmap Heap Scan on orders  (cost=117.24..3918.37 rows=8275 width=10) (actual time=0.286..2.155 rows=9590 loops=1)
  Heap Blocks: exact=1430
  ->  Bitmap Index Scan on orders_created_at_idx  (cost=0.00..115.17 rows=8275 width=0) (actual time=0.196..0.196 rows=9590 loops=1)

Node dưới quét index gom vị trí dòng, node trên đọc heap theo thứ tự page để không nhảy qua lại. Heap Blocks: exact=1430 là 1.430 page để lấy 9.590 dòng. Nếu bitmap quá lớn so với bộ nhớ, nó chuyển sang lossy và thêm dòng Rows Removed by Index Recheck.

Hash Join với customers (50.000 dòng) làm bảng băm:

HashAggregate  (cost=13885.61..13885.64 rows=3 width=14) (actual time=85.364..85.365 rows=3 loops=1)
  ->  Hash Join  (cost=1396.00..11385.61 rows=500000 width=6) (actual time=4.192..54.857 rows=500000 loops=1)
        Hash Cond: (o.customer_id = c.id)
        ->  Hash  (cost=771.00..771.00 rows=50000 width=10) (actual time=4.133..4.133 rows=50000 loops=1)
              Buckets: 65536  Batches: 1  Memory Usage: 2661kB

Hash Join cần một bên (bên được băm) vừa trong work_mem × hash_mem_multiplier (mặc định 4MB × 2,0). Batches: 1 là vừa. Lớn hơn 1 nghĩa là chia lượt và ghi tạm ra đĩa. Chi tiết ở join algorithms.

Sort tràn ra disk:

Sort  (cost=90193.92..91443.92 rows=500000 width=10) (actual time=140.183..160.070 rows=500000 loops=1)
  Sort Method: external merge  Disk: 10344kB
  Buffers: local read=3677, temp read=5149 written=5575

Disk: 10344kB là kích thước file tạm cuối cùng. temp read/written là số block 8 kB đã chạm, lớn hơn nhiều vì external merge ghi và đọc lại qua nhiều lượt. Hướng xử lý đầu tiên là giảm lượng dữ liệu cần sort (lọc thêm, LIMIT, index đã đúng thứ tự), rồi mới tới work_mem.

Tự chạy lại

Toàn bộ output trong bài lấy từ một script tạo hai bảng tạm (500.000 đơn hàng, 50.000 khách hàng) rồi chạy lần lượt tám tình huống:

cd examples
docker compose up -d postgres
docker compose exec -T postgres psql -U hub -d hub < src/postgres-explain/explain-demo.sql

Bảng tạm chỉ tồn tại trong session đó nên không để lại gì sau khi thoát. Số cụ thể trên máy bạn sẽ khác, nhưng hình dạng plan và các dấu hiệu thì giống.

Ví dụ thực tế

Ví dụ thực tế

Endpoint lịch sử đơn hàng chậm dần theo tháng. Không đoán trên máy dev:

1. Bật pg_stat_statements (cột total_exec_time, mean_exec_time) để tìm câu SQL tốn nhiều nhất.
2. Bật auto_explain với auto_explain.log_min_duration = '500ms' để plan của query chậm tự vào log.
3. Lấy câu SQL và tham số thật, chạy EXPLAIN (ANALYZE, BUFFERS) trên bản sao dữ liệu cỡ production.

Đọc kết quả:

• Seq Scan kèm Rows Removed by Filter hàng trăm nghìn là thiếu index.
• Sort kiểu external merge trong khi màn hình chỉ hiện 20 dòng là sort cả tập trước khi cắt trang (xem keyset pagination).
• Plan dài thì dán vào explain.dalibo.com hoặc explain.depesz.com để thấy node tốn thời gian nhất.

Trade-offs

Ưu điểm

• Cho thấy PostgreSQL thật sự làm gì, thay vì suy đoán từ câu SQL
• ANALYZE và BUFFERS cho phép so ước lượng với số đo thật của cùng một lần chạy
• Xuất được FORMAT JSON cho công cụ phân tích tự động

Nhược điểm

• EXPLAIN ANALYZE chạy query thật, nên tốn đúng tài nguyên mà query đó tốn
• Thời gian phụ thuộc cache và tải máy; hai lần chạy liên tiếp có thể chênh nhau đáng kể
• Plan của query lớn dài hàng chục dòng, dễ sa vào đọc từng dòng thay vì tìm node đáng ngờ

Sai lầm thường gặp

Sai lầm thường gặp

Chạy EXPLAIN ANALYZE với UPDATE/DELETE/INSERT mà quên rằng nó thực thi thật. Dữ liệu sẽ đổi, lock được lấy, trigger chạy. Bọc trong transaction rồi huỷ:

BEGIN;
EXPLAIN (ANALYZE, BUFFERS) UPDATE orders SET status = 'refunded' WHERE id = 420000;
ROLLBACK;

ROLLBACK hoàn tác dữ liệu, nhưng không thu hồi email đã gửi từ trigger, sequence đã nhảy số, hay thời gian đã giữ lock. EXPLAIN ANALYZE còn thêm overhead đo thời gian từng node, nên có thể chậm hơn chạy thường; thêm TIMING OFF nếu chỉ cần số dòng.

Sai lầm khác: so cost với mili giây, hoặc cộng actual time của mọi dòng. Thời gian node cha đã gồm node con; cost là đơn vị riêng của planner.

🎮 Thử tay

• Query chậm dần: đọc EXPLAIN thật trên bảng 30 triệu dòng.

Checklist khi đọc plan của query chậm

1. Chạy EXPLAIN (ANALYZE, BUFFERS) (PG17 phải ghi rõ BUFFERS) với câu SQL và tham số thật, trên dữ liệu cỡ production.
2. Với UPDATE/DELETE/INSERT: bọc trong BEGIN … ROLLBACK, và nhớ trigger, sequence, lock vẫn có tác dụng.
3. So rows ước lượng với actual rows; lệch nhiều lần thì xem thống kê trước khi thêm index.
4. Nhân actual time và actual rows với loops; dưới Gather, loops gồm cả leader và worker.
5. Tìm Filter kèm Rows Removed lớn, Buffers lớn so với số dòng trả về, Sort Method: external merge, Batches lớn hơn 1.
6. Không so cost với mili giây và không cộng actual time của các node.

Tóm tắt

Tóm tắt

• Plan là cây node; đọc từ node thụt sâu nhất lên trên, vì node con chạy trước
• cost/rows là ước lượng trước khi chạy; actual time/actual rows/loops/Buffers là số đo của lần chạy thật
• Bốn bước chẩn đoán: tìm node tốn thời gian, so estimate với actual, xem Buffers so với số dòng trả về, kiểm tra loops
• Với loops > 1, actual time và actual rows là trung bình mỗi lần chạy — nhân với loops mới ra công thật
• cost không phải mili giây: trong bài này cost 13.885 chạy 85 ms còn cost 90.193 chạy 169 ms
• EXPLAIN ANALYZE thực thi câu lệnh thật, kể cả UPDATE/DELETE
• Buffers: local trong bài là do dùng bảng TEMP; bảng thường hiện shared
• Dưới Gather, loops bằng số process (leader cộng worker)
• Tìm query chậm bằng pg_stat_statements và auto_explain, rồi mới EXPLAIN

Tham khảo

• PostgreSQL 17 — Using EXPLAIN
• PostgreSQL 17 — Examining Index Usage