OceanBase 数据库 V4.2.3 及之后版本可以通过 DBMS_PROFILER 系统来进行存储过程内慢 SQL 的行级耗时性能定位。
OceanBase PL 执行可能存在潜在的性能问题，通常我们需要通过技术手段定位 PL 中的性能原因，再通过改写等手段规避或者优化。但是，在 OceanBase 数据库 V4.2.3 之前的版本中，定位 PL 性能问题的手段相对有限，大部分场景只能通过 GV$OB_SQL_AUDIT 视图确认 PL 和其内部 SQL 的执行时间差异来分析性能问题，对语法块（WHILE、FOR 等）和语句级别的执行时间缺乏有效诊断手段。
在某些业务跑批等场景下，通常是在循环语句中大量反复执行相同的 SQL 语句来完成业务统计或者更新。若触发 SQL AUDIT 视图淘汰机制，则导致无法有效记录完整的 PL 和 SQL 语句的执行时间，难以准确定位和解决性能瓶颈问题。因此，OceanBase 数据库引入了新的性能剖析机制（dbms_profiler），记录更细粒度的执行时间，准确收集每一行的执行时间，从而有效诊断 PL 运行时的性能问题。
详细说明
性能测试 PL
delimiter $$
CREATE OR REPLACE PROCEDURE do_something_3 (p_times IN NUMBER) AS
l_dummy NUMBER;
BEGIN
FOR i IN 1 .. p_times LOOP
SELECT l_dummy + 1
INTO l_dummy
FROM dual;
END LOOP;
END;
$$
delimiter $$
CREATE OR REPLACE PROCEDURE do_something_2 (p_times IN NUMBER) AS
BEGIN
FOR i IN 1 .. p_times LOOP
do_something_3(p_times => p_times);
END LOOP;
END;
$$
delimiter $$
CREATE OR REPLACE PROCEDURE do_something_1 (p_times IN NUMBER) AS
BEGIN
FOR i IN 1 .. p_times LOOP
do_something_2(p_times => p_times);
END LOOP;
END;
$$
delimiter ;
使用方式
启动剖析器
call DBMS_PROFILER.start_profiler(run_comment => 'zxtest_do_something: ' || SYSDATE);
关闭剖析器
call DBMS_PROFILER.stop_profiler();
查询每次启动的 runid 和时间、注释等信息
select * from plsql_profiler_runs;
查询每次执行中每个 PL 单元的信息
--runid为当前启动剖析器是分配的id。
select * from plsql_profiler_units where runid=17;
查询每次执行每行的耗时
select * from plsql_profiler_data where runid=17;
信息汇总
SELECT u.runid,
u.unit_number,
u.unit_type,
u.unit_owner,
u.unit_name,
d.line#,
d.total_occur,
d.total_time,
d.min_time,
d.max_time
FROM plsql_profiler_units u
JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
WHERE u.runid = 17 and u.unit_name in ('DO_SOMETHING_1','DO_SOMETHING_2','DO_SOMETHING_3')
ORDER BY u.unit_number, d.line#;
源码查看
SELECT u.runid,
u.unit_number,
u.unit_type,
s.type,
u.unit_owner,
u.unit_name,
d.line#,
s.text,
d.total_occur,
d.total_time,
d.min_time,
d.max_time
FROM plsql_profiler_units u
JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
JOIN all_source s ON u.unit_owner=s.owner AND u.unit_name=s.name AND d.line#=s.line
WHERE u.runid = 1 and u.unit_name in ('DO_SOMETHING_1','DO_SOMETHING_2','DO_SOMETHING_3')
ORDER BY u.unit_number, d.line#;
测试结果
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> call DBMS_PROFILER.start_profiler(run_comment => 'zxtest_do_something: ' || SYSDATE);
Query OK, 0 rows affected (0.022 sec)
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> call do_something_1(p_times => 10);
Query OK, 0 rows affected (0.199 sec)
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> call DBMS_PROFILER.stop_profiler();
Query OK, 0 rows affected (0.147 sec)
--每次启动的 runid 和时间、注释等信息
--最后一行为测试结果
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> select * from plsql_profiler_runs;
+-------+-------------+-------------+-----------+--------------------------------+----------------+-----------------+--------------+--------+
| RUNID | RELATED_RUN | RUN_OWNER | RUN_DATE | RUN_COMMENT | RUN_TOTAL_TIME | RUN_SYSTEM_INFO | RUN_COMMENT1 | SPARE1 |
+-------+-------------+-------------+-----------+--------------------------------+----------------+-----------------+--------------+--------+
| 1 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 2 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 3 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 49000000000 | NULL | NULL | NULL |
| 4 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 5 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 15000000000 | NULL | NULL | NULL |
| 6 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 7 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 8 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 9 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 10 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 10000000000 | NULL | NULL | NULL |
| 11 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 12 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 13 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 14 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 15 | NULL | SETTLEADMIN | 05-DEC-24 | do_something: 05-DEC-24 | 0 | NULL | NULL | NULL |
| 16 | NULL | SETTLEADMIN | 09-DEC-24 | do_something: 09-DEC-24 | 8000000000 | NULL | NULL | NULL |
| 17 | NULL | SETTLEADMIN | 09-DEC-24 | zxtest_do_something: 09-DEC-24 | 7000000000 | NULL | NULL | NULL |
+-------+-------------+-------------+-----------+--------------------------------+----------------+-----------------+--------------+--------+
--每次执行中每个 PL 单元的信息
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> select * from plsql_profiler_units where runid=17;
+-------+-------------+--------------+-------------+----------------+----------------+------------+--------+--------+
| RUNID | UNIT_NUMBER | UNIT_TYPE | UNIT_OWNER | UNIT_NAME | UNIT_TIMESTAMP | TOTAL_TIME | SPARE1 | SPARE2 |
+-------+-------------+--------------+-------------+----------------+----------------+------------+--------+--------+
| 17 | 310867 | PACKAGE BODY | SYS | DBMS_PROFILER | 02-DEC-24 | 0 | NULL | NULL |
| 17 | 500359 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_3 | 09-DEC-24 | 0 | NULL | NULL |
| 17 | 500360 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_2 | 09-DEC-24 | 0 | NULL | NULL |
| 17 | 500361 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_1 | 09-DEC-24 | 0 | NULL | NULL |
+-------+-------------+--------------+-------------+----------------+----------------+------------+--------+--------+
--每次执行每行的耗时
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> select * from plsql_profiler_data where runid=17;
+-------+-------------+-------+-------------+------------+----------+----------+--------+--------+--------+--------+
| RUNID | UNIT_NUMBER | LINE# | TOTAL_OCCUR | TOTAL_TIME | MIN_TIME | MAX_TIME | SPARE1 | SPARE2 | SPARE3 | SPARE4 |
+-------+-------------+-------+-------------+------------+----------+----------+--------+--------+--------+--------+
| 17 | 310867 | 1 | 2 | 10371 | 2169 | 8202 | NULL | NULL | NULL | NULL |
| 17 | 310867 | 11 | 2 | 997 | 359 | 638 | NULL | NULL | NULL | NULL |
| 17 | 310867 | 14 | 2 | 82153 | 23109 | 59044 | NULL | NULL | NULL | NULL |
| 17 | 310867 | 80 | 1 | 2765 | 2765 | 2765 | NULL | NULL | NULL | NULL |
| 17 | 310867 | 122 | 1 | 4102 | 4102 | 4102 | NULL | NULL | NULL | NULL |
| 17 | 310867 | 123 | 1 | 5898 | 5898 | 5898 | NULL | NULL | NULL | NULL |
| 17 | 500359 | 1 | 100 | 356062 | 2312 | 25303 | NULL | NULL | NULL | NULL |
| 17 | 500359 | 2 | 100 | 121283 | 700 | 9009 | NULL | NULL | NULL | NULL |
| 17 | 500359 | 4 | 1000 | 268831 | 193 | 11091 | NULL | NULL | NULL | NULL |
| 17 | 500359 | 5 | 1000 | 60829022 | 22812 | 4636191 | NULL | NULL | NULL | NULL |
| 17 | 500360 | 1 | 10 | 46980 | 3380 | 8429 | NULL | NULL | NULL | NULL |
| 17 | 500360 | 3 | 100 | 27091 | 204 | 451 | NULL | NULL | NULL | NULL |
| 17 | 500360 | 4 | 100 | 3006870 | 19294 | 186324 | NULL | NULL | NULL | NULL |
| 17 | 500361 | 1 | 1 | 31967 | 31967 | 31967 | NULL | NULL | NULL | NULL |
| 17 | 500361 | 3 | 10 | 3191 | 256 | 628 | NULL | NULL | NULL | NULL |
| 17 | 500361 | 4 | 10 | 381646 | 28464 | 61232 | NULL | NULL | NULL | NULL |
+-------+-------------+-------+-------------+------------+----------+----------+--------+--------+--------+--------+
-- 对应到存储过程
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> SELECT u.runid,
u.unit_number,
u.unit_type,
u.unit_owner,
u.unit_name,
d.line#,
d.total_occur,
d.total_time,
d.min_time,
d.max_time
FROM plsql_profiler_units u
JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
WHERE u.runid = 17 and u.unit_name in ('DO_SOMETHING_1','DO_SOMETHING_2','DO_SOMETHING_3')
ORDER BY u.unit_number, d.line#;
+-------+-------------+-----------+-------------+----------------+-------+-------------+------------+----------+----------+
| RUNID | UNIT_NUMBER | UNIT_TYPE | UNIT_OWNER | UNIT_NAME | LINE# | TOTAL_OCCUR | TOTAL_TIME | MIN_TIME | MAX_TIME |
+-------+-------------+-----------+-------------+----------------+-------+-------------+------------+----------+----------+
| 17 | 500359 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_3 | 1 | 100 | 356062 | 2312 | 25303 |
| 17 | 500359 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_3 | 2 | 100 | 121283 | 700 | 9009 |
| 17 | 500359 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_3 | 4 | 1000 | 268831 | 193 | 11091 |
| 17 | 500359 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_3 | 5 | 1000 | 60829022 | 22812 | 4636191 |
| 17 | 500360 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_2 | 1 | 10 | 46980 | 3380 | 8429 |
| 17 | 500360 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_2 | 3 | 100 | 27091 | 204 | 451 |
| 17 | 500360 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_2 | 4 | 100 | 3006870 | 19294 | 186324 |
| 17 | 500361 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_1 | 1 | 1 | 31967 | 31967 | 31967 |
| 17 | 500361 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_1 | 3 | 10 | 3191 | 256 | 628 |
| 17 | 500361 | PROCEDURE | SETTLEADMIN | DO_SOMETHING_1 | 4 | 10 | 381646 | 28464 | 61232 |
+-------+-------------+-----------+-------------+----------------+-------+-------------+------------+----------+----------+
10 rows in set (0.007 sec)
和 source 表 join 可以查看 PL 源码
obclient(SETTLEADMIN@oracle)[SETTLEADMIN]> SELECT u.runid,
u.unit_number,
u.unit_type,
s.type,
u.unit_owner,
u.unit_name,
d.line#,
s.text,
d.total_occur,
d.total_time,
d.min_time,
d.max_time
FROM plsql_profiler_units u
JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
JOIN all_source s ON u.unit_owner=s.owner AND u.unit_name=s.name AND d.line#=s.line
WHERE u.runid = 17 and u.unit_name in ('DO_SOMETHING_1','DO_SOMETHING_2','DO_SOMETHING_3')
ORDER BY u.unit_number, d.line#;
+-------+-------------+-----------+-----------+-------------+----------------+-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------+------------+----------+----------+
| RUNID | UNIT_NUMBER | UNIT_TYPE | TYPE | UNIT_OWNER | UNIT_NAME | LINE# | TEXT | TOTAL_OCCUR | TOTAL_TIME | MIN_TIME | MAX_TIME |
+-------+-------------+-----------+-----------+-------------+----------------+-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------+------------+----------+----------+
| 17 | 500359 | PROCEDURE | PROCEDURE | SETTLEADMIN | DO_SOMETHING_3 | 1 | PROCEDURE do_something_3 (p_times IN NUMBER) AS
l_dummy NUMBER;
BEGIN
FOR i IN 1 .. p_times LOOP
SELECT l_dummy + 1
INTO l_dummy
FROM dual;
END LOOP;
END; | 100 | 356062 | 2312 | 25303 |
| 17 | 500360 | PROCEDURE | PROCEDURE | SETTLEADMIN | DO_SOMETHING_2 | 1 | PROCEDURE do_something_2 (p_times IN NUMBER) AS
BEGIN
FOR i IN 1 .. p_times LOOP
do_something_3(p_times => p_times);
END LOOP;
END; | 10 | 46980 | 3380 | 8429 |
| 17 | 500361 | PROCEDURE | PROCEDURE | SETTLEADMIN | DO_SOMETHING_1 | 1 | PROCEDURE do_something_1 (p_times IN NUMBER) AS
BEGIN
FOR i IN 1 .. p_times LOOP
do_something_2(p_times => p_times);
END LOOP;
END; | 1 | 31967 | 31967 | 31967 |
+-------+-------------+-----------+-----------+-------------+----------------+-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------------+------------+----------+----------+
3 rows in set (0.117 sec)
注意事项
调试存储过程通过编译插桩实现，
DBMS_PROFILER.start_profiler会在在当前package start profiler，所以抓不到当前 package 里的执行情况， 如果想抓取当前 package A 的执行情况，需要嵌套一层 package B， 通过 package B 调用 package A。数据统计表生成在当前执行
DBMS_PROFILER系统包的 schema 下。
数据统计表详情
提供以下表来记录汇总的统计信息：
-- plsql_profiler_runs
create table plsql_profiler_runs
(
runid number primary key, -- unique run identifier,
-- from plsql_profiler_runnumber
related_run number, -- runid of related run (for client/
-- server correlation)
run_owner varchar2(32), -- user who started run
run_date date, -- start time of run
run_comment varchar2(2047), -- user provided comment for this run
run_total_time number, -- elapsed time for this run
run_system_info varchar2(2047), -- currently unused
run_comment1 varchar2(2047), -- additional comment
spare1 varchar2(256) -- unused
);
comment on table plsql_profiler_runs is 'Run-specific information for the PL/SQL profiler';
此表用来记录剖析器每次启动的 runid 和时间、注释等信息。 其中 runid 由 plsql_profiler_runnumber SEQUENCE 分配，只有启动剖析器时分配一次，预期不会有性能问题。
plsql_profiler_units
create table plsql_profiler_units
(
runid number references plsql_profiler_runs,
unit_number number, -- internally generated library unit #
unit_type varchar2(32), -- library unit type
unit_owner varchar2(32), -- library unit owner name
unit_name varchar2(32), -- library unit name
-- timestamp on library unit, can be used to detect changes to
-- unit between runs
unit_timestamp date,
total_time number DEFAULT 0 NOT NULL,
spare1 number, -- unused
spare2 number, -- unused
--
primary key (runid, unit_number)
);
comment on table plsql_profiler_units is 'Information about each library unit in a run';
此表用来记录每次执行中每个 PL 单元的信息，total_time 列需要使用 rollup_unit/rollup_run 接口手动更新，其他列会自动记录。
-- plsql_profiler_data
create table plsql_profiler_data
(
runid number, -- unique (generated) run identifier
unit_number number, -- internally generated library unit #
line# number not null, -- line number in unit
total_occur number, -- number of times line was executed
total_time number, -- total time spent executing line
min_time number, -- minimum execution time for this line
max_time number, -- maximum execution time for this line
spare1 number, -- unused
spare2 number, -- unused
spare3 number, -- unused
spare4 number, -- unused
--
primary key (runid, unit_number, line#),
foreign key (runid, unit_number) references plsql_profiler_units
);
comment on table plsql_profiler_data is 'Accumulated data from all profiler runs';
影响租户
影响 OceanBase 数据库中的 Oracle 租户，对于 SYS 租户和 MySQL 租户无影响。
适用版本
OceanBase 数据库 V4.2.3 及之后版本。
