8 Using the PL/SQL Hierarchical Profiler

Hierarchical Profiler Database Table Columns

Table 8-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 8-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 8-5 has a row for each variation of that subprogram. Each variation has its own LINE# and HASH (see "Distinguishing Between Overloaded Subprograms").

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

Table 8-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.

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.

Hierarchical Profiler Tables for Sample PL/SQL Procedure

The hierarchical profiler tables for the PL/SQL procedure test in "Collecting Profile Data" are shown in Example 8-3 through Example 8-5.

RUNID  RUN_TIMESTAMP                 TOTAL_ELAPSED_TIME  RUN_COMMENT
1      10-APR-06 12.01.56.766743 PM  2637                 First run of TEST

RUNID  SYMBOLID  OWNER  MODULE      TYPE          NAMESPACE  FUNCTION
1      1                                          PLSQL      __anonymous_block
1      2                                          PLSQL      __plsql_vm
1      3         HR     TEST        PROCEDURE     PLSQL      TEST
1      4         HR     TEST        PROCEDURE     PLSQL      TEST.FOO
1      5         SYS    DBMS_HPROF  PACKAGE_BODY  PLSQL      STOP_PROFILING
1      6         HR     TEST        PROCEDURE     SQL        __static_sql_exec_line5

LINE#  CALLS  HASH              SUBTREE_ELAPSED_TIME  FUNCTION_ELAPSED_TIME
0      2      980980E97E42F8EC  2554                  342
0      2      980980E97E42F8EC  2637                  83
1      1      980980E97E42F8EC  2212                  28
3      3      980980E97E42F8EC  2184                  126
57     1      980980E97E42F8EC  0                     0
5      3      980980E97E42F8EC  1998                  1998

RUNID  PARENTSYMID  CHILDSYMID  SUBTREE_ELAPSED_TIME  FUNCTION_ELAPSED_TIME  CALLS
1      2            1           2554                   342                   2
1      1            3           2212                   28                    1
1      3            4           2184                   126                   3
1      1            5           0                      0                     1
1      4            6           1998                   1998                  3

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

Examples of Calls to DBMS_HPROF.analyze with Options

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

Example 8-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.

-- Create package

CREATE OR REPLACE PACKAGE pkg 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 packaged subprograms

CREATE OR REPLACE PROCEDURE test2 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 "Creating Hierarchical Profiler Tables".)

-- 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;
/

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)

In addition, 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

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

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

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

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 "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)

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.

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)

Improvements: 689793 microsecs (elapsed time)

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

In addition, 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

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

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

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

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

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

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)

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)