DBMS_PROFILER

The DBMS_PROFILER package was introduced in Oracle8i to allow developers to profile the run-time behavior of PL/SQL code, making it easier to identify performance bottlenecks which can then be investigated more closely.

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 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;