DBMS_Profiler
The DBMS_PROFILER package was introduced in Oracle8i
to allow developers to profile the run-time behaviour of PL/SQL code,
making it easier to identify performance bottlenecks which can then be
investigated more closely.
The Oracle PL/SQL profiler allows one to see how much time was spent on
each and every line of PL/SQL code.
Why is this important?
When tuning PL/SQL, it is important to see where time is being spent.
Without the ability to profile PL/SQL, one is simply guessing as to
where the time was spent.
When in use, three tables get populated with the run information:
PLSQL_PROFILER_RUNS
PLSQL_PROFILER_UNITS
PLSQL_PROFILER_DATA
The profiler session is initiated with a DBMS_PROFILER.START_PROFILER
The PL/SQL package, procedure, and/or function is then executed. When
the profiling session is complete, a DBMS_PROFILER.STOP_PROFILING
command is issued. During the profiling session, data is being
collected and populated into the three above-mentioned tables.
The PLSQL_PROFILER_RUNS has information about each time the profiler is
started, including the comment entered when the profiler session was
initiated.
The PLSQL_PROFILE_UNITS contains information about the PL/SQL code
executed during the run. Each procedure, function, and package will
have its own line in this table.
The PLSQL_PROFILE_DATA contains the executed lines of code, code
execution time, and more.
Link this table with USER_OBJECT to get the actual text code associated
with the profiling information.
The profiler is easy to setup and easy to use. Tools like Quest
Software’s TOAD provides a nice GUI interface to this profiler.
Installation
The first step is to install the DBMS_PROFILER package,
this package is not automatically loaded by Oracle:
CONNECT sys/password@service AS SYSDBA
@$ORACLE_HOME/rdbms/admin/profload.sql
CREATE USER profiler IDENTIFIED BY profiler DEFAULT TABLESPACE users QUOTA UNLIMITED ON users;
GRANT connect TO profiler;
GRANT create table to profiler;
GRANT create sequence to profiler;
CREATE or replace PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs;
CREATE or replace PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units;
CREATE or replace PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;
CREATE or replace PUBLIC SYNONYM plsql_profiler_runnumber FOR profiler.plsql_profiler_runnumber;
CONNECT profiler/profiler@service
@$ORACLE_HOME/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;
Understanding
the Profiler Process
Profiling is initiated with the START_PROFILER program. Start this
process then execute the PL/SQL routine to be profiled. When execution
is done, run the STOP_PROFILER program. This will stop the profiling
process and write the collected information to the profiler tables.
There are two more routines that control the collection of profiler
data: PAUSE_PROFILER and RESUME_PROFILER. These routines might be
useful if only certain statistics are of interest from a rather large
PL/SQL program, or
perhaps called subroutines are not desired to be profiled. These
routines are typically imbedded in the PL/SQL code.
The FLUSH_DATA routine can also be called to periodically write the
collected information to the profiler tables. This might be useful if
the STOP_PROFILER routine is taking an excessive amount of time when
profiling larger PL/SQL routines. This routine is typically embedded in
the PL/SQL code.
When the START_PROFILER routine is started, the Oracle RDBMS collects a
variety of information about the PL/SQL routine while it is being
executed. The STOP_PROFILER then stops this collection process and
writes the collected information to the three profiler tables.
These tables are then examined using SQL to view the results of the
profiler collection.
Quick
Example:
Connect as the user who owns the code to test. In this example, SCOTT
Then we create a dummy procedure to profile:
CREATE OR REPLACE PROCEDURE do_something (p_times IN NUMBER) AS
l_dummy NUMBER;
BEGIN
FOR i IN 1 .. p_times LOOP
SELECT l_dummy + 1
INTO l_dummy
FROM dual;
END LOOP;
END;
/
Next we start the profiler, run our procedure and stop the profiler:
DECLARE
l_result BINARY_INTEGER;
BEGIN
l_result := DBMS_PROFILER.start_profiler(run_comment => 'Run_do_something: ' || SYSDATE);
do_something(p_times => 100);
l_result := DBMS_PROFILER.stop_profiler;
END;
/
or
exec DBMS_PROFILER.START_PROFILER('Loop Example');
exec do_something(p_times => 100);
execute DBMS_PROFILER.STOP_PROFILER;
With the profile complete we can analyze the data to see which bits of
the process took the most time, with all times presented in
nanoseconds. First we check out
which runs we have:
SET LINESIZE 200
SET TRIMOUT ON
COLUMN runid FORMAT 99999
COLUMN run_comment FORMAT A50
SELECT runid, run_owner, run_date, run_comment
FROM plsql_profiler_runs
ORDER BY runid;
RUNID RUN_DATE RUN_COMMENT
------ ------------------ ---------------------------------------------
1 26/NOV/07 14:00:58 Run_do_something: 26/NOV/07 14:00:58
2 26/NOV/07 14:01:04 Loop Example
By default, when you query for the results, Oracle will place several
lines of ‘<anonymous>’ in the UNIT_OWNER column. This information
is the overhead that Oracle incurred executing the code, not the code
itself.
Since I am not interested in this clutter, I coded the SQL to just show
me the profiler information of interest to me. We can then use the
appropriate RUNID value in the following query:
COLUMN runid FORMAT 9999
COLUMN unit_number FORMAT 9999
COLUMN unit_type FORMAT A15
COLUMN unit_owner FORMAT A15
select runid, unit_number, unit_type, unit_owner, unit_timestamp, unit_name
from plsql_profiler_units
where unit_owner <> '<anonymous>'
and runid = &rpt_runid;
RUNID UNIT_NUMBER UNIT_TYPE UNIT_OWNER UNIT_TIMESTAMP UNIT_NAME
----- ----------- --------------- --------------- ------------------ --------------------------------
1 2 PROCEDURE SCOTT 26/NOV/07 14:00:25 DO_SOMETHING
Finally I join the tables with the user_source code table to get each
line of code and its execution times:
COLUMN unit_name FORMAT A20
COLUMN line# FORMAT 9999
COLUMN passes FORMAT 9999
COLUMN total_time FORMAT 999999.99999
select pu.unit_name, pd.line#, pd.total_occur passes,
round(pd.total_time / 1000000000,5) total_time, us.text text
from plsql_profiler_data pd, plsql_profiler_units pu, user_source us
where pd.runid = &rpt_runid
and pd.unit_number = &rpt_unitid
and pd.runid = pu.runid
and pd.unit_number = pu.unit_number
and us.name = pu.unit_name
and us.line = pd.line#
and us.type in ('PACKAGE BODY','PROCEDURE','FUNCTION');
UNIT_NAME LINE# PASSES TOTAL_TIME TEXT
--------------- ---------- ---------- ---------- ---------------------------------------------
DO_SOMETHING 1 1 .00001 PROCEDURE do_something (p_times IN NUMBER)
AS
DO_SOMETHING 4 101 .00003 FOR i IN 1 .. p_times LOOP
DO_SOMETHING 5 100 .00515 SELECT l_dummy + 1
DO_SOMETHING 9 1 0 END;
Finally, this code cleans up the profiler tables.
delete
from plsql_profiler_data;
delete from plsql_profiler_units;
delete from plsql_profiler_runs;
commit;
All these steps can be easily performed by executing the following SCRIPT.
TOAD Users
Quest Software has implemented the PL/SQL Profiler into the TOAD tool.
This option has been available for quite a while.
It's very easy to use and the whole process is easily handled from the
TOAD environment.
Starting and stopping the profiler is easily accomplished by clicking
on the Toggle PL/SQL Profiler button .
If this button is grayed out, then the TOAD Server Side objects need to
be executed (Tools ! Server Side Objects Wizard).
Click the Toggle PL/SQL Profiler button again to stop profiling.
The same profile tables are populated but TOAD also formats this same
outout using a nice interactive wizard.
Use Database ! Profiler Analysis menu item to access the Profiler
Analysis.
The output is easily visible.
Select your executed code from the list and click on the arrow button
in the circle.