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 -- First, we take a date and convert it to a date by converting it
12 -- to a character string using the same format we will use to
13 -- convert it BACK to a date again
14 --
15 -- Oh, then we convert it back to a character string
16 --
17 -- In Julian format, which is a number
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 -- Okay, so we had a Julian date as a number but we changed it to
27 -- a character string so we could go back and make it a ...
28 -- NUMBER ... again
29 --
30 2 .00008374 .00004187 SELECT TO_NUMBER (varch_value)
31 INTO num_value
32 FROM dual;
33
34 --
35 -- So, we finally make up our mind and keep it a number and
36 -- return it from the function
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 -- So now we take a date and extract the time portion of it,
51 -- convert that BACK to a date, then convert THAT to a string
52 -- of seconds and convert THAT to a number
53 --
54 -- Is it me, or are we essentially driving across town just to
55 -- go next door?
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 -- Oooo, now we divide that total number of seconds by ...
65 -- wait for it ...
66 -- any second now ...
67 -- 60! Who would have thought that 60 seconds equals
68 -- one minute?
69 --
70 2 .00011595 .00005797 SELECT (secs_elapsed / 60)
71 INTO mins_elapsed
72 FROM dual;
73
74 --
75 -- Before we rest on our laurels we return the minutes since midnight
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 -- Oh, yeah, because we just WROTE that wonderful function
100 --
101 -- So, okay, we take our date values and return the Julian
102 -- representations of them using all of the mathematical
103 -- aerobics from earlier
104 --
105 -- I guess this is so much easier than simply subtracting
106 -- them
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 -- Woo-hoo! Higher math time! Subtract the Julian dates
118 -- and get the number of days
119 --
120 -- Isn't that what we'd get if we just subtracted the
121 -- submitted dates as-is?
122 --
123 -- Of course it is
124 --
125 1 .00006844 .00006844 SELECT (high_julian - low_julian)
126 INTO num_days
127 FROM dual;
128
129 --
130 -- Now we calculate the total minutes elapsed
131 -- using our values generated by our extreme
132 -- gyrations
133 --
134 -- I'm out of breath just thinking about all of this work
135 --
136 1 .00006280 .00006280 SELECT (num_days * 1440)
137 INTO num_minutes
138 FROM dual;
139
140 --
141 -- And now we put those other mathematical moves
142 -- to use
143 --
144 -- Tell me again why we think we're smarter than
145 -- the average bear?
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 -- Now this is disgusting
157 --
158 -- Using a TEMP variable to aid in simple mathematical
159 -- processing
160 --
161 1 .00002576 .00002576 SELECT (min_high - min_low)
162 INTO temp_mins
163 FROM dual;
164
165 --
166 -- And this is better than:
167 -- select (end_date - start_date)*1440 because?
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 -- First, we take a date and convert it to a date by converting it
12 -- to a character string using the same format we will use to
13 -- convert it BACK to a date again
14 --
15 -- Oh, then we convert it back to a character string
16 --
17 -- In Julian format, which is a number
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 -- Okay, so we had a Julian date as a number but we changed it to
27 -- a character string so we could go back and make it a ...
28 -- NUMBER ... again
29 --
30 2 .00008374 .00004187 SELECT TO_NUMBER (varch_value)
31 INTO num_value
32 FROM dual;
33
34 --
35 -- So, we finally make up our mind and keep it a number and
36 -- return it from the function
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 -- So now we take a date and extract the time portion of it,
51 -- convert that BACK to a date, then convert THAT to a string
52 -- of seconds and convert THAT to a number
53 --
54 -- Is it me, or are we essentially driving across town just to
55 -- go next door?
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 -- Oooo, now we divide that total number of seconds by ...
65 -- wait for it ...
66 -- any second now ...
67 -- 60! Who would have thought that 60 seconds equals
68 -- one minute?
69 --
70 2 .00011595 .00005797 SELECT (secs_elapsed / 60)
71 INTO mins_elapsed
72 FROM dual;
73
74 --
75 -- Before we rest on our laurels we return the minutes since midnight
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 -- Oh, yeah, because we just WROTE that wonderful function
100 --
101 -- So, okay, we take our date values and return the Julian
102 -- representations of them using all of the mathematical
103 -- aerobics from earlier
104 --
105 -- I guess this is so much easier than simply subtracting
106 -- them
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 -- Woo-hoo! Higher math time! Subtract the Julian dates
118 -- and get the number of days
119 --
120 -- Isn't that what we'd get if we just subtracted the
121 -- submitted dates as-is?
122 --
123 -- Of course it is
124 --
125 1 .00006844 .00006844 SELECT (high_julian - low_julian)
126 INTO num_days
127 FROM dual;
128
129 --
130 -- Now we calculate the total minutes elapsed
131 -- using our values generated by our extreme
132 -- gyrations
133 --
134 -- I'm out of breath just thinking about all of this work
135 --
136 1 .00006280 .00006280 SELECT (num_days * 1440)
137 INTO num_minutes
138 FROM dual;
139
140 --
141 -- And now we put those other mathematical moves
142 -- to use
143 --
144 -- Tell me again why we think we're smarter than
145 -- the average bear?
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 -- Now this is disgusting
157 --
158 -- Using a TEMP variable to aid in simple mathematical
159 -- processing
160 --
161 1 .00002576 .00002576 SELECT (min_high - min_low)
162 INTO temp_mins
163 FROM dual;
164
165 --
166 -- And this is better than:
167 -- select (end_date - start_date)*1440 because?
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.
