Skip to main content

Error stack function now (12.2) includes backtrace information!

The DBMS_UTILITY has long (since 10.2) offered three functions that are very handy when either tracing execution or logging errors:
  • FORMAT_CALL_STACK - answering the question "How did I get here?"
  • FORMAT_ERROR_STACK - answering the question "What was the error?" (or a stack of errors, depending on the situation)
  • FORMAT_ERROR_BACKTRACE - answering the question "On what line was my error raised?"
Therefore (and prior to 12.2), if you wanted to get the error information + the line number on which the error was raised, you would need to call both of the "*ERROR*" as in:

CREATE OR REPLACE PROCEDURE p3
   AUTHID DEFINER
IS
BEGIN
   p2;
EXCEPTION
   WHEN OTHERS
   THEN
      DBMS_OUTPUT.put_line (DBMS_UTILITY.format_error_stack);
      DBMS_OUTPUT.put_line (DBMS_UTILITY.format_error_backtrace);
      RAISE;
END;

Of course, in the real world, you would not display the text on the screen. You would write them to a log table via an autonomous transaction procedure, as I show in this simple error logging package.

When I run the above procedure on a version of Oracle Database through 12.1, I might see output like this: 

ORA-06501: PL/SQL: program error

ORA-06512: at "STEVEN.P1", line 4
ORA-06512: at "STEVEN.PKG", line 6
ORA-06512: at "STEVEN.P2", line 5
ORA-06512: at "STEVEN.P3", line 5

In other words: the error stack shows just the error message, and the backtrace shows just the backtrace.

But as of 12.2, the error stack function has been enhanced to also include backtrace information (more details available in this My Oracle Support note). So the output run on 12.2, 18.1 or higher shows: 

ORA-06501: PL/SQL: program error
ORA-06512: at "STEVEN.P1", line 4
ORA-06512: at "STEVEN.PKG", line 6
ORA-06512: at "STEVEN.P2", line 5

ORA-06512: at "STEVEN.P1", line 4
ORA-06512: at "STEVEN.PKG", line 6
ORA-06512: at "STEVEN.P2", line 5
ORA-06512: at "STEVEN.P3", line 5

Nice stuff!

Labels:

Comments

  1. iudithApril 28, 2018 at 6:45 AM

    Hello Steven,

    I have observed this weird behavior on LiveSQL, and, if I remember it correctly, this was the behavior on LiveSQL still before migrating to 12.2.

    Since this is still the only environment that I can access, I sent you a small sample
    for testing this in a different (or "normal") environment.

    Also, unfortunately, the support documents are only accessible for customers who have a paid license for Oracle support :(

    So, it would be great if you could post the content of that support document on this blog,
    ( or, maybe elsewhere on Devgym, as a resource ), for allowing also "the poor" ones to see it.

    Without this post, and even in spite of it, I am still not sure that this new "behavior" is indeed an intended one, and not a bug or side-effect of some other software change.

    I would also underline that the sample presented in the 18c documentation for DBMS_UTILITY.FORMAT_ERROR_BACKTRACE is still the same as in the older versions, and, in light of the change you specified in this post, its presented output might be wrong.

    I am not sure that making such a deliberate change is definitely a right decision, since it might break existing logic of applications that use these functions for their error logging.


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete
    Replies
    1. Steven FeuersteinApril 28, 2018 at 8:44 AM

      Iudith,

      Here is the key text from the MOS note (the code examples reflect what I show above). It is an enhancement not a bug or side effect.

      The exception handling behavior of the function DBMS_UTILITY.FORMAT_ERROR_STACK has been changed in 12.2. The PL/SQL error back trace is now enhanced to add an ORA-6512 whenever an exception handler or a PL/SQL unit is left looking for a handler unlike it's behavior in the previous releases. The ORA-6512 are cleared only when their corresponding exception is cleared, thus preserving the back trace on re-raise and for multiple exceptions.

      I will notify the doc team about the need to upgrade the description of the format error stack function (backtrace is not affected).

      I suppose it is possible that this change will affect applications, but it seems like a very small probability. Can you think of "existing logic" that someone might write that would then be broken by this change?

      Delete
  2. iudithApril 30, 2018 at 12:27 PM

    Hello Steven,

    Here is an example of what happens when two exceptions are put successively on the stack:

    CREATE OR REPLACE PROCEDURE plch_proc1
    IS
    BEGIN
    RAISE NO_DATA_FOUND; --> initial exception
    END plch_proc1;
    /

    -- Procedure created.


    CREATE OR REPLACE PROCEDURE plch_proc2
    IS
    BEGIN
    plch_proc1;
    EXCEPTION
    WHEN OTHERS
    THEN
    RAISE VALUE_ERROR; --> raise a different exception
    END plch_proc2;
    /

    -- Procedure created.


    CREATE OR REPLACE PROCEDURE plch_proc3
    IS
    BEGIN
    plch_proc2;
    /*RERAISE*/
    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);

    RAISE; --> reraise same exception
    END plch_proc3;
    /

    -- Procedure created.


    -- the test
    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);
    END;
    /

    ----- BEFORE RAISE; -----
    ----- ERROR -----
    ORA-06502: PL/SQL: numeric or value error
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-01403: no data found
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4

    ----- BACKTRACE -----
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 4

    ----- AFTER RAISE; -----
    ----- ERROR -----
    ORA-06502: PL/SQL: numeric or value error
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 15
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-01403: no data found
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 4

    ----- BACKTRACE -----
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 15
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 4
    ORA-06512: at line 2

    ( will be continued, because if size limitation ... )

    ReplyDelete
  3. iudithApril 30, 2018 at 12:28 PM

    ( continued ... )

    From here, it looks like not only the FORMAT_ERROR_STACK was changed by having the ORA-06512 lines added, but the FORMAT_ERROR_BACKTRACE also has some duplicate lines ...

    In my opinion, this output is very unreadable.

    Regardless of any exceptions that were raised, each procedure was called only once.

    However, the FORMAT_ERROR_STACK shows PLCH_PROC2 twice (in each of BEFORE/AFTER RAISE sections), and also PLCH_PROC3 twice in the AFTER RAISE sections.

    The same duplicates also appear in FORMAT_ERROR_BACKTRACE.

    As by my understanding, the meaning of "preserving the back trace on re-raise and for multiple exceptions" in the MOS document was supposed to be that the FORMAT_ERROR_BACKTRACE does not "stop" on the closest RAISE statement when looking backwards, but instead it goes all the way up to the line where the original exception was raised.

    In our case, this would mean that not only PLCH_PROC3 will appear in the backtrace, but also PLCH_PROC2 and PLCH_PROC1, but each of them should still appear once only.

    Or, in case that the same procedure does appears twice because once it is considered a caller of another procedure (like PLCH_PROC2 calling PLCH_PROC1) and a second time because of a RAISE statement that it executes explicitly (like PLCH_PROC2 raising VALUE_ERROR),
    then these two occurrences should better be adjacent in the output.


    Also, the sentence "The PL/SQL error back trace is now enhanced to add an ORA-6512 whenever an exception handler or a PL/SQL unit is left looking for a handler" sounds a little unclear about what exactly will be added to FORMAT_ERROR_STACK.

    The first impression might be that, if we examine both these functions at the same point in the code, then FORMAT_ERROR_STACK will in fact contain all the information in FORMAT_ERROR_BACKTRACE, in addition to the errors themselves.

    And, in the example above, this is indeed so for the AFTER RAISE section, but not for the BEFORE RAISE section, where backtrace does have an additional line for PLCH_PROC3.

    From the information shown above, with all the duplicates, and without "knowing" the code,
    I find it quite difficult to deduct the exact order and place where the exceptions were raised.


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete
    Replies
    1. AnonymousMay 8, 2018 at 4:34 AM

      I agree with Iudith.
      >From the information shown above, with all the duplicates, and without "knowing" the code,
      >I find it quite difficult to deduct the exact order and place where the exceptions were raised.

      The problem is even worse. it seems to me that the ORA-06512 is added in different positions in the backtrace stack (and therefor also in the error stack), depending on whether added by a RAISE in the when others section, or if there was no exception handler.

      Delete
    2. Steven FeuersteinMay 8, 2018 at 4:36 AM

      Issues like these get the most attention when our customers submit SRs that include descriptions of how the problem adversely affects their applications. If one of you could do this, and include the examples shown above, that would be fantastic!

      Delete
    3. AnonymousMay 17, 2018 at 3:48 AM

      I plan to do that. But since I know how tedious it is to raise an SR, it will probably be after Kscope18 until I find time to do it.

      Delete
    4. Steven FeuersteinMay 17, 2018 at 3:49 AM

      Thanks and....sigh.....ah, to be able to right all the wrongs in the world!

      Delete
  4. iudithMay 8, 2018 at 7:49 AM

    Hello All,

    I am very content that Sven does agree with me :)

    Maybe saying that such a change does "adversely affect" an application would mean "
    going too far", because these functions are more targeted to the use of developers,
    rather than to that of application users.

    Steven, as I know you, you always did afford a much heavier importance to the use of an organized and consistent way of handling errors ... surely a much heavier one than I ever did.

    Unfortunately, now I am only a "private customer" ... so I cannot perform such "privileged"
    actions like opening SR's and other similar :(

    Anyway, I guess that this "enhancement" introduced in 12.2 is a result of some other request,
    or maybe some complaint about FORMAT_ERROR_STACK not containing "enough information" ...
    so it would be nice to hear (from inside) where does this change originate from.

    The only thing that I myself would have thought to add would be the "extension" of the
    FORMAT_ERROR_BACKTRACE to continue past the closest RAISE statement,
    and still leaving the FORMAT_ERROR_STACK as it was.


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete
  5. AnonymousJanuary 11, 2019 at 7:37 AM

    I think this change is just great. It's still possible to get error message, error code separately to show it nicely and you need less code lines to get a proper log.

    I also think, that if debug information change/add is a such a disaster for an application, then this application's usability is dubious.

    ReplyDelete

Post a Comment

Popular posts from this blog

Running out of PGA memory with MULTISET ops? Watch out for DISTINCT!

A PL/SQL team inside Oracle made excellent use of nested tables and MULTISET operators in SQL, blending data in tables with procedurally-generated datasets (nested tables).  All was going well when they hit the dreaded: ORA-04030: out of process memory when trying to allocate 2032 bytes  They asked for my help.  The error occurred on this SELECT: SELECT  *    FROM header_tab trx    WHERE (generated_ntab1 SUBMULTISET OF trx.column_ntab)       AND ((trx.column_ntab MULTISET             EXCEPT DISTINCT generated_ntab2) IS EMPTY) The problem is clearly related to the use of those nested tables. Now, there was clearly sufficient PGA for the nested tables themselves. So the problem was in executing the MULTISET-related functionality. We talked for a bit about dropping the use of nested tables and instead doing everything in SQL, to avoid the PGA error. That would, however require lots of wo...
4 comments
Read more

How to Pick the Limit for BULK COLLECT

This question rolled into my In Box today: In the case of using the LIMIT clause of BULK COLLECT, how do we decide what value to use for the limit? First I give the quick answer, then I provide support for that answer Quick Answer Start with 100. That's the default (and only) setting for cursor FOR loop optimizations. It offers a sweet spot of improved performance over row-by-row and not-too-much PGA memory consumption. Test to see if that's fast enough (likely will be for many cases). If not, try higher values until you reach the performance level you need - and you are not consuming too much PGA memory.  Don't hard-code the limit value: make it a parameter to your subprogram or a constant in a package specification. Don't put anything in the collection you don't need. [from Giulio Dottorini] Remember: each session that runs this code will use that amount of memory. Background When you use BULK COLLECT, you retrieve more than row with each fetch, ...
4 comments
Read more

PL/SQL 101: Three ways to get error message/stack in PL/SQL

The PL/SQL Challenge quiz for 10 September - 16 September 2016 explored the different ways you can obtain the error message / stack in PL/SQL. Note: an error stack is a sequence of multiple error messages that can occur when an exception is propagated and re-raised through several layers of nested blocks. The three ways are: SQLERRM - The original, traditional and (oddly enough) not currently recommended function to get the current error message. Not recommended because the next two options avoid a problem which you are unlikely  to run into: the error stack will be truncated at 512 bytes, and you might lose some error information. DBMS_UTILITY.FORMAT_ERROR_STACK - Returns the error message / stack, and will not truncate your string like SQLERRM will. UTL_CALL_STACK API - Added in Oracle Database 12c, the UTL_CALL_STACK package offers a comprehensive API into the execution call stack, the error stack and the error backtrace.  Note: check out this LiveSQL script if...
5 comments
Read more