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。
接口名称 |
描述 |
---|---|
DBE_PROFILER.PL_START_PLPROFILING |
允许用户对目标存储过程进行profiling。 |
DBE_PROFILER.PL_CLEAR_PROFILING |
删除某次或所有profiling后储存在系统表里的数据。 |
- DBE_PROFILER.PL_START_PLPROFILING
允许用户对目标存储过程进行profiling。DBE_PROFILER.PL_START_PLPROFILING函数原型为:
1
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函数原型为:
1
DBE_PROFILER.PL_CLEAR_PROFILING (run_id varchar2) return void;
表3 DBE_PROFILER.PL_CLEAR_PROFILING接口参数说明 参数
描述
run_id
非空值时,表示删除某次profiling数据的唯一标识;为空值时,表示删除所有profiling后的数据。
执行存储过程生成的分析数据存储在数据库系统表里,相关表信息如下所示:
表名 |
---|
- DBE_PROFILER.PL_PROFILING_FUNCTIONS表信息如下
- 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表信息如下
- 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暂不支持记录包含自治事务的存储过程的信息。
示例
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 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 |
--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; |