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

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

• 1.sys创建dbms_profiler
• 2.创建profiler用户，对应表和序列，赋权
• 3.sys为表和序列创建public同义词
• 4.使用dbms_profiler收集执行时间信息
• 5.查询并分析结果

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。