合 PG中如何获取函数中正在执行的真实SQL语句(定位存储过程中最耗时部分)
Tags： PGPostgreSQL存储过程慢SQL函数正在执行SQL语句
👉 本文共约3787个字，系统预计阅读时间或需15分钟。
目录
- 一、 问题背景
- 二、 方法汇总及对比
- 三、 直接分析函数代码
- 四、 raise notice打标记
- 五、 auto_explain显示每个SQL执行计划
- 六、 设置pg_stat_statements.track=all
- 七、 使用plprofiler插件
- 一、 plProfiler插件简介
- 二、 plProfiler插件安装
- 1. 安装准备
- 2. plprofiler下载及安装
- 3. 数据库中创建插件
- 三、 plProfiler插件测试
- 1. 测试案例准备
- 2. 密码配置
- 3. plprofiler调用函数
- 4. 报表展示
- 四、 常见报错处理
- 1. 编译报错
- 2. plprofiler客户端安装报错
- 3. plprofiler命令执行报错
- 4. plprofiler无法识别到
- 5. plprofiler要求输入用户密码
- 6. plprofiler输出报表为空
- 参考
一、 问题背景
开发反馈PG中某函数执行时间很长，超过30分钟，想看看慢在其中哪一段SQL。但是如果直接通过pg_stat_activity查询，只能看到上层执行函数的语句，而不像oracle和SqlServer能看到当前在执行什么。咨询群友们得到了几种方法，下面测试和对比一下。
简单模拟如下：
1 2 3 4 5 6 7 8 9 10 11 12 13 | create table test(id int); INSERT INTO test(id) VALUES (generate_series(1, 10000)); create table test2(id int); INSERT INTO test2(id) VALUES (generate_series(1, 10000)); create or replace function test_f() returns int as $$ select count(*) from test; select count(*) from test2; select count(*) from test,test2; $$ language sql; |
执行函数
查看运行情况
1 2 | select pid,usename,substring(query from 0 for 50),now()-query_start as time,wait_event_type,wait_event from pg_stat_activity where state = 'active'; |
二、 方法汇总及对比
三、 直接分析函数代码
\sf 函数名 可以查看函数代码，这适用于函数非常简单的场景，例如我们的例子
如果函数中SQL很长，输出可能会错行，不方便分析，可以用psql将其导出成文本。
1 | psql -c "\sf test_f" > test_f.sql |
四、 raise notice打标记
注意raise要用plpgsql语言，像上面用sql会报错，为方便测试稍微做点改造。
1 2 3 4 5 6 7 8 9 10 11 12 13 | CREATE OR REPLACE FUNCTION test_f_2() RETURNS integer AS $$ declare num int; BEGIN raise notice 'notice 1, start at: %',clock_timestamp(); insert into test select count(*) from test; raise notice 'notice 2, start at: %',clock_timestamp(); select count(*) into num from test,test2; raise notice 'notice 3, start at: %',clock_timestamp(); insert into test2 select count(*) from test2; return num; END; $$ LANGUAGE plpgsql; |
输出如下
五、 auto_explain显示每个SQL执行计划
对于业务量大的库，不适合全局抓取SQL，可以在客户端开启。设置以下参数，核心是log_nested_statements = true，展示函数内所有SQL执行计划。
1 2 3 4 5 6 7 | LOAD '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; |
效果如下
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 | postgres=# select test_f(); ------------- SQL 1执行时间 LOG: duration: 3.000 ms plan: Query Text: select count(*) from test; select count(*) from test2; select count(*) from test,test2; Aggregate (cost=170.00..170.01 rows=1 width=8) (actual time=2.998..2.999 rows=1 loops=1) Output: count(*) Buffers: shared hit=45 -> Seq Scan on public.test (cost=0.00..145.00 rows=10000 width=0) (actual time=0.007..1.506 rows=10000 loops=1) Output: id Buffers: shared hit=45 ------------- SQL 2执行时间 LOG: duration: 2.924 ms plan: Query Text: select count(*) from test; select count(*) from test2; select count(*) from test,test2; Aggregate (cost=170.00..170.01 rows=1 width=8) (actual time=2.923..2.923 rows=1 loops=1) Output: count(*) Buffers: shared hit=45 -> Seq Scan on public.test2 (cost=0.00..145.00 rows=10000 width=0) (actual time=0.007..1.450 rows=10000 loops=1) Output: id Buffers: shared hit=45 ------------- SQL 3执行时间（可以看到占比最大） LOG: duration: 48553.037 ms plan: Query Text: select count(*) from test; select count(*) from test2; select count(*) from test,test2; Aggregate (cost=1500315.00..1500315.01 rows=1 width=4) (actual time=48553.031..48553.033 rows=1 loops=1) Output: count(*) Buffers: shared hit=90 -> Nested Loop (cost=0.00..1250315.00 rows=100000000 width=0) (actual time=0.013..33346.371 rows=100000000 loops=1) Buffers: shared hit=90 -> Seq Scan on public.test (cost=0.00..145.00 rows=10000 width=0) (actual time=0.006..19.550 rows=10000 loops=1) Output: test.id Buffers: shared hit=45 -> Materialize (cost=0.00..195.00 rows=10000 width=0) (actual time=0.000..1.126 rows=10000 loops=10000) Buffers: shared hit=45 -> Seq Scan on public.test2 (cost=0.00..145.00 rows=10000 width=0) (actual time=0.005..1.944 rows=10000 loops=1) Buffers: shared hit=45 ------------- 总执行时间 LOG: duration: 48559.722 ms plan: Query Text: select test_f(); Result (cost=0.00..0.26 rows=1 width=4) (actual time=48559.714..48559.715 rows=1 loops=1) Output: test_f() Buffers: shared hit=180 test_f ----------- 100000000 (1 row) |
本人提供Oracle(OCP、OCM)、MySQL(OCP)、PostgreSQL(PGCA、PGCE、PGCM)等数据库的培训和考证业务，私聊QQ646634621或微信dbaup66，谢谢！
