Oracle Performance and Engineering

After yesterday's post where I said that Oracle10g PL/SQL compiler 'understands' if an expression will remain constant within a LOOP and does NOT execute it once per iteration of the loop.

I also used the following code piece on 9i and 10g -

declare
a number := 10;
b number := 23892;
c number := 42784782;
d number;
e number;
begin
dbms_profiler.start_profiler;
for i in 1 .. 1000000 loop
d := a * b * c;
e := (d * 1001);
end loop;
dbms_profiler.stop_profiler;
end;

On 9i it took 5.01 seconds (today, on 1st execution)
On 10g it took 1.69 seconds (today, on 1st execution)

I received an email asking me how did I derive that 10g does not evaluate the constant expression once per loop. It could as well be the 'natural optimization' of 10g compiler.

Thanks for asking. And sorry for not have given more supporting document. It was a great question to ask. Really.

As you could see this time I've included DBMS_PROFILER in the code to see how many times each line is actually executed for 1 million iteration of the loop. After both the executions I ran Oracle-supplied proftab.sql (an excellent formatting tool for PL/SQL profiling data - formats the report in HTML) against each run.

This is what I found -

on 9i -

Profiled Run 21 (plsql_profiler_runs)

Run	Date	Total Time1	Comment
21	03-MAY-05 18:01:01	4.64	03-MAY-05

Note 1: Total Time is in seconds

Profiled PL/SQL Libraries (plsql_profiler_units)

Unit	Owner	Name	Type	Timestamp	Total Time1	Text Header
1			ANONYMOUS BLOCK		3.57

Note 1: Total Time is in seconds

Top 10 profiled source lines in terms of Total Time (plsql_profiler_data)

Top	Total Time1	Times Executed	Min Time2	Max Time2	Unit	Owner	Name	Type	Line	Text
1	1.44	1000000	0.00	0.00	1			ANONYMOUS BLOCK	11
2	1.28	1000000	0.00	0.00	1			ANONYMOUS BLOCK	10
3	0.86	1000001	0.00	0.00	1			ANONYMOUS BLOCK	9

Note 1: Total Time is in seconds



on 10g -

Profiled Run 50 (plsql_profiler_runs)

Run	Date	Total Time1	Comment
50	03-MAY-05 17:59:40	1.51	03-MAY-05

Note 1: Total Time is in seconds

Profiled PL/SQL Libraries (plsql_profiler_units)

Unit	Owner	Name	Type	Timestamp	Total Time1	Text Header
1			ANONYMOUS BLOCK		0.74

Note 1: Total Time is in seconds

Top 10 profiled source lines in terms of Total Time (plsql_profiler_data)

Top	Total Time1	Times Executed	Min Time2	Max Time2	Unit	Owner	Name	Type	Line	Text
1	0.74	1000000	0.00	0.00	1			ANONYMOUS BLOCK	9

Note 1: Total Time is in seconds
Note 2: Min and Max Time for one execution of this line (in seconds)


We see, three lines - line # 9, 10 and 11 - were executed 1 million times with 9i. Whereas, *only* one line - line #9 - is executed 1 million times with 10g!

So what's on line# 10 and #11?


for i in 1 .. 1000000 loop --## line 9
d := a * b * c; --## line 10 - not in the LOOP with 10g but iterated on 9i
e := (d * 1001); --## line 11 - not in the LOOP with 10g but iterated on 9i

Since expressions in line#10 and line#11 do NOT change with iterations - Oracle actually does not evaluate it every time with the loop. Oracle 'understands' d and e above are "constants" and takes it out of the loop.

Isn't it cool?

BTW, if you're tuning PL/SQL program units, DBMS_PROFILER is the coolest profiling tool. Just 'start' and 'stop' profiling it across your program as shown above. Download the cool proftab.sql utility from Oracle metalink. Run the proftab.sql and get a HTML formatted report which will show you how much time the total program unit took, how much time each line took cumulatively, which were the most expensive lines, which lines were executed most etc. In other words, you know your bottlenecks and it's HTML!