Oracle Scratchpad

November 28, 2014

Line Numbers

Filed under: Oracle,Performance,Troubleshooting — Jonathan Lewis @ 12:49 pm GMT Nov 28,2014

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.

rem
rem     Script:         source_test.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Nov 2014
rem

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.

Update (Nov 2019)

The example above is now too simple to demonstrate the issue; starting with 12.2.0.1 the error is reported at line 6 regardless of the value of the plsql_optimize_level. The problem is still present, however, but needs a more complex example to show it. (h/t to @SvenWeller for alerting me, and for supplying a suggestion for a newer demo).

I’m going to use “inlining” of a function – and the example I’ve got is so simple that I won’t need to use the pragma to force the function inline:


rem
rem     Script:         source_test_2.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Nov 2019
rem
rem     Last tested
rem             19.3.0.0
rem

alter session set plsql_optimize_level = 3;

create or replace procedure silly
as
        m_n number;

        function my_func(in_val in number) return number is
        begin
                return exp(sqrt(ln(in_val)));
        end;

begin
        for i in 1..1000000 loop
                m_n := my_func(-1);
        end loop;
end;
/

execute silly

alter session set plsql_optimize_level = 0;
alter procedure silly compile;
execute silly

column text format a60

select  line, text 
from    user_source
where   name = 'SILLY'
and     type = 'PROCEDURE'
order by
        line
;

And here’s the output (with a little cosmetic tidying) – the call to ln(-1) will automatically fail:


BEGIN silly; END;

*
ERROR at line 1:
ORA-06502: PL/SQL: numeric or value error
ORA-06512: at "TEST_USER.SILLY", line 11
ORA-06512: at line 1


BEGIN silly; END;

*
ERROR at line 1:
ORA-06502: PL/SQL: numeric or value error
ORA-06512: at "TEST_USER.SILLY", line 7
ORA-06512: at "TEST_USER.SILLY", line 12
ORA-06512: at line 1


      LINE TEXT
---------- -------------------------------------------------------------
         1 procedure silly
         2 as
         3      m_n number;
         4
         5      function my_func(in_val in number) retu rn number is
         6      begin
         7              return exp(sqrt(ln(in_val)));
         8      end;
         9
        10 begin
        11      for i in 1..1000000 loop
        12              m_n := my_func(-1);
        13      end loop;
        14 end;

The listing from user_source shows us that the call to the function is at line 12, but the call to ln(-1) will take place at line 7.

When we set the plsql_optimize_level to 3 the plsql optimizer copies the function inline, which somehow makes the ln() call take place at line 11.

When the plsql_optimize_level is zero the error appears in the “expected” lines – first at line 7 where the ln(-1) takes place, then echoing back to line 12 where the call to the function took place.

 

Leave a Comment »

No comments yet.

RSS feed for comments on this post. TrackBack URI

Comments and related questions are welcome.

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Powered by WordPress.com.