PL/SQL Hierarchical Profiler in Oracle Database 11g Release 1

The PL/SQL hierarchical profiler was introduced in Oracle 11g Release 1 to allow developers to gather and analyze hierarchical profiler data for PL/SQL programs. The hierarchical profiler consists of the DBMS_HPROF package, which feels similar to the DBMS_PROFILER and DBMS_TRACE packages, and the plshprof command line utility to converts the profile information into HTML format.

DBMS_HPROF
plshprof

DBMS_HPROF

The DBMS_HPROF package is installed by default, but to use it we need to grant execute permission on the package, and provide a directory to write the raw profiler information to.

CONN sys/password@db11g AS SYSDBA
GRANT EXECUTE ON dbms_hprof TO test;

CREATE OR REPLACE DIRECTORY profiler_dir AS '/tmp/';
GRANT READ, WRITE ON DIRECTORY profiler_dir TO test;

We can now use the profiler from the test user, but in order to analyze the results, we need to install the hierarchical profiler tables in the test user by running the "$ORACLE_HOME/rdbms/admin/dbmshptab.sql" script.

CONN test/test@db11g
@?/rdbms/admin/dbmshptab.sql

This script creates three tables and a sequence in the test user.

SQL> SELECT table_name FROM user_tables;

TABLE_NAME
------------------------------
DBMSHP_PARENT_CHILD_INFO
DBMSHP_FUNCTION_INFO
DBMSHP_RUNS

3 rows selected.

SQL> SELECT sequence_name FROM user_sequences;

SEQUENCE_NAME
------------------------------
DBMSHP_RUNNUMBER

1 row selected.

SQL>

Next we create some dummy procedures to profile. The do_something_1 procedure calls the do_something_2 procedure, which in turn calls the do_something_3 procedure.

CREATE OR REPLACE PROCEDURE do_something_3 (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;
/

CREATE OR REPLACE PROCEDURE do_something_2 (p_times  IN  NUMBER) AS
BEGIN
  FOR i IN 1 .. p_times LOOP
    do_something_3(p_times => p_times);
  END LOOP;
END;
/

CREATE OR REPLACE PROCEDURE do_something_1 (p_times  IN  NUMBER) AS
BEGIN
  FOR i IN 1 .. p_times LOOP
    do_something_2(p_times => p_times);
  END LOOP;
END;
/

Next we start the hierarchical profiler using the START_PROFILING procedure, run the do_something_1 procedure and stop the profiler using the STOP_PROFILING procedure.

BEGIN
  DBMS_HPROF.start_profiling (
    location => 'PROFILER_DIR',
    filename => 'profiler.txt');
   
  do_something_1(p_times => 10);

  DBMS_HPROF.stop_profiling;
END;
/

PL/SQL procedure successfully completed.

SQL>

With the profile complete we can run the ANALYZE function to analyze the raw data and place it in the hierarchical profiler tables.

SET SERVEROUTPUT ON
DECLARE
  l_runid  NUMBER;
BEGIN
  l_runid := DBMS_HPROF.analyze (
               location    => 'PROFILER_DIR',
               filename    => 'profiler.txt',
               run_comment => 'Test run.');
                    
  DBMS_OUTPUT.put_line('l_runid=' || l_runid);
END;
/
l_runid=1

PL/SQL procedure successfully completed.

SQL>

The output shows us the RUNID of the analyze run. We can also find this in the DBMSHP_RUNS table.

SET LINESIZE 200
SET TRIMOUT ON

COLUMN runid FORMAT 99999
COLUMN run_timestamp FORMAT A30
COLUMN run_comment FORMAT A50
SELECT runid,
       run_timestamp,          
       total_elapsed_time,    
       run_comment          
FROM   dbmshp_runs
ORDER BY runid;

 RUNID RUN_TIMESTAMP                  TOTAL_ELAPSED_TIME RUN_COMMENT
------ ------------------------------ ------------------ -------------------------------------------
     1 31-AUG-2007 11:01:57.403778                 98515 Test run.

1 row selected.

SQL>

We use the appropriate RUNID value to query the DBMSHP_FUNCTION_INFO table.

COLUMN owner FORMAT A20
COLUMN module FORMAT A20
COLUMN type FORMAT A20
COLUMN function FORMAT A25

SELECT symbolid,
       owner,
       module,
       type,
       function
FROM   dbmshp_function_info
WHERE  runid = 1
ORDER BY symbolid;

  SYMBOLID OWNER                MODULE               TYPE                 FUNCTION
---------- -------------------- -------------------- -------------------- -------------------------
         1 SYS                  DBMS_HPROF           PACKAGE BODY         STOP_PROFILING
         2 TEST                 DO_SOMETHING_1       PROCEDURE            DO_SOMETHING_1
         3 TEST                 DO_SOMETHING_2       PROCEDURE            DO_SOMETHING_2
         4 TEST                 DO_SOMETHING_3       PROCEDURE            DO_SOMETHING_3
         5 TEST                 DO_SOMETHING_3       PROCEDURE            __static_sql_exec_line5

5 rows selected.

SQL>

This output allows us to identify the SYMBOLID of our top level procedure. In this case we can see that the do_something_1 procedure has a SYMBOLID of "2". We can use this value to query the hierarchical information.

SET LINESIZE 130
COLUMN name FORMAT A30
COLUMN function FORMAT A25
SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
       fi.function,
       pci.subtree_elapsed_time,
       pci.function_elapsed_time,
       pci.calls
FROM   dbmshp_parent_child_info pci
       JOIN dbmshp_function_info fi ON pci.runid = fi.runid AND pci.childsymid = fi.symbolid
WHERE  pci.runid = 1
CONNECT BY PRIOR childsymid = parentsymid
START WITH pci.parentsymid = 2;

NAME                           FUNCTION                  SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME      CALLS
------------------------------ ------------------------- -------------------- --------------------- ----------
  TEST.DO_SOMETHING_2          DO_SOMETHING_2                           98402                   959         10
    TEST.DO_SOMETHING_3        DO_SOMETHING_3                           97443                 10431        100
      TEST.DO_SOMETHING_3      __static_sql_exec_line5                  87012                 87012       1000

3 rows selected.

SQL>

The results display the hierarchy of function calls, along with elapsed times for the function and the subtree as a whole.

plshprof

The plshprof utility provides an alternative to analyzing and querying the data manually. More detail about the utility can be found here, but for now we will stick with a basic example. The following command line shows the generation of a HTML file (/tmp/plshprof_output.html) from the profiler raw data file (/tmp/profiler.txt).

$ plshprof -output /tmp/plshprof_output /tmp/profiler.txt
PLSHPROF: Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
[5 symbols processed]
[Report written to '/tmp/plshprof_output.html']
$

The HTML output from the utility can be seen on the plshprof_output.html page.

When provided with two raw data files, the plshprof utility produces a difference report. The following code performs a second profiler run, with the number of loops set to "20".

BEGIN
  DBMS_HPROF.start_profiling (
    location => 'PROFILER_DIR',
    filename => 'profiler2.txt');
   
  do_something_1(p_times => 20);

  DBMS_HPROF.stop_profiling;
END;
/

PL/SQL procedure successfully completed.

SQL>

We can now run a difference report using the two data files.

$ plshprof -output /tmp/plshprof_diff_output /tmp/profiler.txt /tmp/profiler2.txt
PLSHPROF: Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
[5 symbols processed]
[Report written to '/tmp/plshprof_diff_output.html']
$

The HTML output from the utility can be seen on the plshprof_diff_output.html page.

For further information see:

Hope this helps. Regards Tim...

Back to the Top.