PostgreSQL 查询偶发变慢怎么查：用 auto_explain 把慢的那一次执行计划抓下来（实测 1ms 和 650ms 是同一条 SQL）

写这篇前我列了 5 个角度：给一年前的自己的建议、常见说法哪里不对、换个定义、对小团队为什么重要、用别的领域类比。最后选了第二个：网上很多偶发慢的建议是先加 shared_buffers、重建索引、VACUUM，我不同意。不知道慢的那一次走了什么计划之前，改任何参数都是猜。

换个定义更好理解：偶发慢 = 数据分布不均 + 计划对某些参数不合适。规划器按统计平均值估算，客户 7 有 2 万行，它估算 11,626–12,817 行，觉得「倒着扫 created_at 索引，很快就能凑够 20 行」；实际客户 7 的订单都在一年前，要倒着扫过 164 万行才凑够。

所以第一步不是优化，而是取证：auto_explain 就是 PostgreSQL 自带的「行车记录仪」，超过阈值的语句自动把计划写进日志。

SQL：SELECT id FROM orders WHERE customer_id = $1 AND status = 'paid' ORDER BY created_at DESC LIMIT 20。每个参数跑 3 次，客户 7 跑两轮。

普通客户的计划是 Bitmap Index Scan on orders_customer_idx → Sort → Limit，几十行排个序就完；客户 7 的计划是 Index Scan Backward using orders_created_idx，带 Filter (customer_id = 7 AND status = 'paid')。规划器估算的 cost 只有 199，实际要读 165 万个缓冲页。

会话级试用（需要超级用户）：LOAD 'auto_explain'; SET auto_explain.log_min_duration = '100ms'; SET auto_explain.log_analyze = on; SET auto_explain.log_buffers = on; SET auto_explain.log_timing = off;。长期使用写进 postgresql.conf：session_preload_libraries = 'auto_explain'，再加上面几个参数，新连接生效、不用重启；放 shared_preload_libraries 也可以，但要重启。

测试库日志原文（用 psql 的 \bind 走扩展协议传参）：LOG: duration: 698.868 ms plan: / Query Parameters: $1 = '7' / Limit (cost=0.43..199.27 rows=20) (actual rows=20 loops=1) / Buffers: shared hit=1653767 / -> Index Scan Backward using orders_created_idx on orders (cost=0.43..127427.84 rows=12817) / Filter: ((customer_id = 7) AND (status = 'paid'::text)) / Rows Removed by Filter: 1644859。

这一段日志把三件事都说清了：慢的是哪个参数（$1 = '7'）、走了什么计划（倒着扫 created_at 索引）、为什么慢（过滤掉 164 万行）。Query Parameters 这一行由 auto_explain.log_parameter_max_length 控制，默认 -1 记录完整参数值；参数里有手机号、邮箱等敏感数据时，可以设成 0 关掉或设一个截断长度。

pgbench -M prepared -c 8 -j 4 -T 20，脚本是随机普通客户的上面那条 SQL（平均 0.06ms），每种配置跑 3 次。结果四组都在 12.2 万–13.8 万 tps 之间，组内 3 次的波动（如关闭 auto_explain 时 124,122–137,744）比组间差异还大，测不出稳定差别。

我对这组数的态度是：它只说明「在这台机器、这种很短的索引查询上，开 log_analyze + log_timing=off 没有明显代价」，不能推到复杂查询。官方文档对 log_analyze 的提醒很直接：开启后所有语句都会逐节点计时，不管是否最终被记录，可能带来非常大的性能影响。生产上我会先 log_timing=off，再配 sample_rate，在预发环境压一轮再上。

我把 statement_timeout 设成 300ms 再跑客户 7：客户端收到 ERROR: canceling statement due to statement timeout，日志里只有 ERROR 和 STATEMENT 两行，没有计划。RESET statement_timeout 后再跑同一条，auto_explain 才记下 duration: 666.035 ms 和完整计划。原因是 auto_explain 在语句正常执行结束时才输出，被取消的语句走不到那一步。

这意味着：如果你的应用超时设得很紧（比如 1s），而 log_min_duration 设成 3s，那最该抓的语句永远抓不到。log_min_duration 要明显小于 statement_timeout；超时报错本身怎么查，见 PostgreSQL 报错速查里的 canceling statement due to statement timeout 页。

计划的问题是「按时间倒序找某个客户的前 20 条」只能二选一：要么按客户找全再排序，要么按时间扫再过滤。CREATE INDEX orders_cust_created_idx ON orders (customer_id, created_at DESC) 之后，两件事一个索引就能做完：客户 7 三次 1.378 / 0.974 / 0.696ms，计划变成 Index Scan using orders_cust_created_idx、Index Cond: (customer_id = 7)、Buffers shared hit=23；客户 1001 和占 40% 的客户 1 也都在 0.77–1.45ms。

代价：这个索引 61MB，表 222MB，写入多一个索引维护。生产上用 CREATE INDEX CONCURRENTLY，避免长时间锁表；建之前先确认没有长事务，否则 CONCURRENTLY 会一直等。