Tag Archives: benchmarking

PL/SQL Profiling 3: Flat Profiler

Posted on by
Reply

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






 

PL/SQL Profiling 2: Hierarchical Profiler

Posted on by
Reply

This article describes the use of Oracle’s hierarchical PL/SQL profiler (DBMS_HProf) 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 first. Here are links to the other three articles:

PL/SQL Profiling 1: Overview
PL/SQL Profiling 3: Flat 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 hierarchical profiler setup and use is described in the Oracle document Using the PL/SQL Hierarchical 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 Hierarchical 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 
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  HProf_Utils.Start_Profiling;
  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
VAR RUN_ID NUMBER
DECLARE
  l_call_count       PLS_INTEGER := 0;
BEGIN

  Prof_Test.R_Calls_R(l_call_count);

  :RUN_ID := HProf_Utils.Stop_Profiling(
    p_run_comment => 'Profile for small test program with recursion',
    p_filename    => 'hp_example_general.html');
  Utils.W('Run id is ' || :RUN_ID);
END;
/
SET TIMING OFF
@hprof_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 includes a call to a custom utility, HProf_Utils.Stop_Profiling, that stops the profiling and analyses the trace file created in two ways:

  • Writing a (standard) HTML report on the results using a DBMS_HProf call
  • Writing the results to standard tables created during installation using a DBMS_HProf call

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 1: General

The results in this section come from the script hprof_queries.sql that queries the tables populated by the analyse step.

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

 Run Id Run Time                      Microsecs Seconds Comment
------- ---------------------------- ---------- ------- ------------------------------------------------------------
     12 02-JUN-20 06.30.37.128000 AM     823833   0.820 Profile for small test program with recursion

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

Owner Module            Sy Function                  Line# Subtree MicroS Function MicroS Calls
----- ---------------- --- ------------------------- ----- -------------- --------------- -----
APP   HPROF_UTILS        4 STOP_PROFILING               61             26              26     1
APP   PROF_TEST          5 A_CALLS_B                    71         128199            9631     1
APP   PROF_TEST          6 A_CALLS_B@1                  71          87951           27332     1
APP   PROF_TEST          7 B_CALLS_A                    63         118568           30617     1
APP   PROF_TEST          8 B_CALLS_A@1                  63          60619           60619     1
APP   PROF_TEST          9 DBFUNC                      134          62114           62114     2
APP   PROF_TEST         10 R_CALLS_R                   114          27684            9234     1
APP   PROF_TEST         11 R_CALLS_R@1                 114          18428           18426     1
APP   PROF_TEST         12 __pkg_init                    0              3               3     1
APP   TABLE_COUNT_TYPE  13 TABLE_COUNT_TYPE             50         521332              31     1
APP   TABLE_COUNT_TYPE  22 __static_sql_exec_line55     55         521301          521301     1
SYS   DBMS_HPROF        14 STOP_PROFILING              747              0               0     1
SYS   DBMS_HPROF        23 __static_sql_exec_line700   700             67              67     1
SYS   DBMS_OUTPUT       15 GET_LINES                   180             79              79     3
SYS   DBMS_OUTPUT       16 NEW_LINE                    117              0               0     2
SYS   DBMS_OUTPUT       17 PUT                          77             23              23     2
SYS   DBMS_OUTPUT       18 PUT_LINE                    109             24               1     2
                         1 __anonymous_block             0        1818326             590     5
                         2 __plsql_vm                    0        1848468              17     6
                         3 __plsql_vm@1                  0          31993               4     1
                        19 __dyn_sql_exec_line12        12         133537          133537     1
                        20 __sql_fetch_line13           13        1100678         1100678     1
                        21 __static_sql_exec_line8       8          34400            2407     1

23 rows selected.

The “Subtree MicroS” and “Function MicroS” values are the total times in microseconds for the subtree including function, and function-only processing, respectively.

In the “Function” column, as well as procedure and function names in upper case, there are a number of names with a prefix “__”. The meanings of these are outlined in a table in the Oracle document mentioned above and reproduced below:


Notice that some of the function names have a suffix “@1”. These correspond to recursive calls, as will be clear from the network diagram later.

The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, (with joins to DBMSHP_FUNCTION_INFO to get parent and child function details) were:

Parent: Module            Sy Function                       Child:  Module            Sy Function                       Subtree MicroS Function MicroS Calls
------- ---------------- --- ------------------------------ ------- ---------------- --- ------------------------------ -------------- --------------- -----
APP     HPROF_UTILS        4 STOP_PROFILING                 SYS     DBMS_HPROF        14 STOP_PROFILING                              0               0     1
APP     PROF_TEST          5 A_CALLS_B                      APP     PROF_TEST          7 B_CALLS_A                              118568           30617     1
APP     PROF_TEST          7 B_CALLS_A                      APP     PROF_TEST          6 A_CALLS_B@1                             87951           27332     1
APP     PROF_TEST         11 R_CALLS_R@1                    SYS     DBMS_OUTPUT       18 PUT_LINE                                    2               0     1
APP     PROF_TEST          6 A_CALLS_B@1                    APP     PROF_TEST          8 B_CALLS_A@1                             60619           60619     1
APP     PROF_TEST         10 R_CALLS_R                      APP     PROF_TEST         11 R_CALLS_R@1                             18428           18426     1
APP     PROF_TEST         10 R_CALLS_R                      SYS     DBMS_OUTPUT       18 PUT_LINE                                   22               1     1
APP     TABLE_COUNT_TYPE  13 TABLE_COUNT_TYPE               APP     TABLE_COUNT_TYPE  22 __static_sql_exec_line55               521301          521301     1
SYS     DBMS_OUTPUT       18 PUT_LINE                       SYS     DBMS_OUTPUT       17 PUT                                        23              23     2
SYS     DBMS_OUTPUT       18 PUT_LINE                       SYS     DBMS_OUTPUT       16 NEW_LINE                                    0               0     2
                           1 __anonymous_block                                        21 __static_sql_exec_line8                 34400            2407     1
                           1 __anonymous_block                                        20 __sql_fetch_line13                    1100678         1100678     1
                           1 __anonymous_block                                        19 __dyn_sql_exec_line12                  133537          133537     1
                           1 __anonymous_block              SYS     DBMS_OUTPUT       15 GET_LINES                                  79              79     3
                           1 __anonymous_block              APP     TABLE_COUNT_TYPE  13 TABLE_COUNT_TYPE                       521332              31     1
                           1 __anonymous_block              APP     PROF_TEST         10 R_CALLS_R                               27684            9234     1
                           3 __plsql_vm@1                   APP     PROF_TEST          9 DBFUNC                                  31989           31989     1
                           2 __plsql_vm                     APP     PROF_TEST          9 DBFUNC                                  30125           30125     1
                           1 __anonymous_block              APP     HPROF_UTILS        4 STOP_PROFILING                             26              26     1
                           2 __plsql_vm                                                1 __anonymous_block                     1818326             590     5
                          21 __static_sql_exec_line8                                   3 __plsql_vm@1                            31993               4     1

21 rows selected.

The “Subtree MicroS” and “Function MicroS” 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.

Network Diagrams for Example 1: General

The DBMSHP_PARENT_CHILD_INFO holds parent-child links between functions, while the function detail information is held in DBMSHP_FUNCTION_INFO. The following three columns occur in both tables (descriptions from the Oracle doc):

  • SUBTREE_ELAPSED_TIME – Elapsed time, in microseconds, for subprogram, including time spent in descendant subprograms
  • FUNCTION_ELAPSED_TIME – Elapsed time, in microseconds, for subprogram, excluding time spent in descendant subprograms
  • CALLS – Number of calls to subprogram

In the DBMSHP_FUNCTION_INFO they are aggregates for the subprogram overall, whereas in the DBMSHP_PARENT_CHILD_INFO they are aggregates for the subprogram when called from its parent.

The data in the tables represent a directed network (or ‘digraph’) of nodes and links. A root node is defined as a node that has no parent node, and we may have isolated root nodes that do not appear in the links table. It can sometimes be useful when querying network data to add a dummy node as a parent of all the root nodes, creating a single root for the network and ensuring all the non-dummy nodes appear as child nodes in the adjusted links set. Here is a diagram of the adjusted network for this example, with just the links and the function numbers included:


Notice that there are four (real) root nodes, two of which are isolated. Notice also that there are two loops in the network, whereby nodes (functions) 9 and 18 can be reached by two different paths each. However, there are no cycles since no node is both ancestor and descendant of another.

We can display more of the information the HProf utility produces in extended versions of the network diagram, where we’ll separate the network into its four subnetworks, shown in two diagrams.


This diagram, of the first subnetwork, has the function names and shows the total elapsed times used by the functions within the nodes, and the elapsed times used by the functions when called by their parents within the links.

Loops and Hierarchies

The 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 them to be duplicated. We’ll see how to filter out the duplicates in the queries section below.


This diagram is for the other three subnetworks.

Network Query Output for Example 1: General

Function tree                   Sy Owner Module           Inst.  Subtree MicroS Function MicroS Calls Row
------------------------------ --- ----- ---------------- ------ -------------- --------------- ----- ---
__plsql_vm                       2                                      1848468              17     6   1
  __anonymous_block              1                                      1818326             590     5   2
    __sql_fetch_line13          20                                      1100678         1100678     1   3
    TABLE_COUNT_TYPE            13 APP   TABLE_COUNT_TYPE                521332              31     1   4
      __static_sql_exec_line55  22 APP   TABLE_COUNT_TYPE                521301          521301     1   5
    __dyn_sql_exec_line12       19                                       133537          133537     1   6
    __static_sql_exec_line8     21                                        34400            2407     1   7
      __plsql_vm@1               3                                        31993               4     1   8
        DBFUNC                   9 APP   PROF_TEST        1 of 2          31989           31989     1   9
    R_CALLS_R                   10 APP   PROF_TEST                        27684            9234     1  10
      R_CALLS_R@1               11 APP   PROF_TEST                        18428           18426     1  11
        PUT_LINE                18 SYS   DBMS_OUTPUT      1 of 2              2               0     1  12
          PUT                   17 SYS   DBMS_OUTPUT      1 of 2             23              23     2  13
          NEW_LINE              16 SYS   DBMS_OUTPUT      1 of 2              0               0     2  14
      PUT_LINE                  18 SYS   DBMS_OUTPUT      2 of 2             22               1     1  15
    GET_LINES                   15 SYS   DBMS_OUTPUT                         79              79     3  18
    STOP_PROFILING               4 APP   HPROF_UTILS                         26              26     1  19
      STOP_PROFILING            14 SYS   DBMS_HPROF                           0               0     1  20
  DBFUNC                         9 APP   PROF_TEST        2 of 2          30125           30125     1  21
A_CALLS_B                        5 APP   PROF_TEST                       128199            9631     1  22
  B_CALLS_A                      7 APP   PROF_TEST                       118568           30617     1  23
    A_CALLS_B@1                  6 APP   PROF_TEST                        87951           27332     1  24
      B_CALLS_A@1                8 APP   PROF_TEST                        60619           60619     1  25
__static_sql_exec_line700       23 SYS   DBMS_HPROF                          67              67     1  26
__pkg_init                      12 APP   PROF_TEST                            3               3     1  27

25 rows selected.

The report query script hprof_queries.sql queries the network in two ways, using Oracle’s proprietary Connect By syntax, and also using the ANSI standard recursive subquery factoring. The output above comes from the recursive subquery factoring query. The query code is discussed in a later section.

Notes on Output

Recursive Calls – “@1” Suffix

The hierarchical profiler appends a suffix “@1” on to functions called recursively, as in A_CALLS_B@1 and B_CALLS_A@1 which is an example of mutual recursion between A_CALLS_B and B_CALLS_A.

Anonymous Block (__anonymous_block)

This function corresponds to invocations of anonymous blocks, obviously enough. However, there is an apparent anomaly in the number of calls listed, 5, 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 corresponds to external invocations of PL/SQL such as from a SQL*Plus session. There are 6 calls, 5 of them presumably being linked with the external anonymous blocks, and the 6’th 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

Package Initialization (__pkg_init)

The Prof_Test package has a package variable g_num that is initialized to 0 on first invocation, which gives rise to the __pkg_init function in the output.

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, an optimization feature new 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.

Link Duplication

As mentioned earlier, hierarchical queries cause links to be duplicated below any loops, as the queries follow all paths. However, in the output above we have a single record for each of the links, including the additional root node dummy links. This is achieved by filtering out the duplicates in an additional subquery. 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 (rows 13 and 14 are omitted here).

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
BEGIN

  HProf_Utils.Start_Profiling;
  DBMS_Lock.Sleep(3);

  DBMS_Lock.Sleep(6);

  :RUN_ID := HProf_Utils.Stop_Profiling(
    p_run_comment => 'Profile for DBMS_Lock.Sleep',
    p_filename    => 'hp_example_sleep.html');
  Utils.W('Run id is ' || :RUN_ID);
END;
/
SET TIMING OFF
@hprof_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 trace file is analysed in two ways:

  • Writing a (standard) HTML report on the results using a DBMS_HProf call
  • Writing the results to standard tables created during installation using a DBMS_HProf call

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 hprof_queries.sql that queries the tables populated by the analyse step.

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

 Run Id Run Time                      Microsecs Seconds Comment
------- ---------------------------- ---------- ------- ------------------------------------------------------------
     22 18-JUN-20 12.49.56.816000 PM   10997855  11.000 Profile for DBMS_Lock.Sleep

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

Owner Module            Sy Function                  Line# Subtree MicroS Function MicroS Calls
----- ---------------- --- ------------------------- ----- -------------- --------------- -----
APP   HPROF_UTILS        2 STOP_PROFILING               61             87              87     1
APP   SLEEP_BI           3 SLEEP_BI                      0        1999602             327     1
LIB   UTILS              4 SLEEP                       351        1999268          999837     1
LIB   UTILS              5 __pkg_init                    0              2               2     1
LIB   UTILS              6 __pkg_init                    0              5               5     1
SYS   DBMS_HPROF         7 STOP_PROFILING              747              0               0     1
SYS   DBMS_HPROF        11 __static_sql_exec_line700   700             77              77     1
SYS   DBMS_LOCK          8 SLEEP                       207        9997626         9997626     3
SYS   DBMS_LOCK          9 __pkg_init                    0              3               3     1
                         1 __plsql_vm                    0        1999606               4     1
                        10 __static_sql_exec_line6       6        2005266            5660     1

11 rows selected.

The “Subtree MicroS” and “Function MicroS” values are the total times in microseconds for the subtree including function, and function-only processing, respectively.

The records produced in the functions parent-child table, DBMSHP_PARENT_CHILD_INFO, (with joins to DBMSHP_FUNCTION_INFO to get parent and child function details) were:

Parent: Module            Sy Function                       Child:  Module            Sy Function                       Subtree MicroS Function MicroS Calls
------- ---------------- --- ------------------------------ ------- ---------------- --- ------------------------------ -------------- --------------- -----
APP     HPROF_UTILS        2 STOP_PROFILING                 SYS     DBMS_HPROF         7 STOP_PROFILING                              0               0     1
APP     SLEEP_BI           3 SLEEP_BI                       LIB     UTILS              5 __pkg_init                                  2               2     1
APP     SLEEP_BI           3 SLEEP_BI                       LIB     UTILS              6 __pkg_init                                  5               5     1
APP     SLEEP_BI           3 SLEEP_BI                       LIB     UTILS              4 SLEEP                                 1999268          999837     1
LIB     UTILS              4 SLEEP                          SYS     DBMS_LOCK          8 SLEEP                                  999431          999431     1
                          10 __static_sql_exec_line6                                   1 __plsql_vm                            1999606               4     1
                           1 __plsql_vm                     APP     SLEEP_BI           3 SLEEP_BI                              1999602             327     1

7 rows selected.

The “Subtree MicroS” and “Function MicroS” 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.

Network Diagrams for Example 2: Sleep



The network diagram shows 5 nodes appearing as (real) roots, of which one (8) is also linked as a child.


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.

Oracle HProf HTML Reports

A standard HTML report can be produced after the profiling is stopped, by a call to one of the Analyze methods. The custom procedure below calls this method to write the report to a CLOB field, then calls DBMS_XSLProcessor.CLOB2File to write the contents to file.

The second Analyze call populates the tables read by the custom queries.

FUNCTION Stop_Profiling(
            p_run_comment                  VARCHAR2,                       -- run comment
            p_filename                     VARCHAR2) RETURN PLS_INTEGER IS -- file name for html report
  l_report_clob   CLOB;
BEGIN

  DBMS_HProf.Stop_Profiling;
  DBMS_HProf.Analyze(trace_id => g_trace_id, report_clob => l_report_clob);
  DBMS_XSLProcessor.CLOB2File(cl => l_report_clob, flocation => 'INPUT_DIR', fname => p_filename);
  RETURN DBMS_HProf.Analyze(trace_id => g_trace_id, run_comment => p_run_comment);

END Stop_Profiling;

The driver scripts specify the file name hp_example_general.html and hp_example_sleep.html, and these are written to the folder in the Oracle directory INPUT_DIR. The files for the examples are included in the associated GitHub project. The report starts with a list of the included subreports, as in the screenshot below:


Here is a screenshot for the first of the subreports for the general example:

Network Queries

The queries are in the script hprof_queries.sql, and we discuss the network queries in this section. The script also contains simple queries against the base tables. All queries are for a given RUNID, passed in as a sqlplus parameter.

Connect By Query

WITH links (node_fr, node_to, owner, module, function, sub_t, fun_t, calls) AS (
    SELECT  0, fni.symbolid, fni.owner, fni.module, fni.function, fni.subtree_elapsed_time, fni.function_elapsed_time, fni.calls
      FROM dbmshp_function_info fni
     WHERE fni.runid = &RUN_ID
       AND NOT EXISTS (SELECT 1 FROM dbmshp_parent_child_info pci WHERE pci.childsymid = fni.symbolid AND pci.runid = fni.runid)
     UNION ALL
    SELECT pci.parentsymid,
           pci.childsymid,
           fi.owner,
           fi.module ,
           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
)
SELECT RPAD(' ', (LEVEL-1)*2, ' ') || function ftree,
       node_to sy,
       owner,
       module,
       sub_t,
       fun_t,
       calls
  FROM links
CONNECT BY PRIOR node_to = node_fr
START WITH node_fr = 0
ORDER SIBLINGS BY sub_t DESC, fun_t DESC, calls DESC, node_to

Notes on Connect By Query

Links Subquery

In the basic network diagrams we added a dummy root node so that all real nodes appear as child nodes, and this is implemented in the links subquery here as a union between new links to the real root nodes and the original links. This allows the main query connecting the revised links set to cover all nodes.

Sibling Ordering

The ORDER SIBLINGS BY clause allows us to order sibling nodes by subtree elapsed time descending, with additional tie-break columns.

Link Duplication

The network for the first example has two loops, and the second loop has two child nodes coming from the end point. Hierarchical queries (both CONNECT BY and recursive subquery factors in Oracle) cause the links below the loop to be duplicated as all paths are followed. This is seen in the output below for the first example, with 28 rows compared with 26 rows for the output displayed earlier, using a query with filtering implemented. The query can be extended to filter out the duplicates using analytic functions, as is implemented for the recursive subquery factoring query.

Function tree                   Sy Owner Module           Subtree MicroS Function MicroS Calls
------------------------------ --- ----- ---------------- -------------- --------------- -----
__plsql_vm                       2                               1848468              17     6
  __anonymous_block              1                               1818326             590     5
    __sql_fetch_line13          20                               1100678         1100678     1
    TABLE_COUNT_TYPE            13 APP   TABLE_COUNT_TYPE         521332              31     1
      __static_sql_exec_line55  22 APP   TABLE_COUNT_TYPE         521301          521301     1
    __dyn_sql_exec_line12       19                                133537          133537     1
    __static_sql_exec_line8     21                                 34400            2407     1
      __plsql_vm@1               3                                 31993               4     1
        DBFUNC                   9 APP   PROF_TEST                 31989           31989     1
    R_CALLS_R                   10 APP   PROF_TEST                 27684            9234     1
      R_CALLS_R@1               11 APP   PROF_TEST                 18428           18426     1
        PUT_LINE                18 SYS   DBMS_OUTPUT                   2               0     1
          PUT                   17 SYS   DBMS_OUTPUT                  23              23     2
          NEW_LINE              16 SYS   DBMS_OUTPUT                   0               0     2
      PUT_LINE                  18 SYS   DBMS_OUTPUT                  22               1     1
        PUT                     17 SYS   DBMS_OUTPUT                  23              23     2
        NEW_LINE                16 SYS   DBMS_OUTPUT                   0               0     2
    GET_LINES                   15 SYS   DBMS_OUTPUT                  79              79     3
    STOP_PROFILING               4 APP   HPROF_UTILS                  26              26     1
      STOP_PROFILING            14 SYS   DBMS_HPROF                    0               0     1
  DBFUNC                         9 APP   PROF_TEST                 30125           30125     1
A_CALLS_B                        5 APP   PROF_TEST                128199            9631     1
  B_CALLS_A                      7 APP   PROF_TEST                118568           30617     1
    A_CALLS_B@1                  6 APP   PROF_TEST                 87951           27332     1
      B_CALLS_A@1                8 APP   PROF_TEST                 60619           60619     1
__static_sql_exec_line700       23 SYS   DBMS_HPROF                   67              67     1
__pkg_init                      12 APP   PROF_TEST                     3               3     1

27 rows selected.

Recursive Subquery Factoring Query

WITH pci_sums (childsymid, subtree_elapsed_time, function_elapsed_time, calls) AS (
    SELECT childsymid, Sum(subtree_elapsed_time), 
                       Sum(function_elapsed_time), 
                       Sum(calls)
      FROM dbmshp_parent_child_info pci
     WHERE runid = &RUN_ID
     GROUP BY childsymid
), full_tree (runid, lev, node_id, sub_t, fun_t, calls, link_id) AS (
    SELECT fni.runid, 0, fni.symbolid,
           fni.subtree_elapsed_time - Nvl(psm.subtree_elapsed_time, 0),
           fni.function_elapsed_time - Nvl(psm.function_elapsed_time, 0),
           fni.calls - Nvl(psm.calls, 0), 'root' || ROWNUM
      FROM dbmshp_function_info fni
      LEFT JOIN pci_sums psm
        ON psm.childsymid = fni.symbolid
     WHERE fni.runid = &RUN_ID
       AND fni.calls - Nvl(psm.calls, 0) > 0
     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 ftree,
       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

Notes on Recursive Subquery Factoring Query

Root Nodes and Child Sums Subquery

A function may be called both as a child of another function, and also at the top level, as the second example showed. We detect this situation by counting the number of calls for the functions in the links table (dbmshp_parent_child_info) and comparing with the number of calls in the functions table (dbmshp_function_info). The difference corresponds to the number of root-level calls, and the root-level timings are the timing differences between the function timings and the sums of the link timings.

Link Duplication

As noted earlier, hierarchical queries (both Connect By and recursive subquery factors in Oracle) cause the links below any loops to be duplicated as all paths are followed. In this query an additional subquery has been added, tree_ranked, that ranks the nodes and links by order of appearance. The node rank is used just for information in the main block, while the link rank is used to eliminate duplicate links. Gaps in the “Row” column indicate where duplicates have been suppressed.

It’s worth remembering this because it’s a general feature of SQL for querying hierarchies, and one that seems not to be 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, such as: PL/SQL Pipelined Function for Network Analysis.

Here is a query structure diagram for the recursive subquery factoring query:


I wrote about query diagramming in August 2012: Query Structure Diagramming

Hierarchical Profiler Feature Summary

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

  • Results are organised as lists of measures by program unit and by ‘unit-within-caller’, and can be represented in a call hierarchy
  • Results are reported at the level of program unit call or ‘tracked operation’; all calls to a given program unit within a single parent unit are aggregated
  • Measures reported are elapsed times and numbers of calls, but not CPU times
  • External program units are included in the profiling
  • Profiling is performed, after initial setup, by means of before and after API calls, followed by querying of results in tables, or viewing of HTML reports






 

Benchmarking Oracle DML: A Case Study I – Update vs Merge, An Example

Posted on by
Reply

Some time ago I was involved in performing a one-off update of a column in an Oracle table of 250 million records, of which about 50 million would be updated. In the initial attempt, in development, the update ran for a very long time before aborting with the error:

ORA-30036: unable to extend segment by 8 in undo tablespace ‘UNDOTBS’

I noted that the updated column featured in two indexes, and realised that the update would likely entail much more work in updating the indexes than in the update of the table. I reasoned that, because the index data are physically stored in a way that depends on the values, changing the values could involve a lot of physical restructuring on disk. Updating the values in the table, on the other hand, probably would not involve much restructuring of the table data, if the storage requirements of the new values were similar to those of the old ones, which they were. Anyway, we changed the process to have it drop the indexes, do the update, then recreate the indexes. There are other, possibly even faster, ways of doing this (as we’ll see), but the change allowed the whole process to complete in around an hour.

Some time later I noticed an OTN thread, Improve query performance instead of aggregrate function, in which the poster requested help in improving the performance of an Oracle update statement (the title is a little misleading). Recalling my earlier experience, I suggested that dropping any indexes that included the updated column would improve performance. As it turned out, the poster stated that the table did not have any indexes, and other posters suggested various alternative ways of doing the update.

In the example there is a product sales table having product id and sales date columns (and a few others unspecified), and the update sets the sales date to a constant value for the earliest sales date for each product. The data model and SQL in the thread are relatively simple, and it occurred to me that it would be interesting to use the example to do a case study of the performance impact of indexes on updates and other DML statements.

In this two-part article I’ll use parameterised datasets to do two sets of comparisons: First, we’ll compare the performance of the original poster’s update statement with a slightly modified version of another poster’s solution using ‘merge’, across a 2-dimensional grid of dataset points with no indexes. Second (in part 2), we’ll compare the performance of both forms of update, plus related delete and insert statements on the 1-dimensional ‘slice’ of dataset points where the updates apply to about half of the total records. In the second set, we’ll run the statements in the presence of: (i) No indexes; (ii) product id index only; (iii) product id and sales date indexes, and we’ll also compare with a Create Table As Select (CTAS) approach.

To do the comparisons, I use my own Oracle benchmarking framework, which I presented at the 2017 Ireland Oracle User Group conference, Dimensional Performance Benchmarking of SQL – IOUG Presentation. The framework, which has been upgraded during this work to cover DML and DDL more fully, including all code for this article, is available on GitHub: A Framework for Dimensional Benchmarking of SQL Performance.

Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 – 64bit Production

Test Data

Data Structure

CREATE TABLE product_sales (product_id NUMBER, sales_date DATE)
/
CREATE INDEX ps_date_n1 ON product_sales (sales_date)
/
CREATE INDEX ps_prd_n1 ON product_sales (product_id)
/

Data Generator

The data generation procedure takes two parameters, a width parameter being the number of products, and a depth parameter being the number of records per product. Rows are generated using two cross-joined subqueries that each generate rows via the common ‘select from dual connect by’ method, as follows:

INSERT INTO product_sales
WITH prod_gen AS (
  SELECT LEVEL + (i - 1)*c_max_rowgen product_id
    FROM DUAL
    CONNECT BY LEVEL <= l_wide_batch_sizes(i)
), day_gen AS (
  SELECT LEVEL rn
    FROM DUAL
    CONNECT BY LEVEL <= p_point_deep
)
SELECT p.product_id, c_start_date + Mod (Abs (DBMS_Random.Random), c_n_days_in_century)
  FROM prod_gen p
 CROSS JOIN day_gen d;

Note that:

  • Product ids are sequential
  • Dates are randomized across the century from 1 January 1900
  • A call is made to DBMS_Random.Seed at the start of the procedure to ensure each call with the same parameters will get the same (pseudo-)random dates
  • The insert occurs within a loop with index i in order to limit the number of rows generated at once (see below for reason)

The reason for limiting the number of rows generated by inserting within a loop is that the Oracle tree-walk mechanism uses memory increasing with number of levels traversed, and I hit the dreaded

Completed with error: ORA-30009: Not enough memory for CONNECT BY operation

There are various ways of avoiding this, including this, Generating lots of rows using connect by – safely!, which suggests cross-joining as many tree-walk subqueries as are necessary to generate the overall number from tree-walks of smaller size. In our situation, however, this approach is problematic because we pass in the desired number as a parameter. To get the exact number desired we would have to create the statement dynamically and create a set of subqueries with the subquery limits being products of the prime factors of the number. This is impractical and in any case the highest prime factor could be too large. For this reason the inserts are performed in batches within a loop over an array containing the batch sizes.

Lower depth values correspond to larger proportions of records to be updated, with smaller numbers of values to be sorted within the product id partitions. For example, at depth 2, around half the records are updated, while at depth 100 around 1% are updated.

Test Case 1: Update vs Merge, no Indexes

Both update and merge statements below are based on statements in the thread mentioned above. I reformatted them and altered the merge to make it consistent with the update in updating all records of minimum date where duplication occurs.

One other change may be worth highlighting: As Steven Feuerstein noted recently, About the Date Literal in Oracle Database, the date literal seems to be under-used by Oracle developers, but it is neater than using To_Date with an explicit format mask. I replaced

TO_DATE (‘01.01.2017’, ‘dd.mm.yyyy’)

with the literal equivalent

DATE ‘2017-01-01’

I incidentally also changed the year for my test data.

Update/Merge Statements

Update (UPD_DML)

UPDATE product_sales sd
   SET sd.sales_date = DATE '1900-01-01'
 WHERE 1=1 AND sd.sales_date = ( 
   SELECT Min(sd2.sales_date)
     FROM product_sales sd2
    WHERE sd.product_id = sd2.product_id   
 )
   AND sd.sales_date != DATE '1900-01-01'

This is essentially the same statement as in the original post by user12251389.

Merge (MRG_DML)

MERGE INTO product_sales tgt
USING (SELECT *
       FROM (
         SELECT rowid arowid, product_id, DATE '1900-01-01' sales_date,
                sales_date AS old_sales_date,
                Rank() OVER (PARTITION BY product_id ORDER BY sales_date) rn
         FROM   product_sales    
       )
       WHERE rn = 1 AND 0 = Decode(sales_date, old_sales_date, 1, 0)) src
   ON (tgt.rowid = src.arowid)
 WHEN MATCHED THEN UPDATE
  SET tgt.sales_date = src.sales_date

This is essentially the same statement as in the post by responder Paulzip, except that where he had Row_Number I have put Rank to allow for duplicate updating in order to be consistent with the update statement.

For my performance testing I added two hinted versions of the above merge, the first of which has the following hint:

no_swap_join_inputs(@”SEL$F5BB74E1″ “TGT”@”SEL$1”)

while the second has two hints. These rather strange-looking hints will be explained below in relation to execution plans.

Results

The four SQL statements were run across a 2-dimensional grid of width and depth data points. After each update the number of records is saved against data point and SQL statement, and the transaction is rolled back. The elapsed and CPU times, and the CPU percentages, are displayed below for wide and deep slices of the grid in the two scrollboxes below. Of course, data creation and rollback times are not included, although the instrumentation reports them separately in the log file.

The detailed results can be seen in the embedded file below.

Wide Slice Graphs

In the wide slice there are 10 million products and from 2 to 100 dates per product, with a maximum of 100 million records. At D=2 about half the records are updated, and at D=100 about 1% are updated.

Elapsed Times: Wide Slice

CPU Times: Wide Slice

CPU Percentages: Wide Slice

Deep Slice Graphs

In the deep slice there are 100 dates per product and from 100,000 to 1,000,000 products, with a maximum of 100 million records. About 1% of the records are updated.

Elapsed Times: Deep Slice

CPU Times: Deep Slice

CPU Percentages: Deep Slice

The results show:

  • The update SQL (UPD_DML) is faster at all data points than the merges, being generally twice as fast or better at the deep data points
  • The
  • At the shallow data points (D=2), the timings are much closer, reflecting in part the fact that proportionally more times goes to doing the actual updating
  • The two hinted versions of the merge are significantly faster than the unhinted version (MRG_DML), and we’ll discuss this in relation to execution plans below

It is interesting to note that the update statement from the original poster in the OTN thread is faster than (the small variation on) the more complex merge statement proposed in the thread to improve performance! I considered whether my substitution of Rank for Row_Number might have been to blame, and found that it did have a significant effect on the execution plan, where it caused a hash join to be used in place of a nested loops join. In fact, the hinted version MRG_HT2 has the same plan as would the Row_Number version, and is faster than the unhinted merge, but still slower than the update.

Execution Plans

The benchmarking framework ensures that the SQL engine hard-parses, and thus re-calculates the optimal execution plan, at each instance, by inserting a functionally meaningless condition x=x into the statement, where x is the number given by the current timestamp to the millisecond formatted thus: To_Char(SYSTIMESTAMP, ‘yymmddhh24missff3’). This results in the SQL id, which is the hash of the SQL text, being different each time.

The execution plan for each SQL statement execution is printed to log, and was the same for each data point. The plans are listed in the scrollbox below at the highest data point.

Execution Plan for Update (UPD_DML)

--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT       |               |      1 |        |      0 |00:01:04.49 |    1516K|   5474 |       |       |          |
|   1 |  UPDATE                | PRODUCT_SALES |      1 |        |      0 |00:01:04.49 |    1516K|   5474 |       |       |          |
|*  2 |   HASH JOIN            |               |      1 |   1001K|    998K|00:00:56.15 |     496K|   5474 |    53M|  8523K|   52M (0)|
|   3 |    VIEW                | VW_SQ_1       |      1 |   1001K|    997K|00:00:37.33 |     248K|      0 |       |       |          |
|*  4 |     FILTER             |               |      1 |        |    997K|00:00:37.15 |     248K|      0 |       |       |          |
|   5 |      SORT GROUP BY     |               |      1 |   1001K|   1000K|00:00:37.09 |     248K|      0 |    70M|    15M|   62M (0)|
|   6 |       TABLE ACCESS FULL| PRODUCT_SALES |      1 |    100M|    100M|00:00:01.62 |     248K|      0 |       |       |          |
|*  7 |    TABLE ACCESS FULL   | PRODUCT_SALES |      1 |     99M|     99M|00:00:12.53 |     248K|   5474 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("SD"."SALES_DATE"="MIN(SD2.SALES_DATE)" AND "SD"."PRODUCT_ID"="ITEM_1")
   4 - filter(MIN("SD2"."SALES_DATE")<>TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))
   7 - filter("SD"."SALES_DATE"<>TO_DATE(' 1900-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

Execution Plan for Merge (MRG_DML)

--------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem | Used-Tmp|
--------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT             |               |      1 |        |      0 |00:02:30.40 |    1516K|    428K|    428K|       |       |          |         |
|   1 |  MERGE                      | PRODUCT_SALES |      1 |        |      0 |00:02:30.40 |    1516K|    428K|    428K|       |       |          |         |
|   2 |   VIEW                      |               |      1 |        |    998K|00:02:02.03 |     496K|    428K|    428K|       |       |          |         |
|*  3 |    HASH JOIN                |               |      1 |    100M|    998K|00:02:01.77 |     496K|    428K|    428K|  2047M|    52M|   55M (1)|    3329K|
|   4 |     TABLE ACCESS FULL       | PRODUCT_SALES |      1 |    100M|    100M|00:00:09.96 |     248K|      0 |      0 |       |       |          |         |
|*  5 |     VIEW                    |               |      1 |    100M|    998K|00:01:33.29 |     248K|  15903 |  15903 |       |       |          |         |
|*  6 |      WINDOW SORT PUSHED RANK|               |      1 |    100M|   1001K|00:01:33.33 |     248K|  15903 |  15903 |    70M|  2904K|   97M (1)|         |
|   7 |       TABLE ACCESS FULL     | PRODUCT_SALES |      1 |    100M|    100M|00:00:11.63 |     248K|      0 |      0 |       |       |          |         |
--------------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("TGT".ROWID="from$_subquery$_007"."AROWID")
   5 - filter(("RN"=1 AND DECODE(INTERNAL_FUNCTION("SALES_DATE"),"OLD_SALES_DATE",1,0)=0))
   6 - filter(RANK() OVER ( PARTITION BY "PRODUCT_ID" ORDER BY "SALES_DATE")<=1)

Execution Plan for Merge with Join Inputs Hint(MHT_DML)

----------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT             |               |      1 |        |      0 |00:02:02.01 |    1516K|  19175 |  15903 |       |       |          |
|   1 |  MERGE                      | PRODUCT_SALES |      1 |        |      0 |00:02:02.01 |    1516K|  19175 |  15903 |       |       |          |
|   2 |   VIEW                      |               |      1 |        |    998K|00:01:51.06 |     496K|  19175 |  15903 |       |       |          |
|*  3 |    HASH JOIN                |               |      1 |    100M|    998K|00:01:50.84 |     496K|  19175 |  15903 |    77M|  5796K|  107M (0)|
|*  4 |     VIEW                    |               |      1 |    100M|    998K|00:01:32.03 |     248K|  15903 |  15903 |       |       |          |
|*  5 |      WINDOW SORT PUSHED RANK|               |      1 |    100M|   1001K|00:01:32.12 |     248K|  15903 |  15903 |    70M|  2904K|   97M (1)|
|   6 |       TABLE ACCESS FULL     | PRODUCT_SALES |      1 |    100M|    100M|00:00:10.95 |     248K|      0 |      0 |       |       |          |
|   7 |     TABLE ACCESS FULL       | PRODUCT_SALES |      1 |    100M|    100M|00:00:10.90 |     248K|   3272 |      0 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("TGT".ROWID="from$_subquery$_007"."AROWID")
   4 - filter(("RN"=1 AND DECODE(INTERNAL_FUNCTION("SALES_DATE"),"OLD_SALES_DATE",1,0)=0))
   5 - filter(RANK() OVER ( PARTITION BY "PRODUCT_ID" ORDER BY "SALES_DATE")<=1)

Execution Plan for Merge with Nested Loops Hint(MH2_DML)

------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name          | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT               |               |      1 |        |      0 |00:02:01.99 |    1516K|  27343 |  15903 |       |       |          |
|   1 |  MERGE                        | PRODUCT_SALES |      1 |        |      0 |00:02:01.99 |    1516K|  27343 |  15903 |       |       |          |
|   2 |   VIEW                        |               |      1 |        |    998K|00:01:34.39 |     496K|  27343 |  15903 |       |       |          |
|   3 |    NESTED LOOPS               |               |      1 |    100M|    998K|00:01:34.16 |     496K|  27343 |  15903 |       |       |          |
|*  4 |     VIEW                      |               |      1 |    100M|    998K|00:01:30.08 |     248K|  15903 |  15903 |       |       |          |
|*  5 |      WINDOW SORT PUSHED RANK  |               |      1 |    100M|   1001K|00:01:30.03 |     248K|  15903 |  15903 |    70M|  2904K|   97M (1)|
|   6 |       TABLE ACCESS FULL       | PRODUCT_SALES |      1 |    100M|    100M|00:00:11.43 |     248K|      0 |      0 |       |       |          |
|   7 |     TABLE ACCESS BY USER ROWID| PRODUCT_SALES |    998K|      1 |    998K|00:00:04.03 |     247K|  11440 |      0 |       |       |          |
------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter(("RN"=1 AND DECODE(INTERNAL_FUNCTION("SALES_DATE"),"OLD_SALES_DATE",1,0)=0))
   5 - filter(RANK() OVER ( PARTITION BY "PRODUCT_ID" ORDER BY "SALES_DATE")<=1)

The choices made by Oracle’s Cost Based Optimiser (CBO) in construction of the execution plan are crucially dependent on the cardinality estimates it makes at each step. The outputs above display these estimates along with the actual numbers of rows returned. We know that the total number of records is 100M, and that approximately 1M of these are updated at the extreme wide/deep data point shown. How accurate are the cardinality estimates in the plans above? Let’s take them in turn.

UPD_DML
Here the update subquery results in a hash join between the table and an internal view in which the records from a separate scan of the table are sorted and filtered to produce the records with minimum date value by product. The estimated cardinality of the view in step #3 is 1001K, which is close to the actual cardinality of 997K.

The view is used as the build table with the table itself in step #7 being used as the probe table. This looks like the right strategy because the smaller rowset is generally preferred as the build table, used to build the hash table for the join.

MRG_DML
The merge statement also has at its heart a hash join between the table and an internal view, but this time the build and probe tables are reversed, and we observe that the cardinality estimate for the view, in step #5, is 100M, whereas the actual is 998K. The CBO has not been able to detect that the rn = 1 condition on the rank function would reduce the cardinality by a factor of about a hundred, so either choice of build table would look similar.

MHT_DML
I wondered how big an effect making the ‘wrong’ choice for the build table would have, and so looked to include a hint to force the ‘correct’ choice, and made this the statement MHT_DML. I wrote an article on the subject of hash join ‘inner’ ordering (as I called it there) last year, A Note on Oracle Join Orders and Hints, which used a simple 3-table query with no subqueries. In simple cases such as that one it is easy to force the choice of build table using the hints (no_)swap_join_inputs (tab) where tab is the alias of the table to be joined to the current rowset.

In more complicated situations with subqueries, such as we have in our merge statement, it is a little harder since we need to specify the target using internal query block names that are not in the original statement. Fortunately, there is an easy way to get the desired hint: The execution plans above are displayed using Oracle’s DBMS_XPlan.Display_Cursor API, and if you pass the keyword OUTLINE to this API, it returns the list of fully specified hints that determine the execution plan. We can extract the relevant hints from this list and modify if necessary. In the unhinted outline there is the hint:

swap_join_inputs(@”SEL$F5BB74E1″ “TGT”@”SEL$1”)

so to reverse the build/probe choice we simply change swap_join_inputs to no_swap_join_inputs.

This improves performance by 19% at the extreme data point.

Incidentally, Tom Kyte discusses in detail how to use these outline hints to investigate different plans and to create baselines using SQL Plan Management in a 2014 Oracle Magazine article (referenced also in part 2 of this current article): On Table Updates and SQL Plan Baselines.

Another way of getting at the hint syntax is to use SQL Developer, as shown here:

MH2_DML
As mentioned above, I wondered what effect the use of Rank instead of the Row_Number used in the OTN thread had on performance. To check this I replaced Rank with Row_Number, ran an Explain Plan, and found quite a big difference in the plan (a hash join changing to a nested loops join), despite the fact that the difference in actual cardinality is extremely small so that the same plan should be optimal for both.

I followed the same approach as in MHT_DML to obtain the hints that would force the same plan as the Row_Number version via the SQL outline. This time two hints were required (you could just take the whole outline set of course):

leading(@”SEL$F5BB74E1″ “from$_subquery$_007″@”SEL$2” “TGT”@”SEL$1″)
use_nl(@”SEL$F5BB74E1” “TGT”@”SEL$1”)

This version perfroms slightly better in CPU terms than the firsted hinted version, with smaller differences in elapsed times, and they perform very similarly at the higher data points.

Conclusions

In part 1 of this article we demonstrated the use of my benchmarking framework for comparing DML with detailed timings, statistics and execution plans across a 2-dimensional grid. In terms of the problem addressed, and general learnings, a couple of points can be made:

  • The ‘obvious’ Update turned out to be faster as well as simpler than a more complicated Merge; Oracle’s own transformation of the update subquery, into a join between the table and an internal view, performed better than the hand-crafted attempt
  • The OUTLINE parameter to DBMS_XPlan.Display_Cursor is very useful to extract more difficult hint syntax (you can also get it from SQL Developer, by right-clicking the hints displayed below an execution plan)
  • We also showed, using a gif example, how to get these hints from SQL Developer
  • Regarding memory problems when generating large numbers of rows for test data, we linked to one solution, and provided an alternative for when that one is inapplicable

The example problem, together with all code used in both parts of this article, and the revisions made to the framework are available here: A Framework for Dimensional Benchmarking of SQL Performance.

Part 2 of the article, which benchmarks different methods for DML in the presence of indexes, is here: Benchmarking Oracle DML: A Case Study II – Effects of Indexes