Once a procedure has been instrumented by adding the calls to BEGINCALL and ENDCALL, you can use the BMC_DEBUG.MSG procedure to add messages which will be written to the log table depending on the setting of the DEBUG LEVEL parameter.
Here is an example :-
SQL> CREATE OR REPLACE PROCEDURE msgtest IS
BEGIN
bmc_debug.begincall('PROCEDURE','MSGTEST');
bmc_debug.msg(1,'This is an overview message');
bmc_debug.msg(3,'This is an intermediate message');
bmc_debug.msg(5,'This is a detailed message');
bmc_debug.endcall('PROCEDURE','MSGTEST');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END msgtest;
/
Procedure created.
So in this procedure we are writing three messages at different DEBUG LEVELs, as specified by the first parameter in the MSG call.
Lets now specify a DEBUG LEVEL for this procedure by inserting a row into the parameter table :-
SQL> INSERT INTO bmc_debug_parameter (param_name, param_value, inherit, package_name, procedure_name)
VALUES ('DEBUG LEVEL',4,'N','PROCEDURE','MSGTEST');
1 row created.
SQL> commit;
Commit complete.
So we have specified that this procedure will run with a DEBUG LEVEL of 4. If we now run it (assuming that DBMS_OUTPUT is enabled) we'll see :-
SQL> exec msgtest;
This is an overview message
This is an intermediate message
PL/SQL procedure successfully completed.
If we examine the BMC_DEBUG_LOG table we'll see :-
SQL> SELECT log_date,sid,package_name,procedure_name,msg_level,msg FROM bmc_debug_log
WHERE procedure_name = 'MSGTEST' ORDER BY log_date;
LOG_DATE SID PACKAGE_NAME PROCEDURE_NAME MSG_LEVEL MSG
---------------------------- ---------- -------------- -------------- ------------ ------------------------------------------- 02-NOV-2014 10:41:56.827809 205 PROCEDURE MSGTEST 1 This is an overview message
02-NOV-2014 10:41:56.836303 205 PROCEDURE MSGTEST 3 This is an intermediate message
So if the current DEBUG LEVEL parameter value which was read by BEGINCALL is greater than or equal to the level specified by the first parameter to MSG, the message text will be written to the BMC_DEBUG_LOG table, along with a timestamp and details of which procedure and session the message originated from. If you are running the procedure interactively with DBMS_OUTPUT enabled, you will also see the messages on screen.
If we update the DEBUG LEVEL for this procedure to 5 and run it again :-
SQL> UPDATE bmc_debug_parameter SET param_value = '5' WHERE procedure_name = 'MSGTEST';
1 row updated.
SQL> commit;
Commit complete;
SQL> TRUNCATE TABLE bmc_debug_log;
Table truncated.
SQL> exec msgtest;
PROCEDURE.MSGTEST begins
This is an overview message
This is an intermediate message
This is a detailed message
PROCEDURE.MSGTEST ends
PL/SQL procedure successfully completed.
We get a few more messages than we were expecting. All three of our MSG calls produced output, as the DEBUG LEVEL was >= all of their msg levels, but we also got messages about the procedure starting and ending. If we look at the BMC_DEBUG_LOG entries :-
SQL> SELECT log_date,sid,package_name,procedure_name,msg_level,flag,msg FROM bmc_debug_log
WHERE procedure_name = 'MSGTEST' ORDER BY log_date;
LOG_DATE SID PACKAGE_NAME PROCEDURE_NAME MSG_LEVEL FLAG MSG
----------------------------- ---------- -------------- -------------- -------------- ---- ---------------------------------- 02-NOV-2014 11:00:59.004780 284 PROCEDURE MSGTEST 5 B PROCEDURE.MSGTEST begins
02-NOV-2014 11:00:59.006182 284 PROCEDURE MSGTEST 1 This is an overview message
02-NOV-2014 11:00:59.007116 284 PROCEDURE MSGTEST 3 This is an intermediate message
02-NOV-2014 11:00:59.008079 284 PROCEDURE MSGTEST 5 This is a detailed message
02-NOV-2014 11:00:59.009094 284 PROCEDURE MSGTEST 5 E PROCEDURE.MSGTEST ends
We see the new messages have a value in the FLAG column. This is used to mark the meaning of certain BMC_DEBUG_LOG rows which are generated by BMC_DEBUG's own procedures.
Some values for FLAG which you'll see are :-
B - The beginning of a procedure or function call
E - The end of a procedure or function call
I - Extra information about a call, such as the call_info value
U - The error message from an unhandled exception
X - The error stack and extra details about an unhandled exception
There are two message levels at which messages from BMC_DEBUG's own procedures are written. By default they are equivalent to DEBUG LEVELs 5 and 10, but can be changed via Global Parameters.
NOTE - In the examples in this documentation I will generally use DEBUG LEVEL 1,2 and 3 for overview messages, 4,5 and 6 for mid-level messgaes, and 7,8 and 9 for very detailed messages. Although the PARAM_VALUE column allows values between 0 and 9999, you may not want to use the entire range of values to avoid confusion. e.g. If you find yourself trying to remember the difference between DEBUG LEVEL 4237 and 4238, you have bigger problems :)
A key point to remember is that once you have added messages to your code, you can dynamically control when they are logged by changing the parameter table. This can be done on a live system without any code redeployment or application restarts, as once the parameter table changes are committed, they will be applied the next time a running procedure calls BMC_DEBUG.BEGINCALL.
Using Constants for Debug Levels
As well as specifying the DEBUG LEVEL at which you'd like a message to be written to the log table by passing an integer as the first parameter to MSG, you can also use some constants which are defined in the BMC_DEBUG package specification :-
log_always CONSTANT PLS_INTEGER := 0;
log_severe CONSTANT PLS_INTEGER := 1;
log_warning CONSTANT PLS_INTEGER := 3;
log_info CONSTANT PLS_INTEGER := 5;
log_verbose CONSTANT PLS_INTEGER := 7;
log_debug CONSTANT PLS_INTEGER := 9;
So to log a message only at DEBUG LEVEL 7 or above, you could use :-
bmc_debug.msg(bmc_debug.log_verbose,'This is a quite detailed message');
The Message Store
When you call BMC_DEBUG.MSG, it does more than just writing the message to the log table if the DEBUG LEVEL is high enough. Every message which is passed to BMC_DEBUG.MSG is written to the message store, which is an in-memory rolling window of the last n messages which were passed to MSG by any instrumented procedures (the number of messages the store can hold is configurable via a Global Parameter).
Messages are recorded in the message store irrespective of the DEBUG LEVEL parameter, and whether or not they are written to the log table. The reason for this is that when an unhandled exception occurs, it is useful to have the details of the last steps or decisions which the failing procedure took. Usually if you need to find the cause of an unhandled exception, the first thing you'd do is to rerun the failed procedure with a high DEBUG LEVEL to see the messages it produces before the failure point. The message store means that when a procedure fails, you already have the messages it would have produced, as the BMC_ERROR.ERROR_HANDLE procedure includes the last 10 messages from the message store in the log table.
To show an example of the message store working, lets create a procedure which will make some BMC_DEBUG,MSG calls at above the current DEBUG LEVEL, and then purposely fail :-
SQL> CREATE OR REPLACE PROCEDURE test3 IS
val1 NUMBER;
BEGIN
bmc_debug.begincall('PROCEDURE','TEST3');
bmc_debug.msg(9,'This is the first message');
bmc_debug.msg(9,'This is the second message');
SELECT object_id INTO val1 FROM user_objects WHERE object_id = -1; -- Will raise NO_DATA_FOUND
bmc_debug.endcall('PROCEDURE','TEST3');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END test3;
/
Procedure created.
SQL> exec test3;
Unhandled Exception : ORA-01403: no data found
Stack Trace - This is the order in which the failing objects were called
ORA-06512: at "DEMO.TEST3", line 7
BMC_DEBUG Call Stack :-
Stack Level 1:Name PROCEDURE.TEST3:Started 08-FEB-2014 17:06:52.848120000 +00:00:Params=0N0N00NP
The last 10 BMC_DEBUG.MSG messages were :-
>PROCEDURE.TEST3 starts
>This is the first message
>This is the second message
ERROR_HANDLE: ROLLBACK to SAVEPOINT SP02_00284_170652853567000
BEGIN test3;
END;
* ERROR at line 1: ORA-01403: no data found
ORA-06512: at "DEMO.TEST3", line 12
ORA-06512: at line 1
PL/SQL procedure successfully completed.
So this is the first exception we've seen in instrumented code. There is a lot of detail here, but for the now lets focus on the message store. If we look at the BMC_DEBUG_LOG messages which were logged for this procedure we see :-
SQL> SELECT log_date,package_name,procedure_name,msg_level,flag,msg
FROM bmc_debug_log WHERE procedure_name = 'TEST3' ORDER BY log_date;
LOG_DATE PACKAGE PROCEDURE MSG_LEVEL FLAG MSG
--------------------- ---------- --------- --------- ---- ---------------------------------------------------
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 U Unhandled Exception : ORA-01403: no data found
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 X Stack Trace - This is the order in which the failing objects were
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 X ORA-06512: at "DEMO.TEST3", line 7
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 STK BMC_DEBUG Call Stack :-
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 STK Stack Level 1:Name PROCEDURE.TEST3:Started
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 M The last 10 BMC_DEBUG.MSG messages were :-
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 M >PROCEDURE.TEST3 starts
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 M >This is the first message
02-NOV-2014 17:06:52 PROCEDURE TEST3 0 M >This is the second message 02-NOV-2014 17:06:52 PROCEDURE TEST3 0 R ERROR_HANDLE: ROLLBACK to SAVEPOINT SP02_00284_170652853567000
As the procedure ran at a DEBUG LEVEL lower than 9, the MSG calls did not write their messages to the log table, but they did write them to the message store. Once the procedure hit the ORA-1403 error, ERROR_HANDLE was invoked by the WHEN OTHERS handler and logged the error details, the call stack contents, and the last 10 message store messages (although it only contained 3 messages).
An extra column from BMC_DEBUG_LOG that we're now selecting is ORIGINAL_LOG_DATE, which is only used when the message store contents is logged. This is the date/time that BMC_DEBUG.MSG was called to log the message, as opposed to the LOG_DATE which was the date/time when the message was written to the log table as a result of the message store being logged.
Advanced Message Store Uses
There are two BMC_DEBUG procedures which you can call if you want to write message store messages to the log table from your own code.
LOG_MSG_STORE accepts parameters for the debug level to log at, and the number of messages to log, so for example :-
bmc_debug.log_msg_store(msglevel => 3, no_of_msgs_to_log => 25);
Will write the last 25 messages at DEBUG LEVEL 3, or nothing if the current DEBUG LEVEL value is less than 3.
LOG_MSGS_FOR_CURRENT_CALL will log at a given DEBUG LEVEL the messages that the current procedure has written to the message store at another DEBUG LEVEL.
This allows you to log what the current procedure would have written to the log table, if it had been running at a specific debug level. This is useful if you detect an error during procedural processing, and want to log the information about what the procedure had done up to that point.
Here is an example :-
SQL> CREATE OR REPLACE PROCEDURE test4 IS
BEGIN
bmc_debug.begincall('PROCEDURE','TEST4');
bmc_debug.msg(9,'This is the first message');
bmc_debug.msg(9,'This is the second message');
-- Log the messages written at debug levels up to 9 at level 0 (meaning always log)
bmc_debug.log_msgs_for_current_call (msglevel_to_write_at => 0, msglevel_to_simulate => 9);
bmc_debug.endcall('PROCEDURE','TEST4');
EXCEPTION
WHEN OTHERS THEN
bmc_error.error_handle();
RAISE;
END test4;
/
Procedure created.
SQL> exec test4;
PL/SQL procedure successfully completed.
SQL> SELECT log_date,package_name,procedure_name,flag,msg
FROM bmc_debug_log WHERE procedure_name = 'TEST4' ORDER BY log_date;
LOG_DATE PACKAGE_NAME PROCEDURE_NAME FLA MSG
--------------------------- --------------- ----------------- --- ----------------------------------------
16-NOV-14 02.55.29.843899 PROCEDURE TEST4 M If PROCEDURE.TEST4 had run at DEBUG LEVEL 9 it would have logged the following messages :-
16-NOV-14 02.55.29.846084 PROCEDURE TEST4 M >PROCEDURE.TEST4 begins
16-NOV-14 02.55.29.846197 PROCEDURE TEST4 M >This is the first message
16-NOV-14 02.55.29.846308 PROCEDURE TEST4 M >This is the second message
So the procedure makes some BMC_DEBUG.MSG calls above the current DEBUG LEVEL, so they aren't written to the log table, but then it calls LOG_MSGS_FOR_CURRENT_CALL. This uses the message store to write all messages which were placed in the message store with DEBUG LEVEL 9 or lower, at level 0 (which means log irrespective of DEBUG LEVEL).
Passing additional parameters to MSG
The MSG procedure can be passed a number of additional parameters to control its behaviour. The definition of the procedure is :-
PROCEDURE msg (msglevel IN PLS_INTEGER,
msg IN VARCHAR2,
flag IN VARCHAR2 DEFAULT NULL,
force_package IN VARCHAR2 DEFAULT NULL,
force_procedure IN VARCHAR2 DEFAULT NULL,
write_to_msg_store IN BOOLEAN DEFAULT TRUE,
write_to_debug_log IN BOOLEAN DEFAULT TRUE,
write_to_app_info IN BOOLEAN DEFAULT TRUE,
write_to_dbms_output IN BOOLEAN DEFAULT TRUE);
We've seen uses of the first two parameters to write regular messages. The extra parameters you can optionally pass are :-
Flag - A 3 character string which will be stored in the FLAG column in BMC_DEBUG_LOG. This allows messages of a certain type to be marked with a flag value so they can be easily located.
Force_package/procedure - These parameters can be used to override the values of the package name and procedure name on the call stack. This is necessary when a procedure wants to write a message when it has not necessarily called BMC_DEBUG.BEINCALL, as can be the case with triggers. (See Instrumenting Triggers for more details).
Write_to_msg_store - A boolean which if TRUE means the passed message is written to the message store. You could call MSG with this parameter set to FALSE if you did not want a message to appear in the message store.
Write_to_debug_log - A boolean which if TRUE means the passed message is written to the BMC_DEBUG_LOG table, if the current DEBUG LEVEL >= the passed msglevel.
Write_to_app_info - A boolean which if TRUE means the passed message is written to the CLIENT_INFO column of V$SESSION using DBMS_APPLICATION_INFO.
Write_to_dbms_output - A boolean which if TRUE means if the passed message is written to the BMC_DEBUG_LOG table, it will also be written to DBMS_OUTPUT, so will appear on the screen if the procedure is being run interactively with DBMS_OUTPUT enabled.
While these parameter mean it is possible to control the behaviour of MSG for each individual call which is made to it, some of these can also be controlled via the Global Parameter table, which is preferable as the parameter values can be changed dynamically.