Tuesday, January 24, 2017

Confused by your error backtrace? Check the optimization level!

The DBMS_UTILITY.FORMAT_ERROR_BACKTRACE (and similar functionality in the UTL_CALL_STACK package) is a tremendously helpful function. It returns a formatted string that allows you to easily trace back to the line number on which an exception was raised.

You know what else is really helpful? The automatic optimization performed by the PL/SQL compiler. The default level is 2, which does an awful lot of optimizing for you. But if you want to get the most out of the optimizer, you can ratchet it up to level 3, which then added subprogram inlining.

Unfortunately, these two wonderful features don't mix all that well. Specifically, if you optimize at level 3, then the backtrace may not point all the way back to the line number in your "original" source code (without inlining, of course).

Run this LiveSQL script to see the following code below "in action."

ALTER SESSION SET plsql_optimize_level = 2
/

CREATE OR REPLACE PROCEDURE proc1
IS
   l_level   INTEGER;

   PROCEDURE inline_proc1
   IS
   BEGIN
      RAISE PROGRAM_ERROR;
   EXCEPTION
      WHEN OTHERS
      THEN
         DBMS_OUTPUT.put_line ('inline_proc1 handler');

         DBMS_OUTPUT.put_line (DBMS_UTILITY.format_error_backtrace);
         RAISE;
   END;
BEGIN
   SELECT plsql_optimize_level
     INTO l_level
     FROM user_plsql_object_settings
    WHERE name = 'PROC1';

   DBMS_OUTPUT.put_line ('Opt level = ' || l_level);

   inline_proc1;
EXCEPTION
   WHEN OTHERS
   THEN
      DBMS_OUTPUT.put_line ('inline handler');

      DBMS_OUTPUT.put_line (DBMS_UTILITY.format_error_backtrace);
      RAISE;
END;
/

BEGIN
   proc1;
END;
/

ALTER SESSION SET plsql_optimize_level = 3
/

ALTER PROCEDURE proc1
COMPILE
/

BEGIN
   proc1;
END;
/

Opt level = 2
inline_proc1 handler
ORA-06512: at "STEVEN.PROC1", line 8

inline handler
ORA-06512: at "STEVEN.PROC1", line 15
ORA-06512: at "STEVEN.PROC1", line 8
ORA-06512: at "STEVEN.PROC1", line 25


Opt level = 3
inline_proc1 handler
ORA-06512: at "STEVEN.PROC1", line 25

inline handler
ORA-06512: at "STEVEN.PROC1", line 25
ORA-06512: at "STEVEN.PROC1", line 25

I hope to have an update from the PL/SQL dev team on this topic soon, but I wanted to make you aware of this in case you get all confused and frustrated.

Check your optimization level! Oh, how do you do that? Here you go:

SELECT p.plsql_optimize_level
  FROM user_plsql_object_settings p
 WHERE name = 'PROC1'
/

3 comments:

  1. Hello Steven,

    It looks to me that even for PLSQL_OPTIMIZE_LEVEL = 2 the output that we see is not exactly as it was supposed to be
    by definition.

    As far as I know the "line 8" was only supposed to be "remembered" by the backtrace value displayed
    in the handler of "inline_proc1", and "forgotten" after re-raising the exception.

    However, we see "line 8" twice in the output.

    Wasn't the output supposed to be as follows ?

    Opt level = 2
    inline_proc1 handler
    ORA-06512: at "STEVEN.PROC1", line 8

    inline handler
    ORA-06512: at "STEVEN.PROC1", line 15
    ORA-06512: at "STEVEN.PROC1", line 25



    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete
    Replies
    1. Huh. Interesting. I am not certain of all the details of how backtrace constructs its stack. I generally focus like a laser on the very top: the line number on which the current exception was raised.

      I can see an argument for including line 8, in the sense that the error stack did "go through" that line. But I do not know if that is an accurate explanation.

      Delete
  2. Hello Steven,

    Just out of curiosity, I performed some tests to compare the
    output of DBMS_UTILITY.FORMAT_ERROR_BACKTRACE with that of
    the UTL_CALL_STACK backtrace functions, and their results
    are the same.

    But, surprisingly enough, the output of DBMS_UTILITY.FORMAT_ERROR_BACKTRACE in 12c contains more lines than its value in 11gR2.

    Specifically, in 12c it shows BOTH the line where the original exception was raised AND the line where it was re-raised,
    so, the same unit name may appear twice in the backtrace output.

    Similarly, the DBMS_UTILITY.FORMAT_ERROR_STACK also contains more lines than its 11gR2 counterpart, looks like in 12c it "repeats" part of the DBMS_UTILITY.FORMAT_ERROR_BACKTRACE info.


    At least, this is the behavior I experienced when testing with
    LiveSQL.

    So, when using a new version, one should not only learn new things,
    but also forget things already considered as known ...

    Anyway, it could be interesting to know whether the changed
    content of the DBMS_UTILITY error functions for 12c
    was deliberate or not.

    Below is the test code I used, if anybody is interested.

    One thing to be mentioned is that trying to call UTL_CALL_STACK.backtrace_unit from an anonymous block
    raises error "ORA-64610: bad depth indicator", so that is why I added the last procedure named test_plch_proc3.


    CREATE OR REPLACE PROCEDURE show_backtrace
    AS
    BEGIN
    DBMS_OUTPUT.put_line('--------------------------');
    DBMS_OUTPUT.put_line('backtrace - depth='||UTL_CALL_STACK.backtrace_depth);
    DBMS_OUTPUT.put_line('--------------------------');

    FOR i IN 1 .. UTL_CALL_STACK.backtrace_depth
    LOOP
    DBMS_OUTPUT.put_line('BACKTRACE_DEPTH=['||i||'] --> '||
    'UNIT=' ||UTL_CALL_STACK.backtrace_unit(i)||
    ' -- LINE='||UTL_CALL_STACK.backtrace_line(i) );
    END LOOP;
    END;
    /

    CREATE OR REPLACE PROCEDURE plch_proc1
    IS
    BEGIN
    RAISE NO_DATA_FOUND;
    END plch_proc1;
    /


    CREATE OR REPLACE PROCEDURE plch_proc2
    IS
    BEGIN
    plch_proc1;
    EXCEPTION
    WHEN OTHERS
    THEN
    RAISE VALUE_ERROR;
    END plch_proc2;
    /

    CREATE OR REPLACE PROCEDURE plch_proc3
    IS
    BEGIN
    plch_proc2;
    EXCEPTION
    WHEN OTHERS
    THEN
    DBMS_OUTPUT.put_line('----- BEFORE RAISE; -----');
    DBMS_OUTPUT.put_line('----- ERROR -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_stack);
    DBMS_OUTPUT.put_line('----- BACKTRACE -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_backtrace);
    -- 12c
    DBMS_OUTPUT.put_line('----- UTL BACKTRACE -----');
    show_backtrace;

    RAISE;
    END plch_proc3;
    /


    CREATE OR REPLACE PROCEDURE test_plch_proc3
    AS
    BEGIN
    plch_proc3;
    EXCEPTION
    WHEN OTHERS
    THEN
    DBMS_OUTPUT.put_line('----- AFTER RAISE; -----');
    DBMS_OUTPUT.put_line('----- ERROR -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_stack);
    DBMS_OUTPUT.put_line('----- BACKTRACE -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_backtrace);
    -- 12c
    DBMS_OUTPUT.put_line('----- UTL BACKTRACE -----');
    show_backtrace;
    END;
    /


    BEGIN
    test_plch_proc3;
    END;
    /


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete