DBMS_PROFILER must be installed as SYS.
Creation of the environment
The DBMS_PROFILER package is not automatically created during default installation or creation of the database. Ask the DBA to create the package using the profload.sql script. Create tables for storing statistics either in one central user or in each individual user, using proftab.sql. If tables are created in one central user, like SYS, then grant DML privileges to all other users. Create public synonym on the tables with the same name.
The tables created are:
PLSQL_PROFILER_RUNS: Run-specific information for the PL/SQL profiler
PLSQL_PROFILER_UNITS: Information about each library unit in a run
PLSQL_PROFILER_DATA: Accumulated data from all profiler runs.
SQL> desc plsql_profiler_runs;
Name Type Nullable Default Comments
--------------- -------------- -------- ------- --------
RUNID NUMBER
RELATED_RUN NUMBER Y
RUN_OWNER VARCHAR2(32) Y
RUN_DATE DATE Y
RUN_COMMENT VARCHAR2(2047) Y
RUN_TOTAL_TIME NUMBER Y
RUN_SYSTEM_INFO VARCHAR2(2047) Y
RUN_COMMENT1 VARCHAR2(2047) Y
SPARE1 VARCHAR2(256) Y
SQL> desc plsql_profiler_units;
Name Type Nullable Default Comments
-------------- ------------ -------- ------- --------
RUNID NUMBER
UNIT_NUMBER NUMBER
UNIT_TYPE VARCHAR2(32) Y
UNIT_OWNER VARCHAR2(32) Y
UNIT_NAME VARCHAR2(32) Y
UNIT_TIMESTAMP DATE Y
TOTAL_TIME NUMBER 0
SPARE1 NUMBER Y
SPARE2 NUMBER Y
SQL> desc plsql_profiler_data;
Name Type Nullable Default Comments
----------- ------ -------- ------- --------
RUNID NUMBER
UNIT_NUMBER NUMBER
LINE# NUMBER
TOTAL_OCCUR NUMBER Y
TOTAL_TIME NUMBER Y
MIN_TIME NUMBER Y
MAX_TIME NUMBER Y
SPARE1 NUMBER Y
SPARE2 NUMBER Y
SPARE3 NUMBER Y
SPARE4 NUMBER Y
A sequence PLSQL_PROFILER_RUNNUMBER provides the run id.
Running and Interpreting Profiler Data
Oracle provides three tables where statistics are populated for a run id. There are many third party tools available to provide customized reports based on this data. Oracle provides profrep.sql and profsum.sql to evaluate data (present in \plsql\demo\). Below I have provided two simple scripts used in the examples above, to check instantly on a program unit execution time. The execution time is stored in milli-seconds.
-----------------------------------------------------------
Script: call_profiler.sql
-----------------------------------------------------------
set head off
set pages 0
select decode(dbms_profiler.start_profiler, '0', 'Profiler started', 'Profiler error')
from dual;
--< place your routine in the below block >--
declare
l_status varchar2(200);
begin
am_perf_chk(2, l_status);
dbms_output.put_line(l_status);
end;
/
select decode(dbms_profiler.stop_profiler, '0', 'Profiler stopped', 'Profiler error')
from dual;
select decode(dbms_profiler.flush_data, '0', 'Profiler flushed', 'Profiler error')
from dual;
select 'runid:' || plsql_profiler_runnumber.currval
from dual;
set head on
set pages 200
-----------------------------------------------------------
Script: evaluate_profiler_results.sql
-----------------------------------------------------------
undef runid
undef owner
undef name
set verify off
select s.line "Line", p.total_occur "Occur", p.total_time "Msec", s.text "Text"
from all_source s, (select u.unit_owner, u.unit_name, u.unit_type, d.line#,
d.total_occur, d.total_time/1000000 total_time
from plsql_profiler_data d, plsql_profiler_units u
where u.runid = &&runid
and u.runid = d.runid
and u.unit_number = d.unit_number) p
where s.owner = p.unit_owner (+)
and s.name = p.unit_name (+)
and s.type = p.unit_type (+)
and s.line = p.line# (+)
and s.name = upper('&&name')
and s.owner = upper('&&owner')
order by s.line;
select exec.cnt/total.cnt * 100 "Code% coverage"
from (select count(1) cnt
from plsql_profiler_data d, plsql_profiler_units u
where d.runid = &&runid
and u.runid = d.runid
and u.unit_number = d.unit_number
and u.unit_name = upper('&&name')
and u.unit_owner = upper('&&owner')) total,
(select count(1) cnt
from plsql_profiler_data d, plsql_profiler_units u
where d.runid = &&runid
and u.runid = d.runid
and u.unit_number = d.unit_number
and u.unit_name = upper('&&name')
and u.unit_owner = upper('&&owner')
and d.total_occur > 0) exec;
undef runid
undef owner
undef name
----------------------------------------------------------------------------
A simple test.
create or replace procedure do_mod
as
cnt number := 0;
begin
dbms_profiler.start_profiler( 'mod' );
for i in 1 .. 500000
loop
cnt := cnt + 1;
if ( mod(cnt,1000) = 0 )
then
commit;
end if;
end loop;
dbms_profiler.stop_profiler;
end;
/
create or replace procedure no_mod
as
cnt number := 0;
begin
dbms_profiler.start_profiler( 'no mod' );
for i in 1 .. 500000
loop
cnt := cnt + 1;
if ( cnt = 1000 )
then
commit;
cnt := 0;
end if;
end loop;
dbms_profiler.stop_profiler;
end;
/
exec do_mod
exec no_mod
----------------------------------------------------------------------------
SQL> select * from plsql_profiler_runs;
RUNID RELATED_RUN RUN_OWNER RUN_DATE RUN_COMMENT RUN_TOTAL_TIME RUN_SYSTEM_INFO RUN_COMMENT1 SPARE1
---------- ----------- -------------- ----------- ----------------- -------------- --------------- ------------ ------
1 0 JUNK 21-Jan-04 7 mod 830462143652
2 0 JUNK 21-Jan-04 7 no mod 344864553455
SQL> select * from plsql_profiler_units;
RUNID UNIT_NUMBER UNIT_TYPE UNIT_OWNER UNIT_NAME UNIT_TIMESTAMP TOTAL_TIME SPARE1 SPARE2
---------- ----------- ------------ ------------ ----------- -------------- ---------- ---------- ----------
1 1 PROCEDURE JUNK DO_MOD 21-Jan-04 7:16 0
2 1 PROCEDURE JUNK NO_MOD 21-Jan-04 7:16 0
SQL> select * from plsql_profiler_data order by runid,line#;
RUNID UNIT_NUMBER LINE# TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME SPARE1 SPARE2 SPARE3 SPARE4
---------- ----------- ---------- ----------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
1 1 3 0 0 0 0
1 1 5 0 0 0 0
1 1 6 500001 8686428666 164546 507538527
1 1 8 500000 1084502521 173206 499184952
1 1 9 500000 5161927080 748419 3598695085
1 1 11 500 9778397533 12979303 474647476
1 1 14 1 1731504 1731504 1731504
1 1 15 0 0 0 0
2 1 3 0 0 0 0
2 1 5 0 0 0 0
2 1 6 500001 8246848412 155885 331121972
2 1 8 500000 8998179293 163707 659078458
2 1 9 500000 8943849763 169853 780866842
2 1 11 500 7846573237 12380065 553948895
2 1 12 500 98466983 173485 2169549
2 1 15 1 1704685 1704685 1704685
2 1 16 0 0 0 0
undef runid
undef owner
undef name
set verify off
select s.line "Line", p.total_occur "Occur", p.total_time "Msec", s.text "Text"
from all_source s, (select u.unit_owner, u.unit_name, u.unit_type, d.line#,
d.total_occur, d.total_time/1000000 total_time
from plsql_profiler_data d, plsql_profiler_units u
where u.runid = &&runid
and u.runid = d.runid
and u.unit_number = d.unit_number) p
where s.owner = p.unit_owner (+)
and s.name = p.unit_name (+)
and s.type = p.unit_type (+)
and s.line = p.line# (+)
and s.name = upper('&&name')
and s.owner = upper('&&owner')
order by s.line;
select exec.cnt/total.cnt * 100 "Code% coverage"
from (select count(1) cnt
from plsql_profiler_data d, plsql_profiler_units u
where d.runid = &&runid
and u.runid = d.runid
and u.unit_number = d.unit_number
and u.unit_name = upper('&&name')
and u.unit_owner = upper('&&owner')) total,
(select count(1) cnt
from plsql_profiler_data d, plsql_profiler_units u
where d.runid = &&runid
and u.runid = d.runid
and u.unit_number = d.unit_number
and u.unit_name = upper('&&name')
and u.unit_owner = upper('&&owner')
and d.total_occur > 0) exec;
undef runid
undef owner
undef name
Line Occur Msec Text
---------- ---------- ---------- --------------------------------------------------------------------------------
1 procedure do_mod
2 as
3 0 0 cnt number := 0;
4 begin
5 0 0 dbms_profiler.start_profiler( 'mod' );
6 500001 86864.2866 for i in 1 .. 500000
7 loop
8 500000 108450.252 cnt := cnt + 1;
9 500000 516192.708 if ( mod(cnt,1000) = 0 )
10 then
11 500 9778.39753 commit;
12 end if;
13 end loop;
14 1 1.731504 dbms_profiler.stop_profiler;
15 0 0 end;
16
17
Code% coverage
--------------
62.5
Line Occur Msec Text
---------- ---------- ---------- --------------------------------------------------------------------------------
1 procedure no_mod
2 as
3 0 0 cnt number := 0;
4 begin
5 0 0 dbms_profiler.start_profiler( 'no mod' );
6 500001 82468.4841 for i in 1 .. 500000
7 loop
8 500000 89981.7929 cnt := cnt + 1;
9 500000 89438.4976 if ( cnt = 1000 )
10 then
11 500 7846.57323 commit;
12 500 98.466983 cnt := 0;
13 end if;
14 end loop;
15 1 1.704685 dbms_profiler.stop_profiler;
16 0 0 end;
17
18
Code% coverage
--------------
66.66666666666
-------------------------------------------------------------------------------------------------------------------
-- connect as SYS
@E:\oracle\ora92\rdbms\admin\profload.sql
-- connect as schema owner
SQL*Plus
@E:\oracle\ora92\rdbms\admin\proftab.sql
@E:\oracle\ora92\plsql\demo\profrep.sql
GRANT create session TO ;
GRANT create procedure TO ;
GRANT create sequence TO ;
GRANT create table TO ;
GRANT create view TO ;
CREATE OR REPLACE PROCEDURE profreset IS
BEGIN
DELETE FROM plsql_profiler_data;
DELETE FROM plsql_profiler_units;
DELETE FROM plsql_profiler_runs;
COMMIT;
END profreset;
/
---------------
--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 a40
column runid format 9999
column secs format 99999.99
column hsecs format 999999.99
column grand_total format 9999.99
column run_comment format a40
column line# format 99999
column pct format 999.9
column unit_owner format a11
spool profsum.log
/* 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/100000000000 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/100000000000 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, '', '',
substr(p1.unit_name,1, 20)) as unit_name,
p1.total_time/100000000000 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 9999.99
prompt =
prompt =
prompt ====================
prompt Percentage of time in each module, summarized across runs
select p1.unit_owner,
decode(p1.unit_name, '', '', substr(p1.unit_name,1, 25)) as unit_name,
p1.total_time/100000000000 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/1000000000 as Hsecs,
p1.total_time/p4.grand_total*100 as pct,
substr(p2.unit_owner, 1, 20) as owner,
decode(p2.unit_name, '', '', 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/1000000000 as hsecs,
p1.total_time/p4.grand_total*100 as pct,
substr(p1.unit_owner, 1, 20) as unit_owner,
decode(p1.unit_name, '', '',
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.log
set linesize 200
====================
Total time
GRAND_TOTAL
-----------
9.96
=
=
====================
Total time spent on each run
RUNID RUN_COMMENT SECS
----- ---------------------------------------- ---------
5 mod 7.14
6 no mod 2.82
=
=
====================
Percentage of time in each module, for each run separately
RUNID RUN_COMMENT UNIT_OWNER UNIT_NAME SECS PERCEN
----- ---------------------------------------- ----------- -------------- --------- ------
5 mod JUNK DO_MOD 7.14 100.0
6 no mod JUNK NO_MOD 2.82 100.0
=
=
====================
Percentage of time in each module, summarized across runs
UNIT_OWNER UNIT_NAME SECS PERCENTAG
----------- -------------- -------- ---------
JUNK DO_MOD 7.14 71.65
JUNK NO_MOD 2.82 28.35
=
=
====================
Lines taking more than 1% of the total time, each run separate
RUNID HSECS PCT OWNER UNIT_NAME LINE# TEXT
----- ---------- ------ ----------- -------------- ------ ----------------------------------------
5 508.20 51.0 JUNK DO_MOD 9 if ( mod(cnt,1000) = 0 )
5 110.42 11.1 JUNK DO_MOD 8 cnt := cnt + 1;
6 100.18 10.1 JUNK NO_MOD 6 for i in 1 .. 500000
6 87.27 8.8 JUNK NO_MOD 8 cnt := cnt + 1;
6 87.14 8.7 JUNK NO_MOD 9 if ( cnt = 1000 )
5 85.98 8.6 JUNK DO_MOD 6 for i in 1 .. 500000
6 rows selected.
=
=
====================
Most popular lines (more than 1%), summarize across all runs
HSECS PCT UNIT_OWNER UNIT_NAME LINE# TEXT
---------- ------ ----------- -------------- ------ ----------------------------------------
508.20 51.0 JUNK DO_MOD 9 if ( mod(cnt,1000) = 0 )
110.42 11.1 JUNK DO_MOD 8 cnt := cnt + 1;
100.18 10.1 JUNK NO_MOD 6 for i in 1 .. 500000
87.27 8.8 JUNK NO_MOD 8 cnt := cnt + 1;
87.14 8.7 JUNK NO_MOD 9 if ( cnt = 1000 )
85.98 8.6 JUNK DO_MOD 6 for i in 1 .. 500000
6 rows selected.
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
----------- -------------- -------------- ------------- ------
JUNK DO_MOD 5 8 62.5
JUNK NO_MOD 6 9 66.7
=
=
====================
Number of lines actually executed for all units
LINES_EXECUTED
--------------
11
=
=
====================
Total number of lines in all units
LINES_PRESENT
-------------
17