合 PG中如何获取函数中正在执行的真实SQL语句(定位存储过程中最耗时部分)

发布日期 2023年4月28日 · 已更新 2023年4月28日

0 161 1

Tags： PG PostgreSQL 存储过程慢SQL 函数正在执行 SQL语句

👉 本文共约3769个字，系统预计阅读时间或需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能看到当前在执行什么。咨询群友们得到了几种方法，下面测试和对比一下。
简单模拟如下：

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;

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;

执行函数

查看运行情况

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';

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将其导出成文本。

psql -c "\sf test_f" > test_f.sql

1	psql -c "\sf test_f" > test_f.sql

四、 raise notice打标记

注意raise要用plpgsql语言，像上面用sql会报错，为方便测试稍微做点改造。

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;

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执行计划。

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;

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;

效果如下

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)

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，谢谢！

后续精彩内容已被站长无情隐藏，请输入验证码解锁本文！

获取验证码：请先关注本站微信公众号，然后回复“验证码”，获取验证码。在微信里搜索“AiDBA”或者“dbaup6”或者微信扫描右侧二维码都可以关注本站微信公众号。

打赏赞(1)

标签： PG PostgreSQL 存储过程慢SQL 函数正在执行 SQL语句

小麦苗

学习或考证，均可联系麦老师，请加微信db_bao或QQ646634621

发表回复取消回复

要发表评论，您必须先登录。

1、声明：本网站有部分文章整合或转载自网络，文章著作权归属原作者或原团队；若有侵权，深表歉意，请联系本站站长进行处理，谢谢！！！
2、本站提供数据库的培训和考证业务，培训包含但不限于Oracle、MySQL、PostgreSQL、SQL Server、国产数据库等，考证包括但不限于Oracle OCP、Oracle OCM、MySQL OCP、PGCA、PGCE、PGCM等，私聊QQ646634621或微信dbaup66，非诚勿扰，谢谢！！！
3、麦老师新建了《西安DBA数据架构师》微信群，有志同道合的朋友可以私聊我入群，我们一起聊技术，聊生活，空了可以喝酒约饭。
4、为了方便大家更有针对性的讨论学习数据库，故新建数据库分类群，包括Oracle群、MySQL群、SQL Server群、PG&GP群、国产&信创群。志同道合的朋友可以入群聊技术聊人生，捣乱的勿进，喷子勿进，极端人士勿进，谢谢。

合 PG中如何获取函数中正在执行的真实SQL语句(定位存储过程中最耗时部分)

一、问题背景

二、方法汇总及对比

三、直接分析函数代码

四、 raise notice打标记

五、 auto_explain显示每个SQL执行计划

相关文章

您可能还喜欢...

发表回复取消回复

网站公告

网站寄语

本站其它工具

搜索本网站

标签云☁

网站日历

网站归档

网站分类

2024 年 11 月
一	二	三	四	五	六	日
				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

合 PG中如何获取函数中正在执行的真实SQL语句(定位存储过程中最耗时部分)

一、 问题背景

二、 方法汇总及对比

三、 直接分析函数代码

四、 raise notice打标记

五、 auto_explain显示每个SQL执行计划

相关文章

您可能还喜欢...

PG启用checksum数据块校验及pg_checksums、pg_verify_checksums命令

《PostgreSQL技术内幕——原理探索》第六章 清理过程（VACUUM）

PGCM培训考证

发表回复 取消回复

网站公告

网站寄语

本站其它工具

搜索本网站

标签云☁

网站日历

网站归档

网站分类

一、问题背景

二、方法汇总及对比

三、直接分析函数代码

《PostgreSQL技术内幕——原理探索》第六章清理过程（VACUUM）

发表回复取消回复