Motivation

Since their inclusion in DB2 UDB V7, SQL procedures have quickly become powerful tools for application development. In addition the SQL Procedural Language (SQL PL) is the natural target language for applications migrated or ported to DB2 UDB from Oracle PL/SQL, Microsoft® SQL Server/Sybase T-SQL, or IBM® Informix® SPL.

While the SQL/PSM standard, and with it SQL PL, provides sophisticated condition handling, this language feature does not provide a way to detect what led up to a particular condition. Furthermore, condition handlers can only be of help if they are coded in all the right places. Also migration from a DBMS, which does not support condition handlers using automated tools such as the migration tool kit (MTK), naturally leaves big gaps in error coverage.

So how do you, as a developer, deal with a SQL0445W Value "100000" has been truncated. SQLSTATE=01004 warning, which you received from your nested billing procedure? Well, you can read through all the procedure code, following the nested calls and hope the problem just jumps out at you. Or you can start the statement event monitor, search for the SQLCA and back-track from there to the SQL procedure source code. To find the path how your procedure got to the warning condition you will need to repeat this step backwards in time. Alternatively you can read through the rest of this article, download the files and just trace the billing procedure.

We will start with the fun part for the impatient reader. This is the SQL procedure tracing API as used by an application developer. Then, for the more curious, I will explain DB2’s underlying, low-level API, which you can use to build upon my efforts.

Back to top

Installation

To install the trace API, you have two options. The first applies if you use one of the platforms for which this article has pre-prepared executables. The second option requires you to compile the API yourself using a C-compiler:

1. You are on a Windows®32-bit system or Linux Intel 32-bit:
   1. download the respective zip file and extract it
   2. copy the sqpltrc executable into sqllib\function\unfenced
   3. connect to the database where you plan to trace, e.g., db2 connect to sample
   4. Bind the sqlpltrc.bnd file to the database: db2 bind sqlpltrc.bnd
   5. Run the DDL script to register the procedures: db2 –tvf sqlpltrc.db2

   You can repeat steps 4 and 5 against as many databases as you wish.

2. For any other platform supported by DB2 UDB,
   1. Download and extract sqlpltrc_source.zip
   2. copy sqlpltrc.sqc and sqlpltrc.exp (on UNIX/Linux) or sqlpltrc.def (on Windows) to sqllib/samples/c
   3. copy bldrtn to bldtrace and add the db2psmd library to the link step of bldtrace and modify the final copy to sqllib/function/unfenced . Note that on Windows the files need to end with .bat , while on UNIX or Linux they need to be marked as executable scripts.

      On Windows the new lines will look like this:

      :link_step rem Link the program. link -debug -out:%1.dll -dll %1.obj db2api.lib db2psmd.lib -def:%1.def rem Copy the routine DLL to the ' function\unfenced&' directory copy %1.dll "%DB2PATH%\function\unfenced" @echo on

      
      

      On AIX ® the changedparts of bldtrace look like:

      # Link the program using the export file $1.exp, xlc_r $EXTRA_CFLAG -qmkshrobj -o $1 $1.o -ldb2 -ldb2psmd -L$DB2PATH/$LIB -bE:$1.exp # Copy the shared library to the sqllib/function/unfenced subdirectory. # Note: the user must have write permission to this directory. rm -f $DB2PATH/function/unfenced/$1 cp $1 $DB2PATH/function/unfenced

      
      

   4. Prep, bind, and deploy the library against the desired database, e.g., bldtrace sqlpltrc sample
   5. Run the DDL script to register the procedures: db2 –tvf sqlpltrc.db2

   Once you have compiled on your development machine, you can deploy on other, compatible platforms, in the same way as described above for Linux and Windows. So you only need a C-compiler once to produce the executable.

Back to top

SQL procedure tracing API

The API can be grouped into three groups:

1. Trace management
2. Trace reporting
3. Trace entries

Let’s walk through these interfaces in order.

1. Trace Management

   As trace management, label the tooling needed to actually do a trace and clean up afterwards.

   • TRACE.SQLPROC_TRACE_ON (IN USERTEMPSPACE VARCHAR(128))

     This procedure turns tracing on for the current session.

     Arguments

     Description

     USERTEMPSPACE

     The user temporary table space DB2 should use to store the trace information. For best performance when tracing in DB2 with DPF the chosen table space should be only on the database partition number of the session’s coordinator. This will also avoid the risk of skew in timestamps if the trace is stored in a database partitioned table space which may confuse the trace reports. If NULL is provided the table space will be chosen as described in the SQL Reference manual for global temporary tables.

   • TRACE.SQLPROC_TRACE_OFF ()

     This procedure turns tracing off for the current session. All trace data collected so far will be lost. The consumed space in the user temporary table space will be freed.

   • TRACE.SQLPROC_TRACE_CLEAR ()

     This procedure deletes the trace data collected so far if tracing is on. The procedure does not switch trace off. The consumed space in the user temporary table space will be freed.

   • TRACE.SQLPROC_TRACE_DUMP ()

     This procedure dumps all the collected trace data into a result set which it returns to the caller. This procedure is included here as a layer of abstraction from the lower level API’s implementation. If you really need the dump data it may be more efficient to write SQL against the API as described later in this article.

     Column name	Column type	Nullable	Description
     EVENTTIME	TIMESTAMP	no	This is the timestamp when the trace event was written.
     ROUTINEID	INTEGER	no	ROUTINEID is the ID of the procedure logging the event as used in SYSCAT.ROUTINES . The ID can be used to find the corresponding ROUTINENAME or SPECIFICNAME in SYSCAT.ROUTINES
     LINE	INTEGER	no	For message trace entries this column contains the approximate line-number of the error or warning in the SQL Procedure. The line number is approximate because DB2’s PSM Virtual Machine (PVM) does some rewriting of SQL PL. For example, it may combine series of SET statements.
     EVENTTYPE	INTEGER	no	The event type is an encoding of ENTRY , EXIT , MESSAGE and DATA . The encoding can be translated from the table TRACE.SQLPROC_TRACE_EVENTS .
     SQLCODE	INTEGER	no	This column holds the SQLCODE when the trace entry was written.
     SQLSTATE	CHAR(5)	no	This column holds the SQLSTATE at the time the trace entry was written
     DATA	VARCHAR(2000)	no	This column contains a user provided text in case of a trace data entry. In case of a non-zero SQLCODE the DATA column contains the message tokens from the SQLCA.

2. Trace reporting

   Two procedures are currently in this class, but they are the centerpieces of the API.

   • TRACE.SQLPROC_TRACE_FORMAT ()

     This procedure analyzes the trace collected so far and produces a readable trace flow report. There are only two columns in the report: A sequential numbering and the formatted trace entry for each event.

   • TRACE.SQLPROC_TRACE_REPORT ()

     This procedure sums up the collected trace and lists how often a given stored procedure was called and how much time passed for all calls. This report can be useful to quickly find bottlenecks within the application. However, the elapsed time must be viewed with caution since the values are skewed by the tracing itself. The more complex and long-running stored procedures are, the more reliable this information will be.

3. Trace entries

   In addition to transparent tracing for SQL procedures, this API also provides for explicit tracing. This feature can be used to enrich the SQL Procedure tracing with explicit trace points, or to add tracing to procedures written in other languages, such as C. Note that, in contrast to transparent tracing of SQL procedures, these trace procedures need to be explicitly invoked. Therefore, even if tracing is disabled an overhead will occur. The procedures are mainly provided for debugging purposes. In high-performance code they should be removed

   • TRACE.SQLPROC_TRACE_PID() RETURNS INTEGER

     This scalar function tests whether tracing is on and returns the current ROUTINEID if tracing is ON. If tracing is OFF the ROUTINEID is NULL. This function should be invoked at the beginning of the SQL Procedure if TRACE.SQLPROC_TRACE_DATA will be called in the procedures body.

   • TRACE.SQLPROC_TRACE_ENTRY (IN SCHEMANAME VARCHAR(128), IN SPECIFICNAME VARCHAR(128), OUT ROUTINEID INT)

     This procedure traces the entry to procedure. It should be called at the very beginning of the procedural logic, right after the variable declarations.

     Argument	Description
     SCHEMANAME	The schema name of the routine that this code describes.
     SPECIFICNAME	The name specified as SPECIFIC NAME in the CREATE PROCEDURE or CREATE FUNCTION statement. Note that it is always good to specify a specific name. Specific names make references to routines a lot easier and they are used extensively by DB2’s error reporting facilities.
     ROUTINEID	This value is DB2’s internal ID for the routine. It will be used as input argument for the subsequently described procedures.

   • TRACE.SQLPROC_TRACE_DATA (IN ROUTINEID INT, IN DATA VARCHAR(2000))

     The purpose of this procedure is to trace arbitrary data. This can be an error-condition, a simple “I was here" message or the content of some host variables. To save codepath when tracing is OFF it is recommended to test whether ROUTINEID is NULL before calling the procedure.

     Argument	Description
     ROUTINEID	The routine id received from TRACE.SQLPROC_TRACE_ENTRY()
     DATA	An arbitrary string, which will be printed as-is in the formatted trace

   • TRACE.SQLPROC_TRACE_EXIT (IN ROUTINEID INT)

     This procedure is the counterpart of TRACE.SQLPROC_TRACE_ENTRY() . It should be called at the very end of the procedural logic of the routine to inform the tracer that the routine is finished. The omission of TRACE.SQLPROC_TRACE_EXIT() when TRACE.SQLPROC_TRACE_ENTRY() was specified will cause wrong results from the trace reporting procedures. To save codepath when tracing is OFF it is recommended to test whether ROUTINEID is NULL before calling the procedure.

     Argument	Description
     ROUTINEID	The routine id received from TRACE.SQLPROC_TRACE_ENTRY()

Back to top

A usage example

Having explained the external API for tracing, now we will walk through a simple example in form of the “3a+1" algorithm.

a ₁ : User input

a _n+1 ::= if a _n is even then a _n /2 else 3a _n +1

We are interested in the number of divisions, multiplications, and total number of steps until a reaches 1 .

DROP PROCEDURE max_three_a_plus_one 
DROP PROCEDURE compute_three_a_plus_one 
DROP PROCEDURE three_a_plus_one 
DROP PROCEDURE a_div_2 

 1 CREATE PROCEDURE a_div_2(INOUT a SMALLINT)  
 2   SET a = a / 2
      
 1 CREATE PROCEDURE three_a_plus_one(INOUT a INTEGER) 
 2   SET a = 3 * a + 1 
        
 1 CREATE PROCEDURE compute_three_a_plus_one 
 2 (IN  a     INTEGER, 
 3  OUT div   SMALLINT, 
 4  OUT mult  SMALLINT, 
 5  OUT steps SMALLINT) 
 6 BEGIN
 7   VALUES(0, 0, 0) INTO div, mult, steps; 
 8   WHILE a <> 1 DO
 9     IF (a / 2) * 2 = a THEN
10       CALL a_div_2(a); 
11       SET div = div + 1; 
12     ELSE
13       CALL three_a_plus_one(a); 
14       SET mult = mult + 1; 
15     END IF; 
16     SET steps = steps + 1; 
17   END WHILE; 
18 END

 1 CREATE PROCEDURE max_three_a_plus_one 
 2 (IN  start    INTEGER, 
 3  IN  stop     INTEGER, 
 4  OUT maxdiv   SMALLINT, 
 5  OUT maxmult  SMALLINT, 
 6  OUT maxsteps SMALLINT) 
 7 BEGIN
 8   DECLARE rtn_id INTEGER;
 9   DECLARE a      INTEGER; 
10   DECLARE div    SMALLINT; 
11   DECLARE mult   SMALLINT; 
12   DECLARE steps  SMALLINT;
13   SET rtn_id = TRACE.SQLPROC_TRACE_PID(); 
14   VALUES (0, 0, 0, start) 
15     INTO maxdiv, maxmult, maxsteps, a; 
16   WHILE a <= stop DO
17     CALL compute_three_a_plus_one 
18         (a, div, mult, steps); 
19     IF rtn_id IS NOT NULL THEN
20       CALL TRACE.SQLPROC_TRACE_DATA
21           (rtn_id, 10, 'A: ' || CHAR(a) || 'Steps: ' || CHAR(steps)); 
22     END IF;
23     SELECT MAX(d), MAX(m), MAX(s), a + 1 
24        INTO maxdiv, maxmult, maxsteps, a 
25        FROM TABLE(VALUES (maxdiv, maxmult, maxsteps), 
26                            (div, mult, steps)) 
27              AS T(d, m, s); 
28   END WHILE; 
29 END
			

You can define these procedures with: db2 –td@ -vf trace_sample.db2

From a tracing point of view procedure max_three_a_plus_one() is noteworthy. While none of the other procedures is instrumented in any way for tracing this one contains explicit tracing code. At the very beginning of the stored procedure (line 13) the SQLPROC_TRACE_PID() UDF is invoked. It returns the ROUTINEID of the max_three_a_plus_one() procedure if and only if tracing is on. If tracing is off the function sets the rtn_id variable to NULL. In line 19 the procedure can now very cheaply test whether tracing is on and write additional trace information by calling SQLPROC_TRACE_DATA in line 20. In this case the procedure traces how many steps were necessary for the given "A" to converge to the number one. The procedure could have an arbitrary number of explicit tracepoints without occuring any significant cost while tracing is off. In practice this technique is very effective to dump input values at the beginning and output values at the end of a procedure. Major decision points within a procedure can also be tracked easily.

But now we must test that the procedure works:

Database Connection Information 
Database server = DB2/NT 8.2.0 
SQL authorization ID = SRIELAU 
Local database alias = DBMTECH 

C:\docs\ibm\Tracing>db2 call max_three_a_plus_one(1, 400, ?, ?, ?) 

Value of output parameters 
-------------------------- 
Parameter Name : MAXDIV 
Parameter Value : 91 

Parameter Name : MAXMULT 
Parameter Value : 52 

Parameter Name : MAXSTEPS 
Parameter Value : 143 

Return Status = 0 

C:\docs\ibm\Tracing>

So far, so good. Now we will “randomly" pick another range of values:

C:\docs\ibm\Tracing>db2 call max_three_a_plus_one(430, 450, ?, ?, ?) 
SQL0413N Overflow occurred during numeric data type conversion. 
SQLSTATE=22003 

C:\docs\ibm\Tracing>

As you can see, that wasn’t all that great. DB2 UDB ran into a math overflow error. But it was neither able to tell us in which procedure the error occurred, nor which variables may have been involved. Note that proper exception handling in SQL PL dictates that each procedure has an error handler that could easily enough have told us the failing procedure. Certainly for this small set of procedures it is easy to guess where the problem lies, but the reason for this example is to showcase tracing. So let’s do that now:

C:\docs\ibm\Tracing>db2 set path = current path, trace 
DB20000I The SQL command completed successfully. 

C:\docs\ibm\Tracing>db2 call sqlproc_trace_on(NULL) 

Return Status = 0 

C:\docs\ibm\Tracing>db2 call max_three_a_plus_one(430, 450, ?, ?, ?) 
SQL0413N Overflow occurred during numeric data type conversion. 
SQLSTATE=22003 

C:\docs\ibm\Tracing>db2 call sqlproc_trace_format() > trace.fmt 

C:\docs\ibm\Tracing>

For convenience, we start by adding the “TRACE" schema to our PATH. This way we don’t have to spell the schema name out for each routine invocation. We then turn tracing on using the default user temporary table space provided by the friendly DBA. After calling the failing routine we then retrieve a formatted trace output. Since the result set contains a lengthy VARCHAR column, it is advisable to redirect the output to a file. In this case we call it trace.fmt:

2445 |<'SRIELAU.COMPUTE_THREE_A_PLUS_ONE (4)
2446 | DAT   Tracepoint 10                      A: 446        Steps: 71
2447 |->SRIELAU.COMPUTE_THREE_A_PLUS_ONE (4)
2448 | |->SRIELAU.THREE_A_PLUS_ONE (1)
... 
2545 | |<'SRIELAU.THREE_A_PLUS_ONE (1) 
2546 | |->SRIELAU.A_DIV_2 (1) 
2547 | |<'SRIELAU.A_DIV_2 (1) 
2548 | |->SRIELAU.THREE_A_PLUS_ONE (1) 
2549 | |<'SRIELAU.THREE_A_PLUS_ONE (1) 
2550 | |->SRIELAU.A_DIV_2 (1) 
2551 | |<'SRIELAU.A_DIV_2 (1) 
2552 | |->SRIELAU.THREE_A_PLUS_ONE (1) 
2553 | |<'SRIELAU.THREE_A_PLUS_ONE (1) 
2554 | | ERR Line 10 SQL0413N Overflow occurred during numeric data type
 conversion. SQLSTATE=22003 
2555 |<'SRIELAU.COMPUTE_THREE_A_PLUS_ONE (4) SQL0413N Overflow occurred 
during numeric data type conversion. SQLSTATE=22003 
2556 | ERR Line 14 SQL0413N Overflow occurred 
during numeric data type conversion. SQLSTATE=22003 
2557 <'SRIELAU.MAX_THREE_A_PLUS_ONE (5) SQL0413N Overflow occurred during numeric data 
type conversion. SQLSTATE=22003 

2557 record(s) selected. 

Return Status = 0

As you can easily see, the source of the error seems to be Line 10 in COMPUTE_THREE_A_PLUS_ONE (4). The (4) indicates that the procedure takes 4 arguments in case there are other procedures of that name in schema “SRIELAU".

10  CALL a_div_2(a);

Since the trace never reached “A_DIV_2" itself the failure must have been during binding in of “A" and a quick lookup reveals that A_DIV_2 takes a SMALLINT while “A" is defined as an INTEGER. So let’s fix that:

C:\docs\ibm\Tracing>db2 drop procedure a_div_2 
DB20000I The SQL command completed successfully. 

C:\docs\ibm\Tracing>db2 create procedure a_div_2(inout a integer) set a = a / 2 
DB20000I The SQL command completed successfully. 

C:\docs\ibm\Tracing>

We now clean out the trace and run again:

C:\docs\ibm\Tracing>db2 call sqlproc_trace_clear() 

Return Status = 0 

C:\docs\ibm\Tracing>db2 call max_three_a_plus_one(430, 450, ?, ?, ?) 

Value of output parameters 
-------------------------- 
Parameter Name : MAXDIV 
Parameter Value : 74 
Parameter Name : MAXMULT 
Parameter Value : 41 
Parameter Name : MAXSTEPS 
Parameter Value : 115 

Return Status = 0 

C:\docs\ibm\Tracing>db2 call sqlproc_trace_report() > trace.rpt 

C:\docs\ibm\Tracing>

Now it worked and we got a report:

Result set 1 
-------------- 

NUMCALLS ELAPSED NAME 
-------- ------------ -------------------------------------- 
       1       0.3284 SRIELAU.MAX_THREE_A_PLUS_ONE (5) 
      21       0.3257 SRIELAU.COMPUTE_THREE_A_PLUS_ONE (4) 
     983       0.0549 SRIELAU.A_DIV_2 (1) 
     501       0.0292 SRIELAU.THREE_A_PLUS_ONE (1) 

4 record(s) selected. 

Return Status = 0

The report can tell us at a glance a few important things. First, we now know which procedures get in fact executed. We know how often they execute and, at least roughly, how much time is spent within them. For more detailed analysis of what goes on within SQL procedures, I recommend taking a look at the SQL PL Profiler, which can be downloaded from DeveloperWorks/DB2 as well.

Back to top

Low-level API

This section described the low-level API, which the trace-utility uses. DB2 UDB V8.2 has gotten three small, but crucial extensions that are exploited here:

• A session-level toggle, which is used to turn tracing on or off.

  The toggle is prototyped in db2psmd.h and available through the db2psmd library.

  #define PSMD_TRACE_MODE_OFF 0 #define PSMD_TRACE_MODE_BASIC 1 int DB2API pda_SetTraceMode( int TraceMode); int DB2API pda_GetTraceMode();

  
  

• A general extension to global temporary tables, which allows temporary tables that are not logged to be completely taken out of transaction control. This extension is required to allow tracing across ROLLBACK statements without losing what has been traced so far.

  DECLARE GLOBAL TEMPORARY TABLE SESSION.TEMP (c1 INTEGER) NOT LOGGED ON ROLLBACK PRESERVE ROWS

  
  

• Awareness of the Procedural Virtual Machine (PVM) to the trace mode.

  If the trace mode is not set to OFF (which is the default), then each entry, exit and non-zero SQL code will be logged in a global temp table with the following name and format:

  DECLARE GLOBAL TEMPORARY TABLE SESSION.SQLPROC_TRACE (EVENTTIME TIMESTAMP NOT NULL , ROUTINEID INTEGER NOT NULL , LINE INTEGER NOT NULL , EVENTTYPE INTEGER NOT NULL , SQLCODE INTEGER NOT NULL , SQLSTATE CHAR(5) NOT NULL , DATA VARCHAR(2000) NOT NULL) ON COMMIT PRESERVE ROWS NOT LOGGED ON ROLLBACK PRESERVE ROWS

  
  

  EVENTTYPE is mapped as such:

  EVENTTYPE	Description
  1	Procedure entry
  2	Procedure exit
  3	Message (SQLCODE <> 0)
  4	User provided data entry

These interfaces are supported by IBM in DB2 UDB V8.2 for LUW. However, the API may evolve or be entirely replaced in future releases, so upward compatibility may not be present. If you choose to exploit this API and you want to be notified of changes, please contact the author of this article.

Back to top

Conclusion and outlook

A simple, yet powerful API is available in DB2 UDB V8.2 for LUW to allow tracing of SQL Procedures. This article provides an example exploitation of this API using an procedure interface. Looking forward there are various areas which could be improved, some of which I want to list here without committing to a timeline:

• While the API provides for a way to do explicit tracing of variables and parameters, it would be more elegant to have tehse capabilities built in. One of the challenges that must be overcome on this path however is security. Certainly not everyone who can execute a stored procedure should be allowed to trace possibly confidential data across the procedure's internal workings. However, in a development environment, you would not want to make every person a DBA.
• The usage of a temporary table limits tracing to procedures of the class MODIFIES SQL DATA. This happens to be the default, so in most cases there is no problem. Nonetheless, there will be procedures that cannot be traced for that reason. Maybe another interface is more appropriate.
• The presented high-level API supports only simple reporting. A much more sophisticated analysis can be made. For example, a stack-trace back could be derived easily from the trace. Aggregating such a trace back yields a quantified call-chain. Which procedure is called by whom and how often? I invite you as a curious reader to extend upon what has been presented here as a seed.
• Having an SQL interface to the trace output provides powerful mining capabilities. In addition to the traceback discussed above one can easily write routines which filter the trace for specific procedures or even trace points.

Back to top

Downloads

Name	Size	Download method
sqlpltrc_Lintel32.zip	18 KB	FTP | HTTP
sqlpltrc_Wintel32.zip	5 KB	FTP | HTTP
sqlpltrc_Source.zip	6 KB	FTP | HTTP

Information about download methods

About the author

Serge Rielau is part of the DB2 Solutions Development team, where he closely works with customers and business partners to port or migrate their applications from competitive RDBMS to DB2 for Linux. UNIX, and Windows. Prior to this role, he worked for 7 years as a team lead and technical manager in the DB2 SQL Compiler Development team. As an expert in the SQL language, Serge is an active participant in the comp.databases.ibm-db2 newsgroup.

Comments (Undergoing maintenance)

Back to top

Trademarks  |  My developerWorks terms and conditions

Table of contents

• Motivation
• Installation
• SQL procedure tracing API
• A usage example
• Low-level API
• Conclusion and outlook
• Downloads
• About the author
• Comments

Local resources

• IBM Innovation Center - Austin, TX
• IBM Innovation Center - Chicago, IL
• IBM Innovation Center - Dallas, TX
• IBM Innovation Center - San Mateo, CA
• IBM Innovation Center - Waltham, MA
• Technical Briefings in North America

My developerWorks community

Dig deeper into Information Management on developerWorks

DB2 pureScale

See how true transparent scaling architecture can be achieved on distributed platforms

Special offers