DBE_PROFILER

plprofiler提供了一个接口，用于分析存储过程的应用程序，可以收集、存储以及删除执行存储过程所涉及的相关数据。

概述

在PL/SQL函数和存储过程中查找性能问题可能会很困难。在系统或扩展视图中唯一可见的是从客户端发送的查询。在调用存储过程的情况下，这只是最外层的存储过程调用。plprofiler扩展可用于快速识别最耗时的存储过程，然后向下查看其中的单个语句耗时情况。

使用此工具，可以在会话中先创建存储过程及相关表信息，然后调用plprofiler接口对存储过程进行profiling，再执行存储过程，此时存储过程分析数据已生成。可以通过查询系统表去获取数据。表5 DBE_PROFILER.PL_PROFILING_FUNCTIONS可以查看此次profiling涉及的存储过程。表6 DBE_PROFILER.PL_PROFILING_DETAILS查看存储过程内每条语句的执行时间细节。表7 DBE_PROFILER.PL_PROFILING_CALLGRAPH查看调用栈信息和对应每个存储过程执行的整体时间。表8 DBE_PROFILER.PL_PROFILING_TRACKINFO查看存储过程每个阶段的执行时间。可以通过接口DBE_PROFILER.PL_CLEAR_PROFILING去删除某次或所有profiling后储存在系统表里的数据。

dbe_profiler工具的原理是在执行pl_start_profiling后，系统会初始化内存以准备记录数据，然后对后续执行的存储过程进行打桩，在关键点记录详细信息，并将这些信息记录在内存中，等待事务提交之后才会将内存中的数据写入四张系统表。在事务中执行dbe_profiler工具时须注意，在事务执行阶段，由于事务未提交，所以内存中的数据不会写入系统表中，只有在执行commit后才会将数据写入系统表。同理，执行rollback后，会将所有数据进行清理。

权限介绍

DBE_PROFILER.PL_PROFILING_FUNCTIONS、 DBE_PROFILER.PL_PROFILING_DETAILS、DBE_PROFILER.PL_PROFILING_CALLGRAPH、DBE_PROFILER.PL_PROFILING_TRACKINFO表普通用户可以访问，仅具有查询记录权限。

包含的接口和系统表

高级功能包DBE_PROFILER支持的所有接口请参见表1 DBE_PROFILER。

表1 DBE_PROFILER
接口名称	描述
DBE_PROFILER.PL_START_PLPROFILING	允许用户对目标存储过程进行profiling。
DBE_PROFILER.PL_CLEAR_PROFILING	删除某次或所有profiling后储存在系统表里的数据。

DBE_PROFILER.PL_START_PLPROFILING

允许用户对目标存储过程进行profiling。DBE_PROFILER.PL_START_PLPROFILING函数原型为：

      
           DBE_PROFILER.PL_START_PLPROFILING (run_id varchar2(64)) return void;

表2 DBE_PROFILER.PL_START_PLPROFILING接口参数说明
参数	描述
run_id	表示此次profiling的执行编号，系统会将用户的session_id和执行编号拼接为形如sessionid_runid的字符串写入表中，作为本次profiling的唯一标识。

DBE_PROFILER.PL_CLEAR_PROFILING

删除某次或所有profiling后储存在系统表里的数据。DBE_PROFILER.PL_CLEAR_PROFILING函数原型为：

      
           DBE_PROFILER.PL_CLEAR_PROFILING (run_id varchar2) return void;

表3 DBE_PROFILER.PL_CLEAR_PROFILING接口参数说明
参数	描述
run_id	非空值时，表示删除某次profiling数据的唯一标识；为空值时，表示删除所有profiling后的数据。

执行存储过程生成的分析数据存储在数据库系统表里，相关表信息如下所示：

表4 表总览
表名
表5 DBE_PROFILER.PL_PROFILING_FUNCTIONS
表6 DBE_PROFILER.PL_PROFILING_DETAILS
表7 DBE_PROFILER.PL_PROFILING_CALLGRAPH
表8 DBE_PROFILER.PL_PROFILING_TRACKINFO

DBE_PROFILER.PL_PROFILING_FUNCTIONS表信息如下

表5 DBE_PROFILER.PL_PROFILING_FUNCTIONS
列	类型	描述
run_id	VARCHAR2(80) NOT NULL	由session_id和执行编号拼接而成的唯一标识
funcoid	BIGINT NOT NULL	存储过程id
schema	TEXT NOT NULL	模式名称
funcname	TEXT NOT NULL	存储过程的名称
total_occur	BIGINT	存储过程执行的总次数
total_time	BIGINT	存储过程执行的总时间

DBE_PROFILER.PL_PROFILING_DETAILS表信息如下

表6 DBE_PROFILER.PL_PROFILING_DETAILS
列	类型	描述
run_id	VARCHAR2(80) NOT NULL	由session_id和执行编号拼接而成的唯一标识
funcoid	BIGINT NOT NULL	存储过程id
line#	INTEGER NOT NULL	行号
source	TEXT	存储过程执行语句
cmd_type	TEXT	语句类型
total_occur	BIGINT	语句的执行次数
total_time	BIGINT	语句的总执行时间
min_time	BIGINT	语句的最短执行时间
max_time	BIGINT	语句的最长执行时间

DBE_PROFILER.PL_PROFILING_CALLGRAPH表信息如下

表7 DBE_PROFILER.PL_PROFILING_CALLGRAPH
列	类型	描述
run_id	varchar2(80) NOT NULL	由session_id和执行编号拼接而成的唯一标识
stack	text[] NOT NULL	调用栈
self_time	bigint	存储过程执行时间

DBE_PROFILER.PL_PROFILING_TRACKINFO表信息如下

表8 DBE_PROFILER.PL_PROFILING_TRACKINFO
列	类型	描述
run_id	VARCHAR2(80) NOT NULL	由session_id和执行编号拼接而成的唯一标识
funcoid	BIGINT NOT NULL	存储过程id
step_name	TEXT NOT NULL	执行阶段名称
loops_count	INTEGER	执行阶段的总次数
max_time	BIGINT	执行阶段的最长执行时间
min_time	BIGINT	执行阶段的最短执行时间
avg_time	BIGINT	执行阶段的平均执行时间
total_time	BIGINT	执行阶段的总执行时间

约束

dbe_profiler.pl_start_profiling不支持在存储过程内使用，在存储过程内调用不生效。
dbe_profiler.pl_start_profiling不支持事务失败记录统计信息到系统表。
dbe_profiler.pl_start_profiling入参runid长度限制为64，超长将会报错。
dbe_profiler.pl_start_profiling入参如果和profiler系统表内的runid重复将会报错。
plprofiler不支持匿名块语句、PACKAGE的初始化语句和嵌套子程序内的语句。
自治事务的提交和回滚不会影响主事务已提交的数据，因此plprofiler暂不支持记录包含自治事务的存储过程的信息。

示例

    
     
       
       
         --step1 创建表和存储过程
gaussdb=# DROP TABLE IF EXISTS t1;
gaussdb=# CREATE TABLE t1 (i int);
gaussdb=# CREATE OR REPLACE PROCEDURE p1() AS
	sql_stmt varchar2(200);
	result number;
BEGIN
    for i in 1..1000 loop
      insert into t1 values(1);
    end loop;
    sql_stmt := 'select count(*) from t1';
    EXECUTE IMMEDIATE sql_stmt into result;
END;
/
gaussdb=# CREATE OR REPLACE PROCEDURE p2() AS
BEGIN
   p1();
END;
/
gaussdb=# CREATE OR REPLACE PROCEDURE p3() AS
BEGIN
    p2();
END;
/

--step2 调用plprofiler接口对存储过程进行profiling
gaussdb=# SELECT dbe_profiler.pl_start_profiling('123');
gaussdb=# CALL p3();

--step3 查询相关profiling信息
--查询dbe_profiler.pl_profiling_functions表查看此次profiling涉及的存储过程
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions ORDER BY run_id, funcoid;
       run_id        | funcoid | schema | funcname | total_occur | total_time 
---------------------+---------+--------+----------+-------------+------------
 140300887521024_123 |   16770 | public | p1()     |           1 |      54217
 140300887521024_123 |   16771 | public | p2()     |           1 |      54941
 140300887521024_123 |   16772 | public | p3()     |           1 |      55758
(3 rows)
--查询dbe_profiler.pl_profiling_details表查看存过内每条语句的执行时间细节
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_details WHERE funcoid = 16770 ORDER BY run_id, funcoid, line#;
       run_id        | funcoid | line# |                   source                    |  cmd_type  | total_occur | total_time | max_time | min_time 
---------------------+---------+-------+---------------------------------------------+------------+-------------+------------+----------+----------
 140300887521024_123 |   16770 |     1 |  DECLARE                                    |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     2 | sql_stmt varchar2(200);                     |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     3 | result number;                              |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     4 | begin                                       |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     5 |     for i in 1..1000 loop                   | FORI       |           1 |      52496 |    52496 |    52496
 140300887521024_123 |   16770 |     6 |       insert into t1 values(1);             | EXECSQL    |        1000 |      51970 |     2115 |       47
 140300887521024_123 |   16770 |     7 |     end loop;                               |            |           0 |          0 |        0 |        0
 140300887521024_123 |   16770 |     8 |     sql_stmt := 'select count(*) from t1';  | ASSIGN     |           1 |        446 |      446 |      446
 140300887521024_123 |   16770 |     9 |     EXECUTE IMMEDIATE sql_stmt into result; | DYNEXECUTE |           1 |       1271 |     1271 |     1271
 140300887521024_123 |   16770 |    10 | end                                         |            |           0 |          0 |        0 |        0
(10 rows)
--查询dbe_profiler.pl_profiling_callgraph表查看调用栈信息和对应每个存过执行的整体时间（total_time、self_time对应调用栈栈顶存储过程的总时间和自身执行时间）
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_callgraph ORDER BY run_id, stack;
       run_id        |                                   stack                                   | self_time 
---------------------+---------------------------------------------------------------------------+-----------
 140300887521024_123 | {"public.p3() oid=16772"}                                                 |       817
 140300887521024_123 | {"public.p3() oid=16772","public.p2() oid=16771"}                         |       724
 140300887521024_123 | {"public.p3() oid=16772","public.p2() oid=16771","public.p1() oid=16770"} |     54217
(3 rows)
--查询dbe_profiler.pl_profiling_trackinfo表查看存储过程每个阶段的执行时间
gaussdb=# SELECT step_name, loops_count FROM dbe_profiler.pl_profiling_trackinfo WHERE funcoid=16770;
  step_name   | loops_count 
--------------+-------------
 init         |           1
 package      |           1
 spictx       |           1
 compile      |           1
 exec_context |           1
 execute      |           1
 exec_cursor  |           1
 cleanup      |           1
 finsh        |           1
(9 rows)

--step4 删除系统表数据
gaussdb=# SELECT dbe_profiler.pl_clear_profiling('');
gaussdb=# SELECT step_name, loops_count FROM dbe_profiler.pl_profiling_trackinfo WHERE funcoid=16770;
 step_name | loops_count 
-----------+-------------
(0 rows)
gaussdb=# DROP TABLE t1;

--step5 profiling包含自治事务的存储过程。
--建表
gaussdb=# CREATE TABLE t2(a int, b int);
--创建包含自治事务的存储过程
gaussdb=# CREATE OR REPLACE PROCEDURE autonomous(a int, b int)  AS 
DECLARE 
	num3 int := a;
	num4 int := b;
	PRAGMA AUTONOMOUS_TRANSACTION;
BEGIN
	insert into t2 values(num3, num4); 
	dbe_output.print_line('just use call.');
END;
/
--创建调用自治事务存储过程的普通存储过程
gaussdb=# CREATE OR REPLACE PROCEDURE autonomous_1(a int, b int)  AS 
DECLARE 
BEGIN
	dbe_output.print_line('just no use call.');
	insert into t2 values(666, 666);
	autonomous(a,b);
END;
/
gaussdb=# SELECT dbe_profiler.pl_start_profiling ('100');
gaussdb=# CALL autonomous(11,22);
--查询表信息
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions ORDER BY run_id, funcoid;
 run_id | funcoid | schema | funcname | total_occur | total_time 
--------+---------+--------+----------+-------------+------------
(0 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_details ORDER BY run_id, funcoid, line#;
 run_id | funcoid | line# | source | cmd_type | total_occur | total_time | max_time | min_time 
--------+---------+-------+--------+----------+-------------+------------+----------+----------
(0 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_callgraph ORDER BY run_id, stack;
 run_id | stack | self_time 
--------+-------+-----------
(0 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_trackinfo ORDER BY run_id, funcoid;
 run_id | funcoid | step_name | loops_count | max_time | min_time | avg_time | total_time 
--------+---------+-----------+-------------+----------+----------+----------+------------
(0 rows)

gaussdb=# SELECT dbe_profiler.pl_start_profiling ('101');
gaussdb=# CALL autonomous_1(11,22);
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions ORDER BY run_id, funcoid;
       run_id        | funcoid |   schema   |    funcname    | total_occur | total_time 
---------------------+---------+------------+----------------+-------------+------------
 140421237831424_101 |   10422 | dbe_output | print_line()   |           1 |        758
 140421237831424_101 |   16771 | public     | autonomous_1() |           1 |      23855
(2 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_details ORDER BY run_id, funcoid, line#;
       run_id        | funcoid | line# |                   source                    | cmd_type | total_occur | total_time | max_time | min_time 
---------------------+---------+-------+---------------------------------------------+----------+-------------+------------+----------+----------
 140421237831424_101 |   10422 |     1 |                                             |          |           0 |          0 |        0 |        0
 140421237831424_101 |   10422 |     2 | BEGIN                                       |          |           0 |          0 |        0 |        0
 140421237831424_101 |   10422 |     3 |     PKG_UTIL.io_print(format, true);        | PERFORM  |           1 |        754 |      754 |      754
 140421237831424_101 |   10422 |     4 | END;                                        |          |           0 |          0 |        0 |        0
 140421237831424_101 |   10422 |     5 |                                             |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     1 |                                             |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     2 | DECLARE                                     |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     3 | BEGIN                                       |          |           0 |          0 |        0 |        0
 140421237831424_101 |   16771 |     4 | dbe_output.print_line('just no use call.'); | PERFORM  |           1 |       2435 |     2435 |     2435
 140421237831424_101 |   16771 |     5 | insert into t2 values(666, 666);            | EXECSQL  |           1 |        602 |      602 |      602
 140421237831424_101 |   16771 |     6 | autonomous(a,b);                            | PERFORM  |           1 |      20813 |    20813 |    20813
 140421237831424_101 |   16771 |     7 | END                                         |          |           0 |          0 |        0 |        0
(12 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_callgraph ORDER BY run_id, stack;
       run_id        |                                  stack                                  | self_time 
---------------------+-------------------------------------------------------------------------+-----------
 140421237831424_101 | {"public.autonomous_1() oid=16771"}                                     |     23097
 140421237831424_101 | {"public.autonomous_1() oid=16771","dbe_output.print_line() oid=10422"} |       758
(2 rows)

gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_trackinfo ORDER BY run_id, funcoid;
       run_id        | funcoid |  step_name   | loops_count | max_time | min_time | avg_time | total_time 
---------------------+---------+--------------+-------------+----------+----------+----------+------------
 140421237831424_101 |   10422 | init         |           1 |        0 |        0 |        0 |          0
 140421237831424_101 |   10422 | package      |           1 |        9 |        9 |        9 |          9
 140421237831424_101 |   10422 | spictx       |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   10422 | compile      |           1 |      383 |      383 |      383 |        383
 140421237831424_101 |   10422 | exec_context |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   10422 | execute      |           1 |     1301 |     1301 |     1301 |       1301
 140421237831424_101 |   10422 | exec_cursor  |           1 |        3 |        3 |        3 |          3
 140421237831424_101 |   10422 | cleanup      |           1 |       11 |       11 |       11 |         11
 140421237831424_101 |   10422 | finsh        |           1 |        0 |        0 |        0 |          0
 140421237831424_101 |   16771 | init         |           1 |        0 |        0 |        0 |          0
 140421237831424_101 |   16771 | package      |           1 |      103 |      103 |      103 |        103
 140421237831424_101 |   16771 | spictx       |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   16771 | compile      |           1 |     1869 |     1869 |     1869 |       1869
 140421237831424_101 |   16771 | exec_context |           1 |        3 |        3 |        3 |          3
 140421237831424_101 |   16771 | execute      |           1 |    24011 |    24011 |    24011 |      24011
 140421237831424_101 |   16771 | exec_cursor  |           1 |        1 |        1 |        1 |          1
 140421237831424_101 |   16771 | cleanup      |           1 |       16 |       16 |       16 |         16
 140421237831424_101 |   16771 | finsh        |           1 |        1 |        1 |        1 |          1
(18 rows)

gaussdb=# SELECT dbe_profiler.pl_clear_profiling('');
gaussdb=# SELECT * FROM dbe_profiler.pl_profiling_functions;
 run_id | funcoid | schema | funcname | total_occur | total_time 
--------+---------+--------+----------+-------------+------------
(0 rows)

gaussdb=# DROP TABLE t2;

        

      

    
   