We've already seen that a procedure which has been instrumented with BMC_DEBUG has this basic structure :-
PROCEDURE procedure_name IS
BEGIN
bmc_debug.begincall('PACKAGE_NAME','PROCEDURE_NAME');
--
-- Your code goes here
--
bmc_debug.endcall('PACKAGE_NAME','PROCEDURE_NAME');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END procedure_name;
While we've already looked into the actions of BEGINCALL and ENDCALL, here we'll detail the purpose of the BMC_ERROR.ERROR_HANDLE procedure and why you need to use it.
By including an outermost WHEN OTHERS exception handler in every procedure or function, you ensure that any unhandled exceptions which occur in an instrumented procedure will be logged, along with all of the details about their execution up to the failure point from the information contained in the call stack.
When an unhandled exception is encountered in instrumented code, the error details are written to the BMC_DEBUG_LOG table irrespective of the DEBUG LEVEL which the procedure is running with. Those details include :-
The ORA- error number and error message, and line number of the failing statement (which is all you would get from an unhandled exception in non-instrumented code)
The name of the failing package/procedure, and the parameters which were passed into it (if they were passed as CALL_INFO to BEGINCALL)
The names of all other procedures on the call stack, and their parameters
The last n messages which were written to the message store, which detail what the procedure did in the steps just before the failure point.
Here is an example of a package containing two procedures which are instrumented, the second of which will intentionally raise an unhandled exception :-
SQL> CREATE OR REPLACE PACKAGE exceptiontest IS
PROCEDURE proca (in_order_id IN NUMBER);
PROCEDURE procb (in_new_order_id IN NUMBER);
END exceptiontest;
/
Package created.
SQL> CREATE OR REPLACE PACKAGE BODY exceptiontest IS
PROCEDURE proca (in_order_id IN NUMBER) IS
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCA','order_id='||in_order_id);
procb(in_order_id + 714);
bmc_debug.endcall($$PLSQL_UNIT,'PROCA');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END proca;
PROCEDURE procb (in_new_order_id IN NUMBER) IS
ct NUMBER;
res NUMBER;
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCB','new_order_id='||in_new_order_id);
SELECT count(*) INTO ct FROM dual WHERE dummy IS NULL;
bmc_debug.msg(7,'About to divide by '||ct);
res := in_new_order_id / ct;
bmc_debug.endcall($$PLSQL_UNIT,'PROCB');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END procb;
END exceptiontest;
/
Package body created.
If we run this without DBMS_OUTPUT enabled and hit the exception :-
SQL> set serveroutput off
SQL> exec exceptiontest.proca(875);
BEGIN exceptiontest.proca(875);
END; * ERROR at line 1: ORA-01476: divisor is equal to zero
ORA-06512: at "DBG_OWNER.EXCEPTIONTEST", line 10
ORA-06512: at line 1
What we see on screen is the same as you'd see without using instrumentation, which is just the name of the failing package and the line number at which the exception was raised.
If we look at the BMC_DEBUG_LOG entries which the failing procedure wrote, we see this :-
SQL> SELECT rownum,log_date,package_name,procedure_name,flag,msg
FROM bmc_debug_log WHERE package_name = 'EXCEPTIONTEST' ORDER BY log_date;
RO LOG_DATE PACKAGE_NAME PROCED FLA MSG
-- --------------------------- ------------- ------ --- --------------------------------------------------------------
1 02-NOV-2014 13:34:55.135675 EXCEPTIONTEST PROCB U Unhandled Exception : ORA-01476: divisor is equal to zero
2 02-NOV-2014 13:34:55.141451 EXCEPTIONTEST PROCB X Stack Trace - This is the order in which the failing objects were called
3 02-NOV-2014 13:34:55.143079 EXCEPTIONTEST PROCB X ORA-06512: at "DBG_OWNER.EXCEPTIONTEST", line 19
4 02-NOV-2014 13:34:55.144494 EXCEPTIONTEST PROCB STK BMC_DEBUG Call Stack :-
5 02-NOV-2014 13:34:55.146406 EXCEPTIONTEST PROCB STK Stack Level 2:Name EXCEPTIONTEST.PROCB:Started 12-NOV-2014 13:34:55.111147000:Params=0N0N00NP:Call_info=new_order_id=1589
6 02-NOV-2014 13:34:55.148126 EXCEPTIONTEST PROCB STK Stack Level 1:Name EXCEPTIONTEST.PROCA:Started 12-NOV-2014 13:34:55.099835000:Params=0N0N00NP:Call_info=order_id=875
7 02-NOV-2014 13:34:55.155038 EXCEPTIONTEST PROCB M The last 10 BMC_DEBUG.MSG messages were :-
8 02-NOV-2014 13:34:55.162347 EXCEPTIONTEST PROCB M >EXCEPTIONTEST.PROCA begins
9 02-NOV-2014 13:34:55.164452 EXCEPTIONTEST PROCB M >EXCEPTIONTEST.PROCB begins
10 02-NOV-2014 13:34:55.166264 EXCEPTIONTEST PROCB M >About to divide by 0
11 02-NOV-2014 13:34:55.168463 EXCEPTIONTEST PROCB R ERROR_HANDLE: ROLLBACK to SAVEPOINT SP02_01351_133455114265000
12 02-NOV-2014 13:34:55.177727 EXCEPTIONTEST PROCA R ERROR_HANDLE: ROLLBACK to SAVEPOINT SP02_01351_133455109002000
There is a lot of information here, so lets go through the messages in detail.
Line 1 shows that an unhandled exception was encountered. The message text gives the ORA- error number and text, and the FLAG value is set to 'U'. We can also see the package and procedure names of the failing procedure, as they are in the PACKAGE_NAME and PROCEDURE_NAME columns in the log table.
Lines 2 and 3 give the PL/SQL stack trace, which contains the line number of the statement which raised the original exception (Line 19 in the package body is the line which performed the division).
Lines 4 to 6 give the dump of the BMC_DEBUG call stack. When running the failing procedures, we started by executing PROCA, which called PROCB, which raised the exception, so at that point there were 2 entries on the call stack. The stack is dumped from the latest call backwards, so the failing call will be first, followed by the procedure which called it, and the procedure which called it etc.
The Started field shows the timestamp when each procedure on the stack began execution.
The Params field gives the values which BEGINCALL read from the BMC_DEBUG_PARAMETER table for each procedure, concatenated together. The values are :-
DEBUG LEVEL
DEBUG LEVEL Inherit
CALL STATS GROUP
CALL STATS GROUP Inherit
PROFILE STATS GROUP
SESSION STATS GROUP
SESSION STATS GROUP Inherit
The last character shows the type of program unit which invoked the procedure, the values are :-
P - The procedure was invoked by another regular procedure
T - The procedure was invoked by a trigger
S - The procedure was invoked by a function which was running inside a SQL statement
The final part of each call stack line is the CALL_INFO value which was passed to BEGINCALL. As these procedures follow the recommendations about encapsulating their most important parameters into the CALL_INFO field when calling BEGINCALL, the stack trace contains this information and tells us which parameters each procedure was called with.
Lines 7 to 10 give the last 10 message store rows (although only 3 messages were present). As PROCB was running with DEBUG LEVEL 0 (we know this from the Params field on line 5) the message from the BMC_DEBUG.MSG call on line 18 of the package was not written to the BMC_DEBUG_LOG table, but it was written to the message store, so can be included in the error report.
Lines 11 and 12 show the ROLLBACK TO SAVEPOINT statements which were run by ERROR_HANDLE in each procedure. By default BEGINCALL creates a savepoint at the start of each procedure, to allow it to undo the changes made by a procedure if it raises an unhandled exception. See Transactions and Savepoints for more details.
It is important to understand what has happened between Lines 11 and 12. Line 11 shows the ROLLBACK TO SAVEPOINT being executed for PROCB. This is done by ERROR_HANDLE when it is processing an unhandled exception, along with some other work such call calling ENDCALL to remove the top entry on the call stack. Once ERROR_HANDLE ended, execution returned to the WHEN OTHERS exception handler in PROCB, the next statement in which was RAISE. This reraised the exception, and propagated it back to PROCA. The exception was then caught by the WHEN OTHERS handler in PROCA, which called ERROR_HANDLE, but rather than logging it again, ERROR_HANDLE knows that the error has already been logged, so it just performs the ROLLBACK TO SAVEPOINT and call to ENDCALL.
How does this help us?
If you're used to dealing with errors from PL/SQL in production environments, you may have already recognised the value of the extra information which the BMC_DEBUG call stack provides. Usually when you're presented with an unhandled exception which occurred on a live system, all you'll get is the basic error report which names the failing package and the line number at which the exception occurred. Your first steps in identifying the problem would usually be :-
Use the line number to find which procedure or function in the package had failed.
Try to work out which parameters the failing procedure had been called with
Run the failing procedure with an increased DEBUG LEVEL or additional logging statements to see what it did directly before it hit the exception.
If you look at the previous example, you'll see that all three of these things are done for you automatically :-
The name of the failing package and procedure are in the BMC_DEBUG_LOG columns for the package and procedure names, as well as being in the first call stack line. Not only that, you are told which procedure called the failing one, and which called that, all the way back to the top level call.
The parameters which were passed into the failing call will be logged in the stack track (so long as they were passed as CALL_INFO to BEGINCALL), but the parameters for every other call on the stack will also be logged, so if the only way to rerun the failing call is to do it by invoking the top level call, you know which parameters that was passed as well
As the message store captures all messages passed to BMC_DEBUG.MSG, irrespective of the DEBUG LEVEL value, the messages can be included in the error trace to show what the procedure did directly before the exception. The number of message store messages which the error report contains is configurable via a global parameter.
Not that I'm overemphasising the point, but if your live production system gave you all this information for unhandled exceptions, would that make your life easier? Hmm .....
Using your own exception handler
If you want to use your own exception handler with instrumented code instead of calling BMC_ERROR.ERROR_HANDLE, you can do so as long as you also invoke some BMC_DEBUG procedures to ensure that the call stack is consistent. Here is an example :-
EXCEPTION
WHEN OTHERS THEN
my_pck.my_error_handler(); -- Use existing exception handler
bmc_debug.dump_call_stack;
bmc_debug.log_msg_store(0);
bmc_debug.rollback_to_current_savepoint;
bmc_debug.endcall(record_stats => FALSE);
RAISE;
END proc;
So rather than calling BMC_ERROR.ERROR_HANDLE, you can use you own handler, and optionally call :-
DUMP_CALL_STACK - This will write the call stack details to BMC_DEBUG_LOG
LOG_MSG_STORE - This will write the last n messages from the message store to BMC_DEBUG_LOG
ROLLBACK_TO_CURRENT_SAVEPOINT - This will rollback to the savepoint created by BEGINCALL
Those calls are optional, but the following are mandatory :-
ENDCALL - You must call BMC_DEBUG.ENDCALL in your WHEN OTHERS handler, in order to keep the call stack accurate. You should also pass the RECORD_STATS parameter as FALSE, so statistics for that call will not be recorded as it terminated with an exception.
RAISE - While this is not part of BMC_DEBUG, you should always reraise the exceptions you catch via a WHEN OTHERS handler. If you do not, your procedure will look as if it always succeeds, irrespective of the severity of the errors it encounters. Code written in that way cannot be relied upon.