Performance is high on the list of IT requirements, especially with queries, functions and stored procedures. Queries have been easy to work with because the execution plan gives all of the details one could need to find trouble spots. When it’s PL/SQL, that’s been a more difficult apple to peel since extracting statements from a procedure or function changes the execution context and, thus, the plan. Oracle provides a very useful utility, the PL/SQL profiler, to aid in finding poorly performing areas of PL/SQL code so they can be addressed. Let’s look at how to configure and use that utility to find problem areas.
Configuring the profiler is fairly easy; in the schema that owns the PL/SQL objects the proftab.sql script (located at $ORACLE_HOME/rdbms/admin) must be run to create the tables that the profiler needs to store run data; those tables are:
PLSQL_PROFILER_UNITS
PLSQL_PROFILER_RUNS
PLSQL_PROFILER_DATA
These three tables are the backbone of the profiler as views are created from them so that reports can be run. Once those tables are created, running the profiler is a simple matter of starting it with a ‘tag’, running the suspect PL/SQL and then stopping it. One ‘warning’ is that the profiler cannot profile code owned by another user unless it’s run when connected as ‘sys as sysdba’, so it’s important that the account that owns the object to be profiled is used to generate the profiler data. [The account used in these examples is BING, and all of the tables and views necessary for the profiler to do its work are created in that schema.]
An example of how to use the profiler once the setup has been successfully completed follows:
set linesize 1000 trimspool on
select dbms_profiler.start_profiler('DATES PACKAGE') from dual;
select dates_pkg.minutes_elapsed(sysdate-10, sysdate) from dual;
select dbms_profiler.stop_profiler from dual;
spool dates_package_profiler_run.rpt
@?/rdbms/admin/profsum
spool off
The first select starts the profiler running; the next select is running the ‘problem’ function to be traced, and the final select turns off profiling. The portion of the script from the ‘spool …’ line to the ‘spool off’ line generates the report for the run, and that report contains a wealth of performance data. The report generated from the script shown above is reproduced below:
View created.
View created.
View created.
View created.
Package created.
No errors.
Package body created.
No errors.
3 rows updated.
PL/SQL procedure successfully completed.
GRAND_TOTA
----------
.00
RUNID RUN_COMMENT SECONDS
---------- ------------------------------------------------------------------------------------------------------------------------ ----------
1 DATES PACKAGE .015
RUNID RUN_COMMENT UNIT_OWNER UNIT_NAME SECONDS PERCEN
---------- -------------------------------------------------------------------------------- -------------------------------- ----------------------------- --------- ------
1 DATES PACKAGE BING DATES_PKG .00 8.9
UNIT_OWNER UNIT_NAME SECONDS PERCENTAG
-------------------------------- ---------------------------------------------------------------------------------------------------- --------- ---------
BING DATES_PKG .00 90.85
.00 9.15
to_char(p1.total_time/(p1.total_occur*p1.min_time),'99999.99')as "Ave/min",
*
ERROR at line 10:
ORA-01476: divisor is equal to zero
RUNID SECONDS OWNER UNIT_NAME LINE
---------- -------- -------------------------------------------------------------------------------- ------------------------------------------------------ ----------
TEXT
-----------------------------------------------------------------------------------------------------------------------------------------------------------
1 .0 BING DATES_PKG 147
SELECT minutes_since_midnight (lowdate)
1 .0 BING DATES_PKG 57
SELECT TO_NUMBER
1 .0 BING DATES_PKG 19
SELECT TO_CHAR
RUNID SECONDS OWNER UNIT_NAME LINE
---------- -------- -------------------------------------------------------------------------------- ------------------------------------------------------- ----------
TEXT
-------------------------------------------------------------------------------------------------------------------------------------------------------------
1 .0 BING DATES_PKG 70
SELECT (secs_elapsed / 60)
1 .0 BING DATES_PKG 108
SELECT julian_date (lowdate)
1 .0 BING DATES_PKG 30
SELECT TO_NUMBER (varch_value)
RUNID SECONDS OWNER UNIT_NAME LINE
---------- -------- -------------------------------------------------------------------------------- ----------------------------------------------------------------
TEXT
-------------------------------------------------------------------------------------------------------------------------------------------------------------
1 .0 BING DATES_PKG 151
SELECT minutes_since_midnight (highdate)
1 .0 BING DATES_PKG 125
SELECT (high_julian - low_julian)
1 .0 BING DATES_PKG 136
SELECT (num_days * 1440)
RUNID SECONDS OWNER UNIT_NAME LINE
---------- -------- -------------------------------------------------------------------------------- ------------------------------------------------------- ----------
TEXT
-------------------------------------------------------------------------------------------------------------------------------------------------------------
1 .0 BING DATES_PKG 112
SELECT julian_date (highdate)
1 .0 BING DATES_PKG 169
SELECT (num_minutes + temp_mins)
1 .0 BING DATES_PKG 161
SELECT (min_high - min_low)
12 rows selected.
SECONDS UNIT_OWNER UNIT_NAME LINE
-------- -------------------------------------------------------------------------------- ------------------------------------------------------------------ ----------
TEXT
------------------------------------------------------------------------------------------------------------------------------------------------------------
.0 BING DATES_PKG 147
SELECT minutes_since_midnight (lowdate)
.0 BING DATES_PKG 57
SELECT TO_NUMBER
.0 BING DATES_PKG 19
SELECT TO_CHAR
SECONDS UNIT_OWNER UNIT_NAME LINE
-------- -------------------------------------------------------------------------------- ----------------------------------------------------------------- ----------
TEXT
-----------------------------------------------------------------------------------------------------------------------------------------------------------
.0 BING DATES_PKG 70
SELECT (secs_elapsed / 60)
.0 BING DATES_PKG 108
SELECT julian_date (lowdate)
.0 BING DATES_PKG 30
SELECT TO_NUMBER (varch_value)
SECONDS UNIT_OWNER UNIT_NAME LINE
-------- -------------------------------------------------------------------------------- ----------------------------------------------------------------- ----------
TEXT
------------------------------------------------------------------------------------------------------------------------------------------------------------
.0 BING DATES_PKG 151
SELECT minutes_since_midnight (highdate)
.0 BING DATES_PKG 125
SELECT (high_julian - low_julian)
.0 BING DATES_PKG 136
SELECT (num_days * 1440)
SECONDS UNIT_OWNER UNIT_NAME LINE
-------- -------------------------------------------------------------------------------- ----------------------------------------------------------------- ----------
TEXT
------------------------------------------------------------------------------------------------------------------------------------------------------------
.0 BING DATES_PKG 112
SELECT julian_date (highdate)
.0 BING DATES_PKG 169
SELECT (num_minutes + temp_mins)
.0 BING DATES_PKG 161
SELECT (min_high - min_low)
12 rows selected.
PL/SQL procedure successfully completed.
UNIT_OWNER UNIT_NAME LINES_EXECUTED
-------------------------------- -------------------------------- --------------
BING DATES_PKG 18
UNIT_OWNER UNIT_NAME LINES_PRESENT
-------------------------------- -------------------------------- -------------
BING DATES_PKG 21
LINES_EXECUTED
--------------
18
LINES_PRESENT
-------------
21
The first section of the report shows what was executed and how long each call took to run; it’s a generalized report that doesn’t provide a lot of detail, but it does pave the way for the tuning investigation as long run times will be reported here first. The next section goes into detail about what was executed and the time each executed statement consumed; it provides the PL/SQL code of ‘relevant’, sections so they can be evaluated and, possibly, investigated:
=================================trace info=================================
===========================Results for run #1 made on 09-FEB-18 09:43:32 =========================
(DATES PACKAGE) Run total time: .02 seconds
Unit #1: . - Total time: .00 seconds
Unit #2: BING.DATES_PKG - Total time: .00 seconds
9 BEGIN
10
11
12
13
14
15
16
17
18
19 2 .00012803 .00006401 SELECT TO_CHAR
20 ( TO_DATE(TO_CHAR(date_to_convert,'MM/DD/YYYY'),'MM/DD/YYYY')
21 , 'J')
22 INTO varch_value
23 FROM dual;
24
25
26
27
28
29
30 2 .00008374 .00004187 SELECT TO_NUMBER (varch_value)
31 INTO num_value
32 FROM dual;
33
34
35
36
37
38 2 0 0 RETURN (num_value);
39 2 .00000402 .00000201 END julian_date;
40
41
42 0 .00000322 FUNCTION minutes_since_midnight (
43 timevalue DATE)
44 RETURN NUMBER
45 IS
46 secs_elapsed NUMBER (20);
47 mins_elapsed NUMBER (20);
48 BEGIN
49
50
51
52
53
54
55
56
57 2 .00026250 .00013125 SELECT TO_NUMBER
58 ( TO_CHAR(TO_DATE(TO_CHAR(timevalue,'HH:MI AM'),'HH:MI AM')
59 , 'SSSSS') )
60 INTO secs_elapsed
61 FROM dual;
62
63
64
65
66
67
68
69
70 2 .00011595 .00005797 SELECT (secs_elapsed / 60)
71 INTO mins_elapsed
72 FROM dual;
73
74
75
76
77 2 .00000080 .00000040 RETURN (mins_elapsed);
78 2 .00000402 .00000201 END minutes_since_midnight;
79
80
81 0 .00000241 FUNCTION minutes_elapsed
82 ( lowdate DATE
83 , highdate DATE )
84 RETURN NUMBER
85 IS
86 final_number NUMBER (20);
87 low_julian NUMBER (20);
88 high_julian NUMBER (20);
.
.
.
98
99
100
101
102
103
104
105
106
107
108 1 .00011353 .00011353 SELECT julian_date (lowdate)
109 INTO low_julian
110 FROM dual;
111
112 1 .00004750 .00004750 SELECT julian_date (highdate)
113 INTO high_julian
114 FROM dual;
115
116
117
118
119
120
121
122
123
124
125 1 .00006844 .00006844 SELECT (high_julian - low_julian)
126 INTO num_days
127 FROM dual;
128
129
130
131
132
133
134
135
136 1 .00006280 .00006280 SELECT (num_days * 1440)
137 INTO num_minutes
138 FROM dual;
139
140
141
142
143
144
145
146
147 1 .00029230 .00029230 SELECT minutes_since_midnight (lowdate)
148 INTO min_low
149 FROM dual;
150
151 1 .00007408 .00007408 SELECT minutes_since_midnight (highdate)
152 INTO min_high
153 FROM dual;
154
155
156
157
158
159
160
161 1 .00002576 .00002576 SELECT (min_high - min_low)
162 INTO temp_mins
163 FROM dual;
164
165
166
167
168
169 1 .00004428 .00004428 SELECT (num_minutes + temp_mins)
170 INTO final_number
171 FROM dual;
172
173 1 0 0 RETURN (final_number);
174
175 1 0 0 END minutes_elapsed;
176 END dates_pkg
Unit #3: . - Total time: .00 seconds
============================================================================
PL/SQL procedure successfully completed.
================== Profiler report - all runs rolled up ===================
Unit .:
Unit BING.DATES_PKG:
9 BEGIN
10
11
12
13
14
15
16
17
18
19 2 .00012803 .00006401 SELECT TO_CHAR
20 ( TO_DATE(TO_CHAR(date_to_convert,'MM/DD/YYYY'),'MM/DD/YYYY')
21 , 'J')
22 INTO varch_value
23 FROM dual;
24
25
26
27
28
29
30 2 .00008374 .00004187 SELECT TO_NUMBER (varch_value)
31 INTO num_value
32 FROM dual;
33
34
35
36
37
38 2 0 0 RETURN (num_value);
39 2 .00000402 .00000201 END julian_date;
40
41
42 0 .00000322 FUNCTION minutes_since_midnight (
43 timevalue DATE)
44 RETURN NUMBER
45 IS
46 secs_elapsed NUMBER (20);
47 mins_elapsed NUMBER (20);
48 BEGIN
49
50
51
52
53
54
55
56
57 2 .00026250 .00013125 SELECT TO_NUMBER
58 ( TO_CHAR(TO_DATE(TO_CHAR(timevalue,'HH:MI AM'),'HH:MI AM')
59 , 'SSSSS') )
60 INTO secs_elapsed
61 FROM dual;
62
63
64
65
66
67
68
69
70 2 .00011595 .00005797 SELECT (secs_elapsed / 60)
71 INTO mins_elapsed
72 FROM dual;
73
74
75
76
77 2 .00000080 .00000040 RETURN (mins_elapsed);
78 2 .00000402 .00000201 END minutes_since_midnight;
79
80
81 0 .00000241 FUNCTION minutes_elapsed
82 ( lowdate DATE
83 , highdate DATE )
84 RETURN NUMBER
85 IS
86 final_number NUMBER (20);
87 low_julian NUMBER (20);
88 high_julian NUMBER (20);
.
.
.
98
99
100
101
102
103
104
105
106
107
108 1 .00011353 .00011353 SELECT julian_date (lowdate)
109 INTO low_julian
110 FROM dual;
111
112 1 .00004750 .00004750 SELECT julian_date (highdate)
113 INTO high_julian
114 FROM dual;
115
116
117
118
119
120
121
122
123
124
125 1 .00006844 .00006844 SELECT (high_julian - low_julian)
126 INTO num_days
127 FROM dual;
128
129
130
131
132
133
134
135
136 1 .00006280 .00006280 SELECT (num_days * 1440)
137 INTO num_minutes
138 FROM dual;
139
140
141
142
143
144
145
146
147 1 .00029230 .00029230 SELECT minutes_since_midnight (lowdate)
148 INTO min_low
149 FROM dual;
150
151 1 .00007408 .00007408 SELECT minutes_since_midnight (highdate)
152 INTO min_high
153 FROM dual;
154
155
156
157
158
159
160
161 1 .00002576 .00002576 SELECT (min_high - min_low)
162 INTO temp_mins
163 FROM dual;
164
165
166
167
168
169 1 .00004428 .00004428 SELECT (num_minutes + temp_mins)
170 INTO final_number
171 FROM dual;
172
173 1 0 0 RETURN (final_number);
174
175 1 0 0 END minutes_elapsed;
176 END dates_pkg
============================================================================
PL/SQL procedure successfully completed.
Each ‘unit’ executed has its own section. These sections start with the line number of the the executed section, and include the number of executions of the code, the total time for all of the executions and the per-execution time. It’s the total time of execution that is reported in the first section of the report; the single execution time is what should be considered when evaluating the code for tuning, as decreasing that value decreases the total execution time. In this example there really aren’t any big ‘offenders’, but some of the code does run a bit longer than the native conversions provided by Oracle. [This example was posted online several years ago as an attempt to provide a different way of calculating date differences. When tested against the native functions these took much longer to complete and consumed more resources. So, the small times reported by the profiler are actually much larger than the times the native functions take to execute.]
With reports like this tuning PL/SQL packages, procedures and functions becomes much easier, as problem sections are easily spotted by the (possibly) exceptionally long overall execution times. It’s then a simple task of extracting the code, and performing the usual tuning steps such as check an execution plan, check table statistics, check for indexes, etc. Even though the execution plan might be slightly different when run within a PL/SQL context the ‘garden variety’ execution plan can be very helpful in spotting parts of the code that aren’t optimal.
Performance tuning requires information, and when there are tools designed to provide such information it’s wise to use them. Oracle provides the PL/SQL Profiler to analyze running PL/SQL objects and code, so they can be written to run better and faster, and use fewer resources. And making code run better, faster and use fewer resources is part of a DBA’s job.
Use the PL/SQL profiler; it will make performance tuning easier.
See all articles by David Fitzjarrell
