使用dbms_profiler收集存储过程每步执行时间

时间：2023-12-26 20:23:19

最近和优化团队的专家学到一个很有意义的内置包：dbms_profiler，专门用于分析Oracle存储过程中的各段代码的时间开销情况，从而快速找到性能瓶颈的步骤。

1.sys创建dbms_profiler

conn /as sysdba

desc dbms_profiler    --先确认dbms_profiler包是否存在，如果不存在则通过下面的方式创建

@?/rdbms/admin/profload.sql

注：文件在%ORACLE_HOME%\RDBMS\ADMIN\profload.sql

主要函数:

start_profiler 启动对该程式监控

stop_profiler 结束对该程式监控

2.创建profiler用户，对应表和序列，赋权

conn / as sysdba;

CREATE USER profiler IDENTIFIED BY profiler;

grant connect,resource to profiler;

conn profiler/profiler;

@?/rdbms/admin/proftab.sql

GRANT SELECT ON plsql_profiler_runnumber TO PUBLIC;

GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_data TO PUBLIC;

GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_units TO PUBLIC;

GRANT SELECT,INSERT,UPDATE,DELETE ON plsql_profiler_runs TO PUBLIC;

备注：

plsql_profiler_runs --prof运行信息

plsql_profiler_units --prof每个单元信息

plsql_profiler_data --prof每个单元的详细数据

plsql_profiler_runnumber --用来生成prof唯一运行编号的序列

3.sys为表和序列创建public同义词

conn /as sysdba;

CREATE PUBLIC SYNONYM plsql_profiler_runnumber FOR profiler.plsql_profiler_runnumber;

CREATE PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs;

CREATE PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units;

CREATE PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;

4.使用dbms_profiler收集执行时间信息

假设我们要对下面这样的一个存储过程进行分析：

CREATE OR REPLACE procedure sp_profiler_test1

as

begin

   for x in 1..10000

   loop

       insert into t_t1 values(x);

   end loop;

   commit;

end sp_profiler_test1;

/

收集该存储过程执行时间信息的方法如下：

set serverout on;

 DECLARE

    v_run_number   integer;

    v_temp1        integer;

 BEGIN

    --启动profiler

    sys.DBMS_PROFILER.start_profiler (run_number => v_run_number);

    --显示当前跟踪的运行序号(后面查询要用)

    DBMS_OUTPUT.put_line ('run_number:' || v_run_number);

    --运行要跟踪的PLSQL

    sp_profiler_test1;   --前一步创建的测试样例存储过程

    --停止profiler

    sys.DBMS_PROFILER.stop_profiler;

 END;

5.查询并分析结果

set linesize 1000

col text format a60

SELECT   d.line#,                      --代码行号

    s.text,                            --源代码

       d.total_time,                   --总共运行时间(单位10亿分之一秒，即10的-9次方。）

       d.total_occur,                  --总共运行次数

       d.min_time,                     --最小运行时间

       d.max_time                      --最大运行时间

    FROM   plsql_profiler_data d, sys.all_source s, plsql_profiler_units u

   WHERE       d.runid = 2             --运行号（上一步执行相关过程时显示号码）

    and u.unit_name = 'SP_PROFILER_TEST1'        --单元名，即被测试的存储过程名

       AND u.runid = d.runid

    AND d.unit_number = u.unit_number

    AND d.total_occur <> 0

    AND s.TYPE(+) = u.unit_type

    AND s.owner(+) = u.unit_owner

    AND s.name(+) = u.unit_name

    AND d.line# = NVL (s.line, d.line#)

   ORDER BY  d.total_time desc, u.unit_number, d.line#;

示例查询结果如下：

     LINE# TEXT                                   TOTAL_TIME TOTAL_OCCUR   MIN_TIME   MAX_TIME

---------- -------------------------------------- ---------- ----------- ---------- ----------

         6        insert into t_t1 values(x);      150147563       10000      13108    3831882

         4    for x in 1..10000                       613220       10001         26       7514

         8    commit;                                  75630           1      75630      75630

         9 end sp_profiler_test1;                       1683           1       1683       1683

Elapsed: 00:00:01.39

说明：LINE#代表对应TEXT的语句在存储过程的第几行，TOTAL_TIME代表执行的总时间（单位ns，10的负9次方秒），TOTAL_OCCUR代表执行的次数，MIN_TIME代表最短单次的运行时间，MAX_TIME代表最长单次的运行时间。

上面这个例子就是存储过程SP_PROFILER_TEST1中的第6行代码insert into t_t1 values(x);消耗时间占比最大，这一步总消耗150ms，执行了10000次，单次执行最短是13108ns，最长是3.83ms。

相关文章