使用PL/SQL PROFILER 剖析PL/SQL代码是快速定位PL/SQL代码段最有效的方法。在上一篇文章使用PL/SQL PROFILER 定位 PL/SQL 瓶颈代码中描述了安装PROFILER，并给出了剖析的示例。本文参照了Tom大师的代码来对比剖析前后的性能并附上其代码。
1、用于实施剖析的存储过程
--环境
sys@USBO> select * from v$version where rownum<2;
BANNER
------------------------------------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
--用于实施剖析的原过程，下面是使用字面量的过程，注意代码中包含了启用与停止profiler
scott@USBO> create or replace procedure binds
2 is
3 v_num number;
4 begin
5 dbms_profiler.start_profiler('binds');
6 for i in 1..100000 loop
7 v_num := dbms_random.random;
8 insert into t1 values (v_num,v_num);
9 end loop;
10 dbms_profiler.stop_profiler;
11 end;
12 /
Procedure created.
--用于实施剖析的原过程，下面是使用绑定量的过程，注意代码中包含了启用与停止profiler
scott@USBO> create or replace procedure literals
2 is
3 v_num number;
4 begin
5 dbms_profiler.start_profiler('literals');
6 for i in 1..100000 loop
7 v_num := dbms_random.random;
8 execute immediate
9 'insert into t1 values ('||v_num||','||v_num||')';
10 end loop;
11 dbms_profiler.stop_profiler;
12 end;
13 /
Procedure created.
--Author : Leshami
--Blog : http://blog.csdn.net/leshami
--清除剖析表中的历史数据(每次剖析对比前执行)
scott@USBO> delete from plsql_profiler_data;
scott@USBO> delete from plsql_profiler_units;
scott@USBO> delete from plsql_profiler_runs;
--分别执行两个不同的过程
scott@USBO> exec literals;
scott@USBO> exec binds;
2、提取剖析对比结果
scott@USBO> @profsum
2 rows updated.
PL/SQL procedure successfully completed.
=
=
====================
total time
GRAND_TOTAL
-----------
58.93
=
=
====================
total time spent on each run
RUNID RUN_COMMENT SECS
------- ----------- ---------
7 literals 53.19
8 binds 5.75
=
=
====================
percentage of time in each module, for each run separately
RUNID RUN_COMMENT UNIT_OWNER UNIT_NAME SECS PERCEN
------- ----------- ----------- -------------- --------- ------
7 literals SCOTT LITERALS 53.19 100.0
8 binds SCOTT BINDS 5.75 100.0
=
=
====================
percentage of time in each module, summarized across runs
UNIT_OWNER UNIT_NAME SECS PERCENTAG
----------- -------------- --------- ---------
SCOTT LITERALS 53.19 90.25
SCOTT BINDS 5.75 9.75
=
=
====================
lines taking more than 1% of the total time, each run separate
RUNID HSECS PCT OWNER UNIT_NAME LINE# TEXT
------- --------- ------- ----------- -------------- ------ ---------------------
7 5221.18 88.6 SCOTT LITERALS 8 execute immediate
8 502.97 8.5 SCOTT BINDS 8 insert into t1 values
(v_num,v_num);
7 73.04 1.2 SCOTT LITERALS 7 v_num :=
dbms_random.random;
=
=
====================
most popular lines (more than 1%), summarize across all runs
HSECS PCT UNIT_OWNER UNIT_NAME LINE# TEXT
--------- ------- ----------- -------------- ------ ---------------------
5221.18 88.6 SCOTT LITERALS 8 execute immediate
502.97 8.5 SCOTT BINDS 8 insert into t1 values
(v_num,v_num);
73.04 1.2 SCOTT LITERALS 7 v_num :=
dbms_random.random;
PL/SQL procedure successfully completed.
=
=
====================
Number of lines actually executed in different units (by unit_name)
UNIT_OWNER UNIT_NAME LINES_EXECUTED LINES_PRESENT PCT
----------- -------------- -------------- ------------- -------
SCOTT LITERALS 4 7 57.1
SCOTT BINDS 4 7 57.1
=
=
====================
Number of lines actually executed for all units
LINES_EXECUTED
--------------
8
=
=
====================
total number of lines in all units
LINES_PRESENT
-------------
14
3、生成剖析结果的脚本
a、脚本profrep.sql
--在执行剖析前需要先执行该脚本以准备环境(仅首次使用)
Rem Copyright (c) Oracle Corporation 1998, 1999. All Rights Reserved.
Rem
Rem NAME
Rem profrep.sql
Rem
Rem DESCRIPTION
Rem PL/SQL Profiler reporting utilities
Rem
Rem NOTES
Rem The reporting procedures expect server output to be set on
Rem Some of the rollup functions commit the transaction.
Rem
-- First create the views used in the reporting package
--
create or replace view plsql_profiler_grand_total as
select sum(total_time) as grand_total from plsql_profiler_units;
create or replace view plsql_profiler_units_cross_run as
select unit_owner, unit_name, unit_type, sum(total_time) as total_time
from plsql_profiler_units group by unit_owner, unit_name, unit_type;
create or replace view plsql_profiler_lines_cross_run as
select p1.unit_owner as unit_owner, p1.unit_name as unit_name,
p1.unit_type as unit_type,
p2.line# as line#,
sum(p2.total_occur) as total_occur,
sum(p2.total_time) as total_time,
min(p2.min_time) as min_time,
max(p2.max_time) as max_time
from plsql_profiler_units p1, plsql_profiler_data p2
where p1.runid=p2.runid and p1.unit_number = p2.unit_number
group by p1.unit_owner, p1.unit_name, p1.unit_type, p2.line#;
create or replace view plsql_profiler_notexec_lines as
select owner, name, type, line, text, total_occur
from all_source t1, plsql_profiler_lines_cross_run t2
where t2.total_occur = 0 and t2.unit_owner = owner
and t2.unit_name = name and t2.unit_type = type and t2.line# = line
order by line asc;
create or replace package prof_report_utilities
authid current_user is
-- Routines to roll up profile information from line level to unit level
--
procedure rollup_unit(run_number IN number, unit IN number);
procedure rollup_run(run_number IN number);
procedure rollup_all_runs;
-- Routines to print a report, treating each run separately
--
procedure print_unit(run_number IN number, unit IN number);
procedure print_run(run_number IN number);
procedure print_detailed_report;
-- Routine to print a single report including information from each run
--
procedure print_summarized_report;
-- Set size of window for reports
procedure set_window_size(window_size IN pls_integer);
end prof_report_utilities;
/
show errors;
create or replace
package body prof_report_utilities is
-- the reports print 'window' lines of source around lines with profiler
-- data, otherwise skipping lines with no data. This is useful when
-- viewing data for units with sparse profiler data.
--
window pls_integer := 10;
last_line_printed number := 999999999;
cursor c2(run number, unit number,
owner_name varchar2, unit_name varchar2, unit_type varchar2) is
select line, text, total_occur, total_time, min_time, max_time
from all_source, plsql_profiler_data
where runid (+) = run and unit_number (+) = unit
and owner = owner_name and name = unit_name and type = unit_type
and plsql_profiler_data.line# (+) = line
order by line asc;
-- c2tab contains the window of lines around any line with interesting
-- data.
type c2tab_t is table of c2%rowtype index by binary_integer;
c2tab c2tab_t;
-- index into the window where previous row was inserted
prev_row pls_integer := 0;
procedure report_exception(which IN varchar2, reraised IN boolean) is
begin
dbms_output.new_line();
dbms_output.new_line();
dbms_output.put('======================================');
dbms_output.put_line('======================================');
dbms_output.put('Exception Number: ');
dbms_output.put(sqlcode);
dbms_output.put(' raised in routine ' || which );
if (reraised)
then
dbms_output.put(' (Will be reraised)');
end if;
dbms_output.new_line();
dbms_output.put('======================================');
dbms_output.put_line('======================================');
end;
-- compute the total time spent executing this unit - the sum of the
-- time spent executing lines in this unit (for this run)
--
procedure rollup_unit(run_number IN number, unit IN number) is
begin
dbms_profiler.rollup_unit(run_number, unit);
exception
when others then
report_exception('Rollup_Unit', true);
raise;
end rollup_unit;
-- rollup all units for the given run
--
procedure rollup_run(run_number IN number) is
begin
dbms_profiler.rollup_run(run_number);
exception
when others then
report_exception('Rollup_Run', true);
raise;
end rollup_run;
procedure rollup_all_runs is
cursor crunid is
select runid from plsql_profiler_runs order by runid asc;
begin
for runidrec in crunid loop
dbms_profiler.rollup_run(runidrec.runid);
end loop crunid;
end rollup_all_runs;
--
-- Reporting functions
--
-- Format and print information on a unit
--
procedure print_unit_header(run_number IN number, unit IN number) is
cursor cuhdr(run_number number, unit number) is
select * from plsql_profiler_units
where runid = run_number and unit_number = unit;
unit_row cuhdr%rowtype;
begin
-- fetch data for the given unit
open cuhdr(run_number, unit);
fetch cuhdr into unit_row;
close cuhdr;
-- format and print the data
dbms_output.put('Unit #');
dbms_output.put(unit_row.unit_number);
dbms_output.put(': ');
dbms_output.put(unit_row.unit_owner || '.' || unit_row.unit_name);
dbms_output.put(' - Total time: ');
dbms_output.put(to_char(unit_row.total_time/1000000000, '99999.99'));
dbms_output.put_line(' seconds');
end print_unit_header;
-- Format and print information on a run
--
procedure print_run_header(run_number IN number) is
cursor crun(run_number number) is
select * from plsql_profiler_runs where runid = run_number;
runidrec crun%rowtype;
begin
open crun(run_number);
fetch crun into runidrec;
close crun;
dbms_output.new_line();
dbms_output.new_line();
dbms_output.put('===========================');
dbms_output.put('Results for run #');
dbms_output.put(runidrec.runid);
dbms_output.put(' made on ');
dbms_output.put(to_char(runidrec.run_date, 'DD-MON-YY HH24:MI:SS'));
dbms_output.put_line(' =========================');
if (runidrec.run_comment is not null) then
dbms_output.put(' (');
dbms_output.put(runidrec.run_comment);
dbms_output.put(') ');
end if;
dbms_output.put('Run total time: ');
dbms_output.put(to_char(runidrec.run_total_time/1000000000, '99999.99'));
dbms_output.put_line(' seconds');
if (runidrec.run_system_info is not null) then
dbms_output.put_line(runidrec.run_system_info);
end if;
end print_run_header;
--
-- Routines for formatting and printing profiler data
--
-- Format and print one line of data and source
--
procedure print_line(line number, lcount number,
running_total number, source varchar2) is
outline varchar2(200); -- temp buffer to hold output
cline varchar2(40); -- number of times this line was executed
total_time varchar2(40); -- total time executing this line
ave_time varchar2(40); -- average time for this line
ave_nano number;
begin
outline := to_char(line, '99G999');
-- format and store away the count and running total
if (lcount is not null) then
cline := to_char(lcount, '99G999G999');
end if;
if (running_total is not null) then
total_time := substr(to_char(running_total/1000000000), 1, 9);
end if;
-- compute average time executing this line and stash it away
if (lcount > 0) then
ave_nano := running_total/lcount;
ave_time := substr(to_char(ave_nano/1000000000), 1, 9);
end if;
-- now put together all the data, the source line and output it
--
outline := outline || ' ' || cline || ' ' ||
total_time || ' ' || ave_time || ' ';
if source is not null then
outline := rpad(outline, 55) || substr(source, 1, (length(source) - 1));
end if;
dbms_output.put_line(outline);
end print_line;
-- insert a c2 row into the window
--
procedure insert_into_window(c2row c2%rowtype) is
next_row pls_integer;
begin
next_row := mod((prev_row + 1), window);
c2tab(next_row) := c2row;
prev_row := next_row;
end insert_into_window;
-- clear out the window (for reuse later)
--
procedure clear_window is
empty_tab c2tab_t;
begin
-- throw away table
c2tab := empty_tab;
prev_row := 0;
end clear_window;
-- print the window and throw it away
--
procedure print_window(start_separator IN boolean) is
next_row pls_integer;
iter pls_integer;
c2row c2%rowtype;
first_line boolean := true;
ct number := c2tab.count;
begin
if (window <= 0) then
return;
end if;
-- compute first row
next_row := mod((prev_row + 1), window);
-- Detect the case where the window hasn't wrapped around yet
if (not c2tab.exists(next_row)) then
next_row := c2tab.next(next_row);
if (next_row is NULL) then
next_row := c2tab.first;
end if;
end if;
for iter in 1..window loop
exit when (ct <= 0);
if (c2tab.exists(next_row)) then
c2row := c2tab(next_row);
if (first_line and (last_line_printed < c2row.line-1)) then
dbms_output.put_line('.');
dbms_output.put_line('.');
dbms_output.put_line('.');
end if;
first_line := false;
print_line(c2row.line, c2row.total_occur,
c2row.total_time, c2row.text);
last_line_printed := c2row.line;
ct := ct - 1;
end if;
next_row := mod((next_row + 1), window);
end loop;
if (not start_separator) then
last_line_printed := 999999999;
end if;
clear_window;
end print_window;
procedure print_unit(run_number number, unit number) is
cursor cuhdr(run number, unit number) is
select * from plsql_profiler_units
where runid = run and unit_number = unit;
unit_row cuhdr%rowtype;
joined_row c2%rowtype;
lcount number;
-- print a trailing window after the last interesting line
print_trailing_window boolean := false;
trail_count pls_integer := 0;
begin
dbms_profiler.rollup_unit(run_number, unit);
-- fetch unit name and type information
open cuhdr(run_number, unit);
fetch cuhdr into unit_row;
close cuhdr;
-- If there was an error previously, cursor "c2" might be open
-- Close it, and ignore the error if it already was
--
begin
close c2;
exception
when others then
null;
end;
open c2(run_number, unit,
unit_row.unit_owner, unit_row.unit_name, unit_row.unit_type);
loop
fetch c2 into joined_row;
exit when c2%notfound;
lcount := joined_row.total_occur;
-- if there is interesting data at this line, print its prefix window
-- and the data itself; else stash away this line c2tab - it may get
-- printed as part of another line's window
if (lcount is not null and lcount <> 0) then
print_window (start_separator => false);
print_line(joined_row.line, joined_row.total_occur,
joined_row.total_time, joined_row.text);
print_trailing_window := true;
trail_count := 0;
else
insert_into_window(joined_row);
-- if we are now accumulating rows after a row with data, increment
-- count of rows accumulated since last interesting row. if we have
-- accumulated a window full of data, print it out.
if (print_trailing_window) then
trail_count := trail_count + 1;
if (trail_count = window) then
print_window(start_separator => true);
print_trailing_window := false;
end if;
end if;
end if;
end loop;
close c2;
-- if the window isn't empty, print it out.
if (print_trailing_window) then
print_window(start_separator => false);
print_trailing_window := false;
end if;
clear_window;
exception
when others then
report_exception('Print_Unit', false);
end print_unit;
procedure print_run(run_number number) is
cursor cunits(run_number number) is
select unit_number from plsql_profiler_units
where runid = run_number order by unit_number asc;
begin
print_run_header(run_number);
dbms_profiler.rollup_run(run_number);
for unitrec in cunits(run_number) loop
print_unit_header(run_number, unitrec.unit_number);
print_unit(run_number, unitrec.unit_number);
end loop;
exception
when others then
report_exception('Print_Run', false);
end print_run;
procedure print_detailed_report is
cursor crunid is
select runid from plsql_profiler_runs order by runid asc;
begin
dbms_output.enable(999999);
dbms_output.put('=================================');
dbms_output.put('trace info');
dbms_output.put_line('=================================');
rollup_all_runs();
for runidrec in crunid loop
print_run(runidrec.runid);
end loop crunid;
dbms_output.new_line;
dbms_output.put('======================================');
dbms_output.put_line('======================================');
exception
when others then
report_exception('Print_Detailed_Report', false);
end print_detailed_report;
procedure print_summarized_unit(owner_name varchar2,
unit_name varchar2, unit_type varchar2) is
cursor c3(uowner varchar2, uname varchar2, utype varchar2) is
select line, text, total_occur, total_time, min_time, max_time
from all_source t1, plsql_profiler_lines_cross_run t2
where owner = uowner and name = uname and type = utype
and t2.unit_owner (+) = uowner and t2.unit_name (+) = uname
and t2.unit_type (+) = utype and t2.line# (+) = line
order by line asc;
datarec c3%rowtype;
lcount number;
-- print a trailing window after the last interesting line
print_trailing_window boolean := false;
trail_count pls_integer := 0;
begin
open c3(owner_name, unit_name, unit_type);
loop
fetch c3 into datarec;
exit when c3%notfound;
lcount := datarec.total_occur;
if (lcount is not null and lcount <> 0) then
print_window (start_separator => false);
print_line(datarec.line,
datarec.total_occur,
datarec.total_time,
datarec.text);
print_trailing_window := true;
trail_count := 0;
else
insert_into_window(datarec);
-- if we are now accumulating rows after a row with data, increment
-- count of rows accumulated since last interesting row. if we have
-- accumulated a window full of data, print it out.
if (print_trailing_window) then
trail_count := trail_count + 1;
if (trail_count = window) then
print_window(start_separator => true);
print_trailing_window := false;
end if;
end if;
end if;
end loop;
close c3;
-- if the window isn't empty, print it out.
if (print_trailing_window) then
print_window(start_separator => false);
print_trailing_window := false;
end if;
clear_window;
exception
when others then
report_exception('Print_Summarized_Unit', false);
end print_summarized_unit;
procedure print_summarized_report is
cursor cunits is
select unit_owner, unit_name, unit_type
from plsql_profiler_units_cross_run
order by unit_owner, unit_name asc;
begin
rollup_all_runs();
dbms_output.enable(9999999);
dbms_output.put('================== Profiler report - all runs rolled up');
dbms_output.put_line(' ===================');
for unitrec in cunits loop
dbms_output.put('Unit ');
dbms_output.put(unitrec.unit_owner);
dbms_output.put('.');
dbms_output.put(unitrec.unit_name);
dbms_output.put_line(':');
print_summarized_unit(unitrec.unit_owner,
unitrec.unit_name, unitrec.unit_type);
end loop;
dbms_output.new_line;
dbms_output.put('======================================');
dbms_output.put_line('======================================');
exception
when others then
report_exception('Print_Summarized_Report', false);
end print_summarized_report;
-- Set size of window for reports
procedure set_window_size(window_size IN pls_integer) is
begin
if (window_size < 0) then
window := 999999999;
else
window := window_size;
end if;
end set_window_size;
end prof_report_utilities;
/
show errors;
b、剖析报告脚本profsum.sql
--file_name: profsum.sql
set echo off
set linesize 5000
set trimspool on
set serveroutput on
set termout off
column owner format a11
column unit_name format a14
column text format a21 word_wrapped
column runid format 999999
column secs format 99999.99
column hsecs format 99999.99
column grand_total format 9999.99
column run_comment format a11 word_wrapped
column line# format 99999
column pct format 9999.9
column unit_owner format a11
spool profsum.out
--Clean out rollup results, and recreate --
update plsql_profiler_units set total_time = 0;
execute prof_report_utilities.rollup_all_runs;
prompt =
prompt =
prompt ====================
prompt total time
select grand_total/1000000000 as grand_total
from plsql_profiler_grand_total;
prompt =
prompt =
prompt ====================
prompt total time spent on each run
select runid,
substr(run_comment,1, 30) as run_comment,
run_total_time/1000000000 as secs
from (select a.runid, sum(a.total_time) run_total_time, b.run_comment
from plsql_profiler_units a, plsql_profiler_runs b
where a.runid = b.runid group by a.runid, b.run_comment )
where run_total_time > 0
order by runid asc;
prompt =
prompt =
prompt ====================
prompt percentage of time in each module, for each run separately
select p1.runid,
substr(p2.run_comment, 1, 20) as run_comment,
p1.unit_owner,
decode(p1.unit_name, '', '<anonymous>',
substr(p1.unit_name,1, 20)) as unit_name,
p1.total_time/1000000000 as secs,
TO_CHAR(100*p1.total_time/p2.run_total_time, '999.9') as percentage
from plsql_profiler_units p1,
(select a.runid, sum(a.total_time) run_total_time, b.run_comment
from plsql_profiler_units a, plsql_profiler_runs b
where a.runid = b.runid group by a.runid, b.run_comment ) p2
where p1.runid=p2.runid
and p1.total_time > 0
and p2.run_total_time > 0
and (p1.total_time/p2.run_total_time) >= .01
order by p1.runid asc, p1.total_time desc;
column secs form 99999.99
prompt =
prompt =
prompt ====================
prompt percentage of time in each module, summarized across runs
select p1.unit_owner,
decode(p1.unit_name, '', '<anonymous>', substr(p1.unit_name,1, 25)) as
unit_name,
p1.total_time/1000000000 as secs,
TO_CHAR(100*p1.total_time/p2.grand_total, '99999.99') as percentage
from plsql_profiler_units_cross_run p1,
plsql_profiler_grand_total p2
order by p1.total_time DESC;
prompt =
prompt =
prompt ====================
prompt lines taking more than 1% of the total time, each run separate
select p1.runid as runid,
p1.total_time/10000000 as hsecs,
p1.total_time/p4.grand_total*100 as pct,
substr(p2.unit_owner, 1, 20) as owner,
decode(p2.unit_name, '', '<anonymous>', substr(p2.unit_name,1, 20)) as
unit_name,
p1.line#,
( select p3.text
from all_source p3
where p3.owner = p2.unit_owner and
p3.line = p1.line# and
p3.name=p2.unit_name and
p3.type not in ( 'PACKAGE', 'TYPE' )) text
from plsql_profiler_data p1,
plsql_profiler_units p2,
plsql_profiler_grand_total p4
where (p1.total_time >= p4.grand_total/100)
AND p1.runid = p2.runid
and p2.unit_number=p1.unit_number
order by p1.total_time desc;
prompt =
prompt =
prompt ====================
prompt most popular lines (more than 1%), summarize across all runs
select p1.total_time/10000000 as hsecs,
p1.total_time/p4.grand_total*100 as pct,
substr(p1.unit_owner, 1, 20) as unit_owner,
decode(p1.unit_name, '', '<anonymous>',
substr(p1.unit_name,1, 20)) as unit_name,
p1.line#,
( select p3.text from all_source p3
where (p3.line = p1.line#) and
(p3.owner = p1.unit_owner) AND
(p3.name = p1.unit_name) and
(p3.type not in ( 'PACKAGE', 'TYPE' ) ) ) text
from plsql_profiler_lines_cross_run p1,
plsql_profiler_grand_total p4
where (p1.total_time >= p4.grand_total/100)
order by p1.total_time desc;
execute prof_report_utilities.rollup_all_runs;
prompt =
prompt =
prompt ====================
prompt Number of lines actually executed in different units (by unit_name)
select p1.unit_owner,
p1.unit_name,
count( decode( p1.total_occur, 0, null, 0)) as lines_executed ,
count(p1.line#) as lines_present,
count( decode( p1.total_occur, 0, null, 0))/count(p1.line#) *100
as pct
from plsql_profiler_lines_cross_run p1
where (p1.unit_type in ( 'PACKAGE BODY', 'TYPE BODY',
'PROCEDURE', 'FUNCTION' ) )
group by p1.unit_owner, p1.unit_name;
prompt =
prompt =
prompt ====================
prompt Number of lines actually executed for all units
select count(p1.line#) as lines_executed
from plsql_profiler_lines_cross_run p1
where (p1.unit_type in ( 'PACKAGE BODY', 'TYPE BODY',
'PROCEDURE', 'FUNCTION' ) )
AND p1.total_occur > 0;
prompt =
prompt =
prompt ====================
prompt total number of lines in all units
select count(p1.line#) as lines_present
from plsql_profiler_lines_cross_run p1
where (p1.unit_type in ( 'PACKAGE BODY', 'TYPE BODY',
'PROCEDURE', 'FUNCTION' ) );
spool off
set termout on
edit profsum.out
set linesize 131
更多参考
DML Error Logging 特性
PL/SQL --> 游标
PL/SQL --> 隐式游标(SQL%FOUND)
批量SQL之 FORALL 语句
批量SQL之 BULK COLLECT 子句
PL/SQL 集合的初始化与赋值
PL/SQL 联合数组与嵌套表
PL/SQL 变长数组
PL/SQL --> PL/SQL记录
SQL tuning 步骤
高效SQL语句必杀技
父游标、子游标及共享游标
绑定变量及其优缺点
dbms_xplan之display_cursor函数的使用
dbms_xplan之display函数的使用
执行计划中各字段各模块描述
使用 EXPLAIN PLAN 获取SQL语句执行计划