Analyzing CLI trace file created using the db2cli.ini file

Applications that access the CLI driver can make use of the CLI trace utility. This utility records all function calls made by the CLI drivers to a trace file, which is useful for problem determination.

This topic discusses how to access and interpret the trace files generated by the tracing utility:

CLI trace file location

If the TraceFileName keyword was used in the db2cli.ini file to specify a fully qualified file name, then the CLI trace file will be in the location specified. If a relative file name was specified for the CLI trace file name, the location of that file will depend on what the operating system considers to be the current path of the application.
Note: If the user executing the application does not have sufficient authority to write to the trace file in the specified path, no file will be generated and no warning or error is given.

The CLI trace utility automatically use the application's process ID and thread sequence number to name the trace files when the TracePathName keyword have been set. For example, a CLI trace of an application with three threads might generate the following CLI trace files: p1680t3124.cli, p1680t3125.cli, p1680t3126.cli.

If no CLI trace output files appear to have been created:
  • Verify that the trace configuration keywords are set correctly in the db2cli.ini file. Issuing the db2 GET CLI CFG FOR SECTION COMMON command from the command line processor is a quick way to do this.
  • Ensure the application is restarted after updating the db2cli.ini file. The CLI trace utility are initialized during application startup. The CLI trace utility can be reconfigured at run time but only if the TraceRefreshInterval keyword was appropriately specified before the application startup.
    Note: Only the Trace and TracePIDList CLI keywords can be reconfigured at run time. Changes made to other CLI keywords, including TraceRefreshInterval, have no effect without an application restart.
  • If the TraceRefreshInterval keyword was specified before the application startup, and if the Trace keyword was initially set to 0, ensure that enough time has elapsed for the CLI trace facility to reread the Trace keyword value.
  • If the TracePathName keyword is used to specify trace directory ensure given directory exist before starting the application.
  • Ensure the application has write access to the specified trace file or trace directory.
  • Check the DB2CLIINIPATH environment variable. If set, the CLI trace facilities expect the db2cli.ini file to be at the location specified by this variable.
  • If "Db2® Common Application Data path" or DB2_COMMON_APP_DATA_TOP_PATH response file keyword was specified during the Db2 product installation, check the path specified in DB2_COMMON_APP_DATA_PATH environment variable (only available on Windows operating systems).
  • If the application uses ODBC to interface with the CLI driver, verify that one of the SQLConnect(), SQLDriverConnect() or SQLBrowseConnect() functions have been successfully called. No entries will be written to the CLI trace files until a database connection has successfully been made.

CLI trace file interpretation

CLI traces always begin with a header that identifies the process ID and thread ID of the application that generated the trace, the time the trace began, and product specific information such as the local Db2 build level and CLI driver version. For example: 
1 [ Process: 1356, Thread: 5656 ]
2 [ Date & Time:               08/05/2011 15:35:00.326001 ]
3 [ Product:                   QDB2/NT Db2 v9.7.400.501 ]
4 [ Level Identifier:          08050107 ]
5 [ CLI Driver Version:        09.02.0000 ]
6 [ Informational Tokens:      "Db2 v9.7.400.501","s110330","IP23237","Fixpack 4" ]
7 [ Install Path:              C:\PROGRA~1\IBM\SQLLIB ]
8 [ db2cli.ini Location2:      C:\Documents and Settings\All Users\Application Data\IBM\DB2\DB2COPY1\cfg\db2cli.ini ]
9 [ CLI Driver Type:           IBM Data Server Runtime Client ]
Note: Trace examples used in this section have line numbers preceding them. These line numbers have been added to aid the discussion and will not appear in an actual CLI trace.
Immediately following the trace header, there are usually a number of trace entries related to environment and connection handle allocation and initialization. For example: 
10  SQLAllocEnv( phEnv=&bffff684 )
11      ---> Time elapsed - +9.200000E-004 seconds

12  SQLAllocEnv( phEnv=0:1 )
13      <--- SQL_SUCCESS   Time elapsed - +7.500000E-004 seconds

14  SQLAllocConnect( hEnv=0:1, phDbc=&bffff680 )
15      ---> Time elapsed - +2.334000E-003 seconds

16  SQLAllocConnect( phDbc=0:1 )
17      <--- SQL_SUCCESS   Time elapsed - +5.280000E-004 seconds

18  SQLSetConnectOption( hDbc=0:1, fOption=SQL_ATTR_AUTOCOMMIT, vParam=0 )
19      ---> Time elapsed - +2.301000E-003 seconds

20  SQLSetConnectOption( )
21      <--- SQL_SUCCESS   Time elapsed - +3.150000E-004 seconds

22  SQLConnect( hDbc=0:1, szDSN="SAMPLE", cbDSN=-3, szUID="", cbUID=-3, 
                              szAuthStr="", cbAuthStr=-3 )
23      ---> Time elapsed - +7.000000E-005 seconds
24  ( DBMS NAME="DB2/LINUX", Version="07.01.0000", Fixpack="0x22010105" )

25  SQLConnect( )
26      <--- SQL_SUCCESS   Time elapsed - +5.209880E-001 seconds
27  ( DSN=""SAMPLE"" )

28  ( UID=" " )

29  ( PWD="*" )

In the trace example, notice that there are two entries for each CLI function call (for example, lines 22-24 and 25-29 for the SQLConnect() function call). This is always the case in CLI traces. The first entry shows the input parameter values passed to the function call while the second entry shows the function output parameter values and return code returned to the application.

The trace example shows that the SQLAllocEnv() function successfully allocated an environment handle ( phEnv=0:1 ) at line 12. That handle was then passed to the SQLAllocConnect() function which successfully allocated a database connection handle ( phDbc=0:1 ) as of line 16. Next, the SQLSetConnectOption() function was used to set the phDbc=0:1 connection's SQL_ATTR_AUTOCOMMIT attribute to SQL_AUTOCOMMIT_OFF ( vParam=0 ) at line 18. Finally, SQLConnect() was called to connect to the target database ( SAMPLE ) at line 22.

Included in the input trace entry of the SQLConnect() function on line 24 is the build and Fix Pack level of the target database server. Other information that might also appear in this trace entry includes input connection string keywords and the code pages of the client and server. For example, suppose the following information also appeared in the SQLConnect() trace entry: 
( Application Codepage=819, Database  Codepage=819,
  Char Send/Recv Codepage=819, Graphic Send/Recv Codepage=819,
  Application Char Codepage=819, Application Graphic Codepage=819 )
This would mean the application and the database server were using the same code page ( 819 ).
The return trace entry of the SQLConnect() function also contains important connection information (lines 27-29 in the trace example). Additional information that might be displayed in the return entry includes any PATCH1 or PATCH2 keyword values that apply to the connection. For example, if PATCH2=27,28 was specified in the db2cli.ini file under the COMMON section, the following line should also appear in the SQLConnect() return entry: 
( PATCH2="27,28" )
Following the environment and connection related trace entries are the statement related trace entries. For example: 
30  SQLAllocStmt( hDbc=0:1, phStmt=&bffff684 )
31      ---> Time elapsed - +1.868000E-003 seconds

32  SQLAllocStmt( phStmt=1:1 )
33      <--- SQL_SUCCESS   Time elapsed - +6.890000E-004 seconds

34  SQLExecDirect( hStmt=1:1, pszSqlStr="CREATE TABLE GREETING (MSG
                                  VARCHAR(10))", cbSqlStr=-3 )
35      ---> Time elapsed - +2.863000E-003 seconds
36  ( StmtOut="CREATE TABLE GREETING (MSG VARCHAR(10))" )

37  SQLExecDirect( )
38      <--- SQL_SUCCESS   Time elapsed - +2.387800E-002 seconds
In the trace example, the database connection handle ( phDbc=0:1 ) was used to allocate a statement handle ( phStmt=1:1 ) at line 32. An unprepared SQL statement was then executed on that statement handle at line 34. If the TraceComm=1 keyword had been set in the db2cli.ini file, the SQLExecDirect() function call trace entries would have shown additional client-server communication information as follows: 
SQLExecDirect( hStmt=1:1, pszSqlStr="CREATE TABLE GREETING (MSG 
                            VARCHAR(10))", cbSqlStr=-3 )
    ---> Time elapsed - +2.876000E-003 seconds
( StmtOut="CREATE TABLE GREETING (MSG VARCHAR(10))" )

    sqlccsend( ulBytes - 232 )
    sqlccsend( Handle - 1084869448 )
    sqlccsend( ) - rc - 0, time elapsed - +1.150000E-004
    sqlccrecv( )
    sqlccrecv( ulBytes - 163 ) - rc - 0, time elapsed - +2.243800E-002

SQLExecDirect( )
    <--- SQL_SUCCESS   Time elapsed - +2.384900E-002 seconds
Notice the additional sqlccsend() and sqlccrecv() function call information in this trace entry. The sqlccsend() call information reveals how much data was sent from the client to the server, how long the transmission took, and the success of that transmission ( 0 = SQL_SUCCESS ). The sqlccrecv() call information then reveals how long the client waited for a response from the server and the amount of data included in the response.

Often, multiple statement handles will appear in the CLI trace. By paying close attention to the statement handle identifier, one can easily follow the execution path of a statement handle independent of all other statement handles appearing in the trace.

Statement execution paths appearing in theCLI trace are usually more complicated than the trace example. For example: 
39  SQLAllocStmt( hDbc=0:1, phStmt=&bffff684 )
40      ---> Time elapsed - +1.532000E-003 seconds

41  SQLAllocStmt( phStmt=1:2 )
42      <--- SQL_SUCCESS   Time elapsed - +6.820000E-004 seconds

43  SQLPrepare( hStmt=1:2, pszSqlStr="INSERT INTO GREETING VALUES ( ? )", 
                cbSqlStr=-3 )
44      ---> Time elapsed - +2.733000E-003 seconds
45  ( StmtOut="INSERT INTO GREETING VALUES ( ? )" )

46  SQLPrepare( )
47      <--- SQL_SUCCESS   Time elapsed - +9.150000E-004 seconds

48  SQLBindParameter( hStmt=1:2, iPar=1, fParamType=SQL_PARAM_INPUT,
                      fCType=SQL_C_CHAR, fSQLType=SQL_CHAR, cbColDef=14,
                      ibScale=0, rgbValue=&080eca70, cbValueMax=15,
                      pcbValue=&080eca4c )
49      ---> Time elapsed - +4.091000E-003 seconds

50  SQLBindParameter( )
51      <--- SQL_SUCCESS   Time elapsed - +6.780000E-004 seconds

52  SQLExecute( hStmt=1:2 )
53      ---> Time elapsed - +1.337000E-003 seconds
54  ( iPar=1, fCType=SQL_C_CHAR, rgbValue="Hello World!!!", pcbValue=14,
      piIndicatorPtr=14 )

55  SQLExecute( )
56      <--- SQL_ERROR   Time elapsed - +5.951000E-003 seconds
In the trace example, the database connection handle ( phDbc=0:1 ) was used to allocate a second statement handle ( phStmt=1:2 ) at line 41. An SQL statement with one parameter marker was then prepared on that statement handle at line 43. Next, an input parameter ( iPar=1 ) of the appropriate SQL type ( SQL_CHAR ) was bound to the parameter marker at line 48. Finally, the statement was executed at line 52. Notice that both the contents and length of the input parameter ( rgbValue="Hello World!!!", pcbValue=14 ) are displayed in the trace on line 54.
The SQLExecute() function fails at line 52. If the application calls a diagnostic CLI function like SQLError() to diagnose the cause of the failure, then that cause will appear in the trace. For example: 
57  SQLError( hEnv=0:1, hDbc=0:1, hStmt=1:2, pszSqlState=&bffff680,
              pfNativeError=&bfffee78, pszErrorMsg=&bffff280,
              cbErrorMsgMax=1024, pcbErrorMsg=&bfffee76 )
58      ---> Time elapsed - +1.512000E-003 seconds

59  SQLError( pszSqlState="22001", pfNativeError=-302, pszErrorMsg="[IBM][CLI
       Driver][DB2/LINUX] SQL0302N  The value of a host variable in the EXECUTE 
       or OPEN statement is too large for its corresponding use.
       SQLSTATE=22001", pcbErrorMsg=157 )
60      <--- SQL_SUCCESS   Time elapsed - +8.060000E-004 seconds
The error message returned at line 59 contains the Db2 native error code that was generated ( SQL0302N ), the sqlstate that corresponds to that code ( SQLSTATE=22001 ) and a brief description of the error. In this example, the source of the error is evident: on line 52, the application is trying to insert a string with 14 characters into a column defined as VARCHAR(10) on line 34.
If the application does not respond to a CLI function warning or error return code by calling a diagnostic function like SQLError(), the warning or error message should still be written to the CLI trace. However, the location of that message in the trace may not be close to where the error actually occurred. Furthermore, the trace will indicate that the error or warning message was not retrieved by the application. For example, if not retrieved, the error message in the example might not appear until a later, seemingly unrelated CLI function call as follows: 
SQLDisconnect( hDbc=0:1 )
    ---> Time elapsed - +1.501000E-003 seconds
    sqlccsend( ulBytes - 72 )
    sqlccsend( Handle - 1084869448 )
    sqlccsend( ) - rc - 0, time elapsed - +1.080000E-004
    sqlccrecv( )
    sqlccrecv( ulBytes - 27 ) - rc - 0, time elapsed - +1.717950E-001
( Unretrieved error message="SQL0302N  The value of a host variable in the
  EXECUTE or OPEN statement is too large for its corresponding use.
  SQLSTATE=22001" )

SQLDisconnect( )
    <--- SQL_SUCCESS   Time elapsed - +1.734130E-001 seconds
The final part of a CLI trace should show the application releasing the database connection and environment handles that it allocated earlier in the trace. For example: 
58  SQLTransact( hEnv=0:1, hDbc=0:1, fType=SQL_ROLLBACK )
59      ---> Time elapsed - +6.085000E-003 seconds
60  ( ROLLBACK=0 )

61  SQLTransact( )
        <--- SQL_SUCCESS   Time elapsed - +2.220750E-001 seconds

62  SQLDisconnect( hDbc=0:1 )
63      ---> Time elapsed - +1.511000E-003 seconds

64  SQLDisconnect( )
65      <--- SQL_SUCCESS   Time elapsed - +1.531340E-001 seconds

66  SQLFreeConnect( hDbc=0:1 )
67      ---> Time elapsed - +2.389000E-003 seconds

68  SQLFreeConnect( )
69      <--- SQL_SUCCESS   Time elapsed - +3.140000E-004 seconds

70  SQLFreeEnv( hEnv=0:1 )
71      ---> Time elapsed - +1.129000E-003 seconds

72  SQLFreeEnv( )
73      <--- SQL_SUCCESS   Time elapsed - +2.870000E-004 seconds