Shortest Path Analysis of Large Networks by SQL and PL/SQL – Intro

Posted on August 12, 2022 by BrendanP

This is an introduction to an article, Shortest Path Analysis of Large Networks by SQL and PL/SQL, on the use of SQL and PL/SQL to solve shortest path network problems on an Oracle database. It provides solutions in pure SQL (based on previous articles by the author), and solutions in PL/SQL with embedded SQL that scale better for larger problems.

It applies the solutions to a range of problems, upto a size of 2,800,309 nodes and 109,262,592 links.

Standard and custom methods for execution time profiling of the code are included, and one of the algorithms implemented in PL/SQL is tuned based on the profiling.

The two PL/SQL entry points have automated unit tests using the Math Function Unit Testing design pattern, Trapit – Oracle PL/SQL unit testing module.

Movie Morsel: Six Degrees of Kevin Bacon

All code and examples are available on GitHub.

There is a series of mp4 recordings, in the mp4 folder on GitHub, briefly going through the sections of the blog post, which can also be viewed via Twitter:

Twitter Recordings

The contents of the article are listed below.

PL/SQL Profiling 4: Custom Code Timing

Posted on June 28, 2020 by BrendanP

This article describes the use of a custom code timing PL/SQL package, Timer_Set, on two example program structures. The examples are designed to illustrate its behaviour over as many different scenarios as possible, while keeping the examples as simple as possible. 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, of which this is the third. Here are links to the other three articles:

PL/SQL Profiling 1: Overview
PL/SQL Profiling 2: Hierarchical Profiler
PL/SQL Profiling 3: Flat Profiler

All source code, including installation scripts, is available on GitHub:
GitHub: Oracle PL/SQL Profiling
Tweet with recording attached

For this custom code timing demonstration I created a new version of the package used by the the Oracle profiling demos, and driver scripts (prefixed ts_) for the same examples.

These use an ‘object-oriented’ timing package that I wrote a few years ago Timer_Set: Oracle PL/SQL code timing module on GitHub to instrument at procedure and section level. It is often considered good practice to implement timing and other instrumentation permanently in production code.

In both examples a new timer set object is created, calls are made to increment timers within the set, and at the end a report on the timings is written to log. The way the timer set operates in general is illustrated by a diagram taken from the GitHub module:

Setup

The GitHub project linked to above includes scripts for setup of prerequisites such as grants and tables, and for installation of the custom code used for this demonstration. As described in the overview article, there are two example scripts profiled.

Example 1: General. This covers a wide range of scenarios
Example 2: Sleep. This covers the particular example of DBMS_Lock.Sleep

Timer Set Data Model

A logical data model is shown below. There are no physical tables involved.

Example 1: General

The example was descibed in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
PROMPT B1: A_Calls_B 
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN
  Timer_Set_Test.Init;
  Timer_Set_Test.A_Calls_B(l_call_count);

END;
/
PROMPT SQL: Static DB function call
SELECT Timer_Set_Test.DBFunc
  FROM DUAL;

PROMPT B2: Static DB function; dynamic SQL; object constructor
DECLARE
  l_cur              SYS_REFCURSOR;
  l_ret_val          PLS_INTEGER;
  l_tab_count        Table_Count_Type;

BEGIN

  SELECT Timer_Set_Test.DBFunc
    INTO l_ret_val
    FROM DUAL;

  OPEN l_cur FOR 'SELECT Count(*) FROM all_tab_columns'; 
  Timer_Set_Test.Increment_Time('Open cursor');
  FETCH l_cur INTO l_ret_val; 
  Timer_Set_Test.Increment_Time('Fetch from cursor');
  CLOSE l_cur;
  Timer_Set_Test.Increment_Time('Close cursor');

  l_tab_count := Table_Count_Type('EMP');
  Timer_Set_Test.Increment_Time('Construct object');

END;
/
PROMPT B3: R_Calls_R; write times
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  Timer_Set_Test.R_Calls_R(l_call_count);

  Timer_Set_Test.Write_Times;

END;
/
SET TIMING OFF

The script is structured as an anonymous block, B1, then a stand-alone SQL query, followed by two more anonymous blocks, B2 and B3. The timer set is constructed in the first block within the call:

  Timer_Set_Test.Init

The script then increments timers at several points, again through calls to Timer_Set_Test, while Timer_Set_Test itself has timer calls inside. The results of the timing are listed at the end by the call:

  Timer_Set_Test.Write_Times;

Results for Example 1: General

Timer Set: Timer_Set_Test, Constructed at 27 Jun 2020 07:52:51, written at 07:52:52
===================================================================================
Timer                      Elapsed         CPU       Calls       Ela/Call       CPU/Call
----------------------  ----------  ----------  ----------  -------------  -------------
A_Calls_B, section one        0.01        0.02           2        0.00600        0.01000
A_Calls_B, section two        0.03        0.02           2        0.01450        0.01000
B_Calls_A: 2                  0.03        0.03           1        0.03100        0.03000
B_Calls_A: 4                  0.06        0.06           1        0.06100        0.06000
DBFunc                        0.08        0.06           2        0.03850        0.03000
Open cursor                   0.00        0.00           1        0.00100        0.00000
Fetch from cursor             0.27        0.29           1        0.27400        0.29000
Close cursor                  0.00        0.00           1        0.00000        0.00000
Construct object              0.03        0.01           1        0.02500        0.01000
R_Calls_R                     0.04        0.03           2        0.02000        0.01500
(Other)                       0.00        0.00           1        0.00100        0.00000
----------------------  ----------  ----------  ----------  -------------  -------------
Total                         0.55        0.52          15        0.03673        0.03467
----------------------  ----------  ----------  ----------  -------------  -------------
[Timer timed (per call in ms): Elapsed: 0.00971, CPU: 0.01068]

Notes on Output

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:
```
  Increment_Time('B_Calls_A: ' || x_call_no);
```
The output shows how much of the elapsed time comes from CPU usage; in particular, note that R_Calls_R calls an inlined procedure Rest_a_While that does a square root operation in a loop to consume CPU time, and we can see that elapsed and CPU times are the same
The timer 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 Total line values are calculated using timing differences betwee reporting and construction of the timer set
The (Other) line values are calculated using the diffeences between the Total line values and the sums of the specific line values
The Timer timed line allows the overhead of the timing itself to be estimated
The ‘object-oriented’ approach allows multiple programs to be be timed at multiple levels, without interference between timings
Formatting such as column widths and decimal places can be specified as parameters in the reporting API call, and here take the default values

Example 2: Sleep

The example was described in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
PROMPT B1: Construct timer set; DBMS_Lock.Sleep, 3 + 6; insert to trigger_tab; write timer set
DECLARE
  l_timer_set       PLS_INTEGER;
BEGIN
  l_timer_set := Timer_Set.Construct('Profiling DBMS_Lock.Sleep');
  DBMS_Lock.Sleep(3);
  Timer_Set.Increment_Time(l_timer_set, '3 second sleep');

  INSERT INTO trigger_tab VALUES (2, 0.5);
  Timer_Set.Increment_Time(l_timer_set, 'INSERT INTO trigger_tab VALUES (2, 0.5)');

  DBMS_Lock.Sleep(6);
  Timer_Set.Increment_Time(l_timer_set, '6 second sleep');
  Utils.W(Timer_Set.Format_Results(l_timer_set));

END;
/
SET TIMING OFF

The script constructs a timer set, then makes calls to a system procedure, DBMS_Lock.Sleep, which sleeps without using CPU time, then inserts to a table with a Before Insert trigger that calls a custom sleep procedure, Utils.Sleep. Utils.Sleep itself calls DBMS_Lock.Sleep to do non-CPU sleeping and also runs a mathematical operation in a loop to use CPU time. Timers are incremented after each main call, and the results of the timing are writtten out at the end.

Results for Example 2: Sleep

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]

Notes on Output

The two direct calls to the sleep procedure DBMS_Lock.Sleep consumed elapsed time of 3 and 6 seconds, as specified in the calls, but no CPU time
The insert statement consumed 2 seconds elapsed time, of which 1 second comes from CPU time, matching the field values, which the trigger uses to determine elapsed time and fraction of CPU time

Timer Set Custom Code Timing Feature Summary

We can summarise the features of Timer Set custom code timing in the following points:

Results are organised as tables of measures for lists of timers in one or more sets
Results are reported at the level of code section, and timing is aggregated between calls to API methods
Measures reported are elapsed times, numbers of calls, and CPU times
External program units may be included in the profiling: calls can be timed; internal profiling requires code changes
Profiling is performed, after initial setup, by means of instrumentation within the program units to be profiled, including an API call to return results

I applied my Timer_Set code timing package to some demo PL/SQL APIs in a Github module that also demonstrtates logging and unit testing. This is described here: Oracle PL/SQL API Demos Github Module

PL/SQL Profiling 3: Flat Profiler

Posted on June 28, 2020 by BrendanP

This article describes the use of Oracle’s flat PL/SQL profiler (DBMS_PROFILER) on two example program structures. The examples are designed to illustrate its behaviour over as many different scenarios as possible, while keeping the examples as simple as possible. 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, of which this is the second. Here are links to the other three articles:

PL/SQL Profiling 1: Overview
PL/SQL Profiling 2: Hierarchical Profiler
PL/SQL Profiling 4: Custom Code Timing

All source code, including installation scripts, is available on GitHub:
GitHub: Oracle PL/SQL Profiling
Tweet with recording attached

Setup

The flat profiler setup and use is described in the Oracle document DBMS_PROFILER. The GitHub project linked to above includes scripts for setup of prerequisites such as grants and tables, and for installation of the custom code used for this demonstration. As described in the overview article, there are two example scripts profiled.

Example 1: General. This covers a wide range of scenarios
Example 2: Sleep. This covers the particular example of DBMS_Lock.Sleep

PL/SQL Flat Profiler: Data Model

Example 1: General

The example was descibed in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
PROMPT B1: Start profiling; A_Calls_B 
VAR RUN_ID NUMBER
DECLARE
  l_call_count       PLS_INTEGER := 0;
  l_result           PLS_INTEGER;
BEGIN

  l_result := DBMS_Profiler.Start_Profiler(
          run_comment => 'Profile for small test program with recursion',
          run_number  => :RUN_ID);

  Utils.W('Start: profile run id = ' || :RUN_ID);
  Prof_Test.A_Calls_B(l_call_count);

END;
/
PROMPT SQL: Static DB function call
SELECT Prof_Test.DBFunc
  FROM DUAL;

PROMPT B2: Static DB function; dynamic SQL; object constructor
DECLARE
  l_cur              SYS_REFCURSOR;
  l_ret_val          PLS_INTEGER;
  l_tab_count        Table_Count_Type;

BEGIN

  SELECT Prof_Test.DBFunc
    INTO l_ret_val
    FROM DUAL;

  OPEN l_cur FOR 'SELECT Count(*) FROM all_tab_columns'; 
  FETCH l_cur INTO l_ret_val; 
  CLOSE l_cur;

  l_tab_count := Table_Count_Type('EMP');

END;
/
PROMPT B3: R_Calls_R; stop profiling
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  Prof_Test.R_Calls_R(l_call_count);

  Utils.W('Stop: result = ' || DBMS_Profiler.Stop_Profiler);
  
END;
/
SET TIMING OFF
@dprof_queries :RUN_ID

The script is structured as an anonymous block, B1, then a stand-alone SQL query, followed by two more anonymous blocks, B2 and B3. Profiling is started by a call to DBMS_Profiler.Start_Profiler in the first block.

The last block stops the profiling. The custom queries are run at the end from the script dprof_queries.sql, passing in the run identifier that’s been saved in a bind variable.

Results for Example 1: General

The results in this section come from the script dprof_queries.sql that queries the tables populated by the profiler.

Example 1: General – Run Header

The record produced in the run table, PLSQL_PROFILER_RUNS, was:

 Run Id Time     Seconds  Microsecs
------- -------- ------- ----------
      1 07:52:12   0.766     766000

Example 1: General – Profiler Data Summaries

Profiler data overall summary (PLSQL_PROFILER_DATA):

Seconds  Microsecs    Calls
------- ---------- --------
  0.731     730945       70

Profiler data summary by unit (PLSQL_PROFILER_DATA):

Unit                 Unit# Seconds  Microsecs    Calls
-------------------- ----- ------- ---------- --------
<anonymous>              1   0.000         47        3
<anonymous>              3   0.000         63        2
<anonymous>              4   0.000        103        2
<anonymous>              5   0.402     401821        6
<anonymous>              7   0.000        103        2
<anonymous>              8   0.000         87        3
PROF_TEST                2   0.309     308722       48
TABLE_COUNT_TYPE         6   0.020      20000        4

Example 1: General – Profiler Data by Unit

The records produced in the functions table, PLSQL_PROFILER_DATA, are listed below in order of unit name, then unit number and line number. The table is joined to PLSQL_PROFILER_UNITS to get the unit name and other details, which are then used to outer-join to the system view ALL_SOURCE to get the line of source code for stored units (i.e. not for anonymous blocks).

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          0   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     2
  0.000          2   0.000   0.000        0 <anonymous>              1 ANONYMOUS BLOCK     6
  0.000         26   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    10
  0.000         18   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    11
  0.000          1   0.000   0.000        1 <anonymous>              1 ANONYMOUS BLOCK    13
  0.000         63   0.000   0.000        2 <anonymous>              3 ANONYMOUS BLOCK     1
  0.000        103   0.000   0.000        2 <anonymous>              4 ANONYMOUS BLOCK     1
  0.000          8   0.000   0.000        0 <anonymous>              5 ANONYMOUS BLOCK     1
  0.000        139   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK     8
  0.151     150687   0.151   0.151        1 <anonymous>              5 ANONYMOUS BLOCK    12
  0.251     250899   0.251   0.251        1 <anonymous>              5 ANONYMOUS BLOCK    13
  0.000         30   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK    14
  0.000         55   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK    16
  0.000          3   0.000   0.000        1 <anonymous>              5 ANONYMOUS BLOCK    18
  0.000        103   0.000   0.000        2 <anonymous>              7 ANONYMOUS BLOCK     1
  0.000          4   0.000   0.000        0 <anonymous>              8 ANONYMOUS BLOCK     1
  0.000          0   0.000   0.000        1 <anonymous>              8 ANONYMOUS BLOCK     2
  0.000         44   0.000   0.000        1 <anonymous>              8 ANONYMOUS BLOCK     5
  0.000         39   0.000   0.000        1 <anonymous>              8 ANONYMOUS BLOCK     7
  0.000          0   0.000   0.000        0 <anonymous>              8 ANONYMOUS BLOCK     9
  0.000          1   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY        1 PACKAGE BODY Prof_Test AS
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY       44 g_num NUMBER := 0;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY       71 PROCEDURE A_Calls_B(
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       75 x_call_no := x_call_no + 1;
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       76 PRAGMA INLINE (Rest_a_While, 'YES');
  0.017      16691   0.004   0.013        2 PROF_TEST                2 PACKAGE BODY       77 Rest_a_While(1000 * x_call_no);
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       79 PRAGMA INLINE (Rest_a_While, 'YES'); -- Both pragmas are required
  0.034      33515   0.009   0.025        2 PROF_TEST                2 PACKAGE BODY       80 Rest_a_While(2000 * x_call_no);
  0.000          1   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       82 IF x_call_no < 4 THEN
  0.000          1   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       83 B_Calls_A(x_call_no);
  0.000          2   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       86 END A_Calls_B;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY       94 PROCEDURE B_Calls_A(
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       98 x_call_no := x_call_no + 1;
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY       99 PRAGMA INLINE (Rest_a_While, 'YES');
  0.126     126418   0.044   0.083        2 PROF_TEST                2 PACKAGE BODY      100 Rest_a_While(5000 * x_call_no);
  0.000          1   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      102 IF x_call_no < 4 THEN
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      103 A_Calls_B(x_call_no);
  0.000          1   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      106 END B_Calls_A;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY      114 PROCEDURE R_Calls_R(
  0.000         40   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      118 DBMS_Output.Put_Line('In R_Calls_R, x_call_no = ' || x_call_no);
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      119 x_call_no := x_call_no + 1;
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      120 PRAGMA INLINE (Rest_a_While, 'YES');
  0.041      40688   0.015   0.026        2 PROF_TEST                2 PACKAGE BODY      121 Rest_a_While(3000 * x_call_no);
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      123 IF x_call_no < 2 THEN
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      124 R_Calls_R(x_call_no);
  0.000          2   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      127 END R_Calls_R;
  0.000          3   0.000   0.000        0 PROF_TEST                2 PACKAGE BODY      134 FUNCTION DBFunc
  0.000          0   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      138 PRAGMA INLINE (Rest_a_While, 'YES');
  0.091      91346   0.042   0.049        2 PROF_TEST                2 PACKAGE BODY      139 Rest_a_While(10000);
  0.000          2   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      141 RETURN 99;
  0.000          2   0.000   0.000        2 PROF_TEST                2 PACKAGE BODY      143 END DBFunc;
  0.000          0   0.000   0.000        1 PROF_TEST                2 PACKAGE BODY      145 END Prof_Test;
  0.000          3   0.000   0.000        0 TABLE_COUNT_TYPE         6 TYPE BODY          50 CONSTRUCTOR FUNCTION Table_Count_Type(
  0.000          1   0.000   0.000        1 TABLE_COUNT_TYPE         6 TYPE BODY          54 SELF.search_str := p_search_str;
  0.020      19991   0.020   0.020        1 TABLE_COUNT_TYPE         6 TYPE BODY          55 SELECT Count(*)
  0.000          3   0.000   0.000        1 TABLE_COUNT_TYPE         6 TYPE BODY          60 RETURN;
  0.000          2   0.000   0.000        1 TABLE_COUNT_TYPE         6 TYPE BODY          62 END;

58 rows selected.

Notes on Output

The manual has notes on interpreting output, DBMS_PROFILER Operational Notes, and we can add some notes here on the output above.

Unit Names and Numbers

Unit numbers appear to be consecutive integers generated at run time in the order in which the units are encountered. Unit names for saved source code units such as packages and types are the names of the stored units. Anonymous blocks of PL/SQL are not stored as saved units and so do not have their own names, and are assigned the name <anonymous>, but separate top-level blocks have distinct unit numbers.

Named Units and Source Lines

Named units such as package and type bodies have source code lines accessible in the system view ALL_SOURCE, and these are displayed in the output above. See the query section below for the join code.

Anonymous Blocks

We can't include the source text for anonymous blocks as it is not stored in the database. However, we can generally work out which unit numbers correspond to which blocks manually, and then use the line numbers to identify the corresponding source lines, with the line numbers being counted from the first line in the block as line 1. For example, line 11 in the output above for unit 1 used about 1ms and can be seen to correspond to the 11'th line in the block labelled B1 in the driver script:

  Prof_Test.A_Calls_B(l_call_count);

PRAGMA INLINE

Calls to the Rest_a_While procedure in package Prof_Test are preceded by the inline pragma that causes the procedure code to be inlined by the PL/SQL engine. In this case we do not see any references to lines numbers 49-59 in Prof_Test where the procedure is located, only to the calling statements on lines 75, 78, 98, 119 and 137.

Example 2: Sleep

The example was descibed in PL/SQL Profiling 1: Overview. The driver script is shown below:

SET TIMING ON
VAR RUN_ID NUMBER
PROMPT B1: Start profiling; DBMS_Lock.Sleep, 3 + 6; stop profiling
DECLARE
  l_result           PLS_INTEGER;
BEGIN

  l_result := DBMS_Profiler.Start_Profiler(
          run_comment => 'Profile for DBMS_Lock.Sleep example',
          run_number  => :RUN_ID);

  Utils.W('Start: profile run id = ' || :RUN_ID);

  DBMS_Lock.Sleep(3);

  INSERT INTO trigger_tab VALUES (2, 0.5);

  DBMS_Lock.Sleep(6);

  Utils.W('Stop: result = ' || DBMS_Profiler.Stop_Profiler);

END;
/
SET TIMING OFF
@dprof_queries :RUN_ID

The script runs the start profiling procedure, then makes calls to a system procedure, DBMS_Lock.Sleep, which sleeps without using CPU time, then inserts to a table with a Before Insert trigger that calls a custom sleep procedure, Utils.Sleep, and finally calls a custom utility that stops the profiling and analyses the trace file created. Utils.Sleep itself calls DBMS_Lock.Sleep to do non-CPU sleeping and also runs a mathematical operation in a loop to use CPU time. The custom queries are run at the end from the script hprof_queries.sql, passing in the run identifier that's been saved in a bind variable.

Results for Example 2: Sleep

The results in this section come from the script dprof_queries.sql that queries the tables populated by the profiler.

This second example was added after I came across an AskTom post concerning a discrepancy between reported times at the aggregate level and detail levels for the flat profiler. I posted a suggestion that using the hierarchical profiler might resolve the problem Try the hierarchical profiler..., and then added this second example to my original article in 2013 (since extended).

Example 2: Sleep - Run Header

The record produced in the run table, PLSQL_PROFILER_RUNS, was:

 Run Id Time     Seconds  Microsecs
------- -------- ------- ----------
      2 07:52:22  11.000   11000000

Example 2: Sleep - Profiler Data Summaries

Profiler data overall summary (PLSQL_PROFILER_DATA):

Seconds  Microsecs    Calls
------- ---------- --------
  0.000        265        7

Profiler data summary by unit (PLSQL_PROFILER_DATA):

Unit                 Unit# Seconds  Microsecs    Calls
-------------------- ----- ------- ---------- --------
<anonymous>              1   0.000        242        5
SLEEP_BI                 2   0.000         23        2

Example 2: Sleep - Profiler Data by Unit and Line

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.

Notes on Output

Calls to Units with EXECUTE ONLY Access

The manual states "you cannot use the package to profile units for which EXECUTE ONLY access has been granted". In this example there are calls to two units where this applies: the system package DBMS_Lock, and the custom utility package Utils, which is in a different schema (lib) from the one (app) in which the script is run.

In the output above we can see the lines from which the calls are made but nothing within the units called.

Aggregate/Detail Timing Discrepancy

As was noted in the AskTom thread referenced above, where the flat profiler does not provide data for program units, such as DBMS_Lock.Sleep, the timings at the detail level do not add up to the overall time recorded in the runs table. As there were three calls using elapsed time of 11 seconds in total the total recorded in the runs table is 11 seconds, while this 11 seconds is missing from the detail records, which add up to only 265 microseconds in total.

Queries

The queries are in the script dprof_queries.sql. All queries are for a given RUNID, passed in as a sqlplus parameter.

Run Header Query

SELECT runid,
       To_Char(run_date, 'hh24:mi:ss') run_date,
       Round(run_total_time/1000000000, 3) seconds,
       Round(run_total_time/1000, 0)  micro_s
  FROM plsql_profiler_runs
 WHERE runid = &RUN_ID

RUN_TOTAL_TIME in nanoseconds is converted to seconds and microseconds

Profiler Data Overall Summary Query

SELECT Round(Sum(dat.total_time/1000000000), 3) seconds,
       Round(Sum(dat.total_time/1000), 0)  micro_s,
       Sum(dat.total_occur) calls
  FROM plsql_profiler_data dat
 WHERE dat.runid = &RUN_ID

This query sums the times and calls in PLSQL_PROFILER_DATA for the given RUNID

Profiler Data Summary by Unit Query

SELECT unt.unit_name,
       dat.unit_number,
       Round(Sum(dat.total_time/1000000000), 3) seconds,
       Round(Sum(dat.total_time/1000), 0)  micro_s,
       Sum(dat.total_occur) calls
  FROM plsql_profiler_data dat
  JOIN plsql_profiler_units unt
    ON unt.runid = dat.runid
   AND unt.unit_number = dat.unit_number
 WHERE dat.runid = &RUN_ID
 GROUP BY unt.unit_name,
          dat.unit_number
 ORDER BY 1, 2, 3

This query sums the times and calls in PLSQL_PROFILER_DATA by unit name and number, for the given RUNID

Lines Query

SELECT Round(dat.total_time/1000000000, 3) seconds,
       Round(dat.total_time/1000, 0)  micro_s,
       Round(dat.min_time/1000000000, 3) min_secs,
       Round(dat.max_time/1000000000, 3) max_secs,
       dat.total_occur calls,
       unt.unit_name,
       dat.unit_number,
       unt.unit_type,
       dat.line#,
       Trim(src.text) text
  FROM plsql_profiler_data dat
  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             != 'ANONYMOUS BLOCK'
   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            = &RUN_ID
 ORDER BY unt.unit_name, unt.unit_number, dat.line#

This query lists the times and calls in PLSQL_PROFILER_DATA, for the given RUNID
PLSQL_PROFILER_UNITS is joined on UNIT_NUMBER
The view ALL_SOURCE is outer-joined on UNIT_NAME, UNIT_OWNER, UNIT_TYPE, LINE# to give the source line for stored source
Anonymous blocks do not have any saved source lines

Flat Profiler Feature Summary

We can summarise the features of the Flat Profiler in the following points:

Results are organised as lists of measures by line
Results are reported at the line level
Measures reported are elapsed times and numbers of calls, but not CPU times
External program units may not be included in the profiling (they are included only if the user can debug the unit)
Profiling is performed, after initial setup, by means of before and after API calls, followed by querying of results in tables

Twitter Recordings

Contents

Setup

Timer Set Data Model

Example 1: General

Results for Example 1: General

Notes on Output

Example 2: Sleep

Results for Example 2: Sleep

Notes on Output

Timer Set Custom Code Timing Feature Summary

Setup

PL/SQL Flat Profiler: Data Model

Example 1: General

Results for Example 1: General

Example 1: General – Run Header

Example 1: General – Profiler Data Summaries

Example 1: General – Profiler Data by Unit

Notes on Output

Unit Names and Numbers

Named Units and Source Lines

Anonymous Blocks

PRAGMA INLINE

Example 2: Sleep

Results for Example 2: Sleep

Example 2: Sleep - Run Header

Example 2: Sleep - Profiler Data Summaries

Example 2: Sleep - Profiler Data by Unit and Line

Notes on Output

Calls to Units with EXECUTE ONLY Access

Aggregate/Detail Timing Discrepancy

Queries

Run Header Query

Profiler Data Overall Summary Query

Profiler Data Summary by Unit Query

Lines Query

Flat Profiler Feature Summary