Notes on Profiling Oracle PL/SQL

'Everything should be made as simple as possible, but not simpler'

This phrase is often attributed to Albert Einstein, although the attribution is apparently questionable:
Everything Should Be Made as Simple as Possible, But Not Simpler. In any case it's not a bad approach to follow, even if the quote did come from a non-Oracle guy :).

I recently started looking at the hierarchical profiler tool with a view to using it in an upcoming project. In order to understand the tool properly, I felt it would be a good idea to start by using it to profile a test program that would be as simple as possible while covering as wide a range of scenarios as possible. This article documents the results of that profiling, highlighting the different scenarios covered, discusses the output from the profiler, and includes a query I wrote to display the function call tree.

The article goes on to illustrate profiling through manual code instrumentation, and by the old flat profiler (DBMS_Profiler) on the same test program, concluding that each method has its own strengths and weaknesses.

Setup
The hierarchical profiler setup and use is described in Oracle® Database Advanced Application Developer's Guide 11g Release 2 (11.2), and some code snippets are available here:PL/SQL Hierarchical Profiler in Oracle Database 11g Release 1

Scenarios
The test program consists of a driving script, Test_Rep_p.sql (attached), that calls a package (HProf_Test) and an object type (Table_Count_Type), both defined in the attached script, HProf_Test_Code.sql. The test program covers the following scenarios:

  • Multiple root calls (__plsql_vm, A_CALLS_B)
  • Recursive procedure calls (procedure calling itself: R_CALLS_R)
  • Mutually recursive procedure calls (procedures call each other: A_CALLS_B and B_CALLS_A)
  • Procedure called by multiple procedures (child with multiple parents: PUT_LINE)
  • Procedure 'inlined' within PL/SQL (Rest_a_While)
  • Static SQL within PL/SQL (__static_sql_exec_line8)
  • Dynamic SQL within PL/SQL (__dyn_sql_exec_line12)
  • 'Everything should be made as simple as possible, but not simpler'

    This phrase is often attributed to Albert Einstein, although the attribution is apparently questionable:
    Everything Should Be Made as Simple as Possible, But Not Simpler. In any case it's not a bad approach to follow, even if the quote did come from a non-Oracle guy :).

    I recently started looking at the hierarchical profiler tool with a view to using it in an upcoming project. In order to understand the tool properly, I felt it would be a good idea to start by using it to profile a test program that would be as simple as possible while covering as wide a range of scenarios as possible. This article documents the results of that profiling, highlighting the different scenarios covered, discusses the output from the profiler, and includes a query I wrote to display the function call tree.

    The article goes on to illustrate profiling through manual code instrumentation, and by the old flat profiler (DBMS_Profiler) on the same test program, concluding that each method has its own strengths and weaknesses.

    Setup
    The hierarchical profiler setup and use is described in Oracle® Database Advanced Application Developer's Guide 11g Release 2 (11.2), and some code snippets are available here:PL/SQL Hierarchical Profiler in Oracle Database 11g Release 1

    Scenarios
    The test program consists of a driving script, Test_Rep_p.sql (attached), that calls a package (HProf_Test) and an object type (Table_Count_Type), both defined in the attached script, HProf_Test_Code.sql. The test program covers the following scenarios:

    • Multiple root calls (__plsql_vm, A_CALLS_B)
    • Recursive procedure calls (procedure calling itself: R_CALLS_R)
    • Mutually recursive procedure calls (procedures call each other: A_CALLS_B and B_CALLS_A)
    • Procedure called by multiple procedures (child with multiple parents: PUT_LINE)
    • Procedure 'inlined' within PL/SQL (Rest_a_While)
    • Static SQL within PL/SQL (__static_sql_exec_line8)
    • Dynamic SQL within PL/SQL (__dyn_sql_exec_line12)
    • Database function called from SQL in SQL*Plus (DBFUNC)
    • Database function called from SQL in PL/SQL (DBFUNC)
    • Object constructor call (TABLE_COUNT_TYPE)

    Call Structure Diagram
    HProf - CSD

    Raw Results
    The attached script Test_Rep_h.sql was used to report on the results. The record produced in the run table, DBMSHP_RUNS, was:

         RUNID RUN_TIMESTAMP                   MICRO_S    SECONDS RUN_COMMENT
    ---------- ---------------------------- ---------- ---------- ------------------------------------------------------------
            11 04-MAR-13 07.07.36.803000        890719        .89 Profile for small test program with recursion

    The records produced in the functions table, DBMSHP_FUNCTION_INFO, were:

    OWNER MODULE               FUNCTION                         ID  LINE#      SUB_T      FUN_T  CALLS
    ----- -------------------- ------------------------------ ---- ------ ---------- ---------- ------
    NET   HPROF_TEST           A_CALLS_B                         4     40      62340       4450      1
    NET   HPROF_TEST           A_CALLS_B@1                       5     40      43729      13663      1
    NET   HPROF_TEST           B_CALLS_A                         6     38      57890      14161      1
    NET   HPROF_TEST           B_CALLS_A@1                       7     38      30066      30066      1
    NET   HPROF_TEST           DBFUNC                            8     84      32629      32629      2
    NET   HPROF_TEST           R_CALLS_R                         9     70      12823       4159      1
    NET   HPROF_TEST           R_CALLS_R@1                      10     70       8633       8618      1
    NET   HPROF_TEST           STOP_PROFILING                   11     16         21         21      1
    NET   TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                 12      3      55049         82      1
    NET   TABLE_COUNT_TYPE     __static_sql_exec_line6          22      6      54967      54967      1
    SYS   DBMS_HPROF           STOP_PROFILING                   13     59          0          0      1
    SYS   DBMS_OUTPUT          GET_LINE                         14    129          8          8      3
    SYS   DBMS_OUTPUT          GET_LINES                        15    160         68         60      3
    SYS   DBMS_OUTPUT          NEW_LINE                         16    117          7          7      2
    SYS   DBMS_OUTPUT          PUT                              17     77         28         28      2
    SYS   DBMS_OUTPUT          PUT_LINE                         18    109         46         11      2
                               __anonymous_block                 1      0     809839        521      5
                               __dyn_sql_exec_line12            19     12        226        226      1
                               __plsql_vm                        2      0     828379         58      6
                               __plsql_vm@1                      3      0      14158         11      1
                               __sql_fetch_line13               20     13     726713     726713      1
                               __static_sql_exec_line8          21      8      14418        260      1
    
    22 rows selected.

    The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing.

    The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, were:

    OWNER_P MODULE_P             FUNCTION_P                     OWNER_C MODULE_C             FUNCTION_C                          SUB_T      FUN_T  CALLS
    ------- -------------------- ------------------------------ ------- -------------------- ------------------------------ ---------- ---------- ------
    NET     HPROF_TEST           STOP_PROFILING                 SYS     DBMS_HPROF           STOP_PROFILING                          0          0      1
    NET     HPROF_TEST           R_CALLS_R@1                    SYS     DBMS_OUTPUT          PUT_LINE                               15          6      1
    NET     HPROF_TEST           R_CALLS_R                      SYS     DBMS_OUTPUT          PUT_LINE                               31          5      1
    NET     HPROF_TEST           R_CALLS_R                      NET     HPROF_TEST           R_CALLS_R@1                          8633       8618      1
    NET     HPROF_TEST           B_CALLS_A                      NET     HPROF_TEST           A_CALLS_B@1                         43729      13663      1
    NET     HPROF_TEST           A_CALLS_B@1                    NET     HPROF_TEST           B_CALLS_A@1                         30066      30066      1
    NET     HPROF_TEST           A_CALLS_B                      NET     HPROF_TEST           B_CALLS_A                           57890      14161      1
    NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE               NET     TABLE_COUNT_TYPE     __static_sql_exec_line6             54967      54967      1
    SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          NEW_LINE                                7          7      2
    SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          PUT                                    28         28      2
    SYS     DBMS_OUTPUT          GET_LINES                      SYS     DBMS_OUTPUT          GET_LINE                                8          8      3
                                 __anonymous_block              NET     HPROF_TEST           STOP_PROFILING                         21         21      1
                                 __anonymous_block              SYS     DBMS_OUTPUT          GET_LINES                              68         60      3
                                 __anonymous_block                                           __dyn_sql_exec_line12                 226        226      1
                                 __anonymous_block              NET     HPROF_TEST           R_CALLS_R                           12823       4159      1
                                 __anonymous_block                                           __static_sql_exec_line8             14418        260      1
                                 __plsql_vm                     NET     HPROF_TEST           DBFUNC                              18482      18482      1
                                 __anonymous_block                                           __sql_fetch_line13                 726713     726713      1
                                 __static_sql_exec_line8                                     __plsql_vm@1                        14158         11      1
                                 __plsql_vm                                                  __anonymous_block                  809839        521      5
                                 __plsql_vm@1                   NET     HPROF_TEST           DBFUNC                              14147      14147      1
                                 __anonymous_block              NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                    55049         82      1
    
    22 rows selected.

    The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing, respectively, for the child function while called from all instances of the parent.

    Function Call Tree
    The raw data above can be used to identify processing bottlenecks at a function level, but it's also useful to process the data in order to display the function hierarchies, both for performance tuning and also for understanding the program structure. This is not quite as trivial as it may seem. The oracle-base article provides an SQL statement that attempts to do this:

    SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
           fi.function,
           pci.subtree_elapsed_time,
           pci.function_elapsed_time,
           pci.calls
    FROM   dbmshp_parent_child_info pci
           JOIN dbmshp_function_info fi ON pci.runid = fi.runid AND pci.childsymid = fi.symbolid
    WHERE  pci.runid = :RUN_ID
    CONNECT BY PRIOR childsymid = parentsymid
    START WITH pci.parentsymid = :START_ID

    Here, bind variables replace the original hard-coded values. On running this query I often got the following result:

    ERROR at line 1:
    ORA-01436: CONNECT BY loop in user data

    On the run used in this article, the query returned 157 records, which is obviously incorrect. There is of course a NOCYCLE keyword that can be used to return results in the case of loops. However, it is not worth adding in this case, because there are in fact no loops in the data (at least no cyclic loops - apparent loops are discussed later). Oracle avoids loops by treating a function call that is a descendant of itself as a call to a new function, identified by suffices @1, @2 etc. as we can see from the recursive procedures above (eg R_CALLS_R@1 is the second call of R_CALLS_R, this one from itself). The problem here is that the query is incorrect in its handling of runid, with the result that the tree-walk traverses records from other runs as well as the intended one. A further problem is that there may be several roots, and it would be best to calculate these within a subquery. We can correct these problems by the following query:

    SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
           fi.symbolid || ': ' || fi.function function,
           pci.subtree_elapsed_time sub_t,
           pci.function_elapsed_time fun_t,
           pci.calls
      FROM dbmshp_parent_child_info	pci
      JOIN dbmshp_function_info		fi 
        ON pci.runid	              = fi.runid 
       AND pci.childsymid	       = fi.symbolid
     WHERE pci.runid                   = :RUN_ID
    CONNECT BY PRIOR pci.childsymid    = pci.parentsymid 
           AND pci.runid	              = :RUN_ID
    START WITH pci.parentsymid         IN (SELECT f.symbolid FROM dbmshp_function_info f WHERE NOT EXISTS 
           (SELECT 1 FROM dbmshp_parent_child_info i WHERE i.childsymid = f.symbolid AND i.runid = :RUN_ID) AND f.runid = :RUN_ID)
           AND pci.runid	              = :RUN_ID

    This query returns the results:

    NAME                           FUNCTION                            SUB_T      FUN_T  CALLS
    ------------------------------ ------------------------------ ---------- ---------- ------
      .                            1: __anonymous_block              809,839        521      5
        NET.HPROF_TEST             9: R_CALLS_R                       12,823      4,159      1
          NET.HPROF_TEST           10: R_CALLS_R@1                     8,633      8,618      1
            SYS.DBMS_OUTPUT        18: PUT_LINE                           15          6      1
              SYS.DBMS_OUTPUT      16: NEW_LINE                            7          7      2
              SYS.DBMS_OUTPUT      17: PUT                                28         28      2
          SYS.DBMS_OUTPUT          18: PUT_LINE                           31          5      1
            SYS.DBMS_OUTPUT        16: NEW_LINE                            7          7      2
            SYS.DBMS_OUTPUT        17: PUT                                28         28      2
        NET.HPROF_TEST             11: STOP_PROFILING                     21         21      1
          SYS.DBMS_HPROF           13: STOP_PROFILING                      0          0      1
        NET.TABLE_COUNT_TYPE       12: TABLE_COUNT_TYPE               55,049         82      1
          NET.TABLE_COUNT_TYPE     22: __static_sql_exec_line6        54,967     54,967      1
        SYS.DBMS_OUTPUT            15: GET_LINES                          68         60      3
          SYS.DBMS_OUTPUT          14: GET_LINE                            8          8      3
        .                          19: __dyn_sql_exec_line12             226        226      1
        .                          20: __sql_fetch_line13            726,713    726,713      1
        .                          21: __static_sql_exec_line8        14,418        260      1
          .                        3: __plsql_vm@1                    14,158         11      1
            NET.HPROF_TEST         8: DBFUNC                          14,147     14,147      1
      NET.HPROF_TEST               8: DBFUNC                          18,482     18,482      1
      NET.HPROF_TEST               6: B_CALLS_A                       57,890     14,161      1
        NET.HPROF_TEST             5: A_CALLS_B@1                     43,729     13,663      1
          NET.HPROF_TEST           7: B_CALLS_A@1                     30,066     30,066      1
    
    24 rows selected.

    This is better, but we can identify some further issues.

    Missing Roots
    The true root results are missing: For example, A_CALLS_B is missing. This arises because the query is traversing the link records (DBMSHP_PARENT_CHILD_INFO), while the root information is stored in the nodes (DBMSHP_FUNCTION_INFO). This suggests a change from the CONNECT BY syntax to Oracle's v11.2 recursive subquery factoring syntax, which allows you easily to start from the nodes, then traverse recursively via the links. (Incidentally, moving the start of profiling to its own block would result in A_CALLS_B appearing under __anonymous_block, but I prefer to retain the current structure in order to deal with the general case in which multiple roots are possible.)

    Duplicate Links
    Notice that function PUT_LINE is reported separately under R_CALLS_R and R_CALLS_R@1, and the timings differ. Also, its own child calls appear under each of its instances, but in those cases the timings are identical. The reason for this is that in the first case, there are separate records of the times used in each call, whereas in the second, the child calls have only a single record giving the total times across both instances of the parent call. The call from R_CALLS_R shows (9 - 4 = ) 5µs used in child calls, while the call from R_CALLS_R@1 shows 14µs. The child calls show totals of (3 + 16 = ) 19µs, equalling the sum across the parent calls.

    At this point it is worth looking at this from the more general perspective of a hierarchical data structure where parents can have multiple children and children multiple parents, with one or more roots. If a network diagram were constructed there would be loops apparent indicating multiple routes between nodes. In these situations, Oracle's hierarchical queries effectively traverse all routes, and this is what causes the link duplication (in other scenarios this behaviour can cause big performance problems, but probably not here). Oracle's cycle detection mechanism does not trigger because the loops do not result in any node being a descendant of itself (as noted above, extra nodes are generated by the profiler to avoid this).

    It seems to me better to avoid this duplication, and also to signal those cases where times are not aggregated up the tree. We can achieve this by the use of analytic functions. Note that, although the query below refers to the specific tables and attributes for this problem, the proposed solution could be used for any member of this general class of problem. The new query, which orders sibling records by descending subtree elapsed time, is:

    WITH last_run AS (
    SELECT Max (runid) runid FROM dbmshp_runs
    ), full_tree (runid, lev, node_id, sub_t, fun_t, calls, link_id) AS (
    SELECT fni.runid, 0, fni.symbolid, fni.subtree_elapsed_time, fni.function_elapsed_time, fni.calls, 'root' || ROWNUM
      FROM dbmshp_function_info fni
      JOIN last_run lrn
        ON lrn.runid = fni.runid
     WHERE NOT EXISTS (SELECT 1 FROM dbmshp_parent_child_info pci WHERE pci.childsymid = fni.symbolid AND pci.runid = fni.runid)
     UNION ALL
    SELECT ftr.runid, 
           ftr.lev + 1, 
           pci.childsymid, 
           pci.subtree_elapsed_time, 
           pci.function_elapsed_time, 
           pci.calls,
           pci.parentsymid || '-' || pci.childsymid
      FROM full_tree ftr
      JOIN dbmshp_parent_child_info pci
        ON pci.parentsymid = ftr.node_id
       AND pci.runid = ftr.runid
    ) SEARCH DEPTH FIRST BY sub_t DESC, fun_t DESC, calls DESC, node_id SET rn
    , tree_ranked AS (
    SELECT runid, node_id, lev, rn, 
           sub_t, fun_t, calls, 
           Row_Number () OVER (PARTITION BY node_id ORDER BY rn) node_rn,
           Count (*) OVER (PARTITION BY node_id) node_cnt,
           Row_Number () OVER (PARTITION BY link_id ORDER BY rn) link_rn
      FROM full_tree
    )
    SELECT RPad (' ', trr.lev*2, ' ') || fni.function "Function tree",
           fni.symbolid sy, fni.owner, fni.module,
           CASE WHEN trr.node_cnt > 1 THEN trr.node_rn || ' of ' || trr.node_cnt END "Inst.",
           trr.sub_t, trr.fun_t, trr.calls, 
           trr.rn "Row"
      FROM tree_ranked trr
      JOIN dbmshp_function_info fni
        ON fni.symbolid = trr.node_id
       AND fni.runid = trr.runid
     WHERE trr.link_rn = 1
     ORDER BY trr.rn

    Query Structure Diagram
    HProf - QSD

    The results are then:

    Function tree                        SY OWNER MODULE               Inst.         SUB_T      FUN_T  CALLS  Row
    ----------------------------------- --- ----- -------------------- -------- ---------- ---------- ------ ----
    __plsql_vm                            2                                        828,379         58      6    1
      __anonymous_block                   1                                        809,839        521      5    2
        __sql_fetch_line13               20                                        726,713    726,713      1    3
        TABLE_COUNT_TYPE                 12 NET   TABLE_COUNT_TYPE                  55,049         82      1    4
          __static_sql_exec_line6        22 NET   TABLE_COUNT_TYPE                  54,967     54,967      1    5
        __static_sql_exec_line8          21                                         14,418        260      1    6
          __plsql_vm@1                    3                                         14,158         11      1    7
            DBFUNC                        8 NET   HPROF_TEST           1 of 2       14,147     14,147      1    8
        R_CALLS_R                         9 NET   HPROF_TEST                        12,823      4,159      1    9
          R_CALLS_R@1                    10 NET   HPROF_TEST                         8,633      8,618      1   10
            PUT_LINE                     18 SYS   DBMS_OUTPUT          1 of 2           15          6      1   11
              PUT                        17 SYS   DBMS_OUTPUT          1 of 2           28         28      2   12
              NEW_LINE                   16 SYS   DBMS_OUTPUT          1 of 2            7          7      2   13
          PUT_LINE                       18 SYS   DBMS_OUTPUT          2 of 2           31          5      1   14
        __dyn_sql_exec_line12            19                                            226        226      1   17
        GET_LINES                        15 SYS   DBMS_OUTPUT                           68         60      3   18
          GET_LINE                       14 SYS   DBMS_OUTPUT                            8          8      3   19
        STOP_PROFILING                   11 NET   HPROF_TEST                            21         21      1   20
          STOP_PROFILING                 13 SYS   DBMS_HPROF                             0          0      1   21
      DBFUNC                              8 NET   HPROF_TEST           2 of 2       18,482     18,482      1   22
    A_CALLS_B                             4 NET   HPROF_TEST                        62,340      4,450      1   23
      B_CALLS_A                           6 NET   HPROF_TEST                        57,890     14,161      1   24
        A_CALLS_B@1                       5 NET   HPROF_TEST                        43,729     13,663      1   25
          B_CALLS_A@1                     7 NET   HPROF_TEST                        30,066     30,066      1   26
    
    24 rows selected.

    Notice that we now have a single record for each of the 22 links, plus the two root nodes. Also, the "Inst." column lists the instance number of a function having more than one instance, and the children of any such function are only listed once with the gaps in the "Row" column indicating where duplicates have been suppressed.

    Network Diagrams
    It may be interesting to display the call tree in two diagrams, one for each root.
    Root __plsql_vm
    HProf - Net

    Root A_CALLS_B
    HProf - Net2

    Notes on Tree Output
    Anonymous Block (__anonymous_block)
    This function seems to correspond to invocations of anonymous blocks, obviously enough. However, there is an apparent anomaly in the number of calls listed, 6, because the driving program has only three such blocks, and there are none in the called PL/SQL code. I would surmise that the apparent discrepancy arises from the enabling of SERVEROUTPUT, which appears to result in a secondary block being associated with each explicit SQL*Plus block, that issues a call to GET_LINES to process buffered output.

    PL/SQL Engine (__plsql_vm)
    This function seems to correspond to external invocations of PL/SQL such as from a SQL*Plus session. There are 7 calls, 6 of them presumably being linked with the external anonymous blocks, and the seventh with DBFUNC, where a PL/SQL function is called from a SQL statement from SQL*Plus.

    Notice that the SQL statement calling a database function from within PL/SQL generates the recursive call to the engine, __plsql_vm@1

    Second Root (A_CALLS_B)
    The above function does not have the __plsql_vm/__anonymous_block ancestry that might be expected because profiling only started within the enclosing block.

    Inlined Procedure (Rest_a_While)
    I wrote a small procedure, Rest_a_While, to generate some elapsed time in the recursive procedures, but preceded it with the INLINE pragma, a new optimisation feature in 11g. This had the desired effect of removing the calls from the profiling output and including the times in the calling procedures. Rest_a_While does not make the obvious call to DBMS_Lock.Sleep because that procedure cannot be inlined. subprogram inlining in 11g provides some analysis of the inlining feature.

    Sibling Ordering
    We have ordered siblings by descending subtree elapsed time, using the SEARCH clause. It would be nice to have the option to order the siblings by initial invocation time, but Oracle does not provide the data to do this.

    Loops and Hierarchies
    The first diagram shows two loops, where there are two routes between the loop start and end points, indicated by different colours. The second loop has two child nodes coming from the end point, and hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links to be duplicated. Our query has filtered out the duplicates by analytic functions.

    It's worth remembering this because it's a general feature of SQL for querying hierarchies, and judging by Oracle forums, not one that's widely understood. For larger hierarchies it can cause serious performance problems, and may justify a PL/SQL programmed solution that need not suffer the same problem.

    Manual Instrumentation
    Oracle's hierarchical profiler clearly provides extremely useful information on both performance and structure of PL/SQL programs with very little effort. However, it does have the limitation of only providing information down to the subprogram level (which includes embedded SQL statements in this context). It is also often considered good practice to implement timing and other instrumentation permanently in production code, sometimes in a switchable fashion. In the test program, one of the called procedures, A_Calls_B, makes two calls to the inlined procedure, Rest_a_While, the second doing about twice as much work as the first. The profiler reports total within-function times of 4,450µs and 13,663µs on first and second calls, respectively (the work is scaled by a call number parameter, equal to 1, then 3).

    I created a second instance of the package and driver script (suffix _TS) to illustrate manual instrumentation. This uses an 'object-oriented' timing package that I wrote a couple of years ago Code Timing and Object Orientation and Zombies (November, 2010) to instrument at procedure and section level. I multiplied the work in Rest_a_While by a factor of ten to get larger times. This produced the output:

    Timer Set: HProf, Constructed at 05 Mar 2013 10:21:27, written at 10:21:30
    ==========================================================================
    [Timer timed: Elapsed (per call): 0.04 (0.000044), CPU (per call): 0.05 (0.000050), calls: 1000, '***' denotes corrected line below]
    
    Timer                       Elapsed          CPU          Calls        Ela/Call        CPU/Call
    ----------------------   ----------   ----------   ------------   -------------   -------------
    A_Calls_B, section one         0.06         0.05              2         0.03150         0.02500
    A_Calls_B, section two         0.12         0.12              2         0.06050         0.06000
    B_Calls_A: 2                   0.15         0.16              1         0.15400         0.16000
    B_Calls_A: 4                   0.31         0.30              1         0.30700         0.30000
    DBFunc                         0.32         0.31              2         0.15950         0.15500
    Open cursor                    0.69         0.69              1         0.68900         0.69000
    Fetch from cursor              0.70         0.70              1         0.69600         0.70000
    Close cursor                   0.00         0.00              1         0.00000         0.00000
    Construct object               0.06         0.04              1         0.05500         0.04000
    R_Calls_R                      0.14         0.14              2         0.07000         0.07000
    (Other)                        0.00         0.00              1         0.00000         0.00000
    ----------------------   ----------   ----------   ------------   -------------   -------------
    Total                          2.54         2.51             15         0.16960         0.16733
    ----------------------   ----------   ----------   ------------   -------------   -------------
    

    Notes on Code Timing

    • Calls, CPU and elapsed times have been captured at the section level for A_Calls_B
    • Observe that, while R_Calls_R and A_Calls_B aggregate over all calls, B_Calls_A records values by call; this is implemented simply by including a value that changes with call in the timer name
    • The timing set object is designed to be very low footprint; here 9 statements (calls to Increment_Time), plus a small global overhead, produced 10 result lines, plus associated information
    • The 'object-oriented' approach allows multiple programs to be be timed at multiple levels, without interference between timings
    • There are Perl and Java implementations of this timing set object included in the Scribd article mentioned

    Oracle's Flat Profiler (DBMS_Profiler)
    The hierarchical profiler was introduced in v11.1, while prior to this there was a non-hierarchical profiler, DBMS_Profiler. This package still exists in v11: It is omitted from the advanced application developer's guide for v11, but is described in the packages and types manual (Oracle® Database PL/SQL Packages and Types Reference, 11g Release 2 (11.2)); also, SQL*Developer appears to support only the newer hierarchical verion (via right-click on a package). I thought it interesting to run the older version on the same test program (package Old_Test_Prof, driver script Test_Rep_p_Old.sql and reporting script Test_Rep_h_Old.sql). The output from the first three queries is:

    Run header (PLSQL_PROFILER_RUNS)
    
         RUNID RUN_DATE        MICRO_S    SECONDS
    ---------- ------------ ---------- ----------
             3 11:03:13        2164000       2.16
    
    Profiler data summary (PLSQL_PROFILER_DATA)
    
       MICRO_S SECONDS    CALLS
    ---------- ------- --------
       2126949    2.13       72
    
    Profiler data by time (PLSQL_PROFILER_DATA)
    
       MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
    ---------- ------- -------- -------------------- ----------- ------
        729932    0.73        1                                5     13
        569563    0.57        2 OLD_PROF_TEST                  1     56
        377880    0.38        2 OLD_PROF_TEST                  1     82
        166019    0.17        2 OLD_PROF_TEST                  1     70
        150117    0.15        2 OLD_PROF_TEST                  1     43
         72742    0.07        2 OLD_PROF_TEST                  1     40
         56473    0.06        1 TABLE_COUNT_TYPE               6      6
          3338    0.00        1                                5      8
           258    0.00        1                                5     12
           109    0.00        1                                5     16
            68    0.00        2 OLD_PROF_TEST                  1     67
            66    0.00        2                                4      1
            60    0.00        2                                7      1
            60    0.00        2                                3      1
            44    0.00        1                                5     14
            42    0.00        0                                2      5
            31    0.00        1 OLD_PROF_TEST                  1     18
            26    0.00        1                                8      5
            13    0.00        0                                5      1
             9    0.00        1 TABLE_COUNT_TYPE               6     11
             9    0.00        2 OLD_PROF_TEST                  1     86
             8    0.00        0 OLD_PROF_TEST                  1     51
             8    0.00        1 TABLE_COUNT_TYPE               6     13
             7    0.00        1                                5     18
             6    0.00        0 OLD_PROF_TEST                  1     78
             6    0.00        0 OLD_PROF_TEST                  1     64
             6    0.00        0                                8      1
             6    0.00        1 TABLE_COUNT_TYPE               6      3
             5    0.00        0 OLD_PROF_TEST                  1     35
             5    0.00        0 OLD_PROF_TEST                  1     15
             4    0.00        1                                8      7
             4    0.00        1 OLD_PROF_TEST                  1     76
             3    0.00        1                                2      8
             2    0.00        1 OLD_PROF_TEST                  1     62
             2    0.00        1 OLD_PROF_TEST                  1     13
             2    0.00        1 TABLE_COUNT_TYPE               6      5
             2    0.00        2 OLD_PROF_TEST                  1     72
             2    0.00        2 OLD_PROF_TEST                  1     45
             2    0.00        2 OLD_PROF_TEST                  1     49
             2    0.00        2 OLD_PROF_TEST                  1     46
             2    0.00        2 OLD_PROF_TEST                  1     58
             1    0.00        1 OLD_PROF_TEST                  1     73
             1    0.00        1                                2      6
             1    0.00        1 OLD_PROF_TEST                  1     59
             1    0.00        1 OLD_PROF_TEST                  1     11
             1    0.00        2 OLD_PROF_TEST                  1     54
             1    0.00        2 OLD_PROF_TEST                  1     84
             0    0.00        0 OLD_PROF_TEST                  1      1
             0    0.00        0 OLD_PROF_TEST                  1     88
             0    0.00        0                                8      9
             0    0.00        0                                2      1
             0    0.00        0                                2      2
             0    0.00        0 OLD_PROF_TEST                  1      3
             0    0.00        0 OLD_PROF_TEST                  1      5
             0    0.00        0 OLD_PROF_TEST                  1      9
             0    0.00        0 OLD_PROF_TEST                  1     20
             0    0.00        1 TABLE_COUNT_TYPE               6      4
             0    0.00        1                                8      2
             0    0.00        2 OLD_PROF_TEST                  1     39
             0    0.00        2 OLD_PROF_TEST                  1     55
             0    0.00        2 OLD_PROF_TEST                  1     69
             0    0.00        2 OLD_PROF_TEST                  1     38
             0    0.00        2 OLD_PROF_TEST                  1     81
             0    0.00        2 OLD_PROF_TEST                  1     42
             0    0.00        2 OLD_PROF_TEST                  1     68
    
    65 rows selected.
    
    

    Referring to the package, type and anonymous blocks, I assigned labels to all the lines having more than 10µs, as follows:

       MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
    ---------- ------- -------- -------------------- ----------- ------
        729932    0.73        1                                5     13  B2: FETCH
        569563    0.57        2 OLD_PROF_TEST                  1     56  B_Calls_A (Rest_a_While)
        377880    0.38        2 OLD_PROF_TEST                  1     82  DBFunc (Rest_a_While)
        166019    0.17        2 OLD_PROF_TEST                  1     70  R_Calls_R (Rest_a_While)
        150117    0.15        2 OLD_PROF_TEST                  1     43  A_Calls_B (Rest_a_While, section 2)
         72742    0.07        2 OLD_PROF_TEST                  1     40  A_Calls_B (Rest_a_While, section 1)
         56473    0.06        1 TABLE_COUNT_TYPE               6      6  SELECT
          3338    0.00        1                                5      8  B2: SELECT DBFunc
           258    0.00        1                                5     12  B2: OPEN
           109    0.00        1                                5     16  B2: Assign Table_Count_Type
            68    0.00        2 OLD_PROF_TEST                  1     67  Put_Line
            66    0.00        2                                4      1  Auxiliary SERVEROUTPUT block for B2 (surmised)
            60    0.00        2                                7      1  Auxiliary SERVEROUTPUT block for B3 (surmised)
            60    0.00        2                                3      1  Auxiliary SERVEROUTPUT block for B1 (surmised)
            44    0.00        1                                5     14  B2: CLOSE
            42    0.00        0                                2      5  B1: Call to Start_Profiling 
            31    0.00        1 OLD_PROF_TEST                  1     18  RETURN DBMS_Profiler.Stop_Profiler;
            26    0.00        1                                8      5  B3: Call R_Calls_R
            13    0.00        0                                5      1  B2: DECLARE
    

    Notes on Output of Flat Profiler
    There were six units with no linked information in DBMS_PROFILER_UNITS. By examining the data, I was able to associate unit numbers 2, 5 and 8 with my anonymous blocks B1, B2 and B3. That left three unassigned, and I have surmised that these correspond to the auxiliary blocks associated with processing server output that we earlier surmised when examining the output from the hierarchical profiler.

    • The useful call tree structure is not present in the data from the old profiler
    • However, the results are at a line level, which the hierarchical profiler does not provide; for example, the two sections of A_Calls_B are reported separately
    • Deciphering the output requires significantly more manual effort than with the hierarchical profiler
    • Both old and new profiler have their own advantages, and so both should be considered of value
    • Manual code timing offers more flexibility in terms of aggregating lines and call instances, but requires more effort

    Conclusions

    • Running Oracle's hierarchical profiler would seem to be the default first step in tuning PL/SQL programs from v11.1
    • Some care is needed in interpreting the output data; I've provided a query for displaying the hierarchies
    • Performance is recorded only down to function level, so it will still often be worthwhile to use the old flat profiler in addition
    • Manually timing code sections also still has a part to play, in terms of instrumentation and greater flexibility where necessary






  • Database function called from SQL in SQL*Plus (DBFUNC)
  • Database function called from SQL in PL/SQL (DBFUNC)
  • Object constructor call (TABLE_COUNT_TYPE)

Call Structure Diagram
HProf - CSD

Raw Results
The attached script Test_Rep_h.sql was used to report on the results. The record produced in the run table, DBMSHP_RUNS, was:

     RUNID RUN_TIMESTAMP                   MICRO_S    SECONDS RUN_COMMENT
---------- ---------------------------- ---------- ---------- ------------------------------------------------------------
        11 04-MAR-13 07.07.36.803000        890719        .89 Profile for small test program with recursion

The records produced in the functions table, DBMSHP_FUNCTION_INFO, were:

OWNER MODULE               FUNCTION                         ID  LINE#      SUB_T      FUN_T  CALLS
----- -------------------- ------------------------------ ---- ------ ---------- ---------- ------
NET   HPROF_TEST           A_CALLS_B                         4     40      62340       4450      1
NET   HPROF_TEST           A_CALLS_B@1                       5     40      43729      13663      1
NET   HPROF_TEST           B_CALLS_A                         6     38      57890      14161      1
NET   HPROF_TEST           B_CALLS_A@1                       7     38      30066      30066      1
NET   HPROF_TEST           DBFUNC                            8     84      32629      32629      2
NET   HPROF_TEST           R_CALLS_R                         9     70      12823       4159      1
NET   HPROF_TEST           R_CALLS_R@1                      10     70       8633       8618      1
NET   HPROF_TEST           STOP_PROFILING                   11     16         21         21      1
NET   TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                 12      3      55049         82      1
NET   TABLE_COUNT_TYPE     __static_sql_exec_line6          22      6      54967      54967      1
SYS   DBMS_HPROF           STOP_PROFILING                   13     59          0          0      1
SYS   DBMS_OUTPUT          GET_LINE                         14    129          8          8      3
SYS   DBMS_OUTPUT          GET_LINES                        15    160         68         60      3
SYS   DBMS_OUTPUT          NEW_LINE                         16    117          7          7      2
SYS   DBMS_OUTPUT          PUT                              17     77         28         28      2
SYS   DBMS_OUTPUT          PUT_LINE                         18    109         46         11      2
                           __anonymous_block                 1      0     809839        521      5
                           __dyn_sql_exec_line12            19     12        226        226      1
                           __plsql_vm                        2      0     828379         58      6
                           __plsql_vm@1                      3      0      14158         11      1
                           __sql_fetch_line13               20     13     726713     726713      1
                           __static_sql_exec_line8          21      8      14418        260      1

22 rows selected.

The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing.

The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, were:

OWNER_P MODULE_P             FUNCTION_P                     OWNER_C MODULE_C             FUNCTION_C                          SUB_T      FUN_T  CALLS
------- -------------------- ------------------------------ ------- -------------------- ------------------------------ ---------- ---------- ------
NET     HPROF_TEST           STOP_PROFILING                 SYS     DBMS_HPROF           STOP_PROFILING                          0          0      1
NET     HPROF_TEST           R_CALLS_R@1                    SYS     DBMS_OUTPUT          PUT_LINE                               15          6      1
NET     HPROF_TEST           R_CALLS_R                      SYS     DBMS_OUTPUT          PUT_LINE                               31          5      1
NET     HPROF_TEST           R_CALLS_R                      NET     HPROF_TEST           R_CALLS_R@1                          8633       8618      1
NET     HPROF_TEST           B_CALLS_A                      NET     HPROF_TEST           A_CALLS_B@1                         43729      13663      1
NET     HPROF_TEST           A_CALLS_B@1                    NET     HPROF_TEST           B_CALLS_A@1                         30066      30066      1
NET     HPROF_TEST           A_CALLS_B                      NET     HPROF_TEST           B_CALLS_A                           57890      14161      1
NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE               NET     TABLE_COUNT_TYPE     __static_sql_exec_line6             54967      54967      1
SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          NEW_LINE                                7          7      2
SYS     DBMS_OUTPUT          PUT_LINE                       SYS     DBMS_OUTPUT          PUT                                    28         28      2
SYS     DBMS_OUTPUT          GET_LINES                      SYS     DBMS_OUTPUT          GET_LINE                                8          8      3
                             __anonymous_block              NET     HPROF_TEST           STOP_PROFILING                         21         21      1
                             __anonymous_block              SYS     DBMS_OUTPUT          GET_LINES                              68         60      3
                             __anonymous_block                                           __dyn_sql_exec_line12                 226        226      1
                             __anonymous_block              NET     HPROF_TEST           R_CALLS_R                           12823       4159      1
                             __anonymous_block                                           __static_sql_exec_line8             14418        260      1
                             __plsql_vm                     NET     HPROF_TEST           DBFUNC                              18482      18482      1
                             __anonymous_block                                           __sql_fetch_line13                 726713     726713      1
                             __static_sql_exec_line8                                     __plsql_vm@1                        14158         11      1
                             __plsql_vm                                                  __anonymous_block                  809839        521      5
                             __plsql_vm@1                   NET     HPROF_TEST           DBFUNC                              14147      14147      1
                             __anonymous_block              NET     TABLE_COUNT_TYPE     TABLE_COUNT_TYPE                    55049         82      1

22 rows selected.

The SUB_T and FUN_T values are the total times in microseconds for the subtree including function, and function-only processing, respectively, for the child function while called from all instances of the parent.

Function Call Tree
The raw data above can be used to identify processing bottlenecks at a function level, but it's also useful to process the data in order to display the function hierarchies, both for performance tuning and also for understanding the program structure. This is not quite as trivial as it may seem. The oracle-base article provides an SQL statement that attempts to do this:

SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
       fi.function,
       pci.subtree_elapsed_time,
       pci.function_elapsed_time,
       pci.calls
FROM   dbmshp_parent_child_info pci
       JOIN dbmshp_function_info fi ON pci.runid = fi.runid AND pci.childsymid = fi.symbolid
WHERE  pci.runid = :RUN_ID
CONNECT BY PRIOR childsymid = parentsymid
START WITH pci.parentsymid = :START_ID

Here, bind variables replace the original hard-coded values. On running this query I often got the following result:

ERROR at line 1:
ORA-01436: CONNECT BY loop in user data

On the run used in this article, the query returned 157 records, which is obviously incorrect. There is of course a NOCYCLE keyword that can be used to return results in the case of loops. However, it is not worth adding in this case, because there are in fact no loops in the data (at least no cyclic loops - apparent loops are discussed later). Oracle avoids loops by treating a function call that is a descendant of itself as a call to a new function, identified by suffices @1, @2 etc. as we can see from the recursive procedures above (eg R_CALLS_R@1 is the second call of R_CALLS_R, this one from itself). The problem here is that the query is incorrect in its handling of runid, with the result that the tree-walk traverses records from other runs as well as the intended one. A further problem is that there may be several roots, and it would be best to calculate these within a subquery. We can correct these problems by the following query:

SELECT RPAD(' ', level*2, ' ') || fi.owner || '.' || fi.module AS name,
       fi.symbolid || ': ' || fi.function function,
       pci.subtree_elapsed_time sub_t,
       pci.function_elapsed_time fun_t,
       pci.calls
  FROM dbmshp_parent_child_info	pci
  JOIN dbmshp_function_info		fi 
    ON pci.runid	              = fi.runid 
   AND pci.childsymid	       = fi.symbolid
 WHERE pci.runid                   = :RUN_ID
CONNECT BY PRIOR pci.childsymid    = pci.parentsymid 
       AND pci.runid	              = :RUN_ID
START WITH pci.parentsymid         IN (SELECT f.symbolid FROM dbmshp_function_info f WHERE NOT EXISTS 
       (SELECT 1 FROM dbmshp_parent_child_info i WHERE i.childsymid = f.symbolid AND i.runid = :RUN_ID) AND f.runid = :RUN_ID)
       AND pci.runid	              = :RUN_ID

This query returns the results:

NAME                           FUNCTION                            SUB_T      FUN_T  CALLS
------------------------------ ------------------------------ ---------- ---------- ------
  .                            1: __anonymous_block              809,839        521      5
    NET.HPROF_TEST             9: R_CALLS_R                       12,823      4,159      1
      NET.HPROF_TEST           10: R_CALLS_R@1                     8,633      8,618      1
        SYS.DBMS_OUTPUT        18: PUT_LINE                           15          6      1
          SYS.DBMS_OUTPUT      16: NEW_LINE                            7          7      2
          SYS.DBMS_OUTPUT      17: PUT                                28         28      2
      SYS.DBMS_OUTPUT          18: PUT_LINE                           31          5      1
        SYS.DBMS_OUTPUT        16: NEW_LINE                            7          7      2
        SYS.DBMS_OUTPUT        17: PUT                                28         28      2
    NET.HPROF_TEST             11: STOP_PROFILING                     21         21      1
      SYS.DBMS_HPROF           13: STOP_PROFILING                      0          0      1
    NET.TABLE_COUNT_TYPE       12: TABLE_COUNT_TYPE               55,049         82      1
      NET.TABLE_COUNT_TYPE     22: __static_sql_exec_line6        54,967     54,967      1
    SYS.DBMS_OUTPUT            15: GET_LINES                          68         60      3
      SYS.DBMS_OUTPUT          14: GET_LINE                            8          8      3
    .                          19: __dyn_sql_exec_line12             226        226      1
    .                          20: __sql_fetch_line13            726,713    726,713      1
    .                          21: __static_sql_exec_line8        14,418        260      1
      .                        3: __plsql_vm@1                    14,158         11      1
        NET.HPROF_TEST         8: DBFUNC                          14,147     14,147      1
  NET.HPROF_TEST               8: DBFUNC                          18,482     18,482      1
  NET.HPROF_TEST               6: B_CALLS_A                       57,890     14,161      1
    NET.HPROF_TEST             5: A_CALLS_B@1                     43,729     13,663      1
      NET.HPROF_TEST           7: B_CALLS_A@1                     30,066     30,066      1

24 rows selected.

This is better, but we can identify some further issues.

Missing Roots
The true root results are missing: For example, A_CALLS_B is missing. This arises because the query is traversing the link records (DBMSHP_PARENT_CHILD_INFO), while the root information is stored in the nodes (DBMSHP_FUNCTION_INFO). This suggests a change from the CONNECT BY syntax to Oracle's v11.2 recursive subquery factoring syntax, which allows you easily to start from the nodes, then traverse recursively via the links. (Incidentally, moving the start of profiling to its own block would result in A_CALLS_B appearing under __anonymous_block, but I prefer to retain the current structure in order to deal with the general case in which multiple roots are possible.)

Duplicate Links
Notice that function PUT_LINE is reported separately under R_CALLS_R and R_CALLS_R@1, and the timings differ. Also, its own child calls appear under each of its instances, but in those cases the timings are identical. The reason for this is that in the first case, there are separate records of the times used in each call, whereas in the second, the child calls have only a single record giving the total times across both instances of the parent call. The call from R_CALLS_R shows (9 - 4 = ) 5µs used in child calls, while the call from R_CALLS_R@1 shows 14µs. The child calls show totals of (3 + 16 = ) 19µs, equalling the sum across the parent calls.

At this point it is worth looking at this from the more general perspective of a hierarchical data structure where parents can have multiple children and children multiple parents, with one or more roots. If a network diagram were constructed there would be loops apparent indicating multiple routes between nodes. In these situations, Oracle's hierarchical queries effectively traverse all routes, and this is what causes the link duplication (in other scenarios this behaviour can cause big performance problems, but probably not here). Oracle's cycle detection mechanism does not trigger because the loops do not result in any node being a descendant of itself (as noted above, extra nodes are generated by the profiler to avoid this).

It seems to me better to avoid this duplication, and also to signal those cases where times are not aggregated up the tree. We can achieve this by the use of analytic functions. Note that, although the query below refers to the specific tables and attributes for this problem, the proposed solution could be used for any member of this general class of problem. The new query, which orders sibling records by descending subtree elapsed time, is:

WITH last_run AS (
SELECT Max (runid) runid FROM dbmshp_runs
), full_tree (runid, lev, node_id, sub_t, fun_t, calls, link_id) AS (
SELECT fni.runid, 0, fni.symbolid, fni.subtree_elapsed_time, fni.function_elapsed_time, fni.calls, 'root' || ROWNUM
  FROM dbmshp_function_info fni
  JOIN last_run lrn
    ON lrn.runid = fni.runid
 WHERE NOT EXISTS (SELECT 1 FROM dbmshp_parent_child_info pci WHERE pci.childsymid = fni.symbolid AND pci.runid = fni.runid)
 UNION ALL
SELECT ftr.runid, 
       ftr.lev + 1, 
       pci.childsymid, 
       pci.subtree_elapsed_time, 
       pci.function_elapsed_time, 
       pci.calls,
       pci.parentsymid || '-' || pci.childsymid
  FROM full_tree ftr
  JOIN dbmshp_parent_child_info pci
    ON pci.parentsymid = ftr.node_id
   AND pci.runid = ftr.runid
) SEARCH DEPTH FIRST BY sub_t DESC, fun_t DESC, calls DESC, node_id SET rn
, tree_ranked AS (
SELECT runid, node_id, lev, rn, 
       sub_t, fun_t, calls, 
       Row_Number () OVER (PARTITION BY node_id ORDER BY rn) node_rn,
       Count (*) OVER (PARTITION BY node_id) node_cnt,
       Row_Number () OVER (PARTITION BY link_id ORDER BY rn) link_rn
  FROM full_tree
)
SELECT RPad (' ', trr.lev*2, ' ') || fni.function "Function tree",
       fni.symbolid sy, fni.owner, fni.module,
       CASE WHEN trr.node_cnt > 1 THEN trr.node_rn || ' of ' || trr.node_cnt END "Inst.",
       trr.sub_t, trr.fun_t, trr.calls, 
       trr.rn "Row"
  FROM tree_ranked trr
  JOIN dbmshp_function_info fni
    ON fni.symbolid = trr.node_id
   AND fni.runid = trr.runid
 WHERE trr.link_rn = 1
 ORDER BY trr.rn

Query Structure Diagram
HProf - QSD

The results are then:

Function tree                        SY OWNER MODULE               Inst.         SUB_T      FUN_T  CALLS  Row
----------------------------------- --- ----- -------------------- -------- ---------- ---------- ------ ----
__plsql_vm                            2                                        828,379         58      6    1
  __anonymous_block                   1                                        809,839        521      5    2
    __sql_fetch_line13               20                                        726,713    726,713      1    3
    TABLE_COUNT_TYPE                 12 NET   TABLE_COUNT_TYPE                  55,049         82      1    4
      __static_sql_exec_line6        22 NET   TABLE_COUNT_TYPE                  54,967     54,967      1    5
    __static_sql_exec_line8          21                                         14,418        260      1    6
      __plsql_vm@1                    3                                         14,158         11      1    7
        DBFUNC                        8 NET   HPROF_TEST           1 of 2       14,147     14,147      1    8
    R_CALLS_R                         9 NET   HPROF_TEST                        12,823      4,159      1    9
      R_CALLS_R@1                    10 NET   HPROF_TEST                         8,633      8,618      1   10
        PUT_LINE                     18 SYS   DBMS_OUTPUT          1 of 2           15          6      1   11
          PUT                        17 SYS   DBMS_OUTPUT          1 of 2           28         28      2   12
          NEW_LINE                   16 SYS   DBMS_OUTPUT          1 of 2            7          7      2   13
      PUT_LINE                       18 SYS   DBMS_OUTPUT          2 of 2           31          5      1   14
    __dyn_sql_exec_line12            19                                            226        226      1   17
    GET_LINES                        15 SYS   DBMS_OUTPUT                           68         60      3   18
      GET_LINE                       14 SYS   DBMS_OUTPUT                            8          8      3   19
    STOP_PROFILING                   11 NET   HPROF_TEST                            21         21      1   20
      STOP_PROFILING                 13 SYS   DBMS_HPROF                             0          0      1   21
  DBFUNC                              8 NET   HPROF_TEST           2 of 2       18,482     18,482      1   22
A_CALLS_B                             4 NET   HPROF_TEST                        62,340      4,450      1   23
  B_CALLS_A                           6 NET   HPROF_TEST                        57,890     14,161      1   24
    A_CALLS_B@1                       5 NET   HPROF_TEST                        43,729     13,663      1   25
      B_CALLS_A@1                     7 NET   HPROF_TEST                        30,066     30,066      1   26

24 rows selected.

Notice that we now have a single record for each of the 22 links, plus the two root nodes. Also, the "Inst." column lists the instance number of a function having more than one instance, and the children of any such function are only listed once with the gaps in the "Row" column indicating where duplicates have been suppressed.

Network Diagrams
It may be interesting to display the call tree in two diagrams, one for each root.
Root __plsql_vm
HProf - Net

Root A_CALLS_B
HProf - Net2

Notes on Tree Output
Anonymous Block (__anonymous_block)
This function seems to correspond to invocations of anonymous blocks, obviously enough. However, there is an apparent anomaly in the number of calls listed, 6, because the driving program has only three such blocks, and there are none in the called PL/SQL code. I would surmise that the apparent discrepancy arises from the enabling of SERVEROUTPUT, which appears to result in a secondary block being associated with each explicit SQL*Plus block, that issues a call to GET_LINES to process buffered output.

PL/SQL Engine (__plsql_vm)
This function seems to correspond to external invocations of PL/SQL such as from a SQL*Plus session. There are 7 calls, 6 of them presumably being linked with the external anonymous blocks, and the seventh with DBFUNC, where a PL/SQL function is called from a SQL statement from SQL*Plus.

Notice that the SQL statement calling a database function from within PL/SQL generates the recursive call to the engine, __plsql_vm@1

Second Root (A_CALLS_B)
The above function does not have the __plsql_vm/__anonymous_block ancestry that might be expected because profiling only started within the enclosing block.

Inlined Procedure (Rest_a_While)
I wrote a small procedure, Rest_a_While, to generate some elapsed time in the recursive procedures, but preceded it with the INLINE pragma, a new optimisation feature in 11g. This had the desired effect of removing the calls from the profiling output and including the times in the calling procedures. Rest_a_While does not make the obvious call to DBMS_Lock.Sleep because that procedure cannot be inlined. subprogram inlining in 11g provides some analysis of the inlining feature.

Sibling Ordering
We have ordered siblings by descending subtree elapsed time, using the SEARCH clause. It would be nice to have the option to order the siblings by initial invocation time, but Oracle does not provide the data to do this.

Loops and Hierarchies
The first diagram shows two loops, where there are two routes between the loop start and end points, indicated by different colours. The second loop has two child nodes coming from the end point, and hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links to be duplicated. Our query has filtered out the duplicates by analytic functions.

It's worth remembering this because it's a general feature of SQL for querying hierarchies, and judging by Oracle forums, not one that's widely understood. For larger hierarchies it can cause serious performance problems, and may justify a PL/SQL programmed solution that need not suffer the same problem.

Manual Instrumentation
Oracle's hierarchical profiler clearly provides extremely useful information on both performance and structure of PL/SQL programs with very little effort. However, it does have the limitation of only providing information down to the subprogram level (which includes embedded SQL statements in this context). It is also often considered good practice to implement timing and other instrumentation permanently in production code, sometimes in a switchable fashion. In the test program, one of the called procedures, A_Calls_B, makes two calls to the inlined procedure, Rest_a_While, the second doing about twice as much work as the first. The profiler reports total within-function times of 4,450µs and 13,663µs on first and second calls, respectively (the work is scaled by a call number parameter, equal to 1, then 3).

I created a second instance of the package and driver script (suffix _TS) to illustrate manual instrumentation. This uses an 'object-oriented' timing package that I wrote a couple of years ago Code Timing and Object Orientation and Zombies (November, 2010) to instrument at procedure and section level. I multiplied the work in Rest_a_While by a factor of ten to get larger times. This produced the output:

Timer Set: HProf, Constructed at 05 Mar 2013 10:21:27, written at 10:21:30
==========================================================================
[Timer timed: Elapsed (per call): 0.04 (0.000044), CPU (per call): 0.05 (0.000050), calls: 1000, '***' denotes corrected line below]

Timer                       Elapsed          CPU          Calls        Ela/Call        CPU/Call
----------------------   ----------   ----------   ------------   -------------   -------------
A_Calls_B, section one         0.06         0.05              2         0.03150         0.02500
A_Calls_B, section two         0.12         0.12              2         0.06050         0.06000
B_Calls_A: 2                   0.15         0.16              1         0.15400         0.16000
B_Calls_A: 4                   0.31         0.30              1         0.30700         0.30000
DBFunc                         0.32         0.31              2         0.15950         0.15500
Open cursor                    0.69         0.69              1         0.68900         0.69000
Fetch from cursor              0.70         0.70              1         0.69600         0.70000
Close cursor                   0.00         0.00              1         0.00000         0.00000
Construct object               0.06         0.04              1         0.05500         0.04000
R_Calls_R                      0.14         0.14              2         0.07000         0.07000
(Other)                        0.00         0.00              1         0.00000         0.00000
----------------------   ----------   ----------   ------------   -------------   -------------
Total                          2.54         2.51             15         0.16960         0.16733
----------------------   ----------   ----------   ------------   -------------   -------------

Notes on Code Timing

  • Calls, CPU and elapsed times have been captured at the section level for A_Calls_B
  • Observe that, while R_Calls_R and A_Calls_B aggregate over all calls, B_Calls_A records values by call; this is implemented simply by including a value that changes with call in the timer name
  • The timing set object is designed to be very low footprint; here 9 statements (calls to Increment_Time), plus a small global overhead, produced 10 result lines, plus associated information
  • The 'object-oriented' approach allows multiple programs to be be timed at multiple levels, without interference between timings
  • There are Perl and Java implementations of this timing set object included in the Scribd article mentioned

Oracle's Flat Profiler (DBMS_Profiler)
The hierarchical profiler was introduced in v11.1, while prior to this there was a non-hierarchical profiler, DBMS_Profiler. This package still exists in v11: It is omitted from the advanced application developer's guide for v11, but is described in the packages and types manual (Oracle® Database PL/SQL Packages and Types Reference, 11g Release 2 (11.2)); also, SQL*Developer appears to support only the newer hierarchical verion (via right-click on a package). I thought it interesting to run the older version on the same test program (package Old_Test_Prof, driver script Test_Rep_p_Old.sql and reporting script Test_Rep_h_Old.sql). The output from the first three queries is:

Run header (PLSQL_PROFILER_RUNS)

     RUNID RUN_DATE        MICRO_S    SECONDS
---------- ------------ ---------- ----------
         3 11:03:13        2164000       2.16

Profiler data summary (PLSQL_PROFILER_DATA)

   MICRO_S SECONDS    CALLS
---------- ------- --------
   2126949    2.13       72

Profiler data by time (PLSQL_PROFILER_DATA)

   MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
---------- ------- -------- -------------------- ----------- ------
    729932    0.73        1                                5     13
    569563    0.57        2 OLD_PROF_TEST                  1     56
    377880    0.38        2 OLD_PROF_TEST                  1     82
    166019    0.17        2 OLD_PROF_TEST                  1     70
    150117    0.15        2 OLD_PROF_TEST                  1     43
     72742    0.07        2 OLD_PROF_TEST                  1     40
     56473    0.06        1 TABLE_COUNT_TYPE               6      6
      3338    0.00        1                                5      8
       258    0.00        1                                5     12
       109    0.00        1                                5     16
        68    0.00        2 OLD_PROF_TEST                  1     67
        66    0.00        2                                4      1
        60    0.00        2                                7      1
        60    0.00        2                                3      1
        44    0.00        1                                5     14
        42    0.00        0                                2      5
        31    0.00        1 OLD_PROF_TEST                  1     18
        26    0.00        1                                8      5
        13    0.00        0                                5      1
         9    0.00        1 TABLE_COUNT_TYPE               6     11
         9    0.00        2 OLD_PROF_TEST                  1     86
         8    0.00        0 OLD_PROF_TEST                  1     51
         8    0.00        1 TABLE_COUNT_TYPE               6     13
         7    0.00        1                                5     18
         6    0.00        0 OLD_PROF_TEST                  1     78
         6    0.00        0 OLD_PROF_TEST                  1     64
         6    0.00        0                                8      1
         6    0.00        1 TABLE_COUNT_TYPE               6      3
         5    0.00        0 OLD_PROF_TEST                  1     35
         5    0.00        0 OLD_PROF_TEST                  1     15
         4    0.00        1                                8      7
         4    0.00        1 OLD_PROF_TEST                  1     76
         3    0.00        1                                2      8
         2    0.00        1 OLD_PROF_TEST                  1     62
         2    0.00        1 OLD_PROF_TEST                  1     13
         2    0.00        1 TABLE_COUNT_TYPE               6      5
         2    0.00        2 OLD_PROF_TEST                  1     72
         2    0.00        2 OLD_PROF_TEST                  1     45
         2    0.00        2 OLD_PROF_TEST                  1     49
         2    0.00        2 OLD_PROF_TEST                  1     46
         2    0.00        2 OLD_PROF_TEST                  1     58
         1    0.00        1 OLD_PROF_TEST                  1     73
         1    0.00        1                                2      6
         1    0.00        1 OLD_PROF_TEST                  1     59
         1    0.00        1 OLD_PROF_TEST                  1     11
         1    0.00        2 OLD_PROF_TEST                  1     54
         1    0.00        2 OLD_PROF_TEST                  1     84
         0    0.00        0 OLD_PROF_TEST                  1      1
         0    0.00        0 OLD_PROF_TEST                  1     88
         0    0.00        0                                8      9
         0    0.00        0                                2      1
         0    0.00        0                                2      2
         0    0.00        0 OLD_PROF_TEST                  1      3
         0    0.00        0 OLD_PROF_TEST                  1      5
         0    0.00        0 OLD_PROF_TEST                  1      9
         0    0.00        0 OLD_PROF_TEST                  1     20
         0    0.00        1 TABLE_COUNT_TYPE               6      4
         0    0.00        1                                8      2
         0    0.00        2 OLD_PROF_TEST                  1     39
         0    0.00        2 OLD_PROF_TEST                  1     55
         0    0.00        2 OLD_PROF_TEST                  1     69
         0    0.00        2 OLD_PROF_TEST                  1     38
         0    0.00        2 OLD_PROF_TEST                  1     81
         0    0.00        2 OLD_PROF_TEST                  1     42
         0    0.00        2 OLD_PROF_TEST                  1     68

65 rows selected.

Referring to the package, type and anonymous blocks, I assigned labels to all the lines having more than 10µs, as follows:

   MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE#
---------- ------- -------- -------------------- ----------- ------
    729932    0.73        1                                5     13  B2: FETCH
    569563    0.57        2 OLD_PROF_TEST                  1     56  B_Calls_A (Rest_a_While)
    377880    0.38        2 OLD_PROF_TEST                  1     82  DBFunc (Rest_a_While)
    166019    0.17        2 OLD_PROF_TEST                  1     70  R_Calls_R (Rest_a_While)
    150117    0.15        2 OLD_PROF_TEST                  1     43  A_Calls_B (Rest_a_While, section 2)
     72742    0.07        2 OLD_PROF_TEST                  1     40  A_Calls_B (Rest_a_While, section 1)
     56473    0.06        1 TABLE_COUNT_TYPE               6      6  SELECT
      3338    0.00        1                                5      8  B2: SELECT DBFunc
       258    0.00        1                                5     12  B2: OPEN
       109    0.00        1                                5     16  B2: Assign Table_Count_Type
        68    0.00        2 OLD_PROF_TEST                  1     67  Put_Line
        66    0.00        2                                4      1  Auxiliary SERVEROUTPUT block for B2 (surmised)
        60    0.00        2                                7      1  Auxiliary SERVEROUTPUT block for B3 (surmised)
        60    0.00        2                                3      1  Auxiliary SERVEROUTPUT block for B1 (surmised)
        44    0.00        1                                5     14  B2: CLOSE
        42    0.00        0                                2      5  B1: Call to Start_Profiling 
        31    0.00        1 OLD_PROF_TEST                  1     18  RETURN DBMS_Profiler.Stop_Profiler;
        26    0.00        1                                8      5  B3: Call R_Calls_R
        13    0.00        0                                5      1  B2: DECLARE

Notes on Output of Flat Profiler
There were six units with no linked information in DBMS_PROFILER_UNITS. By examining the data, I was able to associate unit numbers 2, 5 and 8 with my anonymous blocks B1, B2 and B3. That left three unassigned, and I have surmised that these correspond to the auxiliary blocks associated with processing server output that we earlier surmised when examining the output from the hierarchical profiler.

  • The useful call tree structure is not present in the data from the old profiler
  • However, the results are at a line level, which the hierarchical profiler does not provide; for example, the two sections of A_Calls_B are reported separately
  • Deciphering the output requires significantly more manual effort than with the hierarchical profiler
  • Both old and new profiler have their own advantages, and so both should be considered of value
  • Manual code timing offers more flexibility in terms of aggregating lines and call instances, but requires more effort...
  • ...but not as much as I thought. As noted later on the second example, after reading another article on the profiler, I realised that I could join the system table ALL_SOURCE to see the text of the line (where available)

Second example: Flat profiler omits some detail timings
After posting the first draft of this article, which was about the newer hierarchical profiler only, I noticed a new post on an old AskTom thread on the older flat profiler. The post concerned a discrepancy between reported times at the aggregate level and detail levels. I suggested using the hierarchical profiler might resolve the problem Try the hierarchical profiler..., and then added sections on the old profiler and on manual timing to this article for comparison. However, my example programs above do not include the AskTom scenario, so I later decided to add a new small scenario to illustrate it and now report the results here. The new test code consists of a PL/SQL block with two calls to DBMS_Lock.Sleep, for 3 and 6 seconds, with the profiling code around them. The driving scripts and output files are included in the zip file attached, and I list summary results below:

I later came upon another artilce on the flat profiler, Profiling PL/SQL with dbms_profiler where the author has joined the system table ALL_SOURCE to get the text of the line profiled, which makes interpretation easier. I have then updated the line-level query as follows:

PROMPT Profiler data by time (PLSQL_PROFILER_DATA)
SELECT Round (dat.total_time/1000, 0)  micro_s,
       Round (dat.total_time/1000000000, 2) seconds,
       dat.total_occur calls,
       unt.unit_name,
       dat.unit_number,
       dat.line#,
       Trim (src.text) text
  FROM plsql_profiler_data dat
  LEFT JOIN plsql_profiler_units unt
    ON unt.runid            = dat.runid
   AND unt.unit_number      = dat.unit_number
  LEFT JOIN all_source      src
    ON src.type             IN ('PACKAGE BODY','FUNCTION','PROCEDURE','TRIGGER')
   AND src.name             = unt.unit_name 
   AND src.line             = dat.line# 
   AND src.owner            = unt.unit_owner 
   AND src.type             = unt.unit_type
 WHERE dat.runid            = :runid
   AND dat.total_time       > 0
 ORDER BY 1 DESC, 2, 3

Of course the text is only available for stored source, so excludes lines from anonymous blocks.

Flat Profiler

Run header (PLSQL_PROFILER_RUNS)

     RUNID RUN_DATE        MICRO_S    SECONDS
---------- ------------ ---------- ----------
         5 20:34:45        9220000       9.22

Profiler data by unit (PLSQL_PROFILER_DATA)

UNIT_NAME            UNIT_NUMBER    MICRO_S SECONDS    CALLS
-------------------- ----------- ---------- ------- --------
                               2        200    0.00        3
UTILS                          1         30    0.00        3

Profiler data by time (PLSQL_PROFILER_DATA)

   MICRO_S SECONDS    CALLS UNIT_NAME            UNIT_NUMBER  LINE# TEXT
---------- ------- -------- -------------------- ----------- ------ ------------------------------------------------
       136    0.00        1                     2      7
        21    0.00        1                     2     10
        19    0.00        1                     2     14
        14    0.00        0 UTILS                          1    343 FUNCTION Stop_D_Profiling RETURN PLS_INTEGER IS
        13    0.00        1 UTILS                          1    346 RETURN DBMS_Profiler.Stop_Profiler;
         6    0.00        1 UTILS                          1    341 END Start_D_Profiling;
         2    0.00        1 UTILS                          1    339 RETURN l_run_number;

7 rows selected.

Hierarchical Profiler

Run header (DBMSHP_RUNS)

     RUNID RUN_TIMESTAMP                   MICRO_S    SECONDS RUN_COMMENT
---------- ---------------------------- ---------- ---------- -----------------------------
        16 19-MAR-13 21.37.00.571000       9000292          9 Profile for DBMS_Lock.Sleep

Functions called (DBMSHP_FUNCTION_INFO)

OWNER      MODULE               FUNCTION                LINE#      SUB_T      FUN_T  CALLS
---------- -------------------- ---------------------- ------ ---------- ---------- ------
BRENDAN    UTILS                1: STOP_H_PROFILING       322          8          8      1
SYS        DBMS_HPROF           2: STOP_PROFILING          59          0          0      1
SYS        DBMS_LOCK            3: SLEEP                  197    9000279    9000279      2
SYS        DBMS_LOCK            4: __pkg_init               0          5          5      1

Function call parent-child links (DBMSHP_PARENT_CHILD_INFO)

OWNER_P MODULE_P  FUNCTION_P            OWNER_C MODULE_C    FUNCTION_C         SUB_T FUN_T  CALLS
------- --------- --------------------- ------- ----------- ------------------ ----- ----- ------
BRENDAN UTILS     1: STOP_H_PROFILING   SYS     DBMS_HPROF  2: STOP_PROFILING      0     0      1

BPF Recursive Subquery Factor Tree Query

Function tree                              SUB_T      FUN_T  CALLS  Row
------------------------------------- ---------- ---------- ------ ----
3: SYS.DBMS_LOCK.SLEEP                   9000279    9000279      2    1
1: BRENDAN.UTILS.STOP_H_PROFILING              8          8      1    2
  2: SYS.DBMS_HPROF.STOP_PROFILING             0          0      1    3
4: SYS.DBMS_LOCK.__pkg_init                    5          5      1    4

Manual Profiler

Timer Set: Profiling DBMS_Lock.Sleep, Constructed at 19 Mar 2013 21:38:54, written at 21:39:03
==============================================================================================
[Timer timed: Elapsed (per call): 0.05 (0.000045), CPU (per call): 0.04 (0.000040), calls: 1000, '***' denotes corrected line below]

Timer               Elapsed          CPU          Calls        Ela/Call        CPU/Call
--------------   ----------   ----------   ------------   -------------   -------------
3 second sleep         3.00         0.00              1         3.00000         0.00000
6 second sleep         6.00         0.00              1         6.00100         0.00000
(Other)                0.00         0.00              1         0.00000         0.00000
--------------   ----------   ----------   ------------   -------------   -------------
Total                  9.00         0.00              3         3.00033         0.00000
--------------   ----------   ----------   ------------   -------------   -------------

Notes on Results for Second Example

  • The flat profiler shows 9s at header level but only 230µs at detail level because DBMS_Lock.Sleep does not permit profiling by the user running the script
  • The hierarchical profiler shows 9s at header level and a total of 9s in 2 calls to DBMS_Lock.Sleep
  • Manual profiling shows the two calls to DBMS_Lock.Sleep taking 3 and 6 seconds

Conclusions

  • Running Oracle's hierarchical profiler would seem to be the default first step in tuning PL/SQL programs from v11.1
  • Some care is needed in interpreting the output data; I've provided a query for displaying the hierarchies
  • Performance is recorded only down to function level, so it will still often be worthwhile to use the old flat profiler in addition
  • Manually timing code sections also still has a part to play, in terms of instrumentation and greater flexibility where necessary

Brendan HProf Code
Example 2






Leave a Reply

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