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
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
