BEGINCALL and ENDCALL
A detailed look at BEGINCALL and ENDCALL
As we've already mentioned, the first statement in an instrumented procedure should be a call to BMC_DEBUG.BEGINCALL. When this procedure is called, it does the following :-
1. Places the details of the procedure onto the call stack, which is an in-memory list of which procedures have been called. This allows other BMC_DEBUG procedures to know the name of the currently executing procedure, and the name of the procedure which called it.
2. Calculates the BMC_DEBUG parameter values for the procedure which is starting. These include the DEBUG LEVEL which decides which messages are written to the log table, and stats groups which list which statistics are to be collected for this execution of the procedure. The parameters may be read from the BMC_DEBUG_PARAMETER table, but can also be gained without using the table. For example, if the procedure which called this one had the INHERIT flag set to Y for any of its parameter values, those values will be used for the current procedure, instead of being read from the parameter table.
3. Creates a savepoint to allow the changes made by this procedure to be rolled back if necessary, without affecting any other changes which have been made in the current transaction (See Transactions and Savepoints for more details on savepoints).
4. Sets the V$SESSION MODULE and ACTION values to the package and procedure names using DBMS_APPLICATION_INFO. This allows monitoring of which procedures are executing in which sessions at a database level (See Monitoring Execution for more details).
5. Records the initial values for any statistics which are being recorded for the procedure. If any of the parameters CALL STATS GROUP, PROFILE STATS GROUP or SESSION STATS GROUP which apply to this procedure are non-zero, the statistics contained within those groups are read and their values are stored in a global temorary table (GTT). The values will be read again by ENDCALL when the procedure ends, so the difference between the two values will give a delta value representing the work done by the execution of the procedure (See Statistics Collection for more details).
The last statement in the procedure should be a call to BMC_DEBUG.ENDCALL, which can also take the package and procedure names as parameters. This does the following :-
1. Checks the call stack to see that it is consistent (See below for more details of this).
2. Records the final values for any statistics in the GTT, and writes the values for call statistics into the permanent BMC_DEBUG_CALL_STATS table.
3. Removes the top entry from the call stack, so when we return to the calling procedure the value on the top of the stack refers to that procedure.
4. Resets the V$SESSION MODULE and ACTION values to those of the calling procedure, or to NULL if the top-level call is ending.
Passing the package and procedure names to BEGINCALL and ENDCALL
When you call the BMC_DEBUG.BEGINCALL procedure at the start of each of your procedures or functions, you need to pass in the name of the package and procedure you are in, so these values can be added to the call stack, which allows other procedures such as MSG to know which procedure they are in.
So far the examples we've seen have looked like this :-
bmc_debug.begincall('PROCEDURE','TEST1');
With both parameter values being hard-coded. The token $$PLSQL_UNIT can be used to automatically provide one of the parameter values, depending on the type of program unit you are in.
If you are instrumenting a standalone procedure or function (that is, one which is not part of a PL/SQL package), you can use $$PLSQL_UNIT to find the name of the procedure or function. When this is the case you should pass the word 'PROCEDURE' (or 'FUNCTION') as the package name e.g.
bmc_debug.begincall('PROCEDURE',$$PLSQL_UNIT);
If your procedure or function is inside a package, $$PLSQL_UNIT will give you the name of the package, but you'll need to hard-code the name of the procedure e.g.
bmc_debug.begincall($$PLSQL_UNIT,'PROCESS_ORDERS');
While there are ways of finding the current procedure name dynamically, I've found them to not be particularly efficient, and as we should always have one eye on performance, hard-coding the procedure name is the best option.
Detecting instrumentation errors
You may also be wondering why we pass the package and procedure names to ENDCALL as well as BEGINCALL. The reason is that, while it is not mandatory, if you do it allows ENDCALL to detect code which may not have been instrumented correctly.
If you decide to add instrumentation to an existing codebase, one of the biggest problems you'll face is making sure that the calls to ENDCALL are correctly positioned.
The call to BEGINCALL should be the first thing that each procedure or function does, so that's easy. What is not so easy is making sure that the call to ENDCALL is the last thing the procedure does. It is quite common to find code which looks like this :-
PROCEDURE process_order (order_id IN NUMBER) IS BEGIN
IF order_id < 10000 THEN
-- We don't process orders from the old system
RETURN;
END IF;
--
-- Main code goes here ...
-- END;
If you were instrumenting this procedure by placing a call to BEGINCALL at the very start and ENDCALL at the very end, you would have a problem, as if the procedure was called with an order_id < 10000, it would exit without calling ENDCALL, and from that point onwards the call stack would be incorrect.
While this is a big problem, it is also quite easily done. This is where passing the package and procedure names to ENDCALL comes in, as it allows this situation to be detected and reported.
Consider the following packaged procedures which don't pass any parameters to ENDCALL :-
SQL> CREATE OR REPLACE PACKAGE stacktest IS
PROCEDURE proca (order_id IN NUMBER);
PROCEDURE procb (order_id IN NUMBER);
END stacktest;
/
Package created.
SQL> CREATE OR REPLACE PACKAGE BODY stacktest IS
PROCEDURE proca (order_id IN NUMBER) IS
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCA');
procb(order_id);
bmc_debug.msg(3,'Which procedure are we in?');
bmc_debug.endcall;
END proca;
PROCEDURE procb (order_id IN NUMBER) IS
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCB');
IF order_id < 10000 THEN
RETURN; -- Return without calling ENDCALL
END IF;
bmc_debug.endcall;
END procb;
END stacktest;
/
Package body created.
So the procedure PROCA calls the procedure PROCB, which returns without calling ENDCALL if the parameter is < 10000.
Lets set the DEBUG LEVEL to 3 for all procedures in this package :-
SQL> INSERT INTO bmc_debug_parameter (param_name, param_value, inherit, package_name, procedure_name)
VALUES ('DEBUG LEVEL',3,'N','STACKTEST',null);
1 row created.
SQL> commit;
Commit complete.
So now if we run PROCA with a parameter value which is < 10000, lets see what we get :-
SQL> exec stacktest.proca(1234);
Which procedure are we in?
PL/SQL procedure successfully completed.
So the message has been displayed on the screen by DBMS_OUTPUT, but if we check the BMC_DEBUG_LOG table :-
SQL> SELECT log_date,sid,package_name,procedure_name,msg_level,msg FROM bmc_debug_log WHERE package_name = 'STACKTEST'; LOG_DATE SID PACKAGE_NAME PROCEDURE_NAME MSG_LEVEL MSG
----------------------------- --- -------------- -------------- -------------- ----------------------------------------
02-NOV-2014 13:38:01.409821 205 STACKTEST PROCB 3 Which procedure are we in?
Do you see the problem? The BMC_DEBUG.MSG call is inside PROCA, but the message has been logged as if it came from PROCB. This is because PROCB called BEGINCALL to add its details to the call stack, but did not call ENDCALL to remove them, so when the MSG call executes, the call stack thinks we're still inside PROCB.
If we now modify the package so that the calls to ENDCALL are passed the same package and procedure names as BEGINCALL :-
SQL> CREATE OR REPLACE PACKAGE BODY stacktest IS
PROCEDURE proca (order_id IN NUMBER) IS
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCA');
procb(order_id);
bmc_debug.msg(3,'Which procedure are we in?');
bmc_debug.endcall($$PLSQL_UNIT,'PROCA'); -- Pass package/procedure names
END proca;
PROCEDURE procb (order_id IN NUMBER) IS
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCB');
IF order_id < 10000 THEN
RETURN;
END IF;
bmc_debug.endcall($$PLSQL_UNIT,'PROCB'); -- Pass package/procedure names
END procb;
END stacktest;
/
Package body created.
If we run the procedure again, we now get a warning about what has happened :-
SQL> exec stacktest.proca(1234);
Which procedure are we in?
STACK ERROR - ENDCALL was called to end STACKTEST.PROCA, but the stack says the current program unit is STACKTEST.PROCB
STACK ERROR - Did STACKTEST.PROCB exit without calling BMC_DEBUG.ENDCALL?
PL/SQL procedure successfully completed.
When you pass the package and procedure names to ENDCALL, the first thing it does is to check that those names match the top item on the call stack. If they don't then the stack error is reported, as it is most likely that the procedure which is on the top of the stack exited without calling ENDCALL.
NOTE - To correctly instrument PROCB, you would add a call to ENDCALL before the RETURN statement, but you should pass an extra parameter RECORD_STATS as FALSE, which means that no statistics would be recorded for the call, as it exited earlier than usual :-
PROCEDURE procb (order_id IN NUMBER) IS BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCB');
IF order_id < 10000 THEN
bmc_debug.endcall(package_name => $$PLSQL_UNIT, procedure_name => 'PROCB', record_stats => FALSE);
RETURN;
END IF;
-- Regular code goes here
bmc_debug.endcall($$PLSQL_UNIT,'PROCB');
END procb;
The CALL_INFO parameter
Another parameter which can be passed to BMC_DEBUG.BEGINCALL is CALL_INFO, which is a free text field which you can use to provide information about an individual invocation of a procedure or function. The best way to use CALL_INFO is to encapsulate the most important parameters which have been passed to the procedure into a string e.g.
PROCEDURE process_order (order_id IN NUMBER) IS
BEGIN
bmc_debug.begincall($$PLSQL_UNIT,'PROCESS_ORDER','order_id='||order_id);
As you can see, CALL_INFO can be passed positionally as the 3rd parameter to BEGINCALL, or as a named parameter.
There are a number of reasons for encapsulating parameters into CALL_INFO in this way :-
1. When an unhandled exception is logged, the CALL_INFO value is included in the error details. This means that when a procedure fails, you not only know which procedure failed, when, and with which ORA- error, you also know the parameter values which were passed into the failed call. This is a huge time saver when it comes to debugging live code, as often your first task when assessing an unhandled exception is to try to work out which parameters the failing procedure was called with.
2. When statistics are being recorded for individual calls, the CALL_INFO value is logged along with the statistic values. This means that if you are recording, for example, the elapsed time for a procedure if it takes more than x seconds, when the statistic is recorded you will also know the parameter values which caused the excessive execution time.
3. It is possible to dynamically apply BMC_DEBUG parameter values such as DEBUG LEVEL to procedures depending on the parameter values which are passed in to them. This is done via the CALL_INFO_LIKE column in the BMC_DEBUG_PARAMETER table, so you could, for example, apply a high DEBUG LEVEL to a procedure only when it is called with a particular parameter value. (See Using Dynamic Parameters for more details).
It is also possible to set or change the CALL_INFO value after BEGINCALL has been called, with the BMC_DEBUG.SET_CALL_INFO procedure, although setting it as part of the call to BEGINCALL is preferrable as that allows dynamic parameter matching to be used.
Development Shortcuts
When developing instrumented code, it is often convenient to apply a DEBUG LEVEL or CALL STATS GROUP to a procedure to see what it is doing while it is being developed. In this situation, having to manipulate the parameter table to enable instrumentation can be inconvenient, so it is possible to set the DEBUG LEVEL and CALL STATS GROUP by passing parameters to BEGINCALL. This is especially useful when writing anonymous blocks which use instrumentation.
The definition of BEGINCALL is overloaded to allow a number of positional parameter combinations. So far we've seen examples such as :-
bmc_debug.begincall('PROCEDURE','TEST1');
Which is the standard way of calling BEGINCALL, passing the procedure and package names. We've also seen :-
bmc_debug.begincall('PROCEDURE','TEST1','order_id='||in_order_id);
With the 3rd parameter as a VARCHAR2 which sets the CALL_INFO value to the passed parameter value.
It is also possible to pass an INTEGER as the 3rd positional parameter to BEGINCALL :-
bmc_debug.begincall('PROCEDURE','TEST1',7);
If you do this, the 3rd parameter will be taken as the DEBUG LEVEL for this procedure, and will override any parameter table values. You can also follow this parameter with values for the DEBUG LEVEL Inherit flag, CALL STATS GROUP, and CALL STATS GROUP Inherit flag if needed e.g.
bmc_debug.begincall('PROCEDURE','TEST1',7,'Y',34,'N') -- DEBUG LEVEL 7 inherited, CALL STATS GROUP 34
There is one caveat with this method of calling BEGINCALL. In a production environment, parameters such as DEBUG LEVEL should only be set via the parameter table, as that is centrally controllable. If code which sets the DEBUG LEVEL or CALL STATS GROUP to certain hard-coded values is deployed live, it could cause a large number of messages or statistics to be recorded with no central way of disabling them.
To prevent this, there is a global parameter, ALLOW PARAMETER OVERRIDE, which can enable or disable this functionality. Its default value is TRUE, which means the values passed into BEGINCALL in the extra parameters are used, but if this global parameter is set to FALSE, any values passed to BEGINCALL which try to set the DEBUG LEVEL or CALL STATS GROUP will be ignored.