Interrogating the Call Stack

As we've previously seen, the call stack is an in-memory list of the instrumented procedures which are currently executing, with the current procedure being the one on top of the stack.

Its main purpose is to allow BMC_DEBUG to keep track of nested procedure calls, so if, for example, procedure PROCA calls PROCB, which in turn calls PROCC, when PROCC is running the call stack will contain 3 entries :-

DEPTH PACKAGE_NAME PROCEDURE_NAME DEBUG LEVEL DEBUG LEVEL INHERIT CALL STATS GROUP CALL STATS GROUP INHERIT (and other columns) ----- ------------ -------------- ----------- ------------------- ---------------- ------------------------

1 PROCEDURE PROCA 0 N 23 N

2 PROCEDURE PROCB 3 N 55 Y

3 PROCEDURE PROCC 7 N 55 Y

So any procedures inside BMC_DEBUG are able to find out which procedure is currently being executed by looking at the top entry on the call stack. Also, as soon as PROCC completes and calls BMC_DEBUG.ENDCALL as its final action, its call stack entry is removed, making the top stack entry the one with the details of PROCB. This means that as soon as execution returns to PROCB, its parameter values such as DEBUG LEVEL are already available via the top level stack entry and do not need to be re-read from the parameter table.

BMC_DEBUG provides a number of functions which allow you to interrogate the call stack from your code to gain information about the procedure you are running :-

There are also some functions which return information about the Oracle environment :-

Checking the DEBUG LEVEL and the Golden Rule

As we've just seen, BMC_DEBUG provides functions which allow you to interrogate the call stack to gain information about the currently executing procedure.

This can be useful if you want to include detailed debug messages which require extra processing (such as SELECT statements), which you'd want to avoid if the message is not going to be logged. For example, you might want to do this :-

IF bmc_debug.get_debug_level >= 7 THEN

SELECT count(*) INTO ct FROM orders where cust_id = in_cust_id;

bmc_debug.msg(7,'Total orders for this customer : '||ct);

END IF;

So at a DEBUG LEVEL of 7 or above, we're logging a count of the number of orders for the current customer, but as this requires an extra SELECT, we check that the current DEBUG LEVEL is 7 or greater, as if it isn't we're not going to log the message, so there's no point in running the SELECT as that would just be an overhead.

This all sounds fine, but lurking inside that IF is a hidden danger which could cause a very hard to find bug.

This brings us to the Golden Rule of Instrumentation, which you should keep in mind whenever you are considering checking the DEBUG LEVEL in your code. The Golden Rule is as follows :-

"Changing the DEBUG LEVEL should only change what is written to the log table (or screen). There should be no other side-effects."

To understand the full ramifications of this statement, consider the following example. Lets say you have a procedure which, like the above example, performs a check of the DEBUG LEVEL to decide whether to SELECT some extra information to write to the debug log :-

PROCEDURE dont_do_this (in_cust_id IN NUMBER) IS

ct NUMBER;

BEGIN

bmc_debug.begincall('ORDERS','DONT_DO_THIS');

-- Some code goes here

IF bmc_debug.get_debug_level >= 7 THEN

SELECT count(*) INTO ct FROM orders where cust_id = in_cust_id;

bmc_debug.msg(7,'Total orders for this customer : '||ct);

END IF;

-- More code goes here

bmc_debug.endcall('ORDERS','DONT_DO_THIS');

END dont_do_this;

While this looks innocent enough, consider the variable 'ct' and its state at different DEBUG LEVELs.

As the variable has no default value in its declaration, its value at the start of the procedure will be NULL.

If the DEBUG LEVEL the procedure runs at is 7 or higher, the SELECT inside the IF will assign it a non-NULL value, as count(*) always returns a number.

Assuming 'ct' isn't assigned a value at any point before the IF statement, at the 'More code goes here' point in the code 'ct' might be NULL or NOT NULL depending on the DEBUG LEVEL.

If after the 'More code goes here' point there is a statement which uses 'ct' in a context which is sensitive to NULLs (such as an IN list operator), the behaviour of the statement will be different depending on whether the procedure was run with a DEBUG LEVEL of higher or lower than 7.

If, when this procedure was being developed and tested, it was run with a high DEBUG LEVEL to log all messages for debugging purposes, the 'ct' variable would always have a value assigned to it.

When it gets deployed into production, which would by default run everything with a DEBUG LEVEL of 0, the variable would not have a value assigned, and the procedure would produce incorrect results.

Finding this situation, you would use your instrumentation super-powers to increase the DEBUG LEVEL for this procedure to trace what it is doing, only to find that when you do, the procedure executes perfectly and does not encounter the problem ....

This is a very particular type of hell, and one which you will only avoid by being careful about avoiding side-effects when making code conditional on parameter values.

The way to avoid this is to ensure that variables which are affected by code whose execution conditionally depends on a parameter value are assigned a value after the condition e.g.

IF bmc_debug.get_debug_level >= 7 THEN

SELECT count(*) INTO ct FROM orders where cust_id = in_cust_id;

bmc_debug.msg(7,'Total orders for this customer : '||ct);

END IF;

ct := 0; -- Prevent any side-effects

So at the end of this block, the value of 'ct' will be the same irrespective of the DEBUG LEVEL this code runs with.

If you check the DEBUG LEVEL and use certain values to, for example, conditionally perform DML on your own application tables, you really are asking for trouble. Caveat emptor.