PL/SQL Profiling 1 – Overview

This article describes at overview level the use of three PL/SQL profiling methods on two example program structures. The examples are designed to illustrate profiler behaviour over as many different scenarios as possible, while keeping the examples as simple as possible. The first two profilers are Oracle’s hierarchical and flat profiling tools, while the third is the author’s own custom code timing package, Timer_Set. It’s based on an article published in March 2013 on the hierarchical profiler and updated shortly thereafter with the inclusion of Oracle’s older flat profiler and of custom code timing. In June 2020 installation and source code were put onto GitHub, and the article was restructured into an overview article with the detail on the three profiling methods as separate articles. This is the overview and the links to the other three detailed articles are:

PL/SQL Profiling 2: Hierarchical Profiler
PL/SQL Profiling 3: Flat Profiler
PL/SQL Profiling 4: Custom Code Timing

All source code, including installation scripts, and short screen recordings, is available on GitHub:
GitHub: Oracle PL/SQL Profiling

Twitter thread with recordings attached

Scenarios

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 in testing, whether in ‘closed’ unit testing, where there are known expected results, or in ‘open’ exploratory tesing where we are investigating application behaviour, as here. I discussed the issue of test scenario coverage in a 2018 presentation: Database API Viewed As A Mathematical Function: Insights into Testing – OUG Ireland Conference 2018.

At the time of the original article in 2013, I looked at Oracle’s 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. I then added a second simple program to cover some additional scenarios, and also tested the use of Oracle’s flat profiler, and of custom code timing using my own Timer_Set package.

This first article explains the scenarios covered by the two example programs, briefly summarises the results of each method on the second and simpler example, and finishes with a comparison of the features of the three methods. Fuller discussions of each profiling method, with application to both example programs can be found in the specific articles linked above.

The test programs consist of two driving scripts that have one or more PL/SQL blocks with calls to various system and custom packaged procedures and functions.

Example 1: General

The test program for example 1 covers the following scenarios:

  • Multiple root calls
  • Recursive procedure calls (procedure calling itself: R_Calls_R)
  • Mutually recursive procedure calls (procedures call each other: A_Calls_B and B_Calls_A)
  • Program unit called by multiple program units (child with multiple parents: Database Function)
  • Procedure ‘inlined’ within PL/SQL (Rest_a_While)
  • Type body code (Object Constructor)
  • Static SQL from Sqlplus (SELECT 1)
  • Static SQL within PL/SQL (SELECT 2)
  • Dynamic SQL within PL/SQL (SELECT 3)
  • CPU-consuming sleep (Rest_a_While)

Call Structure Diagram

Example 2: Sleep

The test program for example 2 covers the following scenarios:

  • External system program unit (DBMS_Lock.Sleep in SYS schema)
  • External custom program unit (Utils.Sleep in LIB schema)
  • Sleep that uses no CPU time, only elapsed time (DBMS_Lock.Sleep)
  • Sleep that uses CPU time (Utils.Sleep)
  • Trigger code (Before Insert trigger SLEEP_BI)
  • Two calls from the same parent (DBMS_Lock.Sleep from anonymous block twice)
  • Program unit as root call and as child call (DBMS_Lock.Sleep)

Call Structure Diagram

Profiling Overview

In this section I show the data model and a summary of the results of each method on the second and simpler example. For fuller discussion with both examples see the specific articles for each method.

Hierarchical Profiler Overview

PL/SQL Profiling 2: Hierarchical Profiler

Hierarchical Profiler: Data Model

Network Diagram for Example 2: Sleep


The extended network diagram with function names and times included shows 9 seconds of time used by the SLEEP function in two root-level calls and 1 second in a third call as the child of the custom Utils Sleep function.

Network Query Output for Example 2: Sleep
Function tree                   Sy Owner Module           Inst.  Subtree MicroS Function MicroS Calls Row
------------------------------ --- ----- ---------------- ------ -------------- --------------- ----- ---
SLEEP                            8 SYS   DBMS_LOCK        1 of 2        8998195         8998195     2   1
__static_sql_exec_line6         10                                      2005266            5660     1   2
  __plsql_vm                     1                                      1999606               4     1   3
    SLEEP_BI                     3 APP   SLEEP_BI                       1999602             327     1   4
      SLEEP                      4 LIB   UTILS                          1999268          999837     1   5
        SLEEP                    8 SYS   DBMS_LOCK        2 of 2         999431          999431     1   6
      __pkg_init                 6 LIB   UTILS                                5               5     1   7
      __pkg_init                 5 LIB   UTILS                                2               2     1   8
STOP_PROFILING                   2 APP   HPROF_UTILS                         87              87     1   9
  STOP_PROFILING                 7 SYS   DBMS_HPROF                           0               0     1  10
__static_sql_exec_line700       11 SYS   DBMS_HPROF                          77              77     1  11
__pkg_init                       9 SYS   DBMS_LOCK                            3               3     1  12

12 rows selected.

Flat Profiler Overview

PL/SQL Profiling 3: Flat Profiler

Flat Profiler: Data Model

Flat Profiler: Results Extract

The records produced in the functions table, PLSQL_PROFILER_DATA, are listed below in order of unit name, then unit number and line number.

Seconds  Microsecs   Min S   Max S    Calls Unit                 Unit# Type            Line# Line Text
------- ---------- ------- ------- -------- -------------------- ----- --------------- ----- ------------------------------------------------------------------
  0.000          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     1
  0.000          2   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     5
  0.000         23   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK     9
  0.000         10   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    11
  0.000        199   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    13
  0.000          3   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    15
  0.000          5   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    17
  0.000          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK    19
  0.000          2   0.000   0.000        0 SLEEP_BI                 2 TRIGGER             1 TRIGGER sleep_bi
  0.000         20   0.000   0.000        1 SLEEP_BI                 2 TRIGGER             2 BEFORE INSERT
  0.000          1   0.000   0.000        1 SLEEP_BI                 2 TRIGGER             4 FOR EACH ROW

11 rows selected.

Timer Set Overview

PL/SQL Profiling 4: Custom Code Timing

Timer Set: Data Model

Timer Set: Example of Call Structure

Timer Set: Results Extract

Timer Set: Profiling DBMS_Lock.Sleep, Constructed at 27 Jun 2020 07:53:00, written at 07:53:11
==============================================================================================
Timer                                       Elapsed         CPU       Calls       Ela/Call       CPU/Call
---------------------------------------  ----------  ----------  ----------  -------------  -------------
3 second sleep                                 3.00        0.00           1        3.00000        0.00000
INSERT INTO trigger_tab VALUES (2, 0.5)        2.00        1.00           1        1.99900        1.00000
6 second sleep                                 6.00        0.00           1        6.00000        0.00000
(Other)                                        0.00        0.00           1        0.00000        0.00000
---------------------------------------  ----------  ----------  ----------  -------------  -------------
Total                                         11.00        1.00           4        2.74975        0.25000
---------------------------------------  ----------  ----------  ----------  -------------  -------------
[Timer timed (per call in ms): Elapsed: 0.00980, CPU: 0.00980]

Conclusion

Oracle’s hierarchical profiler and flat profiler offer different ways of profiling elapsed time and call usage for PL/SQL programs. After initial setup they perform profiling of code automatically between start and stop API calls, without the need to alter the code being profiled. The level of profiling and organisation of data collection are not configurable. They are intended for one-off use or occasional trouble-shooting, rather than as ongoing instrumentation.

Custom code timing requires insertion of timing code within the profiled code, but offers more flexibility in terms of detail gathered, and also captures CPU time usage. Use of a centralized API such as Timer_Set helps to minimize the code required. It can be used both for trouble-shooting and for ongoing production instrumentation.

Features Summary