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

The hierarchical profiler tables for the PL/SQL procedure test in Collecting Profile Data are shown in Example 15-4 through Example 15-6.

Consider the third row of the table DBMSHP_PARENT_CHILD_INFO (Example 15-6). 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 15-5) 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.

     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

     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

     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

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

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

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.

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.

• SQL ID

• SQL Text (First 50 characters of the SQL text).

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:

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:

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:

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.

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%).

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.

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.

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.

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

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

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.