PL/SQL Hierarchical Profiler Oracle Database 11G release 2 (11.2)

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

profiler_report1 profiler_report2

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.

profiler_sqldeveloper1

Have a fun 🙂

Tomasz

 

 

 

 

 

 

2 thoughts on “PL/SQL Hierarchical Profiler Oracle Database 11G release 2 (11.2)

  1. Man,
    your expatiation is really good and help full for those who is new for Hierarchical Profiler.

    Thanks
    Kamlesh

Leave a Reply

Your email address will not be published. Required fields are marked *