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.