8i | 9i | 10g | 11g | 12c | 13c | 18c | Misc | PL/SQL | SQL | RAC | WebLogic | Linux

Home » Articles » 11g » Here

PL/SQL Hierarchical Profiler in Oracle Database 11g Release 1 (DBMS_HPROF, plshprof)

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

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                 31262 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 TEST                 DO_SOMETHING_1       PROCEDURE            DO_SOMETHING_1
         2 TEST                 DO_SOMETHING_2       PROCEDURE            DO_SOMETHING_2
         3 TEST                 DO_SOMETHING_3       PROCEDURE            DO_SOMETHING_3
         4 SYS                  DBMS_HPROF           PACKAGE BODY         STOP_PROFILING
         5 TEST                 DO_SOMETHING_3       PROCEDURE            __static_sql_exec_line5

5 rows selected.

SQL>

We can combine this with the information from the dbmshp_parent_child_info table to display the hierarchical view of the data. for the specific RUNID.

SET LINESIZE 500 PAGESIZE 1000
COLUMN name FORMAT A100

SELECT RPAD(' ', (level-1)*2, ' ') || a.name AS name,
       a.subtree_elapsed_time,
       a.function_elapsed_time,
       a.calls
FROM   (SELECT fi.symbolid,
               pci.parentsymid,
               RTRIM(fi.owner || '.' || fi.module || '.' || NULLIF(fi.function,fi.module), '.') AS name,
               NVL(pci.subtree_elapsed_time, fi.subtree_elapsed_time) AS subtree_elapsed_time,
               NVL(pci.function_elapsed_time, fi.function_elapsed_time) AS function_elapsed_time,
               NVL(pci.calls, fi.calls) AS calls
        FROM   dbmshp_function_info fi
               LEFT JOIN dbmshp_parent_child_info pci ON fi.runid = pci.runid AND fi.symbolid = pci.childsymid
        WHERE  fi.runid = 1
        AND    fi.module != 'DBMS_HPROF') a
CONNECT BY a.parentsymid = PRIOR a.symbolid
START WITH a.parentsymid IS NULL;

NAME                                                SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME      CALLS
--------------------------------------------------- -------------------- --------------------- ----------
TEST.DO_SOMETHING_1                                                31262                    31          1
  TEST.DO_SOMETHING_2                                              31231                   133         10
    TEST.DO_SOMETHING_3                                            31098                  3241        100
      TEST.DO_SOMETHING_3.__static_sql_exec_line5                  27857                 27857       1000

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 more information see:

Hope this helps. Regards Tim...

Back to the Top.