Postgres如何追溯历史执行计划
前言
pg_show_plans
这是cybertec开源的一款Real-time insights插件，可以实时看到当前库正在运行SQL的执行计划。具体可以参考：https://www.cybertec-postgresql.com/en/products/pg-show-plans/
因为这个插件是real-time的，所以可以结合pg_stat_activity这个视图来看到正在运行的SQL及其执行计划：
postgres=# select p.pid,p.level,p.plan,s.query,wait_event,wait_event_type from pg_show_plans p join pg_stat_activity s on p.pid = s.pid limit 1;
-[ RECORD 1 ]---+--------------------------------------------------------------------------------------------------------------------------------------
pid | 32487
level | 0
plan | Limit (cost=2.25..2.29 rows=1 width=144) +
| -> Hash Join (cost=2.25..21.00 rows=500 width=144) +
| Hash Cond: (pg_show_plans.pid = s.pid) +
| -> Function Scan on pg_show_plans (cost=0.00..10.00 rows=1000 width=48) +
| -> Hash (cost=1.00..1.00 rows=100 width=108) +
| -> Function Scan on pg_stat_get_activity s (cost=0.00..1.00 rows=100 width=108)
query | select p.pid,p.level,p.plan,s.query,wait_event,wait_event_type from pg_show_plans p join pg_stat_activity s on p.pid = s.pid limit 1;
wait_event |
wait_event_type |
postgres=# select p.pid,p.level,p.plan,s.query,wait_event,wait_event_type from pg_show_plans p join pg_stat_activity s on p.pid = s.pid limit 1;
-[ RECORD 1 ]---+---------------------------------------------------------------------------------------------------
pid | 475
level | 0
plan | Update on pgbench_tellers (cost=0.28..8.29 rows=1 width=358) +
| -> Index Scan using pgbench_tellers_pkey on pgbench_tellers (cost=0.28..8.29 rows=1 width=358)+
| Index Cond: (tid = 453)
query | UPDATE pgbench_tellers SET tbalance = tbalance + -2048 WHERE tid = 453;
wait_event | transactionid
wait_event_type | Lock
通过pg_show_plans，我们就不需要再机械地先抓pg_stat_activty的query字段，再去explain看执行计划了。但是还是老问题，这个插件是real-time的，仅能看到某一时刻的运行状态快照，实际的场景中，更多是业务发现了慢SQL，找到我们，我们再去查看是哪些慢SQL导致的性能问题，所以更需要的是追本溯源，总不可能一直盯着，所以pg_show_plans这个插件有一定的局限性。另外还有一个有趣的case，和逻辑复制槽有关，如下：
postgres=# SELECT pg_create_logical_replication_slot('myslot', 'pgoutput');
ERROR: cannot create logical replication slot in transaction that has performed writes
postgres=# SELECT pg_create_logical_replication_slot('myslot', 'wal2json');
ERROR: cannot create logical replication slot in transaction that has performed writes
postgres=# SELECT pg_create_logical_replication_slot('myslot', 'wal2mongo');
ERROR: cannot create logical replication slot in transaction that has performed writes
postgres=# set pg_show_plans.enable = off;
SET
postgres=# SELECT pg_create_logical_replication_slot('myslot', 'pgoutput');
pg_create_logical_replication_slot
------------------------------------
(myslot,0/1572F90)
(1 row)
postgres=# SET pg_show_plans.enable = on;
SET
对于含有逻辑复制、CDC的场景，这个也是比较麻烦的一点，可以参照这个issue：https://gitmemory.com/issue/cybertec-postgresql/pg_show_plans/14/773309816
auto_explain
auto_explain 是 8.4之后添加的一个功能，在contrib目录下直接make就安装好了，可以通过参数配置，在日志里自动记录慢SQL的执行计划，而不需要手工运行explain。auto_explain不需要显式create，在shared_preload_libraries = 'auto_explain'配置即可。涉及到的GUC参数如下：
postgres=# select name,short_desc,setting from pg_settings where name like '%auto_explain%';
name | short_desc | setting
------------------------------------+-------------------------------------------------------------------+---------
auto_explain.log_analyze | Use EXPLAIN ANALYZE for plan logging. | off
auto_explain.log_buffers | Log buffers usage. | off
auto_explain.log_format | EXPLAIN format to be used for plan logging. | text
auto_explain.log_level | Log level for the plan. | log
auto_explain.log_min_duration | Sets the minimum execution time above which plans will be logged. | -1
auto_explain.log_nested_statements | Log nested statements. | off
auto_explain.log_settings | Log modified configuration parameters affecting query planning. | off
auto_explain.log_timing | Collect timing data, not just row counts. | on
auto_explain.log_triggers | Include trigger statistics in plans. | off
auto_explain.log_verbose | Use EXPLAIN VERBOSE for plan logging. | off
auto_explain.log_wal | Log WAL usage. | off
auto_explain.sample_rate | Fraction of queries to process. | 1
(12 rows)
前面三个参数就是explain后面常见的附加项，其他参数介绍见：https://www.postgresql.org/docs/current/auto-explain.html，如
postgres=# explain (analyze,buffers,format text) select * from pg_stat_activity limit 1;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.00..0.29 rows=1 width=444) (actual time=0.153..0.156 rows=1 loops=1)
Buffers: shared hit=2
-> Nested Loop Left Join (cost=0.00..28.51 rows=100 width=444) (actual time=0.152..0.154 rows=1 loops=1)
Join Filter: (s.usesysid = u.oid)
Rows Removed by Join Filter: 8
Buffers: shared hit=2
-> Nested Loop Left Join (cost=0.00..8.02 rows=100 width=380) (actual time=0.133..0.134 rows=1 loops=1)
Join Filter: (s.datid = d.oid)
Rows Removed by Join Filter: 4
Buffers: shared hit=1
-> Function Scan on pg_stat_get_activity s (cost=0.00..1.00 rows=100 width=316) (actual time=0.110..0.110 rows=1 loops=1)
-> Materialize (cost=0.00..1.06 rows=4 width=68) (actual time=0.011..0.016 rows=4 loops=1)
Buffers: shared hit=1
-> Seq Scan on pg_database d (cost=0.00..1.04 rows=4 width=68) (actual time=0.007..0.009 rows=4 loops=1)
Buffers: shared hit=1
-> Materialize (cost=0.00..1.19 rows=13 width=68) (actual time=0.006..0.014 rows=9 loops=1)
Buffers: shared hit=1
-> Seq Scan on pg_authid u (cost=0.00..1.13 rows=13 width=68) (actual time=0.003..0.006 rows=9 loops=1)
Buffers: shared hit=1
Planning:
Buffers: shared hit=27 read=1
Planning Time: 0.550 ms
Execution Time: 0.751 ms
(23 rows)
测试一下，将所有参数都设为on
[postgres@xiongcc ~]$ tail -n 15 pgdata/postgresql.conf
auto_explain.log_analyze = on
auto_explain.log_buffers = on
auto_explain.log_format = text
auto_explain.log_level = log
auto_explain.log_min_duration = 0
auto_explain.log_nested_statements= on
auto_explain.log_settings = on
auto_explain.log_timing = on
auto_explain.log_triggers = on
auto_explain.log_verbose = on
auto_explain.log_wal = on
auto_explain.sample_rate = on
截取部分日志：
2021-04-27 17:09:36.296 CST,"postgres","postgres",815,"[local]",6087d4bb.32f,11661,"UPDATE",2021-04-27 17:09:15 CST,4/743,12580443,LOG,00000,"duration: 0.074 ms plan:
Query Text: UPDATE pgbench_branches SET bbalance = bbalance + -4348 WHERE bid = 49;
Update on public.pgbench_branches (cost=0.00..3.25 rows=1 width=370) (actual time=0.073..0.073 rows=0 loops=1)
Buffers: shared hit=3
WAL: records=1 bytes=74
-> Seq Scan on public.pgbench_branches (cost=0.00..3.25 rows=1 width=370) (actual time=0.032..0.038 rows=1 loops=1)
Output: bid, (bbalance + '-4348'::integer), filler, ctid
Filter: (pgbench_branches.bid = 49)
Rows Removed by Filter: 99
Buffers: shared hit=2
Settings: max_parallel_workers_per_gather = '0'",,,,,,,,,"pgbench","client backend"
2021-04-27 17:09:36.296 CST,"postgres","postgres",815,"[local]",6087d4bb.32f,11662,"UPDATE",2021-04-27 17:09:15 CST,4/743,12580443,LOG,00000,"duration: 0.428 ms",,,,,,,,,"pgbench","client backend"
2021-04-27 17:09:36.297 CST,"postgres","postgres",816,"[local]",6087d4bb.330,11689,"idle in transaction",2021-04-27 17:09:15 CST,5/732,12580448,LOG,00000,"statement: UPDATE pgbench_tellers SET tbalance = tbalance + 4211 WHERE tid = 163;",,,,,,,,,"pgbench","client backend"
2021-04-27 17:09:36.297 CST,"postgres","postgres",816,"[local]",6087d4bb.330,11690,"UPDATE",2021-04-27 17:09:15 CST,5/732,12580448,LOG,00000,"duration: 0.032 ms plan:
Query Text: UPDATE pgbench_tellers SET tbalance = tbalance + 4211 WHERE tid = 163;
Update on public.pgbench_tellers (cost=0.28..8.29 rows=1 width=358) (actual time=0.031..0.032 rows=0 loops=1)
Buffers: shared hit=4
WAL: records=1 bytes=78
-> Index Scan using pgbench_tellers_pkey on public.pgbench_tellers (cost=0.28..8.29 rows=1 width=358) (actual time=0.019..0.020 rows=1 loops=1)
Output: tid, bid, (tbalance + 4211), filler, ctid
Index Cond: (pgbench_tellers.tid = 163)
Buffers: shared hit=3
Settings: max_parallel_workers_per_gather = '0'",,,,,,,,,"pgbench","client backend"
可以看到buffers、wal，具体的SQL以及相应的执行计划，还会输出影响查询规划的配置如max_parallel_workers_per_gather并行度，可以看到，auto_explain这个插件也是不错的性能分析工具👍。不过需要注意几个问题，第一个就是，这些是记录在log里面的，参数一旦没控制好，日志就会特别大，笔者才测试过程中，全开on，压测5分钟，日志上了好几GB，在偌大的日志中，找几条慢SQL眼睛都要花，另外在实际工作中，我们往往还会配置一系列Postgres自带的log参数，如log_min_duration_statement、log_duration等，这无疑也会让日志显得冗余。
第二个就是，auto_explain.log_analyze这个参数，假如设为on，就是真实执行的SQL，对于我们分析SQL的出发点是好的，但是这会造成每一步都即时，假如碰到一个特别复杂的SQL，就会产生比较客观的性能影响。
When this parameter is on, per-plan-node timing occurs for all statements executed, whether or not they run long enough to actually get logged. This can have an extremely negative impact on performance. Turning off auto_explain.log_timing ameliorates the performance cost, at the price of obtaining less information.
所以auto_explain虽然方便，但也要谨慎配置。
pg_store_plans
pg_store_plans，pg_store_plans这个插件可以跟踪执行的所有SQL的执行计划，类似于pg_stat_statements，可以记录历史的SQL以及其执行计划。看样子是个不错的插件👍涉及到的视图是pg_store_plans，和pg_stat_statements这个插件十分类似。
postgres=# \d pg_store_plans
View "public.pg_store_plans"
Column | Type | Collation | Nullable | Default
-------------------------+--------------------------+-----------+----------+---------
userid | oid | | |
dbid | oid | | |
queryid | bigint | | |
planid | bigint | | |
queryid_stat_statements | bigint | | |
plan | text | | |
calls | bigint | | |
total_time | double precision | | |
min_time | double precision | | |
max_time | double precision | | |
mean_time | double precision | | |
stddev_time | double precision | | |
rows | bigint | | |
shared_blks_hit | bigint | | |
shared_blks_read | bigint | | |
shared_blks_dirtied | bigint | | |
shared_blks_written | bigint | | |
local_blks_hit | bigint | | |
local_blks_read | bigint | | |
local_blks_dirtied | bigint | | |
local_blks_written | bigint | | |
temp_blks_read | bigint | | |
temp_blks_written | bigint | | |
blk_read_time | double precision | | |
blk_write_time | double precision | | |
first_call | timestamp with time zone | | |
last_call | timestamp with time zone | | |
但是值得注意的是，pg_store_plans里面的queryid和pg_stat_statements的queryid并不能直接等同queryid is calculated to identify the source query similary to pg_stat_statements but in a different algorithm. plan is calculated in a similar way. 但是大多数时候都是相同的，可以进行join，获取出对应SQL。
涉及到GUC参数和pg_stat_statements类似
postgres=# select name,setting,short_desc from pg_settings where name like '%pg_store%';
name | setting | short_desc
-----------------------------+---------+------------------------------------------------------------------------------
pg_store_plans.log_analyze | off | Use EXPLAIN ANALYZE for plan logging.
pg_store_plans.log_buffers | off | Log buffer usage.
pg_store_plans.log_timing | on | Log timings.
pg_store_plans.log_triggers | off | Log trigger trace.
pg_store_plans.log_verbose | off | Set VERBOSE for EXPLAIN on logging.
pg_store_plans.max | 1000 | Sets the maximum number of plans tracked by pg_store_plans.
pg_store_plans.min_duration | 0 | Minimum duration to record plan in milliseconds.
pg_store_plans.plan_format | text | Selects which format to be appied for plan representation in pg_store_plans.
pg_store_plans.save | on | Save pg_store_plans statistics across server shutdowns.
pg_store_plans.track | top | Selects which plans are tracked by pg_store_plans.
(10 rows)
pg_store_plans.max是指 pg_store_plans跟踪的最大执行计划数量，也就简单理解成pg_store_plans视图里的最大行数，如果超过了的话，最少执行的item就会被丢弃pg_store_plans.save则是持久化的选项，其他类似就不多介绍了。看下效果：
pstgres=# SELECT s.query, s.total_plan_time,s.shared_blks_hit,s.local_blks_hit,s.wal_records,s.wal_fpi,p.plan,
p.calls as "plan calls", s.calls as "stmt calls",
p.total_time / p.calls as "time/call", p.first_call, p.last_call
FROM pg_stat_statements s
JOIN pg_store_plans p ON
(p.queryid = pg_store_plans_hash_query(s.query))
ORDER BY query ASC, "time/call" DESC limit 3;
-[ RECORD 1 ]---+------------------------------------------------------------------------------------------------------------------------------------------
query | explain (analyze,buffers,format json) select 1
total_plan_time | 0
shared_blks_hit | 0
local_blks_hit | 0
wal_records | 0
wal_fpi | 0
plan | Result (cost=0.00..0.01 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=1)
plan calls | 1
stmt calls | 1
time/call | 0.003842
first_call | 2021-04-27 17:00:20.482409+08
last_call | 2021-04-27 17:00:20.482409+08
-[ RECORD 2 ]---+------------------------------------------------------------------------------------------------------------------------------------------
query | explain (analyze,buffers,format text) select 1
total_plan_time | 0
shared_blks_hit | 0
local_blks_hit | 0
wal_records | 0
wal_fpi | 0
plan | Result (cost=0.00..0.01 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=1)
plan calls | 1
stmt calls | 1
time/call | 0.004134
first_call | 2021-04-27 17:00:31.834718+08
last_call | 2021-04-27 17:00:31.834718+08
-[ RECORD 3 ]---+------------------------------------------------------------------------------------------------------------------------------------------
query | explain (analyze,buffers,format text) select * from pg_stat_activity limit 1
total_plan_time | 0
shared_blks_hit | 118
local_blks_hit | 0
wal_records | 0
wal_fpi | 0
plan | Limit (cost=0.00..0.29 rows=1 width=444) (actual time=0.153..0.156 rows=1 loops=1) +
| -> Nested Loop Left (cost=0.00..28.51 rows=100 width=444) (actual time=0.152..0.154 rows=1 loops=1) +
| Join Filter: (s.usesysid = u.oid) +
| Rows Removed by Join Filter: 8 +
| -> Nested Loop Left (cost=0.00..8.02 rows=100 width=380) (actual time=0.133..0.134 rows=1 loops=1) +
| Join Filter: (s.datid = d.oid) +
| Rows Removed by Join Filter: 4 +
| -> Function Scan on pg_stat_get_activity s (cost=0.00..1.00 rows=100 width=316) (actual time=0.110..0.110 rows=1 loops=1)+
| -> Materialize (cost=0.00..1.06 rows=4 width=68) (actual time=0.011..0.016 rows=4 loops=1) +
| -> Seq Scan on pg_database d (cost=0.00..1.04 rows=4 width=68) (actual time=0.007..0.009 rows=4 loops=1) +
| -> Materialize (cost=0.00..1.19 rows=13 width=68) (actual time=0.006..0.014 rows=9 loops=1) +
| -> Seq Scan on pg_authid u (cost=0.00..1.13 rows=13 width=68) (actual time=0.003..0.006 rows=9 loops=1)
plan calls | 1
stmt calls | 1
time/call | 0.157629
first_call | 2021-04-27 17:00:40.786791+08
last_call | 2021-04-27 17:00:40.786791+08
这样我就统计出了历史调用次数最多的SQL以及其执行计划。
小结
通过对比，个人觉得pg_store_plans和auto_explain这两个插件更满足生产需求，pg_show_plans只能看到某一时刻的状态信息，这对于溯源是十分不利的。auto_explain出来的时间较长，提到的两个弊端其实都可以控制，而pg_store_plans这个插件通过视图的方式，对于DBA和运维人员来说更加友好，反正我是不爱在日志里去过滤找半天，虽说pg_store_plans会有小概率和pg_stat_statements对不上的时候，但也足够了，个人倾向于使用pg_store_plans。
原文作者：PostgreSQL学徒；如有侵权，请联系管理员删除。
上一篇：
一文搞懂Postgres中的计划节点
下一篇：
如何查看单条SQL耗费了多少cpu及io
请登录后发表评论
登录
全部评论
