一次慢查询排查：从 pg_stat_statements 到 auto_explain

一、现象

线上一个 PostgreSQL 16 的报表接口，P99 从 400ms 涨到 6.8s，CPU 使用率同步从 30% 冲到 85%。没有发布、没有 DDL 变更，唯一的区别是数据量在两周里从 800 万涨到 1300 万行。

这类问题最容易踩的坑是"先猜再验证"：猜索引没走、猜统计信息过期、猜连接池不够。正确的顺序是先量化，再定位单条语句，最后看执行计划。

二、第一步：找出到底是谁在吃 CPU

先开扩展（需要 superuser，只需一次）：

CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

shared_preload_libraries 里要提前加上 pg_stat_statements，改完重启：

shared_preload_libraries = 'pg_stat_statements'
pg_stat_statements.max = 10000
pg_stat_statements.track = all

按总耗时排序，只看 total_exec_time 前 10：

SELECT
  round(total_exec_time::numeric, 1) AS total_ms,
  calls,
  round(mean_exec_time::numeric, 2)  AS mean_ms,
  round((100 * total_exec_time / sum(total_exec_time) OVER ())::numeric, 1) AS pct,
  rows,
  left(query, 90) AS query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

结果很典型：

一条 SQL 占了 62% 的总耗时，平均 610ms。注意 calls 只有 2104 —— 这说明它不是高频小查询，而是单次就慢。

对比"纯执行时间"和"总时间"能进一步判断是不是锁等待：

SELECT query,
       round(total_exec_time::numeric,1) AS exec_ms,
       round(total_plan_time::numeric,1) AS plan_ms,
       round(shared_blks_hit::numeric / nullif(shared_blks_hit + shared_blks_read, 0) * 100, 2) AS cache_hit_pct
FROM pg_stat_statements
WHERE query LIKE '%order_item%'
ORDER BY total_exec_time DESC LIMIT 5;

如果 cache_hit_pct 低于 95%，说明有大量物理读，索引或内存配置可能不对。

三、第二步：拿到真实参数，复现一次

pg_stat_statements 里的 $1 只是占位符，光看它看不出数据分布。这里上 auto_explain：

ALTER SYSTEM SET session_preload_libraries = 'auto_explain';
ALTER SYSTEM SET auto_explain.log_min_duration = '500ms';
ALTER SYSTEM SET auto_explain.log_analyze = on;
ALTER SYSTEM SET auto_explain.log_buffers = on;
ALTER SYSTEM SET auto_explain.log_nested_statements = on;
SELECT pg_reload_conf();

之后凡是超过 500ms 的语句，执行计划会直接落到 PostgreSQL 日志：

duration: 6182.401 ms  plan:
  Nested Loop  (cost=0.86..2841931.22 rows=1 width=196)
               (actual time=1.204..6180.882 rows=14823 loops=1)
    Buffers: shared hit=4128 read=98741
    ->  Index Scan using idx_order_item_order on order_item
          (actual time=0.031..1024.117 rows=14823 loops=1)
          Index Cond: (order_id = 88231947)
          Filter: (status = 'PAID'::text)
          Rows Removed by Filter: 41120
    ->  Index Scan using orders_pkey on orders
          (cost=0.43..8.32 rows=1 width=12)
          (actual time=0.284..0.285 rows=1 loops=14823)

问题一眼就能看出来：内层 orders 被扫了 14823 次（loops=14823），每次都要读一次索引页 —— 这就是 6 秒的来源。

四、第三步：为什么优化器选了嵌套循环

loops 高、rows 估得准的情况，多半是行数估计错误导致优化器以为外层只有几十行。检查统计信息：

SELECT attname, n_distinct, most_common_vals, most_common_freqs
FROM pg_stats
WHERE tablename = 'order_item' AND attname = 'order_id';

如果 n_distinct 是 -1（表示唯一）而实际 order_id 高度重复，优化器会把"每个订单平均 1 行明细"当成事实，于是选择 nested loop —— 实际上热门订单有 4 万多行明细。

修复分两层：

-- 1) 提高目标列统计精度
ALTER TABLE order_item ALTER COLUMN order_id SET STATISTICS 1000;
ANALYZE order_item;

-- 2) 给最热的查询加复合索引，让 index-only scan 成立
CREATE INDEX CONCURRENTLY idx_order_item_order_status
  ON order_item (order_id, status) INCLUDE (sku_id, qty, amount);

改完之后 loops 从 14823 降到 1，改为 Hash Join，P99 回到 380ms。

五、几个容易忽略的点

• pg_stat_statements 的统计会随 pg_stat_statements_reset() 清零，压测前后记得打点，否则数据不可比。
• auto_explain.log_analyze = on 会带来额外开销（每条语句都要计时），只建议在排查期打开，确认问题后关掉。
• CREATE INDEX CONCURRENTLY 不能在事务块里执行，也不会阻塞写入，但失败会留下 invalid 索引，需要 DROP INDEX 重来。
• 复合索引的列顺序要按"等值在前、范围在后"排，(order_id, status) 比 (status, order_id) 对这条 SQL 更有效。
• 别忘了 ANALYZE 之后再看一次执行计划 —— 只有计划真的变了，才说明统计信息起了作用。

六、小结

一条可复用的排查链路：

1. pg_stat_statements 按 total_exec_time 找 TOP 语句，看 pct 与 mean_exec_time
2. auto_explain 抓真实执行计划，重点看 actual rows 与 loops
3. loops 异常高 → 查 pg_stats 的 n_distinct / most_common_freqs
4. 统计信息修不准 → 提 SET STATISTICS + ANALYZE；执行方式本身错了 → 补复合索引或改写 SQL
5. 改完必须回到第 2 步复验计划，而不是只看耗时变快

数据库性能问题很少是"慢"，多数是"算错了"。把估算和实际摆在一起看，答案通常就在那两行数字里。