One of the presentations I went to at the DOAG conference earlier on this month was called “PL/SQL Tuning, finding the perf. bottleneck with hierarchical profiler” by Radu Parvu from Finland. If you do a lot of PL/SQL programming and haven’t noticed the dbms_hprof package yet make sure you take a good look at it.
A peripheral question that came up at the end of the session asked about problems with line numbers in pl/sql procedures; why, when you get a run-time error, does the reported line number sometimes look wrong, and how do you find the right line. I can answer (or give at least one reason for) the first part, but not the second part; Julian Dontcheff had an answer for the second bit, but unfortunately I failed to take a note of it.
Here’s the SQL to create, run and list a very simple (and silly) procedure.
define m_value = 3 set timing on create or replace procedure silly as m_n number; begin for i in 1..1000000 loop m_n := exp(sqrt(ln(&m_value))); end loop; end; / execute silly list
Here’s the output I got from running this, and the thing I want you to note is the time it takes to run, and the line number reported for the assignment:
Procedure created. Elapsed: 00:00:00.01 PL/SQL procedure successfully completed. Elapsed: 00:00:00.00 1 create or replace procedure silly 2 as 3 m_n number; 4 begin 5 for i in 1..1000000 loop 6 m_n := exp(sqrt(ln(&m_value))); 7 end loop; 8* end;
It seems to take my instance o.oo seconds to perform 1,000,000 evaluations of the exponent of the square root of the natural logarithm of 3 at line 6 of the code. But let’s make two changes; first, let’s try that with the value -1 (which is a little careless if you know your logarithms).
Procedure created. Elapsed: 00:00:00.02 BEGIN silly; END; * ERROR at line 1: ORA-06502: PL/SQL: numeric or value error ORA-06512: at "TEST_USER.SILLY", line 5 ORA-06512: at line 1
Notice that the 6502 error is reported at line 5, not line 6.
Now let’s go back to the value 3, but start the script with the command: alter session set plsql_optimize_level = 0; (the default level is 2, the range is 0 to 3):
Session altered. Elapsed: 00:00:00.00 Procedure created. Elapsed: 00:00:00.01 BEGIN silly; END; * ERROR at line 1: ORA-06502: PL/SQL: numeric or value error ORA-06512: at "TEST_USER.SILLY", line 6 ORA-06512: at line 1
Reducing the pl/sql optimisation level to zero (or one) results in the the error message reporting the problem at line 6 – which matches our original code. So let’s check the effect of running the code at level zero with a valid number for the input.
Session altered. Elapsed: 00:00:00.00 Procedure created. Elapsed: 00:00:00.02 PL/SQL procedure successfully completed. Elapsed: 00:00:24.56
The run time for our pl/sql call has gone up from 0.00 seconds to 24.56 seconds.
Like all good compilers the pl/sql compiler had recognised (at level 2) that we were assigning a constant inside a loop, so it had (effectively) rewritten our code to move the assignment outside the loop, effectively swapping lines 6 and 5, storing the change in the “object” level code, but not in the database copy of the source. The benefit we get (from the default settings) is a saving of 25 seconds of CPU, the (small) penalty we pay is that the lines reported for run-time errors aren’t always going to identify the text that caused the problem.