Retrieve The Call Stack In DB2 For i
September 11, 2013 Michael Sansoterra
Note: The document accompanying this article is available for download here. Troubleshooting problems is often a costly component of application maintenance. Consider the case when the user reports an application crash. Exactly what program crashed? Was it the UI logic or business logic embedded in a service program? If it was a service program, what procedure was running? What was the chain of events that led to the problem? Knowing what the call stack looks like can help answer many of these questions, thereby reducing costly investigation time. Since writing “persistent stored modules” (a.k.a., SQL routines) is increasingly popular on the IBM i, this tip will discuss how to retrieve the call stack within DB2 for i code. This tip assumes the reader is familiar with coding SQL routines in DB2 for i, compiling and creating an RPG service program, and registering RPG logic as a DB2 external function using the CREATE FUNCTION statement. Many modern programming languages such as Java and C# offer a programmatic way to retrieve the call stack. DB2 for i has no such mechanism, but fortunately, the IBM i’s high-level languages (RPG, COBOL, C) can access this information using the Retrieve Call Stack (QWVRCSTK) API. Once an HLL program has accessed this information, it can be made accessible to DB2 as an external function or procedure. This code will work on V5R4 and later. Sample RPG service program CALLSTACKR contains the code to retrieve the current call stack using the QWVRCSTK API. The service program compilation instructions and the SQL CREATE FUNCTION statements required to register the RPG subprocedures for use with SQL are found in the source code header. As a disclaimer; this RPG code retrieves the call stack for OPM and ILE entries. However, with extra coding, QWVRCSTK also supports the retrieval of Java and PASE call stack entries. Further, the code is designed for use as DB2 external user-defined functions. These functions are:
Both of these functions share a parameter in common: Ignore System Libraries. Setting this parameter to ‘Y’ will exclude standard IBM libraries from the call stack (QSYS, QPDA and QSQL). Feel free to add others (like the QHTTP* libs) in the source code if you want additional IBM libraries ignored. Since an SQL-based call stack can contain a large number of entries for standard DB2 related code, using this option will filter out all of that stuff, leaving only references to application code in the call stack. How Did I Get Here? Retrieving The Full Call Stack The GetCallStack table function can map how problem DB2 code arrived at its destination. Let’s say a stored procedure called Procedure3 is potentially called by several other procedures in an application: Procedure1->Procedure2->Procedure3 Procedure1A->Procedure2A->Procedure3 Procedure1B->Procedure2B->Procedure3 Procedure1C->Procedure2C->Procedure3 If an error occurs in Procedure3, it would be useful to trace the procedure chain leading to Procedure3’s execution. Procedure1 shown below calls Procedure2: CREATE PROCEDURE PROCEDURE1 SET OPTION COMMIT=*NONE BEGIN CALL PROCEDURE2; END And Procedure2 calls Procedure3: CREATE PROCEDURE PROCEDURE2 SET OPTION COMMIT=*NONE BEGIN CALL PROCEDURE3; END Procedure3 opens two cursors based on table function GetCallStack: One cursor returns the complete call stack information, and the second shows a subset that excludes the three IBM system libraries: CREATE PROCEDURE QGPL.PROCEDURE3 RESULT SETS 2 SET OPTION COMMIT=*NONE BEGIN DECLARE CALLSTACK_NO_IBM INSENSITIVE CURSOR WITH RETURN TO CLIENT FOR SELECT * FROM TABLE(QGPL.GETCALLSTACK('N')) CS; DECLARE CALLSTACK_W_IBM INSENSITIVE CURSOR WITH RETURN TO CLIENT FOR SELECT * FROM TABLE(QGPL.GETCALLSTACK('Y')) CS; OPEN CALLSTACK_NO_IBM; OPEN CALLSTACK_W_IBM; END; Take a look at what happens when Procedure1 is executed: CALL PROCEDURE1; Now, all three procedures will be called. Because Procedure1 and Procedure2 are in the call stack, they should be included in the two result sets (shown below). For brevity, I removed the request level, activation group name, module name, and module lib columns, and highlighted the “application” SQL routines in the call stack. The first result set has quite a few entries:
The call stack results are returned in reverse order, with the most recent program at the beginning and the entry point at the end. I invoked Procedure1 in the i Navigator’s RunSQL scripts utility, hence, the call stack begins with the QZDASOINIT program. The second result set contains fewer entries because the IBM system programs are excluded:
Each time an ILE C program starts there are two call stack entries: main and _C_pep (program entry point). You can eliminate the unnecessary rows by filtering out the _C_pep value in the WHERE clause. A few notes on the output columns from this table function: The “stack entry” column is a sequential counter for uniquely identifying each row. The “program number” column is a counter that increments each time a new program is encountered on the call stack. Because each program can have multiple procedures in the call stack, this value indicates when a new program boundary is encountered. The “Request Level” column (not shown) is returned from the QWVRCSTK API, but doesn’t seem to convey much information. With as little or much detail as needed, the complete ILE/OPM call stack is available to your SQL application. This information can be very useful in an error handler. If, for example, a stored procedure receives an error, this call stack could be formatted as text, XML, or HTML, stuffed in a LONG VARCHAR or CLOB and saved to a table or IFS file for later review. Procedure4 shown below shows an error handler that wraps the call stack into a simple text string formatted with carriage return/line feed characters (X’0D25′ in US EBCDIC). CREATE PROCEDURE PROCEDURE4 SET OPTION COMMIT=*NONE BEGIN DECLARE @CALLSTACK VARCHAR(6144) NOT NULL DEFAULT 'CS:'; DECLARE CONTINUE HANDLER FOR SQLEXCEPTION BEGIN DECLARE @SQL_STATE CHAR(5) NOT NULL DEFAULT '00000'; DECLARE @MSG_TEXT VARCHAR(70); GET STACKED DIAGNOSTICS EXCEPTION 1 @MSG_TEXT=MESSAGE_TEXT; SET @CALLSTACK='Error '||@MSG_TEXT||X'0D25'; -- When an error occurs, get the call stack FOR DATA AS CALLSTACK_NO_IBM CURSOR FOR SELECT STACKENTRY,PGMNAM,STATEMENT FROM TABLE(QGPL.GETCALLSTACK('Y')) CS WHERE PROCEDURE<>'_C_pep' ORDER BY STACKENTRY DO SET @CALLSTACK=@CALLSTACK || CAST(STACKENTRY AS VARCHAR(10)) || ' ' || PGMNAM || ' stmt: ' || STATEMENT || X'0D25'; END FOR; -- Do something with the text data RETURN; END; -- Erroneous code encountered SIGNAL SQLSTATE '38001' SET MESSAGE_TEXT='I Goofed'; END The formatted call stack text will look like this: Error I Goofed 1 PROCEDURE4 stmt: 0000000081 2 PROCEDURE4 stmt: 0000000041 4 PROCEDURE5 stmt: 0000000014 Who Am I? Retrieving The Current Program Name Let’s take another example of what can be gleaned from the call stack. Programatically getting the name of the current procedure (without hardcoding it) is useful when recording audit information about what code changed a table’s row. SQL Server, for instance, has a metadata function called @@PROCID that will return the unique identifier of an SQL module (procedure, trigger, function). DB2 for i has no such analog (although in limited cases GET DIAGNOSTICS can return the ROUTINE_NAME). The CallStackEntry scalar function can give DB2 the same functionality as @@PROCID and more. The inputs to the CallStackEntry function are:
The function’s output is a VARCHAR(160), but the value it returns is one of two formats depending on how UsePgmLevel was populated:
So how is the function used? Say there’s a need to have a trigger record the table, time, user, and program of a row insert in the following AUDIT_TEST table: CREATE TABLE QGPL.AUDIT_TEST ( TABLE_NAME CHAR(10) NOT NULL, USER CHAR(10) NOT NULL, CHANGE_STAMP TIMESTAMP NOT NULL, CHANGE_PGM CHAR(20)); To make things interesting, several application tables will need this audit table populated and the trigger code should be consistent, if possible. Because of code sharing, of particular interest is the need for the trigger to dynamically get values for the TABLE_NAME (base table) and CHANGE_PGM columns. The CHANGE_PGM is not the trigger itself, but rather the name of the SQL procedure or HLL program that executed an INSERT. Here is one of the many “fancy” application tables that need auditing: CREATE TABLE QGPL.MY_DATA ( DUMMY VARCHAR(256)); The following trigger will record the information in the audit table after data is inserted into table MY_DATA: CREATE OR REPLACE TRIGGER QGPL.TRIGGER_MY_DATA AFTER INSERT ON QGPL.MY_DATA FOR EACH STATEMENT MODE DB2SQL SET OPTION COMMIT=*NONE, USRPRF=*OWNER BEGIN DECLARE @CALLER CHAR(20); DECLARE @TRIGGER CHAR(20); DECLARE @LONG_TABLE VARCHAR(257); DECLARE @TABLE VARCHAR(10); /* Get name of trigger - CHAR(20) */ SET @TRIGGER=QGPL.CALLSTACKENTRY(1,'Y','Y'); /* Get name of base table from trigger catalog */ SELECT EVENT_OBJECT_SCHEMA || '.' || EVENT_OBJECT_TABLE, SYSTEM_EVENT_OBJECT_TABLE INTO @LONG_TABLE, @TABLE FROM QSYS2.SYSTRIGGERS /* Get trigger name based on system program name */ WHERE TRIGGER_PROGRAM_LIBRARY=LEFT(@TRIGGER,10) AND TRIGGER_PROGRAM_NAME=RIGHT(@TRIGGER,10); /* Get name of caller - CHAR(20) */ SET @CALLER=QGPL.CALLSTACKENTRY(2,'Y','Y'); INSERT INTO QGPL.AUDIT_TEST VALUES(@TABLE,USER,CURRENT_TIMESTAMP, @CALLER); END; The trigger uses the CALLSTACKENTRY function with a call stack level of 1 to dynamically get its own name: SET @TRIGGER=QGPL.CALLSTACKENTRY(1,'Y','Y'); Also, the trigger uses the CALLSTACKENTRY function with a call stack level of 2 to get the name of the prior non-IBM program on the call stack. This will either be blank (for dynamic SQL) or the program name of a procedure that ran an INSERT statement: SET @TRIGGER=QGPL.CALLSTACKENTRY(2,'Y','Y'); Now, to validate that it works, create a stored procedure to insert data into table MY_DATA: CREATE OR REPLACE PROCEDURE QGPL.INSERT_MY_DATA SET OPTION COMMIT=*NONE BEGIN INSERT INTO QGPL.MY_DATA VALUES('Hello'); END Invoke the procedure: CALL QGPL.INSERT_MY_DATA; Finally, query the audit table: SELECT * FROM QGPL.AUDIT_TEST; The query of the audit table will show you the following results:
As expected, the trigger dynamically looked up its own system program name and the non-IBM program that called it. The trigger also picked up the table name it is based on (thanks to the SYSTRIGGER catalog view) so that the table name could be included in the audit without hardcoding it in the trigger. Recall that DB2 SQL routines are actually compiled C programs. The system catalog views track the correspondence between the short system name and the long SQL name for all SQL based triggers, procedures and functions. The “Caller” column contains the system name of the calling program; however, the system name can be used to lookup the long SQL name of the caller by using the SYSPROCS catalog view. The one caveat about hardcoding a call stack entry value of 2, is in the thorny case where an INSERT causes multiple triggers to fire. If triggers are potentially nested then code will be required to search the call stack to find the non-IBM/non-trigger code running an INSERT statement. So the exact same trigger code (not including the trigger name and table name) can be used to audit any table. Of course, there is a cost to looking up this information dynamically instead of hardcoding it, but if low code maintenance is your highest priority then this technique is valuable. To sum it up, when your application takes a dive, recording the call stack information can yield valuable insights into how the problem occurred. Likewise, if you need to dynamically look up the name of the current program or caller, the call stack is there to provide the needed info! Michael Sansoterra is a DBA for Broadway Systems in Grand Rapids, Michigan. Send your questions or comments for Mike via the IT Jungle Contact page.
|