使用profiler 评估一段plsql 代码的执行时间-wuxiaobo

点击(此处)折叠或打开

有时候我们在执行一段比较长的plsql程序的时候，发现执行过程比较慢，但又不知道是哪部分出现了性能问题，这时候应该如何快速找到最耗费时间的部分呢？当然有很多方法，但这里推荐一种方法，可以使用dbms_profiler包来观察每一行代码的执行次数和时间。
一、操作步骤
1. 登录到SYS用户，检查dbms_profiler包有没有安装。没有的话运行$ORACLE_HOME/rdbms/admin/profload.sql来创建该包。
2. 将该包的执行权限赋予待调试的用户。
3. 登录到调试用户，运行$ORACLE_HOME/rdbms/admin/proftab.sql创建相关表。
4. 在待优化的PL/SQL程序前后加上运行dbms_profiler包的代码，如下：
BEGIN
DBMS_PROFILER.START_PROFILER('any comment');
...'your pl/sql code'
DBMS_PROFILER.STOP_PROFILER;
...
END;
5. 运行该PL/SQL程序，然后检查PLSQL_PROFILER_DATA表内容，可以从中看到每一行代码的执行次数，每行代码总共的执行时间。
二、具体的例子：
SQL> conn / as sysdba;
Connected.
1.检查是否安装了dbms_profiler包
SQL> desc dbms_profiler;
ERROR:
ORA-04043: object dbms_profiler does not exist
--如果没有安装的话，执行下面的语句安装
SQL> @/disk_dev/oracle/product/9.2.0/rdbms/admin/profload.sql;
Package created.
Grant succeeded.
Synonym created.
Library created.
Package body created.
Testing for correct installation
SYS.DBMS_PROFILER successfully loaded.
PL/SQL procedure successfully completed.
2.把dbms_profiler的执行权限赋于oauser
SQL> grant execute on dbms_profiler to oauser;
Grant succeeded.
3.使用oauser登录，执行proftab.sql，此文件实际是创建plsql_profiler_data、plsql_profiler_units、plsql_profiler_runs三个表，具体proftab.sql的内容如下：
proftab.sql:
drop table plsql_profiler_data cascade constraints;
drop table plsql_profiler_units cascade constraints;
drop table plsql_profiler_runs cascade constraints;
drop sequence plsql_profiler_runnumber;
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';
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';
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';
create sequence plsql_profiler_runnumber start with 1 nocache;
SQL> conn oauser/oauser;
Connected.
SQL> @/disk_dev/oracle/product/9.2.0/rdbms/admin/proftab.sql;
4.创建一个测试的过程，在代码中加入dbms_profiler代码，如下：
create or replace procedure p_dbms_profiler_test
is
i number :=1 ;
v_str varchar2(4000);
begin
dbms_profiler.start_profiler('测试一下');
dbms_output.put_line(i);
for i in 1..100 loop
exit when length(v_str)>100;
v_str := v_str||i;
end loop;
dbms_output.put_line(v_str);
dbms_profiler.stop_profiler;
end p_dbms_profiler_test;
SQL> exec p_dbms_profiler_test;
PL/SQL procedure successfully completed
SQL> exec p_dbms_profiler_test;
PL/SQL procedure successfully completed
SQL> exec p_dbms_profiler_test;
PL/SQL procedure successfully completed
执行一次p_dbms_profiler_test过程，就会分别在plsql_profiler_units和plsql_profiler_runs插入一条信息，在plsql_profiler_data插入具体的过程执行数据。
5.查看结果
通过下面的SQL语句我们可以知道每一行代码的执行次数，时间等等。
SQL> select t1.line#,t3.text,t1.total_occur,t1.total_time,min_time, max_time
2 from plsql_profiler_data t1,plsql_profiler_units t2,user_source t3
3 where t1.runid = t2.runid
4 and t2.unit_name='P_DBMS_PROFILER_TEST'
5 and t2.unit_name = t3.name
6 and t1.line#=t3.line
7 and t1.runid=3
8 order by t1.line#
9 /
LINE# TEXT TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
---------- -------------------------------------------------------------------------------- --
3 i number :=1 ; 0 0 0 0
6 dbms_profiler.start_profiler('测试一下'); 0 0 0 0
7 dbms_output.put_line(i); 1 17000 17000 17000
8 for i in 1..100 loop 56 222000 2000 6000
9 exit when length(v_str)>100; 56 232000 3000 7000
10 v_str := v_str||i; 55 254000 3000 16000
12 dbms_output.put_line(v_str); 1 5000 5000 5000
13 dbms_profiler.stop_profiler; 1 5000 5000 5000
14 end p_dbms_profiler_test; 0 0 0 0
9 rows selected

可以在 Metalink上Note：243755.1中可以下载的PROF.zip 下载 prof 分析脚本 -- 带实验