背景
羲和halo 数据库的服务端编程能力强，不仅支持像java,R,python这种流行的编程语言，另外还内置了一个与oracle plsql功能几乎一致的plsql语言。对于开发人员来说，有语言还是不够的，调试是非常常见的需求，这个调试插件是pldebugger,这里先不讲这个插件，之后发布的文章会详细介绍，现在讲另外一种情况，想知道函数内sql的执行计划如何观测，就需要用到 auto_explain了。
auto_explain
auto_explain 这个模块近期帮了我大忙了，当时甲方觉得函数运行看不到具体的执行时间和执行计划对开发来讲太费劲了，后来翻阅官方文档发现这个工具，用于向日志数据处理超出定义阈值执行时间的SQL的执行计划，更强大的是可以选择是否输出内嵌SQL的执行计划（如函数，存储过程中的SQL）。auto_explain 的输出更详细的解释可以参考EXPLAIN的解释。或者 man EXPLAIN.
SYNOPSIS
EXPLAIN [ ( option [, ...] ) ] statement
EXPLAIN [ ANALYZE ] [ VERBOSE ] statement
where option can be one of:
ANALYZE [ boolean ]
VERBOSE [ boolean ]
COSTS [ boolean ]
BUFFERS [ boolean ]
FORMAT { TEXT | XML | JSON | YAML }
开启的方式有两种：
1. 通过配置文件postgresql.conf
需要重启数据库。
2. 通过LOAD 'auto_explain';
这个只在当前SESSION生效，不需要重启数据库, 需要超级用户权限。
其实还可以设置local_preload_libraries，session_preload_libraries参数来启用。
例子
1.修改配置文件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 #会导致考虑使用嵌套语句（在函数内部执行的语句）进行日志记录。关闭时，只记录顶级查询计划。默认情况下，此参数处于禁用状态。只有超级用户才能更改此设置
下面来执行几条SQL：
SELECT count(*)FROM pg_class, pg_index WHERE oid = indrelid AND indisunique;
日志输出：
duration: 15.528 ms plan:
Query Text: SELECT count(*)FROM pg_class, pg_index WHERE oid = indrelid AND indisunique;
Aggregate (cost=1508.13..1508.14 rows=1 width=8) (actual time=15.516..15.518 rows=1 loops=1)
Output: count(*)
Buffers: shared hit=4723
-> Merge Join (cost=0.84..1490.16 rows=7186 width=0) (actual time=0.038..14.739 rows=7232 loops=1)
Merge Cond: (pg_class.oid = pg_index.indrelid)
Buffers: shared hit=4723
-> Index Only Scan using pg_class_oid_index on pg_catalog.pg_class (cost=0.29..681.64 rows=27530 width=4) (actual time=0.016..4.321 rows=27596 loops=1)
Output: pg_class.oid
Heap Fetches: 661
Buffers: shared hit=365
-> Index Scan using pg_index_indrelid_index on pg_catalog.pg_index (cost=0.29..686.80 rows=7186 width=4) (actual time=0.010..5.221 rows=7232 loops=1)
Output: pg_index.indexrelid, pg_index.indrelid, pg_index.indnatts, pg_index.indnkeyatts, pg_index.indisunique, pg_index.indisprimary, pg_index.indisexclusion, pg_index.indimmediate, pg_index.indisclustered, pg_index.indisvalid, pg_index.indcheckxmin, pg_index.indisready, pg_index.indislive, pg_index.indisreplident, pg_index.indkey, pg_index.indcollation, pg_index.indclass, pg_index.indoption, pg_index.indexprs, pg_index.indpred
Filter: pg_index.indisunique
Rows Removed by Filter: 7047
Buffers: shared hit=4358",,,,,,,,,"psql","client backend",,0
2.通过LOAD 'auto_explain' ;
这个只在当前SESSION生效，不需要重启数据库, 需要超级用户权限。
首先先恢复postgresql.conf的配置，去除前面的配置.然后重启数据库.
普通用户不允许加载auto_explain模块.(普通用户只允许加载$libdir/plugins目录下的模块,但是auto_explain即使拷贝到这个目录也不行)
load 'auto_explain';
set auto_explain.log_analyze =on;
set auto_explain.log_buffers =on;
set auto_explain.log_min_duration =0;
set auto_explain.log_nested_statements =on;
set auto_explain.log_timing =on;
set auto_explain.log_verbose =on;
set client_min_messages ='log';
create or replace procedure sqltest()
as
v_sql varchar2(4000);
BEGIN
v_sql:='create table sqltest_tab as SELECT count(*)FROM pg_class, pg_index WHERE oid = indrelid AND indisunique;';
execute immediate v_sql;
END;
/
call sqltest();
日志输出
statement: create or replace procedure sqltest()
as
v_sql varchar2(4000);
BEGIN
v_sql:='create table sqltest_tab as SELECT count(*)FROM pg_class, pg_index WHERE oid = indrelid AND indisunique;';
execute immediate v_sql;
END;
",,,,,,,,,"psql","client backend",,0
duration: 48.129 ms plan:
Query Text: create table sqltest_tab as SELECT count(*)FROM pg_class, pg_index WHERE oid = indrelid AND indisunique;
Aggregate (cost=1508.13..1508.14 rows=1 width=8) (actual time=25.162..25.166 rows=1 loops=1)
Output: count(*)
Buffers: shared hit=4723
-> Merge Join (cost=0.84..1490.16 rows=7186 width=0) (actual time=0.204..24.009 rows=7232 loops=1)
Merge Cond: (pg_class.oid = pg_index.indrelid)
Buffers: shared hit=4723
-> Index Only Scan using pg_class_oid_index on pg_catalog.pg_class (cost=0.29..681.64 rows=27530 width=4) (actual time=0.083..6.663 rows=27596 loops=1)
Output: pg_class.oid
Heap Fetches: 661
Buffers: shared hit=365
-> Index Scan using pg_index_indrelid_index on pg_catalog.pg_index (cost=0.29..686.80 rows=7186 width=4) (actual time=0.105..9.528 rows=7232 loops=1)
Output: pg_index.indexrelid, pg_index.indrelid, pg_index.indnatts, pg_index.indnkeyatts, pg_index.indisunique, pg_index.indisprimary, pg_index.indisexclusion, pg_index.indimmediate, pg_index.indisclustered, pg_index.indisvalid, pg_index.indcheckxmin, pg_index.indisready, pg_index.indislive, pg_index.indisreplident, pg_index.indkey, pg_index.indcollation, pg_index.indclass, pg_index.indoption, pg_index.indexprs, pg_index.indpred
Filter: pg_index.indisunique
Rows Removed by Filter: 7047
Buffers: shared hit=4358",,,,,"SQL statement ""create table sqltest_tab as SELECT count(*)FROM pg_class, pg_index WHERE oid = indrelid AND indisunique;""
PL/oraSQL function sqltest() line 5 at EXECUTE",,,,"psql","client backend",,0
