PostgreSQL跟踪函数内部执行计划方法

很多人可能在使用pg时会碰到这样的问题：一个SQL单独拿出来执行很快，但是放到函数里面执行就很慢，想要知道函数里面究竟慢在哪里，但是却无从下手。因为我们没办法像对单个SQL一样直接explain来获取执行计划。
例如在oracle中我们可以通过例如10046trace这种方式来看看函数内部慢在哪里，那么在pg中该如何去查看内部的执行计划呢？
auto_explain是pg自带的一个模块，为我们提供了一种方式来自动记录慢速语句的执行计划，而不需要手工运行explain。这在大型应用中追踪未被优化的查询时有用。

auto_explain的输出更详细的解释可以参考expolain的解释，或者man explain。

开启auto_explain有两种方式：
1、 通过配置文件postgresql.conf
需要重启数据库。
2、通过LOAD ‘auto_explain’;
这个只在当前SESSION生效，不需要重启数据库, 需要超级用户权限。

其实还可以设置local_preload_libraries，session_preload_libraries参数来启用。

例子：
1. 修改postgresql.conf配置文件:

shared_preload_libraries = 'auto_explain'  

新增如下配置:

auto_explain.log_min_duration = 0  # 为了方便查看,这里把时间设置为0,所有SQL都会被auto_explain捕获输出.实际使用的时候适当调大。如 100ms  
auto_explain.log_analyze = true  

# 以下可选  
auto_explain.log_verbose = true  
auto_explain.log_buffers = true  
auto_explain.log_nested_statements = true  

2、重启数据库
默认情况下日志记录在日志文件中。
查询：

bill=# select count(*) from tb1;                   
  count  
---------
 1000000
(1 row)

查看log日志：

bill@test180-> tail -f postgresql-2020-05-18_110158.csv
2020-05-18 11:28:52.056 CST,"bill","bill",2160,"[local]",5ec1fd1a.870,3,"SELECT",2020-05-18 11:12:26 CST,3/60,0,LOG,00000,"duration: 70.772 ms  plan:
Query Text: select count(*) from tb1;
Finalize Aggregate  (cost=14542.55..14542.56 rows=1 width=8) (actual time=68.293..68.293 rows=1 loops=1)
  Output: count(*)
  Buffers: shared hit=8334
  ->  Gather  (cost=14542.33..14542.54 rows=2 width=8) (actual time=68.169..70.752 rows=3 loops=1)
        Output: (PARTIAL count(*))
        Workers Planned: 2
        Workers Launched: 2
        Buffers: shared hit=8334
        ->  Partial Aggregate  (cost=13542.33..13542.34 rows=1 width=8) (actual time=65.305..65.305 rows=1 loops=3)
              Output: PARTIAL count(*)
              Buffers: shared hit=8334
              Worker 0: actual time=64.003..64.003 rows=1 loops=1
                Buffers: shared hit=2590
              Worker 1: actual time=63.998..63.998 rows=1 loops=1
                Buffers: shared hit=2654
              ->  Parallel Seq Scan on public.tb1  (cost=0.00..12500.67 rows=416667 width=0) (actual time=0.016..41.887 rows=333333 loops=3)
                    Output: id, info
                    Buffers: shared hit=8334
                    Worker 0: actual time=0.018..42.208 rows=310800 loops=1
                      Buffers: shared hit=2590
                    Worker 1: actual time=0.018..42.225 rows=318400 loops=1
                      Buffers: shared hit=2654",,,,,,,,"explain_ExecutorEnd, auto_explain.c:415","psql"

3、如果你不想看日志这么麻烦，想在client直接显示，也很方便，设置client_min_messages='log’就可以看到auto explain的输出了。

set client_min_messages='log';
set auto_explain.log_min_duration = 0;
set auto_explain.log_analyze = true;
set auto_explain.log_verbose = true;
set auto_explain.log_buffers = true;
set auto_explain.log_nested_statements = true;

我们来看一个输出函数执行计划的例子。
先创建一个简单的函数：

bill=# create function f1(c1 int) returns int as $$
bill$# declare
bill$# rec int;
bill$# begin
bill$# select count(*) from tb1 where id < c1 into rec;
bill$# return rec;
bill$# end;
bill$# $$ language plpgsql strict;

调用函数：
可以看到执行计划直接输出出来了，即使函数十分复杂，内部SQL的执行计划也可以依次输出，这样我们就知道函数慢在哪里了。

bill=# select f1(100);
psql: LOG:  duration: 0.055 ms  plan:
Query Text: select count(*) from tb1 where id < c1
Aggregate  (cost=5.03..5.04 rows=1 width=8) (actual time=0.053..0.053 rows=1 loops=1)
  Output: count(*)
  Buffers: shared hit=4
  ->  Index Only Scan using idx_tb1 on public.tb1  (cost=0.42..4.78 rows=100 width=0) (actual time=0.019..0.040 rows=99 loops=1)
        Output: id
        Index Cond: (tb1.id < 100)
        Heap Fetches: 99
        Buffers: shared hit=4
psql: LOG:  duration: 0.677 ms  plan:
Query Text: select f1(100);
Result  (cost=0.00..0.26 rows=1 width=4) (actual time=0.672..0.672 rows=1 loops=1)
  Output: f1(100)
  Buffers: shared hit=39 read=1
 f1 
----
 99
(1 row)

参考链接：
https://www.postgresql.org/docs/12/auto-explain.html
https://www.postgresql.org/docs/12/runtime-config-client.html