Fw how to use DBMS_PROFILER

DBMS_PROFILER
The DBMS_PROFILER package was introduced in Oracle8i to allows 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 first step is to install the DBMS_PROFILER package:
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;

CREATE PUBLIC SYNONYM plsql_profiler_runs FOR profiler.plsql_profiler_runs;
CREATE PUBLIC SYNONYM plsql_profiler_units FOR profiler.plsql_profiler_units;
CREATE PUBLIC SYNONYM plsql_profiler_data FOR profiler.plsql_profiler_data;
CREATE 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;
Next 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 => 'do_something: ' || SYSDATE);
do_something(p_times => 100);
l_result := DBMS_PROFILER.stop_profiler;
END;
/
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_date,
run_comment,
run_total_time
FROM plsql_profiler_runs
ORDER BY runid;

RUNID RUN_DATE RUN_COMMENT RUN_TOTAL_TIME
----- --------- ---------------------------------- --------------
1 21-AUG-03 do_something: 21-AUG-2003 14:51:54 131072000
We can then use the appropriate RUNID value in the following query:
COLUMN runid FORMAT 99999
COLUMN unit_number FORMAT 99999
COLUMN unit_type FORMAT A20
COLUMN unit_owner FORMAT A20

SELECT u.runid,
u.unit_number,
u.unit_type,
u.unit_owner,
u.unit_name,
d.line#,
d.total_occur,
d.total_time,
d.min_time,
d.max_time
FROM plsql_profiler_units u
JOIN plsql_profiler_data d ON u.runid = d.runid AND u.unit_number = d.unit_number
WHERE u.runid = 1
ORDER BY u.unit_number, d.line#;

RUNID UNIT_NU UNIT_TYPE UNIT_OWNER UNIT_NAME LINE# TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
----- ------- --------------- ----------- ------------ ----- ----------- ---------- -------- --------
1 1 ANONYMOUS BLOCK 4 1 0 0 0
1 1 ANONYMOUS BLOCK 5 1 0 0 0
1 1 ANONYMOUS BLOCK 6 1 0 0 0
1 2 PROCEDURE MY_SCHEMA DO_SOMETHING 4 101 0 0 0
1 2 PROCEDURE MY_SCHEMA DO_SOMETHING 5 100 17408000 0 2048000

5 rows selected.
The results of this query show that line 4 of the DO_SOMETHING procedure ran 101 times but took very little time, while line 5 ran 100 times and took proportionately more time. We can check the line numbers of the source using the following query:
SELECT line || ' : ' || text
FROM all_source
WHERE owner = 'MY_SCHEMA'
AND type = 'PROCEDURE'
AND name = 'DO_SOMETHING';

LINE||':'||TEXT
---------------------------------------------------
1 : PROCEDURE do_something (p_times IN NUMBER) AS
2 : l_dummy NUMBER;
3 : BEGIN
4 : FOR i IN 1 .. p_times LOOP
5 : SELECT l_dummy + 1
6 : INTO l_dummy
7 : FROM dual;
8 : END LOOP;
9 : END;
As expected, the query took proportionately more time than the procedural loop. Assuming this were a real procedure we could use the DBMS_TRACE or the SQL trace facilities to investigate the problem area further.

For further information see:
DBMS_PROFILER
DBMS_TRACE
Hope this helps. Regards Tim...