Sometimes when all the SQL statements are well tuned but the routine still takes noticeable time to execute.
DBMS_PROFILER
Oracle 8i provides a new tool called PL/SQL Profiler. This is a powerful tool to analyze a Program unit execution and determine the runtime behavior.
It gives execution time for individual statemenets in procedure, functtion or package.
This process will be implemented with DBMS_PROFILER package.
Following stats can be generated using this package:
Total # of times each line was executed.
Time spent executing each line. This include SQL statements.
Minimum and maximum duration spent on a specific line of code.
Code that is actually being executed for a given scenario.
CREATION of DBMS_PROFILER Package:
The DBMS_PROFILER package is not automatically created during default installation or creation of the database.
Need to create the package using the profload.sql script. (From $ORACLE_HOME/rdbms/admin)
Create tables for storing statistics either in one central user or in each individual user, using proftab.sql (From $ORACLE_HOME/rdbms/admin). 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.
A sequence PLSQL_PROFILER_RUNNUMBER provides the run id.
DBMS_PROFILER.START_PROFILER
This function tells oracle to start the monitoring process.
An identifier needs to be provided wit each run that is used later to retrieve the statistics.
For example,
v_runstatus := dbms_profiler.start_profiler(‘am’ || to_char(sysdate));
DBMS_PROFILER.STOP_PROFILER
This function tells Oracle to stop the monitoring.
For example,
v_runstatus := dbms_profiler.stop_profiler;
DBMS_PROFILER.FLUSH_DATA
The data collected for an execution is held in the memory. This function tells oracle to save this data in profiler tables and clear the memory.
For example,
v_runstatus := dbms_profiler.flush_data;
All above three functions return the following values :
0 : Successful completion.
1 : Incorrect parameters passed (error_parm).
2 : Data flush operation failed (error_io)
-1 : Mismatch between package and database implementation (error_version).
EXAMPLE USING DBMS_PROFILER
I created a small procedure in MCIF schema as following:
This is the procedure i want to tune and observer its runtime behaviour.
procedure pvm
as
begin
dbms_output.put_line(‘Hello World’);
end;
/
/**********************************
** call_prof.SQL, start and trace the procedure. This will also give a RUNID that will be used for
** check_prof.sql and eval_prof.sql scripts.
**********************************/
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 >—
set serveroutput on
declare
l_status varchar2(200);
begin
pvm;
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
This Above PLSQL block will also give you RUNID which you need to monitor. To view more details about RUNID use following script:
/*********************************
*** check_prof.sql. Chech RUNID wise details.
*********************************/
column runid format 99999999
column run_owner format a30
column run_date format a20
column run_comment format a30
column run_total_time format 9999999999999999
column secs format 99999999
set lines 132
set pages 300
SELECT runid,
run_owner,
run_date,
run_comment,
run_total_time/1000000000 as secs
FROM plsql_profiler_runs
ORDER BY runid
/
/**********************************
*** evel_prof.sql .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
**********************************/
undef runid
undef owner
undef name
column text format a50
set lines 151
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
/****************************
MY executions
****************************/
5:47:18 temp@AWRTEST:-> @call_prof
Profiler started
1 row selected.
Elapsed: 00:00:00.01
Hello World
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
Profiler stopped
1 row selected.
Elapsed: 00:00:00.04
Profiler flushed
1 row selected.
Elapsed: 00:00:00.01
runid:12
1 row selected.
Elapsed: 00:00:00.00
15:47:28 temp@AWRTEST:-> @check_prof
RUNID RUN_OWNER RUN_DATE RUN_COMMENT SECS
——— —————————— ——————– —————————— ———
1 MCIF 16-MAR-06 pvm: 16-MAR-06 0
2 MCIF 16-MAR-06 16-MAR-06 0
3 SYS 21-APR-06 21-APR-06 0
4 MCIF 21-APR-06 21-APR-06 0
5 MCIF 21-APR-06 21-APR-06 0
6 MCIF 21-APR-06 21-APR-06 0
7 MCIF 21-APR-06 21-APR-06 0
8 SYS 21-APR-06 21-APR-06 0
9 MCIF 21-APR-06 21-APR-06 0
10 MCIF 21-APR-06 21-APR-06 0
11 MCIF 21-APR-06 21-APR-06 0
12 MCIF 21-APR-06 21-APR-06 0
12 rows selected.
Elapsed: 00:00:00.01
15:48:16 temp@AWRTEST:-> @eval_prof
Enter value for runid: 12
Enter value for name: pvm
Enter value for owner: MCIF
Line Occur Msec Text
——— ——— ——— ————————————————–
1 0 .00367 procedure pvm
2 as
3 begin
4 1 .030977 dbms_output.put_line(‘Hello World’);
5 1 .003687 end;
5 rows selected.
Elapsed: 00:00:00.23
Code% coverage
————–
66.666667
1 row selected.
Elapsed: 00:00:00.04
15:49:07 temp@AWRTEST:->