DBMS_PROFILER Package



http://www.dba-oracle.com/plsql/t_plsql_profiler.htm

The following Tip is from the outstanding book "Oracle PL/SQL Tuning: Expert Secrets for High Performance Programming" by Dr. Tim Hall, Oracle ACE of the year, 2006:

The dbms_profiler package was introduced in Oracle 8i to allow developers to profile the run-time behavior of PL/SQL code, making it easier to identify performance bottlenecks that can then be investigated more closely.  This section will show how to install and use the profiler, starting with the installation process.

The dbms_profiler package can be loaded by running the $ORACLE_HOME/rdbms/admin/profload.sql script as the SYS user.  The package requires some schema objects, which can be loaded into each schema that uses the profiler or into a central schema.  The schema objects are created by running the $ORACLE_HOME/rdbms/admin/proftab.sql script.

The profiler_setup.sql loads the profiler package, creates a user to hold the profiler schema objects, creates the profiler schema objects and grants the necessary privileges.

profiler_setup.sql

CONN sys/password AS SYSDBA
@$ORACLE_HOME/rdbms/admin/profload.sql

CREATE USER profiler IDENTIFIED BY profiler DEFAULT TAB
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
@$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;

The public grants and synonyms mean that any user in the database can profile their PL/SQL.  To restrict its usage simply alter these grant statements.

Now that the profiler is installed, some PL/SQL is needed to profile.  The profiler_test.sql script creates a procedure that performs a simple query and number conversions. 

profiler_test.sql

CREATE OR REPLACE PROCEDURE profiler_test (p_loops  IN  NUMBER) AS
  l_dummy  NUMBER := 0;
BEGIN
  FOR i IN 1 .. p_loops LOOP
    SELECT l_dummy + 1
    INTO   l_dummy
    FROM   dual;   

    l_dummy := TO_NUMBER(TO_CHAR(l_dummy -1));
  END LOOP;
END;
/
SHOW ERRORS

The run_profiler.sql script initiates the profiler, calls the test procedure and stops the profiler.

run_profiler.sql

DECLARE
  l_result  BINARY_INTEGER;
BEGIN
  l_result := DBMS_PROFILER.start_profiler(run_comment => 'profiler_test: ' || SYSDATE);
  profiler_test(p_loops => 100);
  l_result := DBMS_PROFILER.stop_profiler;
END;
/

The run_profiler.sql script must be run before moving on to the next step.

SQL> @run_profiler.sql

PL/SQL procedure successfully completed.

Once the profile run is complete, the profiler tables can be queried to access the data for the run.  The profiler_runs.sql script displays a list of profiler runs ordered by the runid.

profiler_runs.sql

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;

The output from this script is listed below.

SQL> @profiler_runs.sql

 RUNID RUN_DATE             RUN_COMMENT                          RUN_TOTAL_TIME
------ -------------------- ------------------------------------ --------------
     1 05-APR-2005 13:17:51 profiler_test: 05-APR-2005 13:17:51      1.8829E+10

1 row selected.

SQL>

After the profiler run has been identified, the data associated with this run can be viewed by executing the profiler_run_details.sql script.

profiler_run_details.sql

-- *****************************************************************
-- Parameters:
--   1) runid - The runid identified by the profiler_runs.sql script.
-- *****************************************************************

SET LINESIZE 200
SET VERIFY OFF

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,
       ROUND(d.total_time/d.total_occur) as time_per_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
AND    d.total_time > 0
AND    d.total_occur > 0
ORDER BY (d.total_time/d.total_occur) DESC, u.unit_number, d.line#;

The profiler_run_details.sql script ignores any rows which have executed too quickly to measure and orders the output by the time per occurrence of the line.  All times are calculated in nanoseconds (10-9 seconds).  The output from this script, using the previously identified runid, is displayed below.

SQL> @profiler_run_details.sql 1

 RUNID UNIT_NUMBER UNIT_TYPE       UNIT_OWNER  UNIT_NAME      LINE# TOTAL_OCCUR TIME_PER_OCCUR TOTAL_TIME MIN_TIME  MAX_TIME
------ ----------- --------------- ----------- -------------- ----- ----------- --------------      1           2 PROCEDURE       TEST        PROFILER_TEST      5         100      110530227 1.1053E+10 85586296 682353762
      1           1 ANONYMOUS BLOCK <anonymous> <anonymous>        5           1       41622049   41622049 41622049  41622049
      1           2 PROCEDURE       TEST        PROFILER_TEST      9         100        5092658  509265842  4211708   9108420        1           1 ANONYMOUS BLOCK <anonymous>
<anonymous>        6           1        4843073    4843073  4843073   4843073
      1           2 PROCEDURE       TEST        PROFILER_TEST     11           1       
3675327    3675327  3675327   3675327
      1           2 PROCEDURE       TEST        PROFILER_TEST      2           1        
741993     741993   741993    741993
      1           2 PROCEDURE       TEST        PROFILER_TEST      4         101        
472520   47724501   273777   4791670

7 rows selected.

The references to the anonymous block can be ignored as this is simply the calling code.  Displaying the source along with the line numbers will help in the interpretation of the output.  This can be done using the following query.

SQL> SELECT line || ' : ' || text AS source
  2  FROM   user_source
  3  WHERE  type  = 'PROCEDURE'
  4  AND    name  = 'PROFILER_TEST';

SOURCE
----------------------------------------------------
1 : PROCEDURE profiler_test (p_loops  IN  NUMBER) AS
2 :   l_dummy  NUMBER := 0;
3 : BEGIN
4 :   FOR i IN 1 .. p_loops LOOP
5 :     SELECT l_dummy + 1
6 :     INTO   l_dummy
7 :     FROM   dual;
8 :
9 :     l_dummy := TO_NUMBER(TO_CHAR(l_dummy -1));
10 :   END LOOP;
11 : END;

11 rows selected.

This information shows that line 5, the query, ran 10 times with a time per occurrence of 110,530,227 nanoseconds (approximately 0.11 seconds).  In comparison line 9, the number conversion and assignment, executes the same number of times but has a significantly quicker time per occurrence (approximately 0.005 seconds).  Notice that the for-loop (line 4) executes 101 times.  This is typical as it is the 101st execution in which the loop condition is no longer true so the loop terminates.

This demonstrates how easy it is to identify bottlenecks in PL/SQL procedure and functions.  The output of this trace is focused on the speed of the lines being executed. 

---PL/SQL developer