With 11g release 1 Oracle has introduced new package DBMS_HPROF. It’s very useful for DBAs and developers to analyze execution of PL/SQL code. It enables to gather, store and organize a lot of information about executed code.
Informations gathered by this package are supported by Oracle sqldeveloper which is another great news :).
The PL/SQL hierarchical profiler features:
- easy to install and use
- collect execution times for SQL and PL/SQL code
- keeps results in database tables
- Provides subprogram-level execution summary information, such as:
- Number of calls to the subprogram
- Time spent in the subprogram itself
- Time spent in the subprogram itself and in its descendent’s subprograms
- Detailed parent-children information, for example:
- All callers of a given subprogram (parents)
- All subprograms that a given subprogram called (children)
- How much time was spent in subprogram x when called from y
- How many calls to subprogram x were from y
Installation
Installation consists of three steps
1. Grant execute privilege on package DBMS_HPROF to a database user
grant execute on DBMS_HPROF to tomasz;
2. Grant read, write privilege on a directory object to a database user
NOTE – Oracle sqldeveloper as default use directory plshprof_dir for profiler so I use the name to be consistent with Oracle sqldeveloper
connect / as sysdba create directory plshprof_dir as 'c:\temp'; grant read, write on directory plshprof_dir to tomasz;
3. Create hierarchical profiler tables in user schema. Call script dbmshptab.sql from $ORACLE_HOME.
connect tomasz@ora11g @?/rdbms/admin/dbmshptab.sql
Verification
New objects are created in user schema
select object_name, object_type from user_objects where object_name like 'DBMSH%' order by object_name; OBJECT_NAME OBJECT_TYPE --------------------------- ------------------- DBMSHP_FUNCTION_INFO TABLE DBMSHP_PARENT_CHILD_INFO TABLE DBMSHP_RUNNUMBER SEQUENCE DBMSHP_RUNS TABLE
| Table | Description |
| DBMSHP_RUNS | Contains information about runs |
| DBMSHP_FUNCTION_INFO | Contains information about each profiled function |
| DBMSHP_PARENT_CHILD_INFO | Contains parent-child relation for profiled functions |
Testing
First we need to create test code
create or replace package test_pkg is procedure test_1_prc; procedure test_2_prc; procedure test_3_prc; end; / create or replace package body test_pkg is procedure test_1_prc is begin test_2_prc; end; procedure test_2_prc is v_cnt number; begin test_3_prc; for i in 1..5 loop select count(*) into v_cnt from user_objects; end loop; end; procedure test_3_prc is v_cnt number; begin for i in 1..5 loop select count(*) into v_cnt from user_objects; end loop; end; end; /
Now we can run hierarchical profiler. It will create file with collected statistics. File is created in directory specified by parameter location.
begin dbms_hprof.start_profiling ( location => 'PLSHPROF_DIR', filename => 'plshprof_file.txt' ); test_pkg.test_1_prc; dbms_hprof.stop_profiling; end; /
Here is part of the generated file. Remember it has been created in directory PLSHPROF_DIR so you need to have access to review it.
P#V PLSHPROF Internal Version 1.0 P#! PL/SQL Timer Started P#C PLSQL."TOMASZ"."TEST_PKG"::11."TEST_1_PRC"#980980e97e42f8ec #3 P#X 2 P#C PLSQL."TOMASZ"."TEST_PKG"::11."TEST_2_PRC"#980980e97e42f8ec #9 P#X 2 P#C PLSQL."TOMASZ"."TEST_PKG"::11."TEST_3_PRC"#980980e97e42f8ec #23 P#X 15 P#C SQL."TOMASZ"."TEST_PKG"::11."__static_sql_exec_line29" #29 P#X 67470 P#R P#X 48 P#C SQL."TOMASZ"."TEST_PKG"::11."__static_sql_exec_line29" #29 P#X 43162 P#R ... P#C SQL."TOMASZ"."TEST_PKG"::11."__static_sql_exec_line17" #17 P#X 37831 P#R P#X 17 P#C SQL."TOMASZ"."TEST_PKG"::11."__static_sql_exec_line17" #17 P#X 40269 P#R P#X 11 P#R P#X 1 P#R P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #59 P#R P#! PL/SQL Timer Stopped
These are meanings for prefixes in the file
- P#V – PLSHPROF banner with version number
- P#C – call to subprogram (call event)
- P#R – return from subprogram
- P#X – elapsed time between preceding and following events
- P#! – Comment
Instead of reviewing file you can analyze it and load to Oracle profiler tables. The code is returning on display run identifier which will be used later for reviewing data in profiler tables.
set serveroutput on
declare
v_runid number;
begin
v_runid := dbms_hprof.analyze
( location => 'PLSHPROF_DIR',
filename => 'plshprof_file.txt',
run_comment => 'First run' );
dbms_output.put_line('Run id: '||v_runid);
end;
/
anonymous block completed
Run id: 1
more details about parameters
DBMS_HPROF.ANALYZE ( location VARCHAR2, filename VARCHAR2, summary_mode BOOLEAN DEFAULT FALSE, trace VARCHAR2 DEFAULT NULL, skip PLS_INTEGER DEFAULT 0, collect PLS_INTEGER DEFAULT NULL, run_comment VARCHAR2 DEFAULT NULL) RETURN NUMBER;
Parameters description
- location – directory for profiler data
- filename – file name with profiler data
- summary_mode – default FALSE detailed analysis are done. If TRUE only top-level analysis are done
- trace – analyze only specified part of code. As default is NULL so analyzes are done for entire run. The trace entry must be specified in a special quoted qualified format (including the schema name, module name & function name) as in for example, ‘”
SCOTT“.”PKG“.”FOO“‘ or ‘””.””.”__plsql_vm“‘. If multiple overloads exist for the specified name, all of them will be analyzed. - skip – used only if trace parameter is specified. Specifies how much first invocations are skipped. The default is 0.
- collect – used only if trace is specified. Specified how much invocations are traced. Starts from skip+1’th invocation. The default is 1.
- run_comment – user comment
Review data in tables
DBMSHP_RUNS shows in micro seconds how much time it took to complete our procedure
select runid, total_elapsed_time, run_comment from dbmshp_runs where runid=1; RUNID TOTAL_ELAPSED_TIME RUN_COMMENT ------ ------------------ ------------ 1 5392417 First run
DBMSHP_FUNCTION_INFO shows aggregated information for each profiled function. For example you can find out how much time was consumed by a function or subprogram calls from the function.
select owner, module, type, function, line#, namespace, calls, function_elapsed_time, subtree_elapsed_time from dbmshp_function_info where runid=1; OWNER MODULE TYPE FUNCTION LINE# NAMESPACE CALLS FUNCTION_ELAPSED_TIME SUBTREE_ELAPSED_TIME ------ ---------- ------------ ------------------------ ----- --------- ----- --------------------- -------------------- SYS DBMS_HPROF PACKAGE BODY STOP_PROFILING 59 PLSQL 1 0 0 SYS DBMS_LOCK PACKAGE BODY SLEEP 197 PLSQL 5 4971896 4971896 TOMASZ TEST_PKG PACKAGE BODY TEST_1_PRC 3 PLSQL 1 2 5412752 TOMASZ TEST_PKG PACKAGE BODY TEST_2_PRC 9 PLSQL 1 93 5412750 TOMASZ TEST_PKG PACKAGE BODY TEST_3_PRC 23 PLSQL 1 190 5228468 TOMASZ TEST_PKG PACKAGE BODY __static_sql_exec_line17 17 SQL 5 184189 184189 TOMASZ TEST_PKG PACKAGE BODY __static_sql_exec_line29 29 SQL 5 256382 25638
DBMSHP_PARENT_CHILD_INFO table enables to create tree of execution for profiled code
select
lpad(' ', level, ' ')||pf.function||' -> '||cf.function call,
pc.subtree_elapsed_time,
pc.function_elapsed_time,
pc.calls,
cf.line#
from
(select * from dbmshp_parent_child_info where runid=1) pc,
dbmshp_function_info pf,
dbmshp_function_info cf
where pc.runid=pf.runid
and pc.parentsymid=pf.symbolid
and pc.runid=cf.runid
and pc.childsymid=cf.symbolid
connect by prior pc.childsymid=pc.parentsymid
start with pc.parentsymid = 3;
CALL SUBTREE_ELAPSED_TIME FUNCTION_ELAPSED_TIME CALLS LINE#
------------------------------------------ -------------------- --------------------- ---------- ----------
TEST_1_PRC -> TEST_2_PRC 5412750 93 1 9
TEST_2_PRC -> TEST_3_PRC 5228468 190 1 23
TEST_3_PRC -> SLEEP 4971896 4971896 5 197
TEST_3_PRC -> __static_sql_exec_line29 256382 256382 5 29
TEST_2_PRC -> __static_sql_exec_line17 184189 184189 5 17
plshprof tool
Another option to analyze your profiled code is to use command line utility plshprof.
It generates simple HTML reports directly from the raw profiler data, so can be used instead of loading data into Oracle tables.
$ORACLE_HOME\bin\plshprof
PLSHPROF: Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 – 64bit Production
Usage: plshprof [<option>…] <tracefile1> [<tracefile2>]
Options:
-trace <symbol> (no default) specify function name of tree root
-skip <count> (default=0) skip first <count> invokations
-collect <count> (default=1) collect info for <count> invokations
-output <filename> (default=<symbol>.html or <tracefile1>.html)
-summary print time only
plshprof c:\temp\plshprof_file.txt PLSHPROF: Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production [7 symbols processed] [Report written to 'c:\temp\plshprof_file.txt.html']
You can review output in browser to get details. It’s much easier then review data from tables.
Example screens
Sqldeveloper support
Sqldeveloper fully supports PL/SQL Hierarchical profiler and with a few simple clicks you can quickly get profiler data for your code.
You just need to select code that you want to profile and select Profile option. There are some extra screen (I’m not showing it here) where you can define more details what to profile. Once data are collected you can see it in tab “Profiles” for your procedure, function, package etc.
Sqldeveloper requires to create profiler tables in own schema and expects directory plshprof_dir. You are informed about the requirements when you first try to profile your data.
Have a fun 🙂
Tomasz
Man,
your expatiation is really good and help full for those who is new for Hierarchical Profiler.
Thanks
Kamlesh
Thanks such easy way to explain..