Friday, June 28, 2013

12c - Utl_Call_Stack...

Over the next couple of months, I'll be writing about some cool new little features of Oracle Database 12c - things that might not make the front page of  I'm going to start with a new package - UTL_CALL_STACK.

In the past, developers have had access to three functions to try to figure out "where the heck am I in my code", they were:

Now these routines, while useful, were of somewhat limited use.  Let's look at the format_call_stack routine for a reason why.  Here is a procedure that will just print out the current call stack for us:

ops$tkyte%ORA12CR1> create or replace
  2  procedure Print_Call_Stack
  3  is
  4  begin
  5    DBMS_Output.Put_Line(DBMS_Utility.Format_Call_Stack());
  6  end;
  7  /
Procedure created.

Now, if we have a package - with nested functions and even duplicated function names:

ops$tkyte%ORA12CR1> create or replace
  2  package body Pkg is
  3    procedure p
  4    is
  5      procedure q
  6      is
  7        procedure r
  8        is
  9          procedure p is
 10          begin
 11            Print_Call_Stack();
 12            raise program_error;
 13          end p;
 14        begin
 15          p();
 16        end r;
 17      begin
 18        r();
 19      end q;
 20    begin
 21      q();
 22    end p;
 23  end Pkg;
 24  /

Package body created.

When we execute the procedure PKG.P - we'll see as a result:

ops$tkyte%ORA12CR1> exec pkg.p
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x6e891528         4  procedure OPS$TKYTE.PRINT_CALL_STACK
0x6ec4a7c0        10  package body OPS$TKYTE.PKG
0x6ec4a7c0        14  package body OPS$TKYTE.PKG
0x6ec4a7c0        17  package body OPS$TKYTE.PKG
0x6ec4a7c0        20  package body OPS$TKYTE.PKG
0x76439070         1  anonymous block

BEGIN pkg.p; END;

ERROR at line 1:
ORA-06501: PL/SQL: program error
ORA-06512: at "OPS$TKYTE.PKG", line 11
ORA-06512: at "OPS$TKYTE.PKG", line 14
ORA-06512: at "OPS$TKYTE.PKG", line 17
ORA-06512: at "OPS$TKYTE.PKG", line 20
ORA-06512: at line 1

The bit in red above is the output from format_call_stack whereas the bit in black is the error message returned to the client application (it would also be available to you via the format_error_backtrace API call). As you can see - it contains useful information but to use it you would need to parse it - and that can be trickier than it seems.  The format of those strings is not set in stone, they have changed over the years (I wrote the "who_am_i", "who_called_me" functions, I did that by parsing these strings - trust me, they change over time!).

Starting in 12c - we'll have structured access to the call stack and a series of API calls to interrogate this structure.  I'm going to rewrite the print_call_stack function as follows:

ops$tkyte%ORA12CR1> create or replace
 2  procedure Print_Call_Stack
  3  as
  4    Depth pls_integer := UTL_Call_Stack.Dynamic_Depth();
  6    procedure headers
  7    is
  8    begin
  9        dbms_output.put_line( 'Lexical   Depth   Line    Name' );
 10        dbms_output.put_line( 'Depth             Number      ' );
 11        dbms_output.put_line( '-------   -----   ----    ----' );
 12    end headers;
 13    procedure print
 14    is
 15    begin
 16        headers;
 17        for j in reverse 1..Depth loop
 18          DBMS_Output.Put_Line(
 19            rpad( utl_call_stack.lexical_depth(j), 10 ) ||
 20                    rpad( j, 7) ||
 21            rpad( To_Char(UTL_Call_Stack.Unit_Line(j), '99'), 9 ) ||
 22            UTL_Call_Stack.Concatenate_Subprogram
 23                       (UTL_Call_Stack.Subprogram(j)));
 24        end loop;
 25    end;
 26  begin
 27    print;
 28  end;
 29  /

Here we are able to figure out what 'depth' we are in the code (utl_call_stack.dynamic_depth) and then walk up the stack using a loop.  We will print out the lexical_depth, along with the line number within the unit we were executing plus - the unit name.  And not just any unit name, but the fully qualified, all of the way down to the subprogram name within a package.  Not only that - but down to the subprogram name within a subprogram name within a subprogram name.  For example - running the PKG.P procedure again results in:

ops$tkyte%ORA12CR1> exec pkg.p
Lexical   Depth   Line    Name
Depth             Number
-------   -----   ----    ----
1         6       20      PKG.P
2         5       17      PKG.P.Q
3         4       14      PKG.P.Q.R
4         3       10      PKG.P.Q.R.P
0         2       26      PRINT_CALL_STACK
1         1       17      PRINT_CALL_STACK.PRINT
BEGIN pkg.p; END;

ERROR at line 1:
ORA-06501: PL/SQL: program error
ORA-06512: at "OPS$TKYTE.PKG", line 11
ORA-06512: at "OPS$TKYTE.PKG", line 14
ORA-06512: at "OPS$TKYTE.PKG", line 17
ORA-06512: at "OPS$TKYTE.PKG", line 20
ORA-06512: at line 1

This time - we get much more than just a line number and a package name as we did previously with format_call_stack.  We not only got the line number and package (unit) name - we got the names of the subprograms - we can see that P called Q called R called P as nested subprograms.  Also note that we can see a 'truer' calling level with the lexical depth, we can see we "stepped" out of the package to call print_call_stack and that in turn called another nested subprogram.

This new package will be a nice addition to everyone's error logging packages.  Of course there are other functions in there to get owner names, the edition in effect when the code was executed and more. See UTL_CALL_STACK for all of the details.



Anonymous Anonymous said....

Thank you for giving so much of your personal time to the Oracle community. Would you be willing to blog about your personal study habits and learning methodology?

Sun Jun 30, 05:52:00 PM EDT  

Blogger Thomas Kyte said....

@Anonymous -

if you go back to the 2005-2007 blog entries, that is what many of them are all about... :)

Sun Jun 30, 06:31:00 PM EDT  

Blogger Rahul Puttagunta said....

Awesome. Now, I can tell our developers to not hardcode the subprogram names and hence have inherent bugs during copy-pasting.
Until now, I only championed using $$PLSQL_UNIT and $$PLSQL_LINE.

Mon Jul 01, 10:54:00 AM EDT  

Blogger Dhruva Sen Gupta said....

Now this feature is surely going to make your 'Who called me' code obsolete ;)

Mon Jul 01, 12:19:00 PM EDT  

Blogger bill.coulam said....

This comment has been removed by the author.

Wed Feb 05, 07:35:00 PM EST  

Blogger bill.coulam said....

Had a good talk with Bryn Llewellyn today. Turns out my tests of utl_call_stack were flawed. I'm still left with a couple of wishes after putting utl_call_stack through its paces last night:

1. I imagine backtrace_unit was designed to return the same unit name as seen in the 10g backtrace, but I wish it would return the fantastic fully qualified routine name instead (like the one returned by utl_call_stack.concatenate_subprogram(utl_call_stack.subprogram()

2. Although I don't currently use it in my logging framework, the object type could be parsed out of the old call stack, but is not available in utl_call_stack routines.

Much appreciation to Bryn and Co. for utl_call_stack.subprogram. So nice to finally enable a proc to identify itself w/o jumping through parsing hoops!

Thu Feb 06, 04:16:00 PM EST  


<< Home