Query Profiling — Phân tích hiệu năng truy vấn nâng cao

Query chạy 3 giây trên dev, 30 giây trên production. Tại sao?

Dev có 10K rows, production có 50 triệu. Dev vừa restart nên cache ấm, production đang chịu 500 concurrent connections. Dev không có lock contention, production đang có 3 long-running transactions giữ exclusive locks.

Bạn không thể tối ưu thứ bạn không đo được. Profiling là kỹ năng biến "cảm giác chậm" thành dữ liệu cụ thể — query nào chậm nhất, tại sao chậm, và fix xong có thực sự nhanh hơn không.

Bài này trang bị cho bạn bộ công cụ profiling production-grade trên PostgreSQL: từ EXPLAIN BUFFERS đến pg_stat_statements, từ slow query log đến auto_explain.

Bức tranh tư duy

Profiling query giống hệt bác sĩ chẩn đoán bệnh:

Triệu chứng (Symptoms): "API response chậm 5 giây", "Dashboard timeout"
Chẩn đoán (Diagnosis): Đo lường, xác định query nào gây ra vấn đề
Điều trị (Treatment): Thêm index, rewrite query, partition table
Theo dõi (Monitor): Verify fix có hiệu quả, không gây side effect

🎯 Mục tiêu

Sau bài này bạn sẽ thành thạo workflow profiling hoàn chỉnh: identify slow queries → đọc execution plan chi tiết → fix → verify. Biết dùng pg_stat_statements, slow query log, auto_explain, và EXPLAIN (ANALYZE, BUFFERS) trong production.

Cốt lõi kỹ thuật

1. EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) — Deep Dive

Bạn đã biết EXPLAIN ANALYZE từ bài trước. Giờ đi sâu hơn với BUFFERS và FORMAT JSON — hai options mà production DBA không bao giờ bỏ qua.

sql

EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT)
SELECT u.name, COUNT(o.id) AS order_count, SUM(o.total) AS total_spent
FROM users u
JOIN orders o ON u.id = o.user_id
WHERE o.created_at >= '2024-01-01'
  AND o.status = 'completed'
GROUP BY u.name
ORDER BY total_spent DESC
LIMIT 10;

Output mẫu (đọc từ trong ra ngoài, từ dưới lên trên):

text

Limit (cost=15234.56..15234.58 rows=10 width=48)
      (actual time=245.123..245.130 rows=10 loops=1)
  -> Sort (cost=15234.56..15284.56 rows=20000 width=48)
         (actual time=245.121..245.125 rows=10 loops=1)
        Sort Key: sum(o.total) DESC
        Sort Method: top-N heapsort  Memory: 26kB
        -> HashAggregate (cost=14500.00..14700.00 rows=20000 width=48)
               (actual time=240.500..243.800 rows=18543 loops=1)
              Group Key: u.name
              Batches: 1  Memory Usage: 2465kB
              -> Hash Join (cost=800.00..13500.00 rows=200000 width=25)
                     (actual time=12.300..180.200 rows=198765 loops=1)
                    Hash Cond: (o.user_id = u.id)
                    -> Seq Scan on orders o (cost=0.00..11200.00 rows=200000 width=21)
                           (actual time=0.015..120.500 rows=198765 loops=1)
                          Filter: (status = 'completed' AND created_at >= '2024-01-01')
                          Rows Removed by Filter: 301235
                          Buffers: shared hit=8500 read=2300
                    -> Hash (cost=500.00..500.00 rows=20000 width=12)
                           (actual time=12.100..12.100 rows=20000 loops=1)
                          Buffers: shared hit=320
                          -> Seq Scan on users u (cost=0.00..500.00 rows=20000 width=12)
                                 (actual time=0.010..8.200 rows=20000 loops=1)
                                Buffers: shared hit=320
Planning Time: 0.450 ms
Execution Time: 245.300 ms

Cách đọc — 5 điểm quan trọng:

Metric	Ý nghĩa	Tín hiệu xấu
`actual time`	Thời gian thực tế (ms)	Chênh lớn so với `cost` estimate
`rows` vs estimate	So sánh actual rows vs planned rows	Lệch > 10x → statistics stale
`Buffers: shared hit`	Pages đọc từ cache (RAM)	—
`Buffers: shared read`	Pages phải đọc từ disk	read >> hit → cache miss, I/O bottleneck
`Rows Removed by Filter`	Rows đọc lên nhưng bị loại	Số lớn → cần index trên filter column

💡 HPN Pro Tip: FORMAT JSON cho Tooling

EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) trả kết quả dạng JSON — paste vào explain.dalibo.com hoặc explain.depesz.com để visual hóa execution plan. Nhanh hơn đọc text thủ công rất nhiều.

2. Scan Types — Đọc hiểu hành vi truy cập

Scan Type	Khi nào planner chọn	Hiệu năng
Seq Scan	Không có index, hoặc cần > 10-20% rows	Đọc toàn bộ table, tệ cho bảng lớn
Index Scan	Index tồn tại, selectivity tốt (< 5% rows)	Lookup index → fetch heap page
Index Only Scan	Tất cả cột cần thiết nằm trong index	Tốt nhất — không cần đọc heap
Bitmap Index Scan	Selectivity trung bình (5-20% rows)	Tạo bitmap → batch đọc heap pages

Join Types và khi nào xuất hiện:

Join Type	Khi nào	Chi phí
Nested Loop	Inner table nhỏ, có index	O(n * log m)
Hash Join	Không có index, 1 bảng nhỏ vừa RAM	O(n + m), cần RAM cho hash table
Merge Join	Cả 2 bảng đã sorted theo join key	O(n + m), hiệu quả khi đã có index

3. pg_stat_statements — Top N Slow Queries

Đây là extension quan trọng nhất cho performance monitoring. Nó track thống kê của mọi query đã chạy: tổng thời gian, số lần gọi, rows trả về, block I/O.

sql

-- Bước 1: Enable extension (cần restart PostgreSQL)
-- postgresql.conf:
-- shared_preload_libraries = 'pg_stat_statements'
-- pg_stat_statements.max = 10000
-- pg_stat_statements.track = all

CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

-- Bước 2: Top 10 queries tốn thời gian nhất (tổng cộng)
SELECT
    SUBSTRING(query, 1, 80) AS short_query,
    calls,
    ROUND(total_exec_time::numeric, 2) AS total_time_ms,
    ROUND(mean_exec_time::numeric, 2) AS avg_time_ms,
    ROUND((100 * total_exec_time /
        SUM(total_exec_time) OVER ())::numeric, 2) AS pct_total,
    rows
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

-- Bước 3: Queries có cache miss ratio cao nhất
SELECT
    SUBSTRING(query, 1, 80) AS short_query,
    calls,
    shared_blks_hit,
    shared_blks_read,
    ROUND(
        shared_blks_read::numeric /
        NULLIF(shared_blks_hit + shared_blks_read, 0) * 100, 2
    ) AS cache_miss_pct
FROM pg_stat_statements
WHERE shared_blks_hit + shared_blks_read > 100  -- loại query nhỏ
ORDER BY cache_miss_pct DESC
LIMIT 10;

⚠️ Reset thống kê khi cần

SELECT pg_stat_statements_reset(); — reset toàn bộ stats. Hữu ích sau khi deploy optimization để đo hiệu quả từ đầu. Nhưng đừng reset tự động theo schedule — bạn sẽ mất dữ liệu trending.

4. Slow Query Log — Bắt query chậm tự động

ini

# postgresql.conf
log_min_duration_statement = 500    # Log mọi query chạy > 500ms
log_statement = 'none'               # Không log tất cả (quá nhiều noise)
log_line_prefix = '%t [%p] %u@%d '  # Timestamp, PID, user@database
log_duration = off                   # Không log duration cho MỌI query

Đọc slow query log:

text

2024-07-15 14:23:45 [12345] webapp@production
  LOG: duration: 3245.678 ms  statement:
    SELECT u.*, array_agg(o.id)
    FROM users u
    LEFT JOIN orders o ON u.id = o.user_id
    WHERE u.created_at > '2024-01-01'
    GROUP BY u.id;

Workflow thực tế:

Set log_min_duration_statement = 1000 (1 giây) ban đầu
Giảm dần xuống 500ms, 200ms khi hệ thống tối ưu hơn
Dùng pgBadger để parse log file → report visual

5. pg_stat_user_tables — Thống kê cấp bảng

sql

-- Bảng nào bị Sequential Scan nhiều nhất?
SELECT
    schemaname,
    relname AS table_name,
    seq_scan,
    seq_tup_read,
    idx_scan,
    CASE WHEN seq_scan > 0
        THEN ROUND(seq_tup_read::numeric / seq_scan, 0)
        ELSE 0
    END AS avg_rows_per_seq_scan,
    n_live_tup AS estimated_rows
FROM pg_stat_user_tables
WHERE seq_scan > 50  -- loại bảng ít truy cập
ORDER BY seq_tup_read DESC
LIMIT 10;

-- Bảng nào cần VACUUM gấp?
SELECT
    relname,
    n_live_tup,
    n_dead_tup,
    ROUND(n_dead_tup::numeric / NULLIF(n_live_tup, 0) * 100, 2) AS dead_pct,
    last_vacuum,
    last_autovacuum
FROM pg_stat_user_tables
WHERE n_dead_tup > 10000
ORDER BY dead_pct DESC;

6. auto_explain — Tự động log execution plan

Thay vì chạy EXPLAIN thủ công, auto_explain tự động ghi execution plan cho mọi query chậm.

ini

# postgresql.conf
shared_preload_libraries = 'pg_stat_statements, auto_explain'
auto_explain.log_min_duration = 1000    # Plan cho query > 1s
auto_explain.log_analyze = true          # Include ANALYZE data
auto_explain.log_buffers = true          # Include buffer stats
auto_explain.log_format = 'json'         # JSON cho tooling
auto_explain.log_nested_statements = true # Include subqueries

💡 HPN Pro Tip: auto_explain Overhead

auto_explain.log_analyze = true thêm overhead vì phải collect actual timing. Trên production high-load, bắt đầu với log_analyze = false (chỉ plan, không actual time), rồi bật khi cần deep dive query cụ thể.

7. Production Profiling Workflow

Quy trình 4 bước — lặp lại cho mỗi performance issue:

text

┌─────────────────────────────────────────────────────────┐
│ Step 1: IDENTIFY — Tìm query có vấn đề                 │
│   • pg_stat_statements → top queries by total_time      │
│   • slow query log → queries > threshold                │
│   • APM tool → API endpoints chậm → extract SQL         │
├─────────────────────────────────────────────────────────┤
│ Step 2: MEASURE — Đo chính xác                          │
│   • EXPLAIN (ANALYZE, BUFFERS) trên production data     │
│   • So sánh estimated rows vs actual rows               │
│   • Xác định bottleneck: Seq Scan? Hash Join? Sort?     │
├─────────────────────────────────────────────────────────┤
│ Step 3: OPTIMIZE — Áp dụng fix                          │
│   • Thêm index cho filter/join columns                  │
│   • Rewrite query (subquery → JOIN, OR → UNION ALL)     │
│   • ANALYZE table để update statistics                   │
│   • Partition bảng lớn (xem bài partition-strategies)    │
├─────────────────────────────────────────────────────────┤
│ Step 4: VERIFY — Chứng minh hiệu quả                   │
│   • EXPLAIN (ANALYZE, BUFFERS) lần nữa → so sánh       │
│   • pg_stat_statements_reset() → monitor new stats      │
│   • Check không regression ở queries khác               │
└─────────────────────────────────────────────────────────┘

Thực chiến: Tìm và fix N+1 Query bằng pg_stat_statements

Bài toán: API /users trả response trong 4 giây. Frontend team báo lỗi.

Bước 1: Identify

sql

-- Tìm query gọi nhiều nhất (dấu hiệu N+1)
SELECT
    SUBSTRING(query, 1, 100) AS short_query,
    calls,
    ROUND(mean_exec_time::numeric, 2) AS avg_ms,
    ROUND(total_exec_time::numeric, 0) AS total_ms
FROM pg_stat_statements
WHERE query LIKE '%orders%'
ORDER BY calls DESC
LIMIT 5;

-- Kết quả nghi ngờ:
-- "SELECT * FROM orders WHERE user_id = $1" | calls: 15000 | avg: 0.8ms | total: 12000ms
-- → 15000 lần gọi = N+1 pattern với ~15000 users!

Bước 2: Measure

sql

EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM orders WHERE user_id = 42;
-- Index Scan on idx_orders_user_id (actual time=0.050..0.800 rows=12)
-- Buffers: shared hit=4
-- Nhanh per-query, nhưng x15000 = 12 giây tổng cộng

Bước 3: Optimize — Rewrite sang batch query

sql

-- Thay vì gọi 15000 lần:
-- SELECT * FROM orders WHERE user_id = $1

-- Gọi 1 lần duy nhất:
SELECT u.id, u.name, u.email,
       o.id AS order_id, o.total, o.status
FROM users u
LEFT JOIN orders o ON u.id = o.user_id
WHERE u.active = true
ORDER BY u.id, o.created_at DESC;

Bước 4: Verify

sql

SELECT pg_stat_statements_reset();
-- Chờ 1 giờ traffic production, rồi check lại
-- calls cho query orders giảm từ 15000 → 1
-- total_time giảm từ 12000ms → 150ms

Sai lầm điển hình

⚠️ Cạm bẫy

Profile trên dev rồi kết luận cho production Dev dataset 10K rows — mọi query đều nhanh. Production 50M rows — hoàn toàn khác. Planner chọn plan khác nhau tùy data size. Index Scan trên dev có thể thành Seq Scan trên production. Luôn profile trên production-like data (staging với data gần production).

⚠️ Cạm bẫy

Cold cache vs Warm cache — so sánh không công bằng Lần chạy đầu tiên sau restart: tất cả data đọc từ disk (cold cache). Lần thứ hai: data đã trong shared_buffers (warm cache) — nhanh hơn 10-100x. Khi benchmark, chạy query ít nhất 3 lần và bỏ lần đầu tiên. Hoặc dùng pg_prewarm để warm cache trước khi measure.

⚠️ Cạm bẫy

Statistics stale — Planner dùng dữ liệu cũ Sau bulk INSERT/DELETE lớn, table statistics (pg_statistic) outdated. Planner estimate sai → chọn plan tệ. Chạy ANALYZE table_name; sau mọi data migration lớn. Check last_analyze trong pg_stat_user_tables.

Under the Hood: PostgreSQL Query Planner

Cost Estimation Model

PostgreSQL planner ước tính chi phí mỗi plan dựa trên:

text

Total Cost = (disk pages read * seq_page_cost)
           + (disk pages read randomly * random_page_cost)
           + (rows processed * cpu_tuple_cost)
           + (index entries * cpu_index_tuple_cost)
           + (function calls * cpu_operator_cost)

Các tham số mặc định:

Parameter	Default	Ý nghĩa
`seq_page_cost`	1.0	Chi phí đọc 1 page tuần tự
`random_page_cost`	4.0	Chi phí đọc 1 page ngẫu nhiên (4x tuần tự)
`cpu_tuple_cost`	0.01	Chi phí xử lý 1 row
`cpu_index_tuple_cost`	0.005	Chi phí xử lý 1 index entry
`effective_cache_size`	4GB	Ước tính RAM cho disk cache

💡 HPN Pro Tip: Tuning random_page_cost

Nếu data nằm trọn trong RAM (SSD server với đủ shared_buffers), giảm random_page_cost xuống 1.1-1.5. Mặc định 4.0 giả định spinning disk — khiến planner "sợ" Index Scan và chọn Seq Scan không cần thiết trên SSD.

Tại sao planner chọn Seq Scan dù có Index?

Khi selectivity thấp (query trả > 20% rows), đọc tuần tự nhanh hơn vì:

Seq Scan: đọc pages liên tục, OS prefetch hiệu quả
Index Scan: random I/O cho mỗi row, mỗi heap page fetch là random access

sql

-- Planner tự quyết định dựa trên statistics
-- Force index scan (KHÔNG recommended trong production):
SET enable_seqscan = off;
EXPLAIN ANALYZE SELECT * FROM orders WHERE status = 'completed';
SET enable_seqscan = on;  -- nhớ bật lại!

Checklist ghi nhớ

✅ Checklist triển khai

Setup profiling tools

[ ] Enable pg_stat_statements (shared_preload_libraries, restart required)
[ ] Set log_min_duration_statement (bắt đầu 1000ms, giảm dần)
[ ] Enable auto_explain cho deep dive tự động
[ ] Cài pgBadger hoặc tool parse slow query log

Profiling workflow

[ ] Identify: pg_stat_statements top queries by total_time + calls
[ ] Measure: EXPLAIN (ANALYZE, BUFFERS) trên production-like data
[ ] Optimize: index, rewrite query, partition, ANALYZE table
[ ] Verify: so sánh EXPLAIN before/after, monitor new stats

Đọc execution plan

[ ] Đọc từ trong ra ngoài, từ dưới lên trên
[ ] Check actual rows vs estimated rows (lệch > 10x = stale stats)
[ ] Check Buffers shared read vs hit (read cao = I/O bottleneck)
[ ] Check Rows Removed by Filter (cao = cần index)
[ ] Seq Scan trên bảng lớn + filter = cần index

Production awareness

[ ] Luôn profile trên production-like dataset
[ ] Warm cache trước benchmark (hoặc bỏ lần đầu tiên)
[ ] ANALYZE sau bulk data changes
[ ] Monitor regression sau mỗi optimization

Bài tập luyện tập

🧠 Quiz

Câu 1: pg_stat_statements cho thấy 1 query có calls=50000, avg_time=0.5ms, total_time=25000ms. Đây là dấu hiệu của vấn đề gì?

[ ] A) Query chậm cần optimize bằng index
[x] B) N+1 query pattern — query đơn lẻ nhanh nhưng gọi quá nhiều lần
[ ] C) Lock contention — query bị chờ lock
[ ] D) Cache miss — data phải đọc từ disk

💡 Query mỗi lần chỉ 0.5ms (rất nhanh), nhưng gọi 50000 lần = 25 giây tổng cộng. Đây là N+1 pattern điển hình — ORM gọi query trong vòng lặp. Fix bằng cách batch thành 1 query với JOIN hoặc IN clause.

🧠 Quiz

Câu 2: EXPLAIN ANALYZE output cho thấy "Buffers: shared hit=50, read=4500". Điều này nghĩa là gì?

[ ] A) Query sử dụng 4500 bytes RAM
[ ] B) Query đọc 50 rows từ cache và 4500 rows từ disk
[x] C) 50 pages từ cache (RAM), 4500 pages phải đọc từ disk — cache miss nghiêm trọng
[ ] D) Query cần 4500 index entries

💡 Buffers tính theo pages (8KB mỗi page). shared hit = pages đã trong shared_buffers (RAM), shared read = pages phải đọc từ disk. Tỉ lệ read/(hit+read) = 4500/4550 = 98.9% cache miss. Cần tăng shared_buffers hoặc giảm data scan bằng index/partition.

🧠 Quiz

Câu 3: Khi nào PostgreSQL planner chọn Seq Scan thay vì Index Scan dù bảng có index?

[ ] A) Khi index bị corrupt
[ ] B) Khi bảng có ít hơn 100 rows
[x] C) Khi query cần trả về phần lớn rows trong bảng (selectivity thấp)
[ ] D) Khi đang chạy trong transaction

💡 Với selectivity thấp (ví dụ WHERE status = 'active' mà 80% rows là active), Seq Scan đọc tuần tự nhanh hơn vì OS prefetch hiệu quả. Index Scan phải random I/O cho mỗi row — khi cần nhiều rows, chi phí random access vượt quá lợi ích của index. Planner tính toán dựa trên table statistics.

Spot the Bug: Đọc sai EXPLAIN output

🐛 Spot-the-Bug

Tình huống: Junior DBA nhìn execution plan sau và kết luận "query đã tối ưu vì dùng Index Scan".

sql

EXPLAIN (ANALYZE, BUFFERS)
SELECT * FROM orders WHERE status = 'pending';

text

Index Scan using idx_orders_status on orders
    (cost=0.43..45000.00 rows=800000 width=120)
    (actual time=0.050..3200.500 rows=820000 loops=1)
    Buffers: shared hit=1200 read=65000
Planning Time: 0.200 ms
Execution Time: 3800.100 ms

Bug: Junior kết luận "dùng Index Scan = tối ưu rồi" — nhưng thực tế query đang trả 820K rows từ bảng (ước tính ~1M rows total). Index Scan ở đây thực ra chậm hơn Seq Scan vì phải random I/O cho 820K rows. Buffers read=65000 pages từ disk chứng minh I/O cực nặng.

Fix: Với selectivity thấp thế này, Seq Scan sẽ nhanh hơn. Nhưng câu hỏi thật sự là: tại sao cần SELECT 820K rows? Thêm LIMIT, filter chặt hơn, hoặc paginate. Nếu report cần aggregate, dùng SELECT status, COUNT(*), SUM(total) ... GROUP BY status thay vì fetch tất cả rows.

Liên kết học tiếp

Nội dung này được biên soạn độc quyền bởi HPN. Nếu thấy hữu ích, bạn có thể ủng hộ tôi một ly cà phê nhé ❤️.

Query Profiling — Phân tích hiệu năng truy vấn nâng cao ​

Bức tranh tư duy ​

Cốt lõi kỹ thuật ​

1. EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) — Deep Dive ​

2. Scan Types — Đọc hiểu hành vi truy cập ​

3. pg_stat_statements — Top N Slow Queries ​

4. Slow Query Log — Bắt query chậm tự động ​

5. pg_stat_user_tables — Thống kê cấp bảng ​

6. auto_explain — Tự động log execution plan ​

7. Production Profiling Workflow ​

Thực chiến: Tìm và fix N+1 Query bằng pg_stat_statements ​

Sai lầm điển hình ​

Under the Hood: PostgreSQL Query Planner ​

Cost Estimation Model ​

Checklist ghi nhớ ​

Bài tập luyện tập ​

Câu 1: pg_stat_statements cho thấy 1 query có calls=50000, avg_time=0.5ms, total_time=25000ms. Đây là dấu hiệu của vấn đề gì? ​

Câu 2: EXPLAIN ANALYZE output cho thấy "Buffers: shared hit=50, read=4500". Điều này nghĩa là gì? ​

Câu 3: Khi nào PostgreSQL planner chọn Seq Scan thay vì Index Scan dù bảng có index? ​

Spot the Bug: Đọc sai EXPLAIN output ​

Liên kết học tiếp ​

Query Profiling — Phân tích hiệu năng truy vấn nâng cao

Bức tranh tư duy

Cốt lõi kỹ thuật

1. EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) — Deep Dive

2. Scan Types — Đọc hiểu hành vi truy cập

3. pg_stat_statements — Top N Slow Queries

4. Slow Query Log — Bắt query chậm tự động

5. pg_stat_user_tables — Thống kê cấp bảng

6. auto_explain — Tự động log execution plan

7. Production Profiling Workflow

Thực chiến: Tìm và fix N+1 Query bằng pg_stat_statements

Sai lầm điển hình

Under the Hood: PostgreSQL Query Planner

Cost Estimation Model

Checklist ghi nhớ

Bài tập luyện tập

Câu 1: pg_stat_statements cho thấy 1 query có calls=50000, avg_time=0.5ms, total_time=25000ms. Đây là dấu hiệu của vấn đề gì?

Câu 2: EXPLAIN ANALYZE output cho thấy "Buffers: shared hit=50, read=4500". Điều này nghĩa là gì?

Câu 3: Khi nào PostgreSQL planner chọn Seq Scan thay vì Index Scan dù bảng có index?

Spot the Bug: Đọc sai EXPLAIN output

Liên kết học tiếp