13 Using the PL/SQL Hierarchical Profiler

You can use the PL/SQL hierarchical profiler to identify bottlenecks and performance-tuning opportunities in PL/SQL applications.

The profiler reports the dynamic execution profile of a PL/SQL program organized by function calls, and accounts for SQL and PL/SQL execution times separately. No special source or compile-time preparation is required; any PL/SQL program can be profiled.

This chapter describes the PL/SQL hierarchical profiler and explains how to use it to collect and analyze profile data for a PL/SQL program.

Topics:

13.1 Overview of PL/SQL Hierarchical Profiler

Nonhierarchical (flat) profilers record the time that a program spends within each subprogram—the function time or self time of each subprogram. Function time is helpful, but often inadequate. For example, it is helpful to know that a program spends 40% of its time in the subprogram INSERT_ORDER, but it is more helpful to know which subprograms call INSERT_ORDER often and the total time the program spends under INSERT_ORDER (including its descendant subprograms). Hierarchical profilers provide such information.

The PL/SQL hierarchical profiler:

  • Reports the dynamic execution profile of your PL/SQL program, organized by subprogram calls

  • Accounts for SQL and PL/SQL execution times separately

  • Requires no special source or compile-time preparation

  • Stores results in database tables (hierarchical profiler tables) for custom report generation by integrated development environment (IDE) tools (such as SQL Developer and third-party tools)

  • Provides subprogram-level execution summary information, such as:

    • Number of calls to the subprogram

    • Time spent in the subprogram itself (function time or self time)

    • Time spent in the subprogram itself and in its descendent subprograms (subtree time)

    • 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

The PL/SQL hierarchical profiler is implemented by the DBMS_HPROF package and has two components:

  • Data collection

    The data collection component is an intrinsic part of the PL/SQL Virtual Machine. The DBMS_HPROF package provides APIs to turn hierarchical profiling on and off and write the raw profiler output to a file.

  • Analyzer

    The analyzer component processes the raw profiler output and stores the results in hierarchical profiler tables.

    Note:

    To generate simple HTML reports directly from raw profiler output, without using the Analyzer, you can use the plshprof command-line utility.

13.2 Collecting Profile Data

To collect profile data from your PL/SQL program for the PL/SQL hierarchical profiler, follow these steps:

  1. Ensure that you have these privileges:

    • EXECUTE privilege on the DBMS_HPROF package

    • WRITE privilege on the directory that you specify when you call DBMS_HPROF.START_PROFILING

  2. Use the DBMS_HPROF.START_PROFILING PL/SQL API to start hierarchical profiler data collection in a session.

  3. Run your PL/SQL program long enough to get adequate code coverage.

    To get the most accurate measurements of elapsed time, avoid unrelated activity on the system on which your PL/SQL program is running.

  4. Use the DBMS_HPROF.STOP_PROFILING PL/SQL API to stop hierarchical profiler data collection.

For more information about DBMS_HPROF.START_PROFILING and DBMS_HPROF.STOP_PROFILING, see Oracle Database PL/SQL Packages and Types Reference.

Consider this PL/SQL procedure, test:

CREATE OR REPLACE PROCEDURE test AUTHID DEFINER IS
  n NUMBER;

  PROCEDURE foo IS
  BEGIN
    SELECT COUNT(*) INTO n FROM EMPLOYEES;
  END foo;

BEGIN  -- test
  FOR i IN 1..3 LOOP
    foo;
  END LOOP;
END test;
/

The SQL script in Example 13-1 profiles the execution of the PL/SQL procedure test.

Example 13-1 Profiling a PL/SQL Procedure

BEGIN
  /* Start profiling.
     Write raw profiler output to file test.trc in a directory
     that is mapped to directory object PLSHPROF_DIR
     (see note after example). */

  DBMS_HPROF.START_PROFILING('PLSHPROF_DIR', 'test.trc');
END;
/
-- Run procedure to be profiled
BEGIN
  test;
END;
/
BEGIN
  -- Stop profiling
  DBMS_HPROF.STOP_PROFILING;
END;
/

Note:

A directory object is an alias for a file system path name. For example, if you are connected to the database AS SYSDBA, this CREATE DIRECTORY statement creates the directory object PLSHPROF_DIR and maps it to the file system directory /private/plshprof/results:
CREATE DIRECTORY PLSHPROF_DIR as '/private/plshprof/results';

To run the SQL script in Example 13-1, you must have READ and WRITE privileges on both PLSHPROF_DIR and the directory to which it is mapped. if you are connected to the database AS SYSDBA, this GRANT statement grants READ and WRITE privileges on PLSHPROF_DIR to HR:

GRANT READ, WRITE ON DIRECTORY PLSHPROF_DIR TO HR;

For more information about using directory objects, see Oracle Database SecureFiles and Large Objects Developer's Guide.

13.3 Understanding Raw Profiler Output

Raw profiler output is intended to be processed by the analyzer component of the PL/SQL hierarchical profiler. However, even without such processing, it provides a simple function-level trace of the program. This topic explains how to understand raw profiler output.

Note:

The raw profiler format shown in this chapter is intended only to illustrate conceptual features of raw profiler output. Format specifics are subject to change at each Oracle Database release.

The SQL script in Example 13-1 wrote this raw profiler output to the file test.trc:

P#V PLSHPROF Internal Version 1.0
P#! PL/SQL Timer Started
P#C PLSQL."".""."__plsql_vm"
P#X 1
P#C PLSQL."".""."__anonymous_block"
P#X 66
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."GET_LINES"#660bd56a1b1640db #180
P#X 5
P#R
P#X 29
P#R
P#X 2
P#R
P#C PLSQL."".""."__plsql_vm"
P#X 1
P#C PLSQL."".""."__anonymous_block"
P#X 42
P#C PLSQL."HR"."TEST"::7."TEST"#980980e97e42f8ec #1
P#X 2
P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4
P#X 24
P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6
P#X 165
P#R
P#X 13
P#R
P#X 2
P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4
P#X 3
P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6
P#X 75
P#R
P#X 2
P#R
P#X 2
P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4
P#X 2
P#C SQL."HR"."TEST"::7."__static_sql_exec_line6" #6
P#X 73
P#R
P#X 3
P#R
P#X 1
P#R
P#X 1
P#R
P#X 1
P#R
P#C PLSQL."".""."__plsql_vm"
P#X 2
P#C PLSQL."".""."__anonymous_block"
P#X 69
P#C PLSQL."SYS"."DBMS_OUTPUT"::11."GET_LINES"#660bd56a1b1640db #180
P#X 5
P#R
P#X 35
P#R
P#X 1
P#R
P#C PLSQL."".""."__plsql_vm"
P#X 1
P#C PLSQL."".""."__anonymous_block"
P#X 58
P#C PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec #63
P#R
P#R
P#R
P#! PL/SQL Timer Stopped

Table 13-1 Raw Profiler Output File Indicators

Indicator Meaning

P#V

PLSHPROF banner with version number

P#C

Call to a subprogram (call event)

P#R

Return from a subprogram (return event)

P#X

Elapsed time between preceding and following events

P#!

Comment


Call events (P#C) and return events (P#R) are properly nested (like matched parentheses). If an unhandled exception causes a called subprogram to exit, the profiler still reports a matching return event.

Each call event (P#C) entry in the raw profiler output includes this information:

  • Namespace to which the called subprogram belongs (see Section 13.3.1)

  • Name of the PL/SQL module in which the called subprogram is defined

  • Type of the PL/SQL module in which the called subprogram is defined

  • Name of the called subprogram

    This name might be one of the special function names in Section 13.3.2.

  • Hexadecimal value that represents an MD5 hash of the signature of the called subprogram

    The DBMS_HPROF.analyze PL/SQL API (described in Section 13.4) stores the hash value in a hierarchical profiler table, which allows both you and DBMS_HPROF.analyze to distinguish between overloaded subprograms (subprograms with the same name).

  • Line number at which the called subprogram is defined in the PL/SQL module

    PL/SQL hierarchical profiler does not measure time spent at individual lines within modules, but you can use line numbers to identify the source locations of subprograms in the module (as IDE/Tools do) and to distinguish between overloaded subprograms.

For example, consider this entry in the preceding example of raw profiler output:

P#C PLSQL."HR"."TEST"::7."TEST.FOO"#980980e97e42f8ec #4

The components of the preceding entry have these meanings:

Component Meaning
PLSQL PLSQL is the namespace to which the called subprogram belongs.
"HR"."TEST" HR.TEST is the name of the PL/SQL module in which the called subprogram is defined.
7 7 is the internal enumerator for the module type of HR.TEST. Examples of module types are procedure, package, and package body.
"TEST.FOO" TEST.FOO is the name of the called subprogram.
#980980e97e42f8ec #980980e97e42f8ec is a hexadecimal value that represents an MD5 hash of the signature of TEST.FOO.
#4 4 is the line number in the PL/SQL module HR.TEST at which TEST.FOO is defined.

Note:

When a subprogram is inlined, it is not reported in the profiler output. For information about subprogram inlining, see Oracle Database PL/SQL Language Reference.

When a call to a DETERMINISTIC function is "optimized away," it is not reported in the profiler output. For information about DETERMINISTIC functions, see Oracle Database PL/SQL Language Reference.

13.3.1 Namespaces of Tracked Subprograms

The subprograms that the PL/SQL hierarchical profiler tracks are classified into the namespaces PLSQL and SQL, as follows:

  • Namespace PLSQL includes:

    • PL/SQL subprogram calls

    • PL/SQL triggers

    • PL/SQL anonymous blocks

    • Remote subprogram calls

    • Package initialization blocks

  • Namespace SQL includes SQL statements executed from PL/SQL, such as queries, data manipulation language (DML) statements, data definition language (DDL) statements, and native dynamic SQL statements

13.3.2 Special Function Names

PL/SQL hierarchical profiler tracks certain operations as if they were functions with the names and namespaces shown in Table 13-2.

Table 13-2 Function Names of Operations that the PL/SQL Hierarchical Profiler Tracks

Tracked Operation Function Name Namespace

Call to PL/SQL Virtual Machine

__plsql_vm

PL/SQL

PL/SQL anonymous block

__anonymous_block

PL/SQL

Package initialization block

__pkg_init

PL/SQL

Static SQL statement at line line#

__static_sql_exec_lineline#

SQL

Dynamic SQL statement at line line#

__dyn_sql_exec_lineline#

SQL

SQL FETCH statement at line line#

__sql_fetch_lineline#

SQL


13.4 Analyzing Profile Data

The analyzer component of the PL/SQL hierarchical profiler, DBMS_HPROF.analyze, processes the raw profiler output and stores the results in the hierarchical database tables described in Table 13-3.

Table 13-3 PL/SQL Hierarchical Profiler Database Tables

Table Description

DBMSHP_RUNS

Top-level information for this run of DBMS_HPROF.analyze. For column descriptions, see Table 13-4.

DBMSHP_FUNCTION_INFO

Information for each subprogram profiled in this run of DBMS_HPROF.analyze. For column descriptions, see Table 13-5.

DBMSHP_PARENT_CHILD_INFO

Parent-child information for each subprogram profiled in this run of DBMS_HPROF.analyze. For column descriptions, see Table 13-6.


Topics:

Note:

To generate simple HTML reports directly from raw profiler output, without using the Analyzer, you can use the plshprof command-line utility. For details, see Section 13.5.

13.4.1 Creating Hierarchical Profiler Tables

To create the hierarchical profiler tables in Table 13-3 and the other data structures required for persistently storing profile data, follow these steps:

  1. Run the script dbmshptab.sql (located in the directory rdbms/admin).

    This script creates both the hierarchical profiler tables in Table 13-3 and the other data structures required for persistently storing profile data.

    Note:

    Running the script dbmshptab.sql drops any previously created hierarchical profiler tables.
  2. Ensure that you have these privileges:

    • EXECUTE privilege on the DBMS_HPROF package

    • READ privilege on the directory that DBMS_HPROF.analyze specifies

  3. Use the PL/SQL API DBMS_HPROF.analyze to analyze a single raw profiler output file and store the results in hierarchical profiler tables.

    (For an example of a raw profiler output file, see test.trc in Section 13.3.)

    For more information about DBMS_HPROF.analyze, see Oracle Database PL/SQL Packages and Types Reference.

  4. Use the hierarchical profiler tables to generate custom reports.

The anonymous block in Example 13-2:

  • Invokes the function DBMS_HPROF.analyze function, which:

    • Analyzes the profile data in the raw profiler output file test.trc (from Section 13.3), which is in the directory that is mapped to the directory object PLSHPROF_DIR, and stores the data in the hierarchical profiler tables in Table 13-3.

    • Returns a unique identifier that you can use to query the hierarchical profiler tables in Table 13-3. (By querying these hierarchical profiler tables, you can produce customized reports.)

  • Stores the unique identifier in the variable runid, which it prints.

Example 13-2 Invoking DBMS_HPROF.analyze

DECLARE
  runid NUMBER;
BEGIN
  runid := DBMS_HPROF.analyze(LOCATION=>'PLSHPROF_DIR',
                              FILENAME=>'test.trc');
  DBMS_OUTPUT.PUT_LINE('runid = ' || runid);
END;
/

13.4.2 Understanding Hierarchical Profiler Tables

These topics explain how to use the hierarchical profiler tables in Table 13-3:

13.4.2.1 Hierarchical Profiler Database Table Columns

Table 13-4 describes the columns of the hierarchical profiler table DBMSHP_RUNS, which contains one row of top-level information for each run of DBMS_HPROF.analyze.

The primary key for the hierarchical profiler table DBMSHP_RUNS is RUNID.

Table 13-4 DBMSHP_RUNS Table Columns

Column Name Column Data Type Column Contents

RUNID

NUMBER

Unique identifier for this run of DBMS_HPROF.analyze, generated from DBMSHP_RUNNUMBER sequence.

RUN_TIMESTAMP

TIMESTAMP(6)

Time stamp for this run of DBMS_HPROF.analyze.

RUN_COMMENT

VARCHAR2(2047)

Comment that you provided for this run of DBMS_HPROF.analyze.

TOTAL_ELAPSED_TIME

NUMBER(38)

Total elapsed time for this run of DBMS_HPROF.analyze.


Table 13-5 describes the columns of the hierarchical profiler table DBMSHP_FUNCTION_INFO, which contains one row of information for each subprogram profiled in this run of DBMS_HPROF.analyze. If a subprogram is overloaded, Table 13-5 has a row for each variation of that subprogram. Each variation has its own LINE# and HASH (see Section 13.4.2.2, "Distinguishing Between Overloaded Subprograms.")

The primary key for the hierarchical profiler table DBMSHP_FUNCTION_INFO is RUNID, SYMBOLID.

Table 13-5 DBMSHP_FUNCTION_INFO Table Columns

Column Name Column Data Type Column Contents

RUNID

NUMBER

References RUNID column of DBMSHP_RUNS table. For a description of that column, see Table 13-4.

SYMBOLID

NUMBER

Symbol identifier for subprogram (unique for this run of DBMS_HPROF.analyze).

OWNER

VARCHAR2(32)

Owner of module in which each subprogram is defined (for example, SYS or HR).

MODULE

VARCHAR2(32)

Module in which subprogram is defined (for example, DBMS_LOB, UTL_HTTP, or MY_PACKAGE).

TYPE

VARCHAR2(32)

Type of module in which subprogram is defined (for example, PACKAGE, PACKAGE_BODY, or PROCEDURE).

FUNCTION

VARCHAR2(4000)

Name of subprogram (not necessarily a function) (for example, INSERT_ORDER, PROCESS_ITEMS, or TEST).

This name might be one of the special function names in Section 13.3.2.

For subprogram B defined within subprogram A, this name is A.B.

A recursive call to function X is denoted X@n, where n is the recursion depth. For example, X@1 is the first recursive call to X.

LINE#

NUMBER

Line number in OWNER.MODULE at which FUNCTION is defined.

HASH

RAW(32)

Hash code for signature of subprogram (unique for this run of DBMS_HPROF.analyze).

NAMESPACE

VARCHAR2(32)

Namespace of subprogram. For details, see Section 13.3.1.

SUBTREE_ELAPSED_TIME

NUMBER(38)

Elapsed time, in microseconds, for subprogram, including time spent in descendant subprograms.

FUNCTION_ELAPSED_TIME

NUMBER(38)

Elapsed time, in microseconds, for subprogram, excluding time spent in descendant subprograms.

CALLS

NUMBER(38)

Number of calls to subprogram.


Table 13-6 describes the columns of the hierarchical profiler table DBMSHP_PARENT_CHILD_INFO, which contains one row of parent-child information for each unique parent-child subprogram combination profiled in this run of DBMS_HPROF.analyze.

Table 13-6 DBMSHP_PARENT_CHILD_INFO Table Columns

Column Name Column Data Type Column Contents

RUNID

NUMBER

References RUNID column of DBMSHP_FUNCTION_INFO table. For a description of that column, see Table 13-5.

PARENTSYMID

NUMBER

Parent symbol ID.

RUNID, PARENTSYMID references DBMSHP_FUNCTION_INFO(RUNID, SYMBOLID).

CHILDSYMID

NUMBER

Child symbol ID.

RUNID, CHILDSYMID references DBMSHP_FUNCTION_INFO(RUNID, SYMBOLID).

SUBTREE_ELAPSED_TIME

NUMBER(38)

Elapsed time, in microseconds, for RUNID, CHILDSYMID when called from RUNID, PARENTSYMID, including time spent in descendant subprograms.

FUNCTION_ELAPSED_TIME

NUMBER(38)

Elapsed time, in microseconds, for RUNID, CHILDSYMID when called from RUNID, PARENTSYMID, excluding time spent in descendant subprograms.

CALLS

NUMBER(38)

Number of calls to RUNID, CHILDSYMID from RUNID, PARENTSYMID.


13.4.2.2 Distinguishing Between Overloaded Subprograms

Overloaded subprograms are different subprograms with the same name (see Oracle Database PL/SQL Language Reference).

Suppose that a program declares three subprograms named compute—the first at line 50, the second at line 76, and the third at line 100. In the DBMSHP_FUNCTION_INFO table, each of these subprograms has compute in the FUNCTION column. To distinguish between the three subprograms, use either the LINE# column (which has 50 for the first subprogram, 76 for the second, and 100 for the third) or the HASH column (which has a unique value for each subprogram).

In the profile data for two different runs, the LINE# and HASH values for a function might differ. The LINE# value of a function changes if you insert or delete lines before the function definition. The HASH value changes only if the signature of the function changes; for example, if you change the parameter list.

13.4.2.3 Hierarchical Profiler Tables for Sample PL/SQL Procedure

The hierarchical profiler tables for the PL/SQL procedure test in Section 13.2 are shown in Example 13-3 through Example 13-5.

Example 13-3 DBMSHP_RUNS Table for Sample PL/SQL Procedure

     RUNID RUN_TIMESTAMP                  TOTAL_ELAPSED_TIME RUN_COMMENT
---------- ------------------------------ ------------------ -----------
         1 20-DEC-12 11.37.26.688381 AM                    7
         2 20-DEC-12 11.37.26.700523 AM                    9
         3 20-DEC-12 11.37.26.706824 AM                  123

Example 13-4 DBMSHP_FUNCTION_INFO Table for Sample PL/SQL Procedure

     RUNID    SYMBOLID OWNER   MODULE       TYPE            FUNCTION
---------- ----------- ------- ------------ --------------- -------------------------
         1           1 HR      PKG          PACKAGE BODY    MYPROC
         2           1 HR      PKG          PACKAGE BODY    MYFUNC
         2           2 HR      PKG          PACKAGE BODY    MYPROC
         3           1                                      __anonymous_block
         3           2                                      __plsql_vm
         3           3 HR      PKG          PACKAGE BODY    MYFUNC
         3           4 HR      PKG          PACKAGE BODY    MYPROC
         3           5 HR      TEST2        PROCEDURE       TEST2

LINE#  CALLS HASH                                                             NAMESPACE
----- ------ ---------------------------------------------------------------- -----------
    2      1 9689BA467A19CD19                                                 PLSQL
    7      1 28DC3402BAEB2B0D                                                 PLSQL
    2      1 9689BA467A19CD19                                                 PLSQL
    0      1                                                                  PLSQL
    0      1                                                                  PLSQL
    7      1 28DC3402BAEB2B0D                                                 PLSQL
    2      2 9689BA467A19CD19                                                 PLSQL
    1      1 980980E97E42F8EC                                                 PLSQL

NAMESPACE      SUBTREE_ELAPSED_TIME    FUNCTION_ELAPSED_TIME
----------- ----------------------- ------------------------
PLSQL                             7                        7
PLSQL                             9                        8
PLSQL                             1                        1
PLSQL                           121                       44
PLSQL                           123                        2
PLSQL                             9                        8
PLSQL                             8                        8
PLSQL                            77                       61

Example 13-5 DBMSHP_PARENT_CHILD_INFO Table for Sample PL/SQL Procedure

     RUNID PARENTSYMID CHILDSYMID    SUBTREE_ELAPSED_TIME    FUNCTION_ELAPSED_TIME  CALLS
---------- ----------- ---------- ----------------------- ------------------------ ------
         2           1          2                       1                        1      1
         3           1          5                      77                       61      1
         3           2          1                     121                       44      1
         3           3          4                       1                        1      1
         3           5          3                       9                        8      1
         3           5          4                       7                        7      1

Consider the third row of the table DBMSHP_PARENT_CHILD_INFO (Example 13-5). The RUNID column shows that this row corresponds to the third run. The columns PARENTSYMID and CHILDSYMID show that the symbol IDs of the parent (caller) and child (called subprogram) are 2 and 1, respectively. The table DBMSHP_FUNCTION_INFO (Example 13-4) shows that for the third run, the symbol IDs 2 and 1 correspond to procedures __plsql_vm and __anonymous_block, respectively. Therefore, the information in this row is about calls from the procedure __plsql_vm to the __anonymous_block (defined within __plsql_vm) in the module HR.TEST. This row shows that, when called from the procedure __plsql_vm, the function time for the procedure __anonymous_block is 44 microseconds, and the time spent in the __anonymous_block subtree (including descendants) is 121 microseconds.

13.4.2.4 Examples of Calls to DBMS_HPROF.analyze with Options

For an example of a call to DBMS_HPROF.analyze without options, see Example 13-2.

Example 13-6 creates a package, creates a procedure that invokes subprograms in the package, profiles the procedure, and uses DBMS_HRPROF.analyze to analyze the raw profiler output file. The raw profiler output file is in the directory corresponding to the PLSHPROF_DIR directory object.

Example 13-6 Invoking DBMS_HPROF.analyze with Options

-- Create package

CREATE OR REPLACE PACKAGE pkg AUTHID DEFINER IS
  PROCEDURE myproc (n IN out NUMBER);
  FUNCTION myfunc (v VARCHAR2) RETURN VARCHAR2;
  FUNCTION myfunc (n PLS_INTEGER) RETURN PLS_INTEGER;
END pkg;
/
CREATE OR REPLACE PACKAGE BODY pkg IS
  PROCEDURE myproc (n IN OUT NUMBER) IS
  BEGIN
    n := n + 5;
  END;

  FUNCTION myfunc (v VARCHAR2) RETURN VARCHAR2 IS
    n NUMBER;
  BEGIN
    n := LENGTH(v);
    myproc(n);
    IF n > 20 THEN
      RETURN SUBSTR(v, 1, 20);
    ELSE
      RETURN v || '...';
    END IF;
  END;

  FUNCTION myfunc (n PLS_INTEGER) RETURN PLS_INTEGER IS
    i PLS_INTEGER;
    PROCEDURE myproc (n IN out PLS_INTEGER) IS
    BEGIN
      n := n + 1;
    END;
  BEGIN
    i := n;
    myproc(i);
    RETURN i;
  END;
END pkg;
/

-- Create procedure that invokes package subprograms

CREATE OR REPLACE PROCEDURE test2 AUTHID DEFINER IS
  x NUMBER := 5;
  y VARCHAR2(32767);
BEGIN
  pkg.myproc(x);
  y := pkg.myfunc('hello');
END;

-- Profile test2

BEGIN
  DBMS_HPROF.START_PROFILING('PLSHPROF_DIR', 'test2.trc');
END;
/
BEGIN
  test2;
END;
/
BEGIN
  DBMS_HPROF.STOP_PROFILING;
END;
/
-- If not done, create hierarchical profiler tables (see Section 13.4.1).

-- Call DBMS_HPROF.analyze with options

DECLARE
  runid NUMBER;
BEGIN
  -- Analyze only subtrees rooted at trace entry "HR"."PKG"."MYPROC"

  runid := DBMS_HPROF.analyze('PLSHPROF_DIR', 'test2.trc',
                              trace => '"HR"."PKG"."MYPROC"');

  -- Analyze up to 20 calls to subtrees rooted at trace entry
  -- "HR"."PKG"."MYFUNC".  Because "HR"."PKG"."MYFUNC" is overloaded,
  -- both overloads are considered for analysis.

  runid := DBMS_HPROF.analyze('PLSHPROF_DIR', 'test2.trc',
                              collect => 20,
                              trace => '"HR"."PKG"."MYFUNC"');

  -- Analyze second call to PL/SQL virtual machine

  runid := DBMS_HPROF.analyze('PLSHPROF_DIR', 'test2.trc',
                              skip => 1, collect => 1,
                              trace => '""."".""__plsql_vm"');
END;
/

13.5 plshprof Utility

The plshprof command-line utility (located in the directory $ORACLE_HOME/bin/) generates simple HTML reports from either one or two raw profiler output files. (For an example of a raw profiler output file, see test.trc in Section 13.2.)

You can browse the generated HTML reports in any browser. The browser's navigational capabilities, combined with well chosen links, provide a powerful way to analyze performance of large applications, improve application performance, and lower development costs.

Topics:

13.5.1 plshprof Options

The command to run the plshprof utility is:

plshprof [option...] profiler_output_filename_1 profiler_output_filename_2

Each option is one of these:

Option Description Default
-skip count Skips first count calls. Use only with -trace symbol. 0
-collect count Collects information for count calls. Use only with -trace symbol. 1
-output filename Specifies name of output file symbol.html or tracefile1.html
-summary Prints only elapsed time None
-trace symbol Specifies function name of tree root Not applicable

Suppose that your raw profiler output file, test.trc, is in the current directory. You want to analyze and generate HTML reports, and you want the root file of the HTML report to be named report.html. Use this command (% is the prompt):

% plshprof -output report test.trc

13.5.2 HTML Report from a Single Raw Profiler Output File

To generate a PL/SQL hierarchical profiler HTML report from a single raw profiler output file, use these commands:

% cd target_directory
% plshprof -output html_root_filename profiler_output_filename

target_directory is the directory in which you want the HTML files to be created.

html_root_filename is the name of the root HTML file to be created.

profiler_output_filename is the name of a raw profiler output file.

The preceding plshprof command generates a set of HTML files. Start browsing them from html_root_filename.html.

Topics:

13.5.2.1 First Page of Report

The first page of an HTML report from a single raw profiler output file includes summary information and hyperlinks to other pages of the report.

Sample First Page

PL/SQL Elapsed Time (microsecs) Analysis

2831 microsecs (elapsed time) & 12 function calls

The PL/SQL Hierarchical Profiler produces a collection of reports that present information derived from the profiler output log in a variety of formats. These reports have been found to be the most generally useful as starting points for browsing:

  • Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs)

  • Function Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs)

Also, the following reports are also available:

  • Function Elapsed Time (microsecs) Data sorted by Function Name

  • Function Elapsed Time (microsecs) Data sorted by Total Descendants Elapsed Time (microsecs)

  • Function Elapsed Time (microsecs) Data sorted by Total Function Call Count

  • Function Elapsed Time (microsecs) Data sorted by Mean Subtree Elapsed Time (microsecs)

  • Function Elapsed Time (microsecs) Data sorted by Mean Function Elapsed Time (microsecs)

  • Function Elapsed Time (microsecs) Data sorted by Mean Descendants Elapsed Time (microsecs)

  • Module Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs)

  • Module Elapsed Time (microsecs) Data sorted by Module Name

  • Module Elapsed Time (microsecs) Data sorted by Total Function Call Count

  • Namespace Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs)

  • Namespace Elapsed Time (microsecs) Data sorted by Namespace

  • Namespace Elapsed Time (microsecs) Data sorted by Total Function Call Count

  • Parents and Children Elapsed Time (microsecs) Data

13.5.2.2 Function-Level Reports

The function-level reports provide a flat view of the profile information. Each function-level report includes this information for each function:

  • Function time (time spent in the function itself, also called "self time")

  • Descendants time (time spent in the descendants of the function)

  • Subtree time (time spent in the subtree of the function—function time plus descendants time)

  • Number of calls to the function

  • Function name

    The function name is hyperlinked to the Parents and Children Report for the function.

Each function-level report is sorted on a particular attribute; for example, function time or subtree time.

This sample report is sorted in descending order of the total subtree elapsed time for the function, which is why information in the Subtree and Ind% columns is in bold type:

Sample Report

Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs)

2831 microsecs (elapsed time) & 12 function calls

Subtree Ind% Function Descendant Ind% Calls Ind% Function Name
2831 100% 93 2738 96.7% 2 16.7% __plsq_vm
2738 96.7% 310 2428 85.8% 2 16.7% __anonymous_block
2428 85.8% 15 2413 85.2% 1 8.3% HR.TEST.TEST (Line 1)
2413 85.2% 435 1978 69.9% 3 25.0% HR.TEST.TEST.FOO (Line 3)
1978 69.9% 1978 0 0.0% 3 25.0% HR.TEST.__static_sql_exec_line5 (Line 5)
0 0.0% 0 0 0.0% 1 8.3% SYS.DBMS_HPROF.STOP_PROFILING (Line 53)

13.5.2.3 Module-Level Reports

Each module-level report includes this information for each module (for example, package or type):

  • Module time (time spent in the module—sum of the function times of all functions in the module)

  • Number of calls to functions in the module

Each module-level report is sorted on a particular attribute; for example, module time or module name.

This sample report is sorted by module time, which is why information in the Module, Ind%, and Cum% columns is in bold type:

Sample Report

Module Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs)

166878 microsecs (elapsed time) & 1099 function calls

Module Ind% Cum% Calls Ind% Module Name
84932 50.9% 50.9% 6 0.5% HR.P
67749 40.6% 91.5% 216 19.7% SYS.DBMS_LOB
13340 8.0% 99.5% 660 60.1% SYS.UTL_FILE
839 0.5% 100% 214 19.5% SYS.UTL_RAW
18 0.0% 100% 2 0.2% HR.UTILS
0 0.0% 100% 1 0.1% SYS.DBMS_HPROF

13.5.2.4 Namespace-Level Reports

Each namespace-level report includes this information for each namespace:

  • Namespace time (time spent in the namespace—sum of the function times of all functions in the namespace)

  • Number of calls to functions in the namespace

Each namespace-level report is sorted on a particular attribute; for example, namespace time or number of calls to functions in the namespace.

This sample report is sorted by function time, which is why information in the Function, Ind%, and Cum% columns is in bold type:

Sample Report

Namespace Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs)

166878 microsecs (elapsed time) & 1099 function calls

Function Ind% Cum% Calls Ind% Namespace
93659 56.1% 56.1% 1095 99.6% PLSQL
73219 43.9% 100% 4 0.4% SQL

13.5.2.5 Parents and Children Report for a Function

For each function tracked by the profiler, the Parents and Children Report provides information about parents (functions that call it) and children (functions that it calls). For each parent, the report gives the function's execution profile (subtree time, function time, descendants time, and number of calls). For each child, the report gives the execution profile for the child when called from this function (but not when called from other functions).

The execution profile for a function includes the same information for that function as a function-level report includes for each function (for details, see Section 13.5.2.2, "Function-Level Reports").

This Sample Report is a fragment of a Parents and Children Report that corresponds to a function named HR.P.UPLOAD. The first row has this summary information:

  • There are two calls to the function HR.P.UPLOAD.

  • The total subtree time for the function is 166,860 microseconds—11,713 microseconds (7.0%) in the function itself and 155,147 microseconds (93.0%) in its descendants.

After the row "Parents" are the execution profile rows for the two parents of HR.P.UPLOAD, which are HR.UTILS.COPY_IMAGE and HR.UTILS.COPY_FILE.

The first parent execution profile row, for HR.UTILS.COPY_IMAGE, shows:

  • HR.UTILS.COPY_IMAGE calls HR.P.UPLOAD once, which is 50% of the number of calls to HR.P.UPLOAD.

  • The subtree time for HR.P.UPLOAD when called from HR.UTILS.COPY_IMAGE is 106,325 microseconds, which is 63.7% of the total subtree time for HR.P.UPLOAD.

  • The function time for HR.P.UPLOAD when called from HR.UTILS.COPY_IMAGE is 6,434 microseconds, which is 54.9% of the total function time for HR.P.UPLOAD.

After the row "Children" are the execution profile rows for the children of HR.P.UPLOAD when called from HR.P.UPLOAD.

The third child execution profile row, for SYS.UTL_FILE.GET_RAW, shows:

  • HR.P.UPLOAD calls SYS.UTL_FILE.GET_RAW 216 times.

  • The subtree time, function time and descendants time for SYS.UTL_FILE.GET_RAW when called from HR.P.UPLOAD are 12,487 microseconds, 3,969 microseconds, and 8,518 microseconds, respectively.

  • Of the total descendants time for HR.P.UPLOAD (155,147 microseconds), the child SYS.UTL_FILE.GET_RAW is responsible for 12,487 microsecs (8.0%).

Sample Report

HR.P.UPLOAD (Line 3)

Subtree Ind% Function Ind% Descendant Ind% Calls Ind% Function Name
166860 100% 11713 7.0% 155147 93.0% 2 0.2% HR.P.UPLOAD (Line 3)
Parents:                
106325 63.7% 6434 54.9% 99891 64.4% 1 50.0% HR.UTILS.COPY_IMAGE (Line 3)
60535 36.3% 5279 45.1% 55256 35.6% 1 50.0% HR.UTILS.COPY_FILE (Line 8))
Children:                
71818 46.3% 71818 100% 0 N/A 2 100% HR.P.__static_sql_exec_line38 (Line 38)
67649 43.6% 67649 100% 0 N/A 214 100% SYS.DBMS_LOB.WRITEAPPEND (Line 926)
12487 8.0% 3969 100% 8518 100% 216 100% SYS.UTL_FILE.GET_RAW (Line 1089)
1401 0.9% 1401 100% 0 N/A 2 100% HR.P.__static_sql_exec_line39 (Line 39)
839 0.5% 839 100% 0 N/A 214 100% SYS.UTL_FILE.GET_RAW (Line 246)
740 0.5% 73 100% 667 100% 2 100% SYS.UTL_FILE.FOPEN (Line 422)
113 0.1% 11 100% 102 100% 2 100% SYS.UTL_FILE.FCLOSE (Line 585)
100 0.1% 100 100% 0 N/A 2 100% SYS.DBMS_LOB.CREATETEMPORARY (Line 536)

13.5.3 HTML Difference Report from Two Raw Profiler Output Files

To generate a PL/SQL hierarchical profiler HTML difference report from two raw profiler output files, use these commands:

% cd target_directory
% plshprof -output html_root_filename profiler_output_filename_1 profiler_output_filename_2

target_directory is the directory in which you want the HTML files to be created.

html_root_filename is the name of the root HTML file to be created.

profiler_output_filename_1 and profiler_output_filename_2 are the names of raw profiler output files.

The preceding plshprof command generates a set of HTML files. Start browsing them from html_root_filename.html.

Topics:

13.5.3.1 Difference Report Conventions

Difference reports use these conventions:

  • In a report title, Delta means difference, or change.

  • A positive value indicates that the number increased (regressed) from the first run to the second run.

  • A negative value for a difference indicates that the number decreased (improved) from the first run to the second run.

  • The symbol # after a function name means that the function was called in only one run.

13.5.3.2 First Page of Difference Report

The first page of an HTML difference report from two raw profiler output files includes summary information and hyperlinks to other pages of the report.

Sample First Page

PL/SQL Elapsed Time (microsecs) Analysis – Summary Page

This analysis finds a net regression of 2709589 microsecs (elapsed time) or 80% (3393719 versus 6103308). Here is a summary of the 7 most important individual function regressions and improvements:

Regressions: 3399382 microsecs (elapsed time)

Function Rel% Ind% Calls Rel% Function Name
2075627 +941% 61.1% 0   HR.P.G (Line 35)
1101384 +54.6% 32.4% 5 +55.6% HR.P.H (Line 18)
222371   6.5% 1   HR.P.J (Line 10)

Improvements: 689793 microsecs (elapsed time)

Function Rel% Ind% Calls Rel% Function Name
-467051 -50.0% 67.7% -2 -50.0% HR.P.F (Line 25)
-222737   32.3% -1   HR.P.I (Line 2)#
-5 -21.7% 0.0% 0   HR.P.TEST (Line 46)

The PL/SQL Timing Analyzer produces a collection of reports that present information derived from the profiler's output logs in a variety of formats. The following reports have been found to be the most generally useful as starting points for browsing:

  • Function Elapsed Time (microsecs) Data for Performance Regressions

  • Function Elapsed Time (microsecs) Data for Performance Improvements

Also, the following reports are also available:

  • Function Elapsed Time (microsecs) Data sorted by Function Name

  • Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs) Delta

  • Function Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs) Delta

  • Function Elapsed Time (microsecs) Data sorted by Total Descendants Elapsed Time (microsecs) Delta

  • Function Elapsed Time (microsecs) Data sorted by Total Function Call Count Delta

  • Module Elapsed Time (microsecs) Data sorted by Module Name

  • Module Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs) Delta

  • Module Elapsed Time (microsecs) Data sorted by Total Function Call Count Delta

  • Namespace Elapsed Time (microsecs) Data sorted by Namespace

  • Namespace Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs)

  • Namespace Elapsed Time (microsecs) Data sorted by Total Function Call Count

  • File Elapsed Time (microsecs) Data Comparison with Parents and Children

13.5.3.3 Function-Level Difference Reports

Each function-level difference report includes, for each function, the change in these values from the first run to the second run:

  • Function time (time spent in the function itself, also called "self time")

  • Descendants time (time spent in the descendants of the function)

  • Subtree time (time spent in the subtree of the function—function time plus descendants time)

  • Number of calls to the function

  • Mean function time

    The mean function time is the function time divided by number of calls to the function.

  • Function name

    The function name is hyperlinked to the Parents and Children Difference Report for the function.

The report in Sample Report 1 shows the difference information for all functions that performed better in the first run than they did in the second run. Note that:

  • For HR.P.G, the function time increased by 2,075,627 microseconds (941%), which accounts for 61.1% of all regressions.

  • For HR.P.H, the function time and number of calls increased by 1,101,384 microseconds (54.6%) and 5 (55.6%), respectively, but the mean function time improved by 1,346 microseconds (-0.6%).

  • HR.P.J was called in only one run.

Sample Report 1

Function Elapsed Time (microsecs) Data for Performance Regressions

Subtree Function Rel% Ind% Cum% Descendant Calls Rel% Mean Function Rel% Function Name
4075787 2075627 +941% 61.1% 61.1% 2000160 0   2075627 +941% HR.P.G (Line 35)
1101384 1101384 +54.6% 32.4% 93.5% 0 5 +55.6% -1346 -0.6% HR.P.H (Line 18)
222371 222371   6.5% 100% 0 1       HR.P.J (Line 10)#

The report in Sample Report 2 shows the difference information for all functions that performed better in the second run than they did in the first run.

Sample Report 2

Function Elapsed Time (microsecs) Data for Performance Improvements

Subtree Function Rel% Ind% Cum% Descendant Calls Rel% Mean Function Rel% Function Name
-1365827 -467051 -50.0% 67.7% 67.7% -898776 -2 -50.0% -32 0.0% HR.P.F (Line 25)
-222737 -222737   32.3% 100% 0 -1       HR.P.I (Line 2)
2709589 -5 -21.7% 0.0% 100% 2709594 0   -5 -20.8 HR.P.TEST (Line 46)#

The report in Sample Report 3 summarizes the difference information for all functions.

Sample Report 3

Function Elapsed Time (microsecs) Data sorted by Total Function Call Count Delta

Subtree Function Rel% Ind% Descendant Calls Rel% Mean Function Rel% Function Name
1101384 1101384 +54.6% 32.4% 0 5 +55.6% -1346 -0.6% HR.P.H (Line 18)
-1365827 -467051 +50.0% 67.7% -898776 -2 -50.0% -32 -0.0% HR.P.F (Line 25)
-222377 -222377   32.3% 0 -1       HR.P.I (Line 2)#
222371 222371   6.5% 0 1       HR.P.J(Line 10)#
4075787 2075627 +941% 61.1% 2000160 0   2075627 +941% HR.P.G (Line 35)
2709589 -5 -21.7% 0.0% 2709594 0   -5 -20.8% HR.P.TEST (Line 46)
0 0     0 0       SYS.DBMS_HPROF.STOP_PROFILING (Line 53)

13.5.3.4 Module-Level Difference Reports

Each module-level report includes, for each module, the change in these values from the first run to the second run:

  • Module time (time spent in the module—sum of the function times of all functions in the module)

  • Number of calls to functions in the module

Sample Report

Module Elapsed Time (microsecs) Data sorted by Total Function Elapsed Time (microsecs) Delta

Module Calls Module Name
2709589 3 HR.P
0 0 SYS.DBMS_HPROF

13.5.3.5 Namespace-Level Difference Reports

Each namespace-level report includes, for each namespace, the change in these values from the first run to the second run:

  • Namespace time (time spent in the namespace—sum of the function times of all functions in the namespace)

  • Number of calls to functions in the namespace

Sample Report

Namespace Elapsed Time (microsecs) Data sorted by Namespace

Function Calls Namespace
2709589 3 PLSQL

13.5.3.6 Parents and Children Difference Report for a Function

The Parents and Children Difference Report for a function shows changes in the execution profiles of these from the first run to the second run:

  • Parents (functions that call the function)

  • Children (functions that the function calls)

    Execution profiles for children include only information from when this function calls them, not for when other functions call them.

The execution profile for a function includes this information:

  • Function time (time spent in the function itself, also called "self time")

  • Descendants time (time spent in the descendants of the function)

  • Subtree time (time spent in the subtree of the function—function time plus descendants time)

  • Number of calls to the function

  • Function name

The sample report is a fragment of a Parents and Children Difference Report that corresponds to a function named HR.P.X.

The first row, a summary of the difference between the first and second runs, shows regression: function time increased by 1,094,099 microseconds (probably because the function was called five more times).

The "Parents" rows show that HR.P.G called HR.P.X nine more times in the second run than it did in the first run, while HR.P.F called it four fewer times.

The "Children" rows show that HR.P.X called each child five more times in the second run than it did in the first run.

Sample Report

HR.P.X (Line 11)

Subtree Function Descendant Calls Function Name
3322196 1094099 2228097 5 HR.P.X (Line 11)
Parents:        
6037490 1993169 4044321 9 HR.P.G (Line 38)
-2715294 -899070 -1816224 -4 HR.P.F (Line 28)
Children:        
1125489 1125489 0 5 HR.P.J (Line 10)
1102608 1102608 0 5 HR.P.I (Line 2)

The Parents and Children Difference Report for a function is accompanied by a Function Comparison Report, which shows the execution profile of the function for the first and second runs and the difference between them. This example is the Function Comparison Report for the function HR.P.X:

Sample Report

Elapsed Time (microsecs) for HR.P.X (Line 11) (20.1% of total regression)

HR.P.X (Line 11) First Trace Ind% Second Trace Ind% Diff Diff%
Function Elapsed Time (microsecs) 1999509 26.9% 3093608 24.9% 1094099 +54.7%
Descendants Elapsed Time (microsecs) 4095943 55.1% 6324040 50.9% 2228097 +54.4%
Subtree Elapsed Time (microsecs) 6095452 81.9% 9417648 75.7% 3322196 +54.5%
Function Calls 9 25.0% 14 28.6% 5 +55.6%
Mean Function Elapsed Time (microsecs) 222167.7   220972.0   -1195.7 -0.5%
Mean Descendants Elapsed Time (microsecs) 455104.8   451717.1   -3387.6 -0.7%
Mean Subtree Elapsed Time (microsecs) 677272.4   672689.1   -4583.3 -0.7%