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

由小麦苗 · 发布日期 2023年4月28日 · 已更新 2023年4月28日

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

👉 本文共约3789个字，系统预计阅读时间或需15分钟。

一、问题背景

开发反馈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会报错，为方便测试稍微做点改造。

本人提供Oracle(OCP、OCM)、MySQL(OCP)、PostgreSQL(PGCA、PGCE、PGCM)等数据库的培训和考证业务，私聊QQ646634621或微信db_bao，谢谢！

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)

六、设置pg_stat_statements.track=all

基本上也只适合客户端开启，或者在测试环境reset后单独跑，比auto_explain更难找

set pg_stat_statements.track="all";
select test_f();
select userid::regrole,total_exec_time,query from pg_stat_statements order by total_exec_time desc;

set pg_stat_statements.track="all";

select test_f();

select userid::regrole,total_exec_time,query from pg_stat_statements order by total_exec_time desc;

七、使用plprofiler插件

一、 plProfiler插件简介

plProfiler插件使用C和python语言共同开发，可以收集PL/pgSQL语言（不支持SQL语言）的函数和存储过程的profile信息，并生成html报表。报表以火焰图形式展示函数调用堆栈、耗时占比，还可以查看函数中每个SQL的位置、执行次数、最长执行时间、总时间，清晰明了。
由于依赖于python环境，安装、排错较复杂，对python小白不友好。同时，它也并非旁路监控，必须要手动执行对应函数。

二、 plProfiler插件安装

1. 安装准备

python环境准备
通常Linux环境默认都自带python，不过要注意版本，python 3.2版本以下会在后面踩坑。如果没有的话网上搜索一下怎么安装即可。
pip安装
wget https://pypi.python.org/packages/11/b6/abcb525026a4be042b486df43905d6893fb04f05aac21c32c638e939e447/pip-9.0.1.tar.gz
1
wget https://pypi.python.org/packages/11/b6/abcb525026a4be042b486df43905d6893fb04f05aac21c32c638e939e447/pip-9.0.1.tar.gz
依赖包及python模块安装
yum install python-setuptools pip install configparser pip install html # python 3.2及以上版本 pip install cgi # python 3.2以下版本
1
2
3
4
yum install python-setuptools
pip install configparser
pip install html # python 3.2及以上版本
pip install cgi # python 3.2以下版本
2. plprofiler下载及安装
下载地址：GitHub - bigsql/plprofiler
解压安装包，必须放到源码/contrib 目录下，否则安装会报错
编译安装
cd contrib/plprofiler make install
1
2
cd contrib/plprofiler
make install
安装 plprofiler-client，即plprofiler命令
cd python-plprofiler python ./setup.py install
1
2
cd python-plprofiler
python ./setup.py install
安装psycopg2模块，用于连接pg数据库
pip install psycopg2-binary
1
pip install psycopg2-binary
测试安装情况，若有报错，安装对应模块
plprofiler --help
1
plprofiler --help
3. 数据库中创建插件
create extension plprofiler;
1
create extension plprofiler;
三、 plProfiler插件测试

1. 测试案例准备

安装包中有一个自带的案例

cd /root/postgresql-14.0/contrib/plprofiler/examples/
vi prepdb.sh
# 修改db名，其他不用动
PGDATABASE=postgres

cd /root/postgresql-14.0/contrib/plprofiler/examples/

vi prepdb.sh

# 修改db名，其他不用动

PGDATABASE=postgres

执行该脚本

./prepdb.sh

1	./prepdb.sh

2. 密码配置

出于安全考虑，plprofiler命令行不提供 --password参数，如果有用户密码，需要配置~/.pgpass文件，或者在pg_hba.conf中配置信任本ip（因为plprofiler只能如果--host ip方式访问，不能通过local方式访问）。
注意应该加在md5那行前面，因为 pg_hba.conf 是匹配到就停止的。

3. plprofiler调用函数

plprofiler run --host=192.168.1.108 --port=5432 --user=postgres --dbname=postgres --command "SELECT tpcb(1, 2, 3, -42)" --output tmp.html

1	plprofiler run --host=192.168.1.108 --port=5432 --user=postgres --dbname=postgres --command "SELECT tpcb(1, 2, 3, -42)" --output tmp.html

执行完会弹出以下报表配置内容，可以不改，直接保存退出

[current]
title = PL Profiler Report for current
tabstop = 8
svg_width = 1200
table_width = 80%
desc =
PL Profiler Report for current
4. 报表展示
打开生成的tmp.html文件，以火焰图的形式展示

点击show可以查看函数内部执行情况

总的来说格式是最清晰的，适合复杂函数的分析。
四、常见报错处理
安装和排错过程很坎坷，记录一下...
1. 编译报错
-bash-4.2$ make install
Makefile:26: ../../src/Makefile.global: No such file or directory
Makefile:27: /contrib/contrib-global.mk: No such file or directory
make: *** No rule to make target `/contrib/contrib-global.mk'. Stop.
解决方法：plprofiler 解压到源码/contrib 目录下
2. plprofiler客户端安装报错

报错1

[root@linux01 python-plprofiler]# python ./setup.py install
Traceback (most recent call last):
File "./setup.py", line 1, in
from setuptools import setup
ImportError: No module named setuptools
解决方法：yum install python-setuptools

报错2

[root@linux01 python-plprofiler]# python ./setup.py install
Couldn't find index page for 'configparser' (maybe misspelled?)
Scanning index of all packages (this may take a while)
Reading https://pypi.python.org/simple/
No local packages or download links found for configparser
error: Could not find suitable distribution for Requirement.parse('configparser')
解决方法：pip install configparser
3. plprofiler命令执行报错
[root@linux01 python-plprofiler]# plprofiler --help
Traceback (most recent call last):
...
File "/usr/lib/python2.7/site-packages/plprofiler_client-4.2-py2.7.egg/plprofiler/plprofiler_report.py", line 4, in
import html
ImportError: No module named html
解决方法：pip install html

4. plprofiler无法识别到

-bash-4.2$ plprofiler run --command="select test_f();" --output=test_f.html
could not connect to server: No such file or directory
Is the server running locally and accepting
connections on Unix domain socket "/var/run/postgresql/.s.PGSQL.5432"?
解决方法：加上连接信息
plprofiler run --host=192.168.1.108 --port=5432 --user=postgres --dbname=postgres --command="select test_f();" --output=test_f.html
5. plprofiler要求输入用户密码
plprofiler run --host=192.168.1.108 --port=5432 --user=postgres --dbname=postgres --command="select test_f();" --output=test_f.html
fe_sendauth: no password supplied
解决方法：配置~/.pgpass文件，或者在pg_hba.conf中配置信任本ip（参考前面）

6. plprofiler输出报表为空

报错1

plprofiler run --host=192.168.1.108 --port=5432 --user=postgres --dbname=postgres --command="select test_f();" --output=test_f.html
Traceback (most recent call last):
File "/usr/bin/plprofiler", line 9, in
...
File "/usr/lib/python2.7/site-packages/plprofiler_client-4.2-py2.7.egg/plprofiler/plprofiler.py", line 403, in get_local_report_data
raise Exception("No profiling data found")
Exception: No profiling data found
原因：test_f 函数为sql语言编写（language sql）
解决方法：plprofiler 仅支持 plpgsql语言（LANGUAGE plpgsql）

报错2

plprofiler run --host=192.168.1.108 --port=5432 --user=postgres --dbname=postgres --command "SELECT tpcb(1, 2, 3, -42)" --output tmp.html
"/tmp/tmpGWSbI3.tmp.conf" 10L, 182C written
Traceback (most recent call last):
...
File "/usr/lib/python2.7/site-packages/plprofiler_client-4.2-py2.7.egg/plprofiler/plprofiler_report.py", line 21, in generate
self.out("
%s" %(html.escape(config['title']), ))
AttributeError: 'module' object has no attribute 'escape'

原因：python版本过低（测试的版本为python 2.7），3.2及以上版本才可使用html.escape，旧版本使用cgi.escape
解决方法：修改报错的 /usr/lib/python2.7/site-packages/plprofiler_client-4.2-py2.7.egg/plprofiler/plprofiler_report.py 脚本，加入import cgi，并将html.escape替换为cgi.escape（共两处）

参考

https://blog.csdn.net/Hehuyi_In/article/details/102855303
https://blog.csdn.net/Hehuyi_In/article/details/105039110?spm=1001.2014.3001.5502
https://www.modb.pro/db/86040

打赏赞(1)

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

小麦苗

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

发表回复取消回复

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

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

AI (2)
ClickHouse (5)
DM达梦 (9)
Docker (34)
GBase (34)
Greenplum (85)
HANA (2)
K8S (14)
Kafka (3)
Memcached (2)
MongoDB (3)
MySQL (177)
NoSQL (3)
OceanBase (14)
OGG (43)
openGauss (9)
Oracle (590)
OS (329)
PostgreSQL (229)
Python (26)
Redis (18)
SQL Server (106)
SQLite (1)
StarRocks (9)
TDSQL (5)
TiDB (18)
YMatrix (5)
中间件 (9)
云 (10)
人大金仓KingBase (7)
其它 (78)
培训考证 (43)
大数据 (4)
存储 (4)
巡检监控 (43)
工具 (65)
数据迁移 (16)
架构篇 (9)
生活 (8)
电脑 (14)
网络 (78)
育儿 (5)
视频 (17)
面试笔试 (38)

嘿，我是小麦，需要帮助随时找我哦

18509239930
个人微信
麦老师QQ聊天
个人邮箱
点击加入QQ群
个人微店
回到顶部

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

一、 问题背景

二、 方法汇总及对比

三、 直接分析函数代码

四、 raise notice打标记

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

六、 设置pg_stat_statements.track=all

七、 使用plprofiler插件

一、 plProfiler插件简介

二、 plProfiler插件安装

1. 安装准备

2. plprofiler下载及安装

3. 数据库中创建插件

三、 plProfiler插件测试

1. 测试案例准备

2. 密码配置

3. plprofiler调用函数

PL Profiler Report for current

4. 报表展示

四、 常见报错处理

1. 编译报错

2. plprofiler客户端安装报错

3. plprofiler命令执行报错

4. plprofiler无法识别到

5. plprofiler要求输入用户密码

6. plprofiler输出报表为空

参考

相关文章

您可能还喜欢...

PG之临时表（TEMPORARY TABLE）

PG中的file_fdw、postgres_fdw和dblink

PG逻辑复制插件之pgl_ddl_deploy支持DDL复制

发表回复 取消回复

博客寄语

博客概况

本站其它工具

搜标题

搜索本网站

标签云☁

登陆本博客

博客日历

博客归档

博客分类

一、问题背景

二、方法汇总及对比

三、直接分析函数代码

六、设置pg_stat_statements.track=all

七、使用plprofiler插件

四、常见报错处理

发表回复取消回复