更新时间:2024-11-12 GMT+08:00
分享

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函数原型为:

    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表信息如下
    表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暂不支持记录包含自治事务的存储过程的信息。

示例

  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;

相关文档