4.0 Use logging through SQL Procedures

by | Jul 7, 2008

After you run make successfully, you will notice a file generated known as testsp.sql. The only reason we generate this file instead of giving this file as it is is to calculate the size of logging handle properly for your Linux/Unix platforms. This is due to the fact that different OS may have different size of struct timeb structure. We pass this structure to remember the timestamp of the original open_log and subsequent logger and loginfo statements to show elapsed time.

File: testsp.sql

--#SET TERMINATOR @

SET CURRENT SCHEMA = 'TEST'
@
DROP PROCEDURE TESTSP
@
CREATE PROCEDURE TESTSP()
LANGUAGE SQL
BEGIN
   DECLARE h CHAR(72) FOR BIT DATA;
   DECLARE count INTEGER DEFAULT 0;
   CALL DB2.OPEN_LOG('TESTSP',h);
   SET count = count + 1;
   CALL DB2.LOGINFO(h,'this is a test loginfo '||TRIM(CHAR(COALESCE(count,0)))||' message');
   WHILE (count < 3000)
     DO
     SET count = count + 1;
     CALL DB2.LOGGER(h,'this is a test logger '||TRIM(CHAR(COALESCE(count,0)))||' message');
   END WHILE;
   CALL DB2.CLOSE_LOG(h);
END
@

Create above SQL procedure (testsp) to test the logger.

$ db2 connect to <sample>
$ db2 -tf testsp.sql
$ db2 "call db2.update_sp_config('testsp','y')"

After you run db2.update_sp_config to register testsp token with a value of 'Y', you should go to the home directory of the fenced or instance user depending upon mode that you selected in your makefile and make sure that the splog directory was created.

$ cd ~/splog/sample
$ ls -al
drwxr-xr-x   2 db2inst1 db2iadm1        256 Jul 03 22:16 .
drwxr-xr-x   3 db2inst1 db2iadm1        256 Jul 03 16:29 ..
-rw-r--r--   1 db2inst1 db2iadm1        430 Jul 03 16:29 .splogrc
$ cat .splogrc
global_logging=Y
log_split=Y
sample_testsp=Y

The hidden file .splogrc contains information about stored procedures tokens and value of the debug flag for each token. You also see 2 private token global_logging and log_split which control global logging and log split. It is not expected that you modify this file manually as it is not going to help in any way. The logging procedure db2.update_sp_config maintains this file and also manages shared memory which is used by the logging procedures to control logging. If you want to turn global logging off, call procedure db2.update_sp_config('global_logging','n') and logging stops for all procedures including loginfo and logger calls. This will happen instantly and logging is stopped completely.

After checking that the splog directory, run testsp test procedure to check the logger.

$ db2 "call test.testsp()"

A sample output of testsp.log file is shown below when it is run standalone through a CLP from DB2 server itself.

07-08-2008 12:06:21.199[0.001]:[testsp:db2inst1.080708160121]Begin Stored Procedure *** [3145746]
07-08-2008 12:06:21.203[0.004]:[testsp:db2inst1.080708160121]this is a test loginfo 1 message
07-08-2008 12:06:21.203[0.000]:[testsp:db2inst1.080708160121] this is a test logger 2 message
.
.
07-08-2008 12:06:21.987[0.000]:[testsp:db2inst1.080708160121] this is a test logger 2999 message
07-08-2008 12:06:21.987[0.000]:[testsp:db2inst1.080708160121] this is a test logger 3000 message
07-08-2008 12:06:21.988[0.001]:[testsp:db2inst1.080708160121]End   Stored Procedure *** Elapsed 0.790

07-08-2008 12:06:21.988[0.001] shows timestamp of the statement with elapsed time in seconds since last statement of the logger.

[testsp:db2inst1.080708160121] shows a unique application ID of the instance of the stored procedure running. If you have same copy of the SP running through various connections, you will get a distinct value through combination of 2 tokens after name of the stored procedure token. In this sample case, db2inst1 shows that this process was running locally here and 080708160121 is the application ID.

If this SP was running in 2 threads from a java application, you might see an output as shown below:

07-08-2008 12:20:00.541[0.001]:[testsp:44396.08070816150] this is a test logger 59 message
07-08-2008 12:20:00.541[0.000]:[testsp:44396.08070816150] this is a test logger 60 message
07-08-2008 12:20:00.541[0.000]:[testsp:44396.08070816150] this is a test logger 61 message
07-08-2008 12:20:00.541[0.000]:[testsp:44396.08070816150] this is a test logger 62 message
07-08-2008 12:20:00.542[0.001]:[testsp:44397.08070816150]Begin Stored Procedure *** [3145746]
07-08-2008 12:20:00.542[0.001]:[testsp:44396.08070816150] this is a test logger 63 message
07-08-2008 12:20:00.542[0.000]:[testsp:44397.08070816150]this is a test loginfo 1 message
07-08-2008 12:20:00.542[0.000]:[testsp:44396.08070816150] this is a test logger 64 message
07-08-2008 12:20:00.542[0.000]:[testsp:44397.08070816150] this is a test logger 2 message
07-08-2008 12:20:00.543[0.001]:[testsp:44396.08070816150] this is a test logger 65 message
07-08-2008 12:20:00.543[0.001]:[testsp:44397.08070816150] this is a test logger 3 message
07-08-2008 12:20:00.543[0.000]:[testsp:44396.08070816150] this is a test logger 66 message

You will notice that this SP has different number (44396 and 44397) after testsp token for each thread but it has same number 08070816150 for the java application. You can do a grep on testsp:44396.08070816150 and you will get all logger statements from that Java thread which was running this testsp SP.

Let us take an example, when we run testsp from 2 different db2 command windows at the DB2 server.

1st command shell

db2 "call test.testsp()"

2nd command shell

db2 "call test.testsp()"

A sample output is shown:

07-08-2008 12:40:15.856[0.000]:[testsp:db2inst1.080708160121] this is a test logger 2331 message
07-08-2008 12:40:15.856[0.000]:[testsp:db2inst1.080708163516]Begin Stored Procedure *** [3145746]
07-08-2008 12:40:15.856[0.000]:[testsp:db2inst1.080708160121] this is a test logger 2332 message
07-08-2008 12:40:15.857[0.001]:[testsp:db2inst1.080708163516]this is a test loginfo 1 message
07-08-2008 12:40:15.857[0.001]:[testsp:db2inst1.080708160121] this is a test logger 2333 message
07-08-2008 12:40:15.857[0.000]:[testsp:db2inst1.080708163516] this is a test logger 2 message
07-08-2008 12:40:15.857[0.000]:[testsp:db2inst1.080708160121] this is a test logger 2334 message
07-08-2008 12:40:15.857[0.000]:[testsp:db2inst1.080708163516] this is a test logger 3 message
07-08-2008 12:40:15.857[0.000]:[testsp:db2inst1.080708160121] this is a test logger 2335 message
07-08-2008 12:40:15.858[0.001]:[testsp:db2inst1.080708163516] this is a test logger 4 message

You notice that db2inst1 is constant for each CLP window but the application number after that is different for each CLP window. You can do a grep on testsp:db2inst1.080708160121 to find out all logger statements for that particular CLP window.