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 0.00 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 slightly 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 compiler copies the function inline, which somehow makes the ln() call take place at line 11, perhaps because a copy of the function is left in place but the “return line” is first copied to line 12 and then lines 12 and 11 are swapped because the compiler recognises the constant assigment.

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.

 

1 Comment »

  1. […] 10g Oracle introduced the plsql_optimize_level to affect the way in which the pl/sql optimizer was allowed to manipulate your code. The default […]

    Pingback by Quiz Night | Oracle Scratchpad — September 6, 2021 @ 1:27 pm BST Sep 6,2021 | Reply


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 )

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.

Website Powered by WordPress.com.

%d bloggers like this: