526互联

KingbaseES 查看函数中最耗时的sql

发布时间 2023-09-19 18:46:05作者: KINGBASE研究院

测试

创建测试环境所需表及函数

create table test1(id int);
INSERT INTO test1(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_func() returns bigint
as $$
select count(*) from test1;
select count(*) from test2;
select count(*) from test1,test2;
$$
language sql;

\timing on 

TEST=# select  test_func();
 test_func
-----------
 100000000
(1 row)

Time: 4313.282 ms (00:04.313)

在函数执行期间，可以查看函数运行情况

TEST=# 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';
  pid  | usename |                     substring                     |             time              | wait_event_type | wait_event
-------+---------+---------------------------------------------------+-------------------------------+-----------------+------------
  6209 | system  | select pid,usename,substring(query from 0 for 50) | +000000000 00:00:00.000000000 |                 |
 10351 | system  | select  test_func();                              | +000000000 00:00:02.713997000 |                 |
(2 rows)

使用auto_explain显示每个SQL执行计划

加载auto_explain插件
shared_preload_libraries = 'auto_explain'

对于业务非常大的库，不适合全局抓取SQL，可以在客户端开启参数。
设置以下参数，将log_nested_statements = true，展示函数内所有SQL执行计划，当它关闭时，只记录最外层语句的计划，默认值为off

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;

以下测试过程,可查看函数中的sql执行时间和执行计划

TEST=# select test_func();
-------------  SQL 1执行时间
LOG:  duration: 1.825 ms  plan:
Query Text:
select count(*) from test1;
select count(*) from test2;
select count(*) from test1,test2;

Aggregate  (cost=170.00..170.01 rows=1 width=8) (actual time=1.823..1.823 rows=1 loops=1)
  Output: count(*)
  Buffers: shared read=45
  ->  Seq Scan on public.test1  (cost=0.00..145.00 rows=10000 width=0) (actual time=0.019..1.058 rows=10000 loops=1)
        Output: id
        Buffers: shared read=45

-------------  SQL 2执行时间
LOG:  duration: 1.876 ms  plan:
Query Text:
select count(*) from test1;
select count(*) from test2;
select count(*) from test1,test2;

Aggregate  (cost=170.00..170.01 rows=1 width=8) (actual time=1.873..1.874 rows=1 loops=1)
  Output: count(*)
  Buffers: shared read=45
  ->  Seq Scan on public.test2  (cost=0.00..145.00 rows=10000 width=0) (actual time=0.016..1.124 rows=10000 loops=1)
        Output: id
        Buffers: shared read=45

-------------  SQL 3执行时间（可以看到占比最大）
LOG:  duration: 27710.539 ms  plan:
Query Text:
select count(*) from test1;
select count(*) from test2;
select count(*) from test1,test2;

Aggregate  (cost=1500315.00..1500315.01 rows=1 width=8) (actual time=27710.531..27710.533 rows=1 loops=1)
  Output: count(*)
  Buffers: shared hit=90
  ->  Nested Loop  (cost=0.00..1250315.00 rows=100000000 width=0) (actual time=0.015..19808.482 rows=100000000 loops=1)
        Buffers: shared hit=90
        ->  Seq Scan on public.test1  (cost=0.00..145.00 rows=10000 width=0) (actual time=0.007..5.299 rows=10000 loops=1)
              Output: test1.id
              Buffers: shared hit=45
        ->  Materialize  (cost=0.00..195.00 rows=10000 width=0) (actual time=0.000..0.685 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.004..0.939 rows=10000 loops=1)
                    Buffers: shared hit=45

-------------  总执行时间
LOG:  duration: 27714.881 ms  plan:
Query Text: select test_func();
Result  (cost=0.00..0.26 rows=1 width=8) (actual time=27714.874..27714.875 rows=1 loops=1)
  Output: test_func()
  Buffers: shared hit=157 read=96
 test_func
-----------
 100000000
(1 row)

使用sys_stat_statements_all视图查看函数中select语句耗时

set sys_stat_statements.track="all";
select test_func();
TEST=# select userid::regrole,total_exec_time,query from sys_stat_statements_all order by total_exec_time desc;
 userid |  total_exec_time   |                                                  query

--------+--------------------+-----------------------------------------------------------------------------------------------
----------
 system |        4151.922228 | select test_func()
 system | 4150.4398550000005 | select count(*) from test1,test2
 system |           0.569574 | select count(*) from test1
 system |           0.510945 | select count(*) from test2
 system |           0.108768 | select userid::regrole,total_exec_time,query from sys_stat_statements order by total_exec_time
 desc
 system |                  0 | select userid::regrole,total_exec_time,query from sys_stat_statements_all order by total_exec_
time desc
(6 rows)

使用plprofiler插件也可查看函数内执行时间，内容请参考博客园文档《plprofiler》
https://www.cnblogs.com/kingbase/p/15477503.html