8i | 9i | 10g | 11g | 12c | 13c | 18c | 19c | 21c | 23c | Misc | PL/SQL | SQL | RAC | WebLogic | Linux
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. In versions prior to 18c this is done by running the "$ORACLE_HOME/rdbms/admin/dbmshptab.sql" script.
CONN test/test@db11g @?/rdbms/admin/dbmshptab.sql
From 18c onward the tables are created by running the CREATE_TABLES
procedure.
-- First time. EXEC DBMS_HPROF.create_tables; -- Recreate objects if present. EXEC DBMS_HPROF.create_tables(force_it => TRUE);
Depending on the database version, you will have 3-4 tables and 1-2 sequences.
SQL> SELECT table_name FROM user_tables ORDER BY 1; TABLE_NAME ------------------------------ DBMSHP_FUNCTION_INFO DBMSHP_PARENT_CHILD_INFO DBMSHP_RUNS DBMSHP_TRACE_DATA SQL> SELECT sequence_name FROM user_sequences; SEQUENCE_NAME ------------------------------ DBMSHP_RUNNUMBER DBMSHP_TRACENUMBER 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...