# 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]。 表1DBE_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; ``` 表2DBE_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; ``` 表3DBE_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表信息如下 表5DBE_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表信息如下 表6DBE_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表信息如下 表7DBE_PROFILER.PL_PROFILING_CALLGRAPH | 列 | 类型 | 描述 | |:---|:---|:---| | run_id | varchar2(80) NOT NULL | 由session_id和执行编号拼接而成的唯一标识 | | stack | text\[\] NOT NULL | 调用栈 | | self_time | bigint | 存储过程执行时间 | - DBE_PROFILER.PL_PROFILING_TRACKINFO表信息如下 表8DBE_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; ```