Determining performance problems with DB2 Java applications

Learn the secrets to Java performance troubleshooting with DB2

One of the daily challenges facing application developers and database administrators is dealing with performance issues. While many performance issues lie with database servers, some are associated with the client application. This article brings insight into diagnosing and isolating performance problems from the application client perspective. You'll learn how to troubleshoot performance problems that occur with Java™ applications running against IBM® DB2® for Linux®, UNIX®, and Windows® databases. Once you understand the source of your performance issues, you'll be on the path to a solution.

Ming-Pang Wei, DB2 Advanced Support Specialist, IBM

Ming-Pang Wei joined IBM in 2001 and has held various roles within IBM Canada and IBM Australia. He is an IBM Certified Solutions Expert in Database Administration and Application Development. Currently, he is working as an Application Development Specialist within the IBM DB2 Advanced Support Service team in the IBM Toronto Lab where he helps customers and vendors get the best out of their applications and DB2. He co-authored an IBM Redbook, DB2 9 pureXML Guide.



Jason V. Ma (majason@ca.ibm.com), DB2 Advanced Support Specialist, IBM

Jason V. Ma joined IBM in 2001 and has held various roles within the DB2 for Linux, UNIX, and Windows support organization. He is an IBM certified Advanced Technical Expert for DB2 currently working in the DB2 Advanced Support Service team at the IBM Toronto Lab.



16 August 2007

Also available in Chinese

Introduction to problem determination and DB2 architecture

The purpose of this article is to assist you as an application developer or database administrator with troubleshooting and diagnosing common performance problems you may encounter when deploying a Java application. These include common application development issues such as a hang or slow response.

A good understanding of DB2 architecture, DB2 application drivers, and common DB2 components involved is essential for effective troubleshooting and diagnosis of Java application problems. The DB2 client side is composed of several layers, with each component having its own trace utilities to provide unique information to help diagnose different types of application problems. So we'll start with a look at the DB2 client-server architecture before we begin looking at various diagnostic tools.

Figure 1 provides an overview of the software stack used by DB2 on the client side and on the server side. There are two methods to connect to DB2. Client 1, depicted in Figure 1, is the most commonly used configuration. Here, a DB2 client such as the DB2 Runtime Client is installed with the application. The DB2 Runtime Client also includes the Universal JDBC Type 2 driver (also known as JCC T2).

The second method, depicted as Client 2 in Figure 1, does not require the installation of a DB2 client. Instead of a DB2 client, it uses the Universal JDBC Type 4 driver (also known as JCC T4) and can be downloaded separately. (See the link in the Resources section of this article.) To make use of the JCC T4 driver, the application developer must include db2jcc.jar and the license file db2jcc_license_*.jar in the CLASSPATH used by the application. Both types of clients communicate with the DB2 database server using an open database communication standard called Distributed Relational Database Architecture™ (DRDA®). For more information on DRDA, link to Resources.

Figure 1. DB2 client/server architecture
DB2 Client/Server Architecture

The DB2 client provides many types of application interfaces. Figure 2 shows the application layer detailing the types of applications that can be used with DB2. Most of these applications go through the DB2 Call Level Interface (CLI). The JCC driver is restricted to Java applications, since this is a Java-based driver. When a problem occurs, the application developer can collect a combination of the traces described below, depending on the type of application used.

  1. Call Level Interface (CLI) Trace: Most applications go through the CLI layer.
  2. DB2 trace: This traces the inner workings of the DB2 client side below the user application and at the DRDA communications layer. It can also be used to trace server-side problems.
  3. JCC trace: This is a separate trace utility for applications using the DB2 Universal JDBC Driver.
  4. JDBC trace: This will trace the legacy JDBC Type 2 driver; however it is not frequently used since calls made to this layer will be passed down to the CLI layer.
Figure 2. Expansion of application layer
Expansion of application layer

Here are some key concepts to remember when troubleshooting:

  • Troubleshoot using a top-down approach instead of looking at details and trying to figure out whether or not those details are related to the current problem.
  • Understand the environment and configuration.
    • Where is the application running?
    • Where does the database (or databases) reside?
    • What platform, operating system, and version (fixpak level) of DB2 is on each system?
  • Simplify the environment and application as much as possible.
    • Does executing the same query from outside the application exhibit the same behavior?
    • Does running the query from the server result in the same response, compared with executing it from the client side?
  • Note any recent software or hardware changes.
  • Use the trace facilities available to drill down to find the root cause only after understanding the environment and simplifying the problem domain.
  • Look for any corresponding messages in the client-side and server-side application and DB2 logs.

Overview of Developer Workbench debug facilities

The Developer Workbench provides a comprehensive development environment that facilitates the development and debugging of SQL and Java routines. When creating a stored procedure, be sure to create the routine in debug mode.

Figure 3. Enabling new stored procedure for debugging
Enabling new stored procedure for debugging

We can now create some breakpoints in the stored procedure then click on the Debug dialog box to begin debugging.

Figure 4. Debug dialog box
Debug diaglog box

In the screenshots below, at each breakpoint the debugger stops and displays the current state of the variables in the program.

Figure 5. Debugging stored procedure
Debugging stored procedure1
Figure 6. Debugging stored procedure
Debugging stored procedure2

The Developer Workbench is a handy tool to use when developing a Java application. However, when there is a performance issue, the application developer may not have the benefit of knowing which Java routine or which part of the code is performing inadequately. The DB2 trace facilities can be used to drill down and isolate the application which is causing problems. More details on how to use Developer Workbench can be found in the Resources section.

Overview of the CLI trace

The DB2 IBM Driver for Open Database Connectivity (ODBC) and Call Level Interface (CLI) driver is a callable SQL interface driver to DB2 database servers. The JDBC type 2 driver, DB2 Perl module(DBD:DB2), PHP Data Objects interface for DB2, IBM_DB driver for Ruby on Rails, and .NET/ADO/OLEDB providers are built on IBM Driver for Open Database Connectivity (ODBC) and Call Level Interface (CLI) driver.

The DB2 CLI trace is the trace facility that is built into the IBM driver for Open Database Connectivity (ODBC) and Call Level Interface (CLI) driver. All applications that access the CLI driver directly and indirectly can be traced using CLI trace. The DB2 CLI trace contains various timing information which can be used to diagnose application performance issues.

The links below provide more information regarding CLI tracing:

The CLI trace in Listing 1 shows an out arrow (pointing to right) and an in arrow (pointing to left) for each CLI function. The out arrow shows duration spent in the application since last CLI call. The in arrow shows time spent outside the DB2 client, which include network time (round trip) and time spent on the DB2 server. For example, 1.828213E+001 seconds (around 18 seconds) shown in SQLExecute() call is comprised of the SQL execution time plus network time. One can extract the SELECT statement found in SQLPrepareW() statement and run it locally on the DB2 CLP (Command Line Processor) of the database server. If it takes much less time on the server, the delay could be in the network layer. Please refer to the section Diagnosing network issues with Java applications for investigating network issues. If it takes approximately the same time running on the server, the DBA will have to tune the server and SQL statement.

Listing 1. Execution time in SQLExecute()
SQLPrepareW( hStmt=1:1, pszSqlStr="select * from EMPLOYEE", cbSqlStr=31 ) 
  ---> Time elapsed - +1.728000E-003 seconds
( StmtOut="select * from EMPLOYEE" )
...
...                                
SQLExecute( hStmt=1:1 )                                                   
    ---> Time elapsed - +2.145000E-003 seconds                            
( Package="SYSSH200          ", Section=4 )                               
                                                                          
    sqlccsend( Handle - 186081616 )                                       
    sqlccsend( ulBytes - 487 )                                            
    sqlccsend( ) rc - 0, time elasped - +4.500000E-005                    
    sqlccrecv( timeout - +0.000000E+000 )                                 
    sqlccrecv( ulBytes - 34736 ) - rc - 0, time elapsed - +1.823593E+001  
( Requested Cursor Attributes=3 )                                         
                                                                          
( Reply Cursor Attributes=524298 )                                        
                                                                          
( Actual Cursor Attributes=524299 )                                       
                                                                          
                                                                          
SQLExecute( )                                                             
    <--- SQL_SUCCESS   Time elapsed - +1.828213E+001 seconds

The following CLI trace output shows 1.260248E+002 seconds (around 126 seconds) time spent in the application between CLI calls SQLGetConnectAttr() and SQLColAttributesW(). In other words, the 1.260248E+002 seconds delay occurred within the application. If such delay is not expected, the application developer should investigate the application code.

Listing 2. Execution time in application
SQLGetConnectAttr( hDbc=0:1, fOption=SQL_ATTR_AUTOCOMMIT, pvParam=&0c53fdf0, 
	cbParamMax=-4, pcbParam=<NULL pointer> )
    ---> Time elapsed - +1.407000E-003 seconds

SQLGetConnectAttr( pvParam=0 )
    <--- SQL_SUCCESS   Time elapsed - +1.160500E-002 seconds

SQLColAttributesW( hStmt=1:1, iCol=1, fDescType=SQL_DESC_SCHEMA_NAME, 
	rgbDesc=&0c53fd10, cbDescMax=200, pcbDesc=&0c53fde0, pfDesc=&0c53fdd8 )
    ---> Time elapsed - +1.260248E+002 seconds
    sqlccsend( Handle - 186057520 )
    sqlccsend( ulBytes - 228 )
    sqlccsend( ) rc - 0, time elasped - +8.000000E-006
    sqlccrecv( timeout - +0.000000E+000 )
    sqlccrecv( ulBytes - 4099 ) - rc - 0, time elapsed - +1.311000E-003

SQLColAttributesW( pCharAttribute="MING    ", psCharAttributeByteLen=16 )
    <--- SQL_SUCCESS   Time elapsed - +4.869600E-002 seconds

The following CLI trace shows a connection taking 5.569619E+001 seconds (around 55 seconds). If the delay is only observed during the connection, this could be a symptom of an authentication delay. Please refer to the section Diagnosing authentication issues for more details.

Listing 3. Execution time in SQLDriverConnect()
SQLDriverConnect( hDbc=0:1, hwnd=0:0, szConnStrIn="DSN=sample;UID=ming; 
PWD=********;AUTOCOMMIT=0;CONNECTTYPE=1;", cbConnStrIn=-3, 
szConnStrOut=&0bf9de64, cbConnStrOutMax=256, pcbConnStrOut=&0bf9e044, 
fDriverCompletion=SQL_DRIVER_NOPROMPT ) 
---> Time elapsed - +1.806000E-003 seconds 
sqlccsend( Handle - 199165312 ) 
sqlccsend( ulBytes - 276 ) 
sqlccsend( ) rc - 0, time elasped - +2.440000E-004 
sqlccrecv( ) 
sqlccrecv( ulBytes - 122 ) - rc - 0, time elapsed - +3.849500E-002 
sqlccsend( Handle - 199165312 ) 
sqlccsend( ulBytes - 272 ) 
sqlccsend( ) rc - 0, time elasped - +2.670000E-004 
sqlccrecv( ) 
sqlccrecv( ulBytes - 249 ) - rc - 0, time elapsed - +4.629900E-002 
( DBMS NAME="DB2/AIX64", Version="08.02.0004", Fixpack="0x23050106" ) 
( Application Codepage=1252, Database Codepage=819, Char Send/Recv 
Codepage=1252, Graphic Send/Recv Codepage=1200 ) 
SQLDriverConnect( szConnStrOut="DSN=sample;UID=;PWD=********; 
DBALIAS=DPMP;AUTOCOMMIT=0;CONNECTTYPE=1;", pcbConnStrOut=74 ) 
<--- SQL_SUCCESS Time elapsed - +5.569619E+001 seconds

When taking a CLI trace for a performance problem it is important to use the CLI keyword TRACECOMM and optionally the keyword TRACETIMESTAMP as both these keywords will trace extra timing information to the CLI trace file making it easier to spot any delays in the trace.

Overview of the DB2 trace facility

DB2 traces can be used to trace the layer beneath the application on the client side. It can also be used to trace the server side.

More information on DB2 trace can be found in the developerWorks article DB2 Basics: An Introduction to the DB2 UDB trace facility.

You can use a DB2 trace with timestamps to identify slow network problems. Here are trace instructions that you can use on the client side:

  1. Enter the command db2trc on -t -f trc.dmp .
  2. Recreate performance problem by running the SQL statement from the CLP.
  3. Enter the command db2trc off.

For other DB2 trace options, please refer to the Resources section for the DB2 trace syntax.

Once trace is turned off, a binary dump file will be generated in the path where db2trc command was issued. In this case the dump file is trc.dmp which must be flowed (flw) and formatted (fmt) to ASCII files in order for it to be readable. Using the fmt -c will generate a DRDA trace.

For example:

  1. db2trc flw trc.dmp trc.flw
  2. db2trc fmt trc.dmp trc.fmt
  3. db2trc fmt -c trc.dmp trc_drda.fmt

It should be noted that this procedure needs to be performed on same DB2 fix pack level as where DB2 trace dump file was gathered. The flow file (trc.flw), lists the function calls made by each process and thread. The format file (trc.fmt), will provide detailed information regarding each DB2 function call in the order in which it was written to a trace file. The dump file can be flowed with the -t option, if db2trc on was issued with -t option as shown below.

  1. db2trc flw -t trc.dmp trc.flw

The instructions above create a DB2 trace flow file with timestamps. Listing 4 is a sample of a DB2 trace flow file. The second column is the timestamp with the format ssss:nnnnnnnnn. Where ssss indicates second and nnnnnnnnnn indicates nanoseconds.

Listing 4. DB2 trace with timestamps
5572283 1485:587835949 | | | | | sqlccrecv data [probe 120] 
5572284 1485:587837095 | | | | | | sqlcctcprecv entry 
5572285 1485:587838001 | | | | | | sqlcctcprecv data [probe 1] 
5572286 1485:587839212 | | | | | | | tcprecv entry 
6059823 1570:670189615 | | | | | | | tcprecv data [probe 2] 
6059824 1570:670198964 | | | | | | | tcprecv exit 
6059825 1570:670208194 | | | | | | sqlcctcprecv exit 
6059826 1570:670211750 | | | | | sqlccrecv data [probe 5] 
6059827 1570:670213511 | | | | | sqlccrecv exit

DB2 relies on operating system (OS) application programming interfaces (APIs) to perform network communications. You can think of the function tcprecv() above as a wrapper for the OS API TCP/IP recv() call. The recv() function receives data from a connected socket. As you see in Listing 4, tcprecv() takes approximately 85 seconds (1570 - 1485) to receive data. This 85 seconds is a combination of server response time and network time. If executing the same SQL statement from the CLP on the server takes much less time, a slow network is the primary suspect and the network administrator will need to investigate.

Listing 5 shows how to interpret return codes in the DB2 trace or db2diag.log using the db2diag command.

Listing 5. Interpreting return codes
E:\db2v8\BIN>db2diag -rc fffffb95

Input ECF string 'fffffb95' parsed as 0xFFFFFB95 (-1131).
NOTE: ../sqz/sqlzwhatisrc.C:
V7 input ZRC 0xFFFFFB95 (-1131) may translate to V8 ZRC value of 0x83000
B95 (-2097149035)

ZRC value to map: 0x83000B95 (-2097149035)
V7 Equivalent ZRC value: 0xFFFFBB95 (-17515)

ZRC class :
Unexpected Operating System error (Class Index: 3)
Component:
Unknown component (Component Index: 0)
Undefined as of DB2 v8.1.14.292; s061108

Attempting to lookup value 0xFFFFFB95 (-1131) as a sqlcode Sqlcode -1131
SQL1131N  DARI (Stored Procedure) process has been terminated abnormally.

Overview of DB2 Universal JDBC driver tracing

JDBC Universal Driver (JCC) traces are needed to determine the operations that have occurred or were executing prior to receiving an error message, performance problem or hang. Without this type of information is difficult to determine how the application got into this state. The JCC trace should be run on the system hosting the Java application.

There are multiple methods to collect a JCC trace:

The header of the JCC trace provides a bevy of useful environmental information such as:

  • Operating system and environment variables. This can be used to determine if we are picking up multiple versions of the JCC driver or application libraries.
  • Userid used by the application to connect
  • JDK version and vendor. Ensure the JDK is supported by DB2
  • JCC Driver level and JDBC properties used
  • Version of remote DB2 database

Each JCC driver level corresponds to a DB2 fix pack as depicted in Table 1 (DB2 v8.x) and Table 2 (DB2 v9.x). The product identification returned from a JCC trace are displayed in Table 3.

Table 1. JCC Driver versions included with DB2 v8
JCC VersionDB2 Version
JCC 1.0GA (General Availability or FixPak 0)
JCC 1.1FP1
JCC 1.2FP2
JCC 1.3FP3
JCC 1.5FP4
JCC 1.9FP5
JCC 2.2FP6
JCC 2.3FP7
JCC 2.5FP8
JCC 2.6.80FP9
JCC 2.7.58FP10 SYSPLEX routing support introduced
JCC 2.8.46FP11
JCC 2.9.31FP12
JCC 2.10.27FP13
JCC 2.10.52FP14
Table 2. JCC Driver versions included with DB2 9
JCC VersionDB2 Version
JCC 3.1.57GA (General Availability or FixPak 0)
JCC 3.2.49FP1
JCC 3.3.54 FP2
JCC 3.4.65 FP3
Table 3. Product Version from JCC trace
Database Product VersionDB2 Platform
SQL08027 DB2 v8.x on Linux/Unix/Windows
SQL09011 DB2 v9.x on Linux/Unix/Windows
DSN07012 DB2 for z-Series (z/OS) v7.x
DSN08015 DB2 for z-Series (z/OS) v8.x
V05R04M00 DB2 for i-Series (AS400) V5R4

From the sample JCC trace in Listing 6 we see that the JCC Type 4 application is running on Sun Solaris 5.8 as the user admin and connecting to the database SAMPLE on DB2 v8 for z/OS (DSN08015) using userid DB2INST1.

Listing 6. Sample JCC trace
[ibm][db2][jcc] BEGIN TRACE_DRIVER_CONFIGURATION
[ibm][db2][jcc]  Driver: IBM DB2 JDBC Universal Driver Architecture 2.10.62 
[ibm][db2][jcc] Compatible JRE versions: { 1.3, 1.4, 1.5 }
[ibm][db2][jcc] Target server licensing restrictions: { z/OS: enabled; SQLDS: enabled; 
iSeries: enabled; DB2 for Unix/Windows: enabled; Cloudscape: enabled }
[ibm][db2][jcc] Range checking enabled: true
[ibm][db2][jcc] Bug check level: 0xff
[ibm][db2][jcc] Default fetch size: 64
[ibm][db2][jcc] Default isolation: 2
[ibm][db2][jcc] Collect performance statistics: false
[ibm][db2][jcc] No security manager detected.
[ibm][db2][jcc] Detected local client host: appserver.ibm.com/9.29.3.3
[ibm][db2][jcc] Access to package sun.io is permitted by security manager.
[ibm][db2][jcc] JDBC 1 system property jdbc.drivers = null
[ibm][db2][jcc]  Java Runtime Environment version 1.4.2_07 
[ibm][db2][jcc] Java Runtime Environment vendor = Sun Microsystems Inc.
[ibm][db2][jcc] Java vendor URL = http://java.sun.com/
[ibm][db2][jcc] Java installation directory = /apps/j2re1.4.2_07
[ibm][db2][jcc] Java Virtual Machine specification version = 1.0
[ibm][db2][jcc] Java Virtual Machine specification vendor = Sun Microsystems Inc.
[ibm][db2][jcc] Java Virtual Machine specification name = Java Virtual Machine
Specification
[ibm][db2][jcc] Java Virtual Machine implementation version = 1.4.2_07-b05
[ibm][db2][jcc] Java Virtual Machine implementation vendor = Sun Microsystems Inc.
[ibm][db2][jcc] Java Virtual Machine implementation name = Java HotSpot(TM) Server VM
[ibm][db2][jcc] Java Runtime Environment specification version = 1.4
[ibm][db2][jcc] Java Runtime Environment specification vendor = Sun Microsystems Inc.
[ibm][db2][jcc] Java Runtime Environment specification name = Java Platform API 
Specification
[ibm][db2][jcc] Java class format version number = 48.0
[ibm][db2][jcc] Java class path = :/apps/jakarta-tomcat-5.5.7/common/lib/db2jcc.jar:
/apps/jakarta-tomcat-5.5.7/common/lib/db2jcc_license_cisuz.jar:
/apps/jakarta-tomcat-5.5.7/common/lib/db2jcc_license_cisuz.jar:
/apps/jakarta-tomcat-5.5.7/common/lib/db2jcc_javax.jar:
/apps/jakarta-tomcat-5.5.7/bin/bootstrap.jar:
/apps/jakarta-tomcat-5.5.7/bin/commons-logging-api.jar
[ibm][db2][jcc] Java native library path = /apps/j2re1.4.2_07/lib/sparc/server:
/apps/j2re1.4.2_07/lib/sparc:/apps/j2re1.4.2_07/../lib/sparc:/usr/lib
[ibm][db2][jcc] Path of extension directory or directories = /apps/j2re1.4.2_07/lib/ext
[ibm][db2][jcc]  Operating system name = SunOS 
[ibm][db2][jcc]  Operating system architecture = sparc
[ibm][db2][jcc]  Operating system version = 5.8
[ibm][db2][jcc] File separator ("/" on UNIX) = /
[ibm][db2][jcc] Path separator (":" on UNIX) = :
[ibm][db2][jcc] User's account name = admin
[ibm][db2][jcc] User's home directory = /home/admin
[ibm][db2][jcc] User's current working directory = /apps/jakarta-tomcat-5.5.7/bin
[ibm][db2][jcc] Loaded global properties file: 
/apps/jakarta-tomcat-5.5.7/webapps/ivs/WEB-INF/classes/DB2JccConfiguration.properties
[ibm][db2][jcc] Loaded by Context ClassLoader: WebappClassLoader
...
...
[ibm][db2][jcc] END TRACE_DRIVER_CONFIGURATION
[ibm][db2][jcc] BEGIN TRACE_CONNECTS
[ibm][db2][jcc] Attempting connection to test.ibm.com:50000/SAMPLE
[ibm][db2][jcc] Using properties: { traceFile/tmp/jcctrace.txt, user=DB2INST1, 
password=********} 
[ibm][db2][jcc] END TRACE_CONNECTS
...
...
[ibm][db2][jcc][Connection@16fa474] BEGIN TRACE_CONNECTS
[ibm][db2][jcc][Connection@16fa474]  Successfully connected to server 
jdbc:db2://test.ibm.com:50000/SAMPLE 
[ibm][db2][jcc][Connection@16fa474] User: DB2INST1
[ibm][db2][jcc][Connection@16fa474] Database product name: DB2
[ibm][db2][jcc][Connection@16fa474]  Database product version: DSN08015 
[ibm][db2][jcc][Connection@16fa474] Driver name: IBM DB2 JDBC Universal Driver 
Architecture
[ibm][db2][jcc][Connection@16fa474] Driver version: 2.10.62
[ibm][db2][jcc][Connection@16fa474] DB2 Application Correlator: 
G41E4EB2.GA90.C0E39670F334.0000
[ibm][db2][jcc][Connection@16fa474] END TRACE_CONNECTS
...

Java performance

Performance issues can generally be grouped into two types: intermittent and non-intermittent. Intermittent issues are difficult to troubleshoot since they can occur any time based on workload or application timing. To diagnose an intermittent performance problem, one very useful tool that you can use is db2pd -catch. This tool can be set to execute a script that you can use to collect diagnostic information when a specified error message is returned. The disadvantage is that the information is collected AFTER the error occurs. One ideal use for this tool is to capture snapshot information when the database server hits a capacity threshold. For example the application returns -1224 (SQL1224) when the maximum number of db2agents has been exceeded and DB2 is unable to accept new connections.

You can write a shell script named "db2cos" containing any operating system or DB2 commands you want to execute when DB2 hits the SQL1224 error. Note that this script must be named db2cos; otherwise DB2 will not execute it. More information on db2cos can be found in the DB2 Information Center section on db2cos.

Listing 7. Writing the db2cos script
#!/bin/sh

# DB2 Callout script to collect information for SQL1224

echo "Collecting information for SQL1224">>db2cos.rpt
echo "db2cos script executed at `date`" >>db2cos.rpt
db2pd -agents >>db2cos.rpt

Listing 8 demonstrates how to install the call out script once the shell script is complete. If the error message is related to locking, then lock snapshots should be collected in the db2cos script as well.

Listing 8. Enabling db2cos
$ cp db2cos /home/db2inst1/sqllib

$ db2pd -catch clear all
All error catch flag settings cleared.

$ db2pd -catch -1224
Input ECF string '-1224' parsed as 0xFFFFFB38 (-1224).
Error Catch #1
        Sqlcode:        -1224
        ReasonCode:     0
        ZRC:            0
        ECF:            0
        Component ID:   0
        LockName:       Not Set
        LockType:       Not Set
        Current Count:  0
        Max Count:      255
        Bitmap:         0x461
        Action:         Error code catch flag enabled
        Action:         Execute sqllib/db2cos callout script
        Action:         Produce stack trace in db2diag.log

Recreatable or non-intermittent issues are much easier to diagnose since you can collect additional diagnostic information using tracing. Performance issues with Java applications can be grouped into four general types:

  • Slow execution
  • Hang
  • Non-DB2 issues
  • Error message

Generally, the fourth type (error message) above is the easiest to diagnose due to the error message returned. In this case collect the appropriate traces based on the type of application executed on the client side leading up to the error message. Reviewing the traces will usually provide enough information to resolve the issue. The next section illustrates how to diagnose the first three cases above.

Overview of Java routine implementation

Before diagnosing issues with Java routines which can be defined as stored procedures (SPs) or user defined functions (UDFs), it is necessary to review how a Java routine is invoked. By default, DB2 starts a separate process outside of DB2 to run fenced Java routines called the db2fmp. This precautionary measure is taken because DB2 is executing unknown code written by the application developer. If an exception were to occur, the worst case is that the db2fmp process is terminated without bringing down the entire database. This increased flexibility also allows rogue Java routines to be terminated if they consume too much memory or CPU. If the Java routine were run as unfenced inside the db2agent instead of a db2fmp process, an exception may bring down the entire database.

In addition to defining a Java routines as FENCED or UNFENCED, they can be defined as THREADSAFE or NOT THREADSAFE. The difference is that THREADSAFE Java routines are run as a thread inside the db2fmp process. NOT THREADSAFE Java routines are run in a separate db2fmp process. By default DB2 creates Java routines as THREADSAFE. Since the db2fmp process is run using the fenced userid, its resource limit would be determined by its user limits. Listing 9 shows how to find and modify the fenced userid.

Listing 9. Modify the fenced userid
/home/db2inst1/sqllib/adm: ls -la .fenced
-rw-r--r--   1 nobody  nobody             0 Jun 20 16:49 .fenced

/home/db2inst1/: db2stop
SQL1064N  DB2STOP processing was successful.

/home/db2inst1/: chown db2fenc1 /home/db2inst1/sqllib/adm/.fenced

/home/db2inst1/: db2start
SQL1063N  DB2START processing was successful.

/home/db2inst1/sqllib/adm: ls -la .fenced
-rw-r--r--   1 db2fenc1  fencgrp             0 Jun 20 16:55 .fenced

When an application connects to DB2, one or more db2agent processes are assigned to this application to run queries. When the application calls a Java routine, the communication between the db2agent and db2fmp process goes through the Fenced Mode Communication Pool determined by the DB2 registry variable DB2_FMP_COMM_HEAPSZ. The size of DB2_FMP_COMM_HEAPSZ determines the maximum number of concurrent routines which can be run in an instance. Figure 7 illustrates how a Java routine is called.

Figure 7. Calling a Java routine
Calling a Java routine

Diagnosing slow Java routine execution

As previously seen in Figure 1, there are client and server-side components, each consisting of multiple layers. The first item is to determine whether this is an issue on the client side or server side. To rule out the possibility that Developer Workbench is causing a problem, call the stored procedure from the client side command line processor (if applicable), and check to see if the response time is acceptable.

If its response time is slow or similar to calling the SP from the application, then we can conclude that the application is not the culprit. In this case, proceed to call the stored procedure from the server's command line processor. If the response time is slow, then the Database Administrator should investigate from the server side. The performance problem could be caused by a misconfiguration, tuning issue or poor access plan being used by the optimizer when executing the routine.

Otherwise, we can conclude that the performance degradation is either in the DB2 client code or network. At this point we can collect a DB2 trace with the timestamp option to determine which function is taking the longest to return. For example, are we waiting for TCP/IP? Some applications will call the routine using parameter markers, thus a JDBC or JCC trace will need to be collected to capture the input parameters. Application side logs may also contain this information.

Once the slow SP has been isolated, the application developer should add debug code to the Java routine to determine where the performance bottleneck is. The easiest method of adding debug code is to add INSERT statements into the Java routine. Listing 10 is a script to create the table SP_DEBUG to store the debug information.

Listing 10. DB2 script to create a debug table
connect to sample;
create table sp_debug(sp_name varchar(100), time timestamp, trace_point integer, 
desc varchar(100));
terminate;
Listing 11. Writing debug information to a table
import java.sql.*;
import java.io.*;

 
   public class TEST_JAVASP3
   {
     public static void tEST_JAVASP3  (int input) throws SQLException,
 	Exception
     {
	int errorCode;
	Connection dbCon=null;
	Statement debug_st=null;
	PreparedStatement pstmt=null;
	
      try
      {
      	
        // get caller's connection to the database
   	dbCon = DriverManager.getConnection("jdbc:default:connection");

	// Create a statement handle for to execute debug statements
	debug_st = dbCon.createStatement(); 
	debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3',
		current timestamp, 1,'entry')"); 
     
        String query = "INSERT INTO T1 (C1) VALUES (?)";

	debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3',
		current timestamp, 2,'prepare')");
        
        pstmt = dbCon.prepareStatement(query);
        pstmt.setInt(1, input);
        pstmt.executeUpdate();
  	
  	debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3',
  		current timestamp, 3,'executeUpdate')");

  	/* Cause the stored proc to hang if the input value is 11 */
  	if( input == 11)
  	{
  		while(true);	
  	}
	debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3',
		current timestamp, 4,'done if')");
	debug_st.execute("INSERT INTO SP_DEBUG values('test_javasp3',
		current timestamp, 10,'exit')");

	// Cleanup
	pstmt.close();
	debug_st.close();
	dbCon.close();  	

      }   
      catch (SQLException sqle)
      {
        errorCode = sqle.getErrorCode();
        throw new SQLException( errorCode + " FAILED" ); 
      }
      finally
      {
      	if(pstmt !=null)
      	{pstmt.close();}
      	
      	if(debug_st !=null)
      	{debug_st.close();}
      	
      	if( dbCon != null)
	{dbCon.close();}	
      }

    } // end finally
}
Table 4. Contents of SP_DEBUG table
SP_NAMETIMETRACEPOINTDESC
test_javasp3 2007-07-10-19.25.21.436000 1 entry
test_javasp3 2007-07-10-19.25.21.452000 2 prepare
test_javasp3 2007-07-10-19.25.21.452000 3 executeUpdate
test_javasp3 2007-07-10-19.25.21.452000 4 done if
test_javasp3 2007-07-10-19.25.21.452000 10 exit

The advantage of using the method above is that it is fairly easy to implement. The disadvantage is that if there is no database connection, it will be unable to output the debug information to the table. This will likely not be a problem since serious errors such as this would have already been resolved. Table 4 lists the contents of the debug table after executing the stored procedure. It displays a timestamp along with the part of code that was executed.

An alternative method is to modify the Java routine so that it will write the debug information to a file as shown in Listing 12. In our example a debug parameter was added to the stored procedure definition to enable/disable debugging. There will be extra overhead when adding debug information and thus an application developer may choose to remove the debug code from the production version of the Java routine. Also note that it takes more calls to write out to the file versus inserting the debug information into a table since we need to format a Java timestamp. By default Java timestamps are in milliseconds since January 1st 1970. The Calendar() object is used to format the timestamp (in milliseconds) into a human readable format. The call to debugOut.flush() immediately dumps the character buffer out to the file. Without this call it is possible when debugging a hang issue that no debug output is written because the hang had occurred before the character buffer becomes full.

Listing 12. Writing debug information to file
import java.sql.*;
import java.io.*;
import java.util.*;

 
   public class TEST_JAVASP2
   {
     public static void tEST_JAVASP2  (int input, int debug) throws SQLException,
 	Exception
     {
       int errorCode;
       PrintWriter debugOut=null;
       Calendar cal = null;
       	
      try
      {
      	if (debug == 1)
      	{
      	  cal = Calendar.getInstance();
      	  cal.setTimeInMillis(System.currentTimeMillis() );
      	
      	  // Open debug file
      	  debugOut = new PrintWriter(new FileWriter("sp_debug.txt"));

	  cal.setTimeInMillis(System.currentTimeMillis() );
      	  debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)+ " " 
      	  	+ "tEST_JAVASP2 - entry");
      	 
      	  // Need to flush buffer to disk otherwise when troubleshooting hang 
      	  // issue the output file will be empty
      	  debugOut.flush();
      	}
      	
        // get caller's connection to the database
   	Connection con = DriverManager.getConnection("jdbc:default:connection");
     
        String query = "INSERT INTO T1 (C1) VALUES (?)";

	if (debug == 1)
      	{
	  cal.setTimeInMillis(System.currentTimeMillis() );
  	  debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)+ " " 
  	  	+ "tEST_JAVASP2 - preparing query");
	  debugOut.flush();
	}
	
        PreparedStatement pstmt = con.prepareStatement(query);
        pstmt.setInt(1, input);
        pstmt.executeUpdate();

	if (debug == 1)
      	{
	  cal.setTimeInMillis(System.currentTimeMillis() );
  	  debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)+ " " 
  	  	+ "tEST_JAVASP2 - executed query");
  	  debugOut.flush();
  	}

  	if( input == 11)
  	{
  		for(int i=0;i<10;i++)
  		{ 
  		  if (debug == 1)
      	          {
  		    cal.setTimeInMillis(System.currentTimeMillis() );
  		    debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)
  		    	+ " " + "tEST_JAVASP2 - loop" + " i="+i);
		    debugOut.flush();
  	 	  }
  	  	}		
  	}
  	
  	if (debug == 1)
      	{
  	  cal.setTimeInMillis(System.currentTimeMillis() );
  	  debugOut.println(cal.getTime() + " " + cal.get(Calendar.MILLISECOND)
  	  	+ " " + "tEST_JAVASP2 - exit");
  	  debugOut.flush();
  	  
  	  // Close debug File
  	  debugOut.close();
        }
        
      }   
      catch (SQLException sqle)
      {
        errorCode = sqle.getErrorCode();
        throw new SQLException( errorCode + " FAILED" ); 
      }
      finally
      {
        if(debugOut!=null)
        {debugOut.close(); }	
      	
      }         
    }
}

After you execute the stored procedure, the debug information is written to the plain text file sp_debug.txt. These examples can be modified to provide additional debugging information. The 847 is the number of milliseconds. There are more complex methods of generating debug information such as this example which demonstrates how to trace SQL stored procedures by creating a library of debug calls.

Listing 13. Contents from sp_debug.txt
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - entry
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - preparing query
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - executed query
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=1
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=2
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=3
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=4
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=5
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=6
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=7
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=8
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - loop i=9
Wed Jul 11 16:18:11 EDT 2007 847 tEST_JAVASP2 - exit

Diagnosing Java stored procedure hang

When a Java application or DB2 Java routine hangs we can generate a javacore (also known as a javadump) to determine where it is hanging. This example illustrates how to collect a javacore for a Java routine. Generating a javacore for a Java application is much simpler and is already illustrated in the IBM JDK Diagnostics Guide .

The IBM JDK environment will have to be setup to enable javacores. The setup procedure is slightly different for each platform and IBM JDK used. In our example we are connecting from a JCC application to DB2 V8.x server on AIX®. Please consult the IBM JDK Diagnostics Guide for detailed setup instructions for each platform and IBM JDK.

Listing 14. Enabling Javacores in AIX
$ export JAVA_DUMP_OPTS="ONINTERRUPT(JAVADUMP),ONANYSIGNAL(JAVADUMP)"

$ export IBM_JAVACOREDIR=/db1/j2ma

$ db2set DB2ENVLIST="IBM_JAVACOREDIR JAVA_DUMP_OPTS"

$ ulimit -a
time(seconds)        unlimited
file(blocks)         unlimited
data(kbytes)         131072
stack(kbytes)        32768
memory(kbytes)       32768
coredump(blocks)     unlimited
nofiles(descriptors) 2000

$ db2stop
SQL1064N  DB2STOP processing was successful.

$ db2start
SQL1063N  DB2START processing was successful.

Note that the setup may differ slightly since the JDK level used in this example will differ from yours.

  • JAVA_DUMP_OPTS specifies which signals will trigger a javacore.
  • IBM_JAVACOREDIR specifies the location of the javacore file.
  • DB2ENVLIST is used to pass environment variables to the db2fmp process because the db2start command filters out all user environment variables that do not start with DB2* or db2*.

After that we ensure that the coredump=unlimited for the fenced userid and restart the instance.

In this example the JCC application calls the stored procedure TEST_JAVASP on a remote AIX DB2 server which hangs and does not return. First thing to do is to collect a JCC trace from the client side since we want to know what values where sent to the stored procedure. Perhaps a particular data value is causing the hang.

Listing 15. JCC trace of stored procedure call
[jcc][Time:2007-06-20-17:39:29.388][Thread:main][Connection@54a328] 
prepareStatement (CALL JASON.TEST_JAVASP(?)) called
[jcc][Time:2007-06-20-17:39:29.420][Thread:main][Connection@54a328] 
prepareStatement () returned PreparedStatement@1fc2fb
...
...
[jcc][Time:2007-06-20-17:39:30.967][Thread:main][PreparedStatement@1fc2fb] 
executeUpdate () returned -1
[jcc][SystemMonitor:stop] core: 13.378541ms | network: 9.792076ms | server: 0.0ms
[jcc][Time:2007-06-20-17:39:30.967][Thread:main][PreparedStatement@1fc2fb] 
setInt (1, 11) called
[jcc][SystemMonitor:start] 
[jcc][Time:2007-06-20-17:39:30.967][Thread:main][PreparedStatement@1fc2fb] 
executeUpdate () called
[jcc] [t4][time:2007-06-20-17:39:30.967][thread:main][tracepoint:1][Request.flush]
[jcc][t4]        SEND BUFFER: EXCSQLSTT              (ASCII)           (EBCDIC)
[jcc][t4]        0 1 2 3 4 5 6 7   8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
[jcc][t4] 0000   007ED05100010078  200B00442113A5F9  .~.Q...x ..D!...  .=}...........v9
[jcc][t4] 0010   A281949740404040  4040404040404040  ....@@@@@@@@@@@@  samp            
[jcc][t4] 0020   D5E4D3D3C9C44040  4040404040404040  ......@@@@@@@@@@  NULLID          
[jcc][t4] 0030   4040E2E8E2E2C8F2  F0F0404040404040  @@........@@@@@@    SYSSH200      
[jcc][t4] 0040   404040405359534C  564C303100010005  @@@@SYSLVL01....      ...<.<......
[jcc][t4] 0050   2105F100052111F1  0008211400007FFF  !....!....!.....  ..1....1......".
[jcc][t4] 0060   00062141FFFF0006  2140FFFF00052142  ..!A....!@....!B  ......... ......
jcc][t4] 0070   040005210E010008  190080000000      ...!..........    ..............  
[jcc][t4] 
[jcc][t4]        SEND BUFFER: SQLDTA                 (ASCII)           (EBCDIC)
[jcc][t4] 0000   0024D0030001001E  2412001000100676  .$......$......v  ..}.............
[jcc][t4] 0010   D00300040671E4D0  0001000A147A0000  .....q.......z..  }.....U}.....:..
[jcc][t4] 0020   0000000B                            ....              ....            
[jcc][t4] 
[jcc][t4] [time:2007-06-20-17:39:30.967][thread:main][tracepoint:101]Request flushed.

From the JCC trace taken on the client side we can see that the last operation performed is executeUpdate() when calling the stored procedure JASON.TEST_JAVASP(?) using the input value 11. The DRDA buffers show that we send EXCSQLSTT (execute SQL statement) and SQLDTA (SQL Data) when the trace ends. Since nothing else was returned to the client, the server side should be investigated to determine why nothing was returned. Note that assistance from the DB2 database administrator may be required since the application developer usually does not have access to the server. For more details on DRDA flows please see the Resources section.

On the server side, there are multiple methods to display application information such as using db2pd -applications -db sample, db2 "list applications show detail", etc... In our case we choose to collect an application snapshot to find out what is happening. In the example below the JCC application is connecting from the client IP address 10.1.1.123 port 2582. If the application was on the same system as the DB2 database then Inbound communication address = *LOCAL.hostname . To identify an application from the snapshot the application developer would need to know the application name, userid and database it is connecting to.

Listing 16. Using snapshots to find PID of db2agent associated with application
            Application Snapshot

Application handle                         = 7
Application status                         = UOW Executing
Status change time                         = Not Collected
Application code page                      = 819
Application country/region code            = 0
DUOW correlation token                     = GA123456.GA16.070622200608
Application name                           = db2jcc_application
Application ID                             = GA123456.GA16.070622200608
Sequence number                            = 0003
TP Monitor client user ID                  =
TP Monitor client workstation name         = majason1
TP Monitor client application name         =
TP Monitor client accounting string        =

Connection request start timestamp         = 06/22/2007 16:06:08.388356
Connect request completion timestamp       = 06/22/2007 16:06:08.865863
Application idle time                      = Not Collected
CONNECT Authorization ID                   = J2MA
Client login ID                            = J2MA
Configuration NNAME of client              = majason1
Client database manager product ID         = JCC03020
Process ID of client application           = 0
Platform of client application             = Unknown via DRDA
Communication protocol of client           = TCP/IP

Inbound communication address              = 10.1.1.123 2582
...
Coordinator agent process or thread ID     = 340630 
...

Based on the snapshot information we see that PID 340630 is the db2agent process servicing the call to the stored procedure. However since this is a Java stored procedure it will be run as a fenced stored procedure in a db2fmp process by default. On a threaded system such as Windows this would be a thread ID.

We can use db2pd -fmp to find the db2fmp process executing the stored procedure on behalf of the db2agent. Below we see thread 2571 (0xA0B) in db2fmp PID 313092 is running the Java stored procedure for db2agent PID 340630.

Listing 17. Finding PID of db2fmp associated with application
/home/j2ma/sqllib/db2dump: db2pd -fmp

Database Partition 0 -- Active -- Up 0 days 00:00:30 -- Date 06/27/2007 15:22:43

FMP:
Pool Size:       0
Max Pool Size:   225
Keep FMP:        YES
Initialized:     YES
Trusted Path:    /home/j2ma/sqllib/function/unfenced
Fenced User:     j2ma

FMP Process:
Address            FmpPid     Bit   Flags      ActiveThrd PooledThrd Active
0x078000000016CEA0 313092     64    0x00000003 1          0          No   

   Active Threads:
   Address            FmpPid     EduPid     ThreadId  
   0x078000000016D020 313092     340630     2571      

   Pooled Threads:
   Address            FmpPid     ThreadId  
   No pooled threads.

Now that we know which PID is running the db2fmp we can terminate this process if it is consuming too many resources. If we want to investigate further db2pd -stacks would create a trap file for every DB2 process. Or we can issue kill -36 313092. The signal sent to generate an informational trap file differs between each UNIX platform.

Listing 18. Trap file t313092.000 generated
*******************************************
* A db2fmp process received a sigpre      *
* signal                                  *
*******************************************
* Master Thread TID: 00000001             *
* Waiter Thread TID: 00002314        *
* Number of worker threads in process 00000001 *
* db2fmp flags 0000000f                   *
* thread list *****************************
* Thread TID: 00002571                    *
*******************************************
8.1.0.128 s061108 SQL08027
timestamp: 2007-06-27-15.39.55.254086
instance name: j2ma.000
EDU name     : db2fmp (Java)
Signal #36
uname: S:AIX R:2 V:5 M:0009028F4C00 N:panipuri
process id: 313092
thread id : 2314 (0x90A)
...
...  
<StackTrace>
-------Frame------ ------Function + Offset------
0x000000000000377C ?unknown + 0x0
0x090000000027B54C _event_sleep + 0x9C
0x090000000027BAB0 _event_wait + 0x60
0x0900000000287A5C _cond_wait_local + 0x308
0x0900000000287FD0 _cond_wait + 0x44
0x0900000000288848 pthread_cond_timedwait + 0x25C
0x09000000192C3478 sqloAppWaitOnSync + 0x19C
0x090000001954DACC sqle<ProcessObjects>


timestamp: 2007-06-27-15.39.56.253815
instance name: j2ma.000
EDU name     : db2fmp (Java)
Signal #36
uname: S:AIX R:2 V:5 M:0009028F4C00 N:panipuri
process id: 313092
thread id : 258 (0x102)
kthread id : 397831

<StackTrace>
-------Frame------ ------Function + Offset------
0x000000000000377C ?unknown + 0x0
0x0900000000280724 _p_nsleep + 0xC
0x09000000000350B4 nsleep + 0xAC
0x0900000000040964 sleep + 0x58
0x090000001F9E1E50 sysSignalWait + 0x70
0x090000003170283C signalDispatcherThread + 0xE4
0x0900000031703C58 xmExecuteThread + 0x234
0x090000003170852C threadStart + 0x30
0x090000001F9CCEC4 _start + 0x64
0x0900000000271508 _pthread_body + 0xBC
</StackTrace>

The stacks provide limited information because stored procedures are processes independent of DB2 used to run the application developer's code. We can see that DB2 called the JVM to execute the Java SP. Ideally to diagnose further the application developer should add debug code to their Java SP. An alternative is to generate a javacore file for the db2fmp process to provide additional information.

Since we have already enabled Javacores and found the PID of the db2fmp process executing the stored procedure, we can now generate a javacore. DB2 will dump the javacore file into its db2diag.log instead of a separate javacore file. The javacore must be parsed out using the grep command.

Listing 19. Generating javacore and parsing db2diag.log
$ kill -QUIT <PID of db2fmp>
$ grep MESSAGE /home/j2ma/sqllib/db2dump/db2diag.log >javadump.txt

After generating the javacore search the javacore for native ID:0xA0B. Remember this was the thread id output from db2pd -fmp converted from 2571 (decimal) to 0xA0B (hex). Thread 0xA0B is the one executing the Java stored procedure which hung. It is stuck in line 31 of our application. Referring to the source code in Listing 21 it is in the infinite while(1) loop.

Listing 20.Javacore file
MESSAGE : JVMDG303: JVM Requesting Java core file
MESSAGE : NULL           -----------------------------------------------------------------
MESSAGE : 0SECTION       TITLE subcomponent dump routine
MESSAGE : NULL           ===============================
MESSAGE : 1TISIGINFO     signal 3 received 
MESSAGE : 1TIDATETIME    Date:                 2007/06/27 at 15:24:58
MESSAGE : 1TIFILENAME    Javacore filename:    /db1/j2ma/javacore313092.1182972298.txt
MESSAGE : 0SECTION       XHPI subcomponent dump routine
MESSAGE : NULL           ==============================
MESSAGE : 1XHTIME        Wed Jun 27 15:24:58 2007
MESSAGE : 1XHSIGRECV     SIGQUIT received at 0x7cdb02a639e00002 in <unknown>.
MESSAGE : 1XHFULLVERSION J2RE 1.4.2 IBM AIX 5L for PowerPC (64 bit JVM) 
	build caix64142-20040917
MESSAGE : NULL    
...
...
MESSAGE : 1XMTHDINFO     All Thread Details
MESSAGE : NULL           ------------------
MESSAGE : NULL           
MESSAGE : 2XMFULLTHDDUMP Full thread dump Classic VM (J2RE 1.4.2 IBM AIX 5L for PowerPC 
(64 bit JVM) build caix64142-20040917, native threads):
MESSAGE : 3XMTHREADINFO      "Thread-0" (TID:0x7000000000B8B78, sys_thread_t:0x1130B7340, 
state:R, native ID:0xA0B) prio=5
MESSAGE : 4XESTACKTRACE           at TEST_JAVASP.tEST_JAVASP(TEST_JAVASP.java:31)
MESSAGE : 3XHNATIVESTACK       Native Stack
MESSAGE : NULL                 ------------
...
Listing 21.Source code of stored procedure
1: /* Java stored procedure to insert a value into the database.
2:  * It will hang if it receives the value 11.
3:  * Inputs: input value (integer)
4:  * Ouputs: None
5:  */
6:
7:
8:    import java.sql.*;
9: 
10:   public class TEST_JAVASP
11:   {
12:     public static void tEST_JAVASP  (int input) throws SQLException,
13: 	Exception
14:     {
15:       int errorCode;
16:  
17:      try
18:      {
19:        // get caller's connection to the database
20:   	Connection con = DriverManager.getConnection("jdbc:default:connection");
21:     
22:        String query = "INSERT INTO T1 (C1) VALUES (?)";
23:
24:        PreparedStatement pstmt = con.prepareStatement(query);
25:        pstmt.setInt(1, input);
26:        pstmt.executeUpdate();
27:  
28:  	/* Cause the stored proc to not return if input value is 11 */
29:  	if( input == 11)
30:  	{
31:  	  while(true); 	
32:  	}
33:      }   
34:      catch (SQLException sqle)
35:      {
36:        errorCode = sqle.getErrorCode();
37:        throw new SQLException( errorCode + " FAILED" ); 
38:      }
39:    }
40:  }

Diagnosing network issues with Java applications

Listing 22 executes the JDBC application in the environment further below. For some unknown reason the Java application seems to hang. Let us find out what went wrong.

Client: Legacy JDBC Type 2 Application running on Windows DB2 v9.1

Server: AIX DB2 v8.x (stored procedure is on this system)

Listing 22. Running a Java application
D:\java>java CallTestJavaSPT2 sample majason 12345678
URL is: jdbc:db2:p6db
Trying to connect using Legacy JDBC T2 driver
Connected to database
	
Inserting value 9 into database...
Done inserting value 9
Inserting value 10 into database...
Done inserting value 10
Inserting value 11 into database...

(Ctrl-C executed from client side after a few seconds since the program above seems 
 to hang and never return.)

First thing to do is collect traces on the client side or the system where the application is run. Based on Figure 1 we see that JDBC Type 2 applications go through DB2's CLI layer before reaching the DB2 client-side code. Thus we would collect a concurrent CLI, DB2 and DRDA trace with the timestamp options enabled for the CLI and DB2 trace.

CLI trace shows we are calling CALL TEST_JAVASP(?) stored procedure using a parameter marker. This stored procedure is called three times with different values. We can see that the parameter marker ? is bound once and then the SQL statement is executed three times because there are three calls to SQLExecute() after SQLBindParameter(). Each time SQLExecute() is called we can see the value used for the parameter marker. This value is labeled as iPar (input parameter number) and rgbValue (input parameter value). So for the first iteration is rgbValue=9, followed by rgbValue=10 and finally rgbValue=11 when it hangs.

Listing 23. CLI Trace, input value rgbValue=9
...
[1184187845.736027 - 07/11/2007 17:04:05.736027] 
	SQLPrepareW( hStmt=1:1, pszSqlStr="CALL TEST_JAVASP(?)", cbSqlStr=19 )
[1184187845.748055 - 07/11/2007 17:04:05.748055]     
	---> Time elapsed - +5.700000E-003 seconds
[1184187845.752649 - 07/11/2007 17:04:05.752649] ( StmtOut="CALL TEST_JAVASP(?)" )
[1184187845.758786 - 07/11/2007 17:04:05.758786] 

[1184187845.761948 - 07/11/2007 17:04:05.761948] SQLPrepareW( )
[1184187845.765148 - 07/11/2007 17:04:05.765148]     
	<--- SQL_SUCCESS   Time elapsed - +2.912100E-002 seconds

[1184187845.768377 - 07/11/2007 17:04:05.768377] SQLNumParams( hStmt=1:1, pcPar=&0007f994)
[1184187845.777452 - 07/11/2007 17:04:05.777452]     
	---> Time elapsed - +3.229000E-003 seconds

[1184187845.780470 - 07/11/2007 17:04:05.780470] SQLNumParams( pcPar=1 )
[1184187845.786270 - 07/11/2007 17:04:05.786270]     
	<--- SQL_SUCCESS   Time elapsed - +1.789300E-002 seconds

[1184187845.802512 - 07/11/2007 17:04:05.802512] SQLBindParameter( hStmt=1:1, iPar=1, 
	fParamType=SQL_PARAM_INPUT, fCType=SQL_C_LONG, fSQLType=SQL_INTEGER, cbColDef=0, 
		ibScale=0, rgbValue=&0b7bb808, cbValueMax=4, pcbValue=&0b7bb804 )
[1184187845.835867 - 07/11/2007 17:04:05.835867]    
	 ---> Time elapsed - +1.624200E-002 seconds

[1184187845.839286 - 07/11/2007 17:04:05.839286] SQLBindParameter( )
[1184187845.842363 - 07/11/2007 17:04:05.842363]     
	 <--- SQL_SUCCESS   Time elapsed - +3.985100E-002 seconds

[1184187845.845624 - 07/11/2007 17:04:05.845624] SQLExecute( hStmt=1:1 )
[1184187845.851609 - 07/11/2007 17:04:05.851609]     
	---> Time elapsed - +3.261000E-003 seconds
[1184187845.854865 - 07/11/2007 17:04:05.854865] 
	( Package="SYSSH200          ", Section=4 )
[1184187845.863376 - 07/11/2007 17:04:05.863376] 
[1184187845.880312 - 07/11/2007 17:04:05.880312] 
	( Row=1, iPar=1, fCType=SQL_C_LONG, rgbValue=9, pcbValue=4, piIndicatorPtr=4 )
[1184187845.901568 - 07/11/2007 17:04:05.901568] 
    sqlccsend( Handle - 192938080 )
    sqlccsend( ulBytes - 435 )
    sqlccsend( ) rc - 0, time elasped - +7.000000E-005
    sqlccrecv( timeout - +0.000000E+000 )
    sqlccrecv( ulBytes - 198 ) - rc - 0, time elapsed - +3.571100E-001
[1184187846.270909 - 07/11/2007 17:04:06.270909] ( return=0 )
[1184187846.277250 - 07/11/2007 17:04:06.277250] 
[1184187846.280375 - 07/11/2007 17:04:06.280375] ( COMMIT REQUESTED=1 )
[1184187846.286339 - 07/11/2007 17:04:06.286339] 
    sqlccsend( Handle - 192938080 )
    sqlccsend( ulBytes - 10 )
    sqlccsend( ) rc - 0, time elasped - +6.400000E-005
    sqlccrecv( timeout - +0.000000E+000 )
    sqlccrecv( ulBytes - 54 ) - rc - 0, time elapsed - +4.342000E-003
[1184187846.306069 - 07/11/2007 17:04:06.306069] ( COMMIT REPLY RECEIVED=1 )
[1184187846.312165 - 07/11/2007 17:04:06.312165] 

[1184187846.315283 - 07/11/2007 17:04:06.315283] SQLExecute( )
[1184187846.318434 - 07/11/2007 17:04:06.318434]     
	<--- SQL_SUCCESS   Time elapsed - +4.728100E-001 seconds
Listing 24. CLI Trace, input value rgbValue=10
...
[1184187846.369625 - 07/11/2007 17:04:06.369625] SQLExecute( hStmt=1:1 )
[1184187846.375663 - 07/11/2007 17:04:06.375663]     
	---> Time elapsed - +6.313000E-003 seconds
[1184187846.378759 - 07/11/2007 17:04:06.378759] 
	( Row=1, iPar=1, fCType=SQL_C_LONG, rgbValue=10, pcbValue=4, piIndicatorPtr=4 )
[1184187846.401220 - 07/11/2007 17:04:06.401220] 
    sqlccsend( Handle - 192938080 )
    sqlccsend( ulBytes - 157 )
    sqlccsend( ) rc - 0, time elasped - +6.700000E-005
    sqlccrecv( timeout - +0.000000E+000 )
    sqlccrecv( ulBytes - 80 ) - rc - 0, time elapsed - +8.489000E-003
[1184187846.422672 - 07/11/2007 17:04:06.422672] ( return=0 )
[1184187846.428435 - 07/11/2007 17:04:06.428435] 
[1184187846.432088 - 07/11/2007 17:04:06.432088] ( COMMIT REQUESTED=1 )
[1184187846.438348 - 07/11/2007 17:04:06.438348] 
    sqlccsend( Handle - 192938080 )
    sqlccsend( ulBytes - 10 )
    sqlccsend( ) rc - 0, time elasped - +6.100000E-005
    sqlccrecv( timeout - +0.000000E+000 )
    sqlccrecv( ulBytes - 54 ) - rc - 0, time elapsed - +3.608000E-003
[1184187846.454256 - 07/11/2007 17:04:06.454256] ( COMMIT REPLY RECEIVED=1 )
[1184187846.460343 - 07/11/2007 17:04:06.460343] 

[1184187846.464846 - 07/11/2007 17:04:06.464846] SQLExecute( )
[1184187846.468118 - 07/11/2007 17:04:06.468118]     
	<--- SQL_SUCCESS   Time elapsed - +9.849300E-002 seconds
...
...
Listing 25. CLI Trace, input value rgbValue=11
...
[1184187846.519822 - 07/11/2007 17:04:06.519822] SQLExecute( hStmt=1:1 )
[1184187846.526027 - 07/11/2007 17:04:06.526027]     
	---> Time elapsed - +6.523000E-003 seconds
[1184187846.529060 - 07/11/2007 17:04:06.529060] 
	( Row=1, iPar=1, fCType=SQL_C_LONG, rgbValue=11, pcbValue=4, piIndicatorPtr=4 )
[1184187846.549404 - 07/11/2007 17:04:06.549404] 
    sqlccsend( Handle - 192938080 )
    sqlccsend( ulBytes - 157 )
    sqlccsend( ) rc - 0, time elasped - +7.100000E-005
    sqlccrecv( timeout - +0.000000E+000 )

During the third iteration the CLI trace ends after SQLExecute(). Next step is to simplify and remove the application from the picture. We can create a DB2 script to perform the same function as above.

Listing 26. test.db2
connect to sample user db2inst1 using 12345678;
call test_javasp(9);
call test_javasp(10);
call test_javasp(11);
terminate;

Executing the script on the server side would help to isolate the issue to a client-side or server-side issue. If the script runs fine on the client side then it should be run on the server side. If it hangs running on the server side then the stored procedure will need to be investigated.

For our example lets assume the script runs fine from the server side but fails on the client side. Since the script failed to run on the client side we can rule out any problems with the application layer i.e. JDBC to DB2 CLI interface since the DB2 CLP bypasses the application layer. We can also rule out the server side as well.

Referring again to Figure 1. We see that underneath the application layer is the DB2 client and the DRDA communications layer. Thus we will proceed to investigate these two layers for network delays by reviewing the DB2 and DRDA trace. Any other possible problems should be reviewed by DB2 Technical support.

Open the DRDA trace and find the trace point where we are sending CALL TEST_JAVASP(?) with the input parameters. We can see that each iteration of the input value corresponds to its own DB2 trace point. FDODTA=9 at tracepoint 49130, FDODTA=10 at tracepoint 50460 and finally FDODTA=11 at tracepoint 51714. Note that in DRDA terminology the AR (Application Requestor) is the client and the AS (Application Server) is the server. More information can be found in the Resources section regarding the DRDA flows sent between the client and server.

Listing 27. DRDA trace for CALL TEST_JAVASP(9)
49130	data DB2 UDB DRDA Communication Manager sqljcSend fnc (3.3.54.5.0.1177)
	pid 2088 tid 2484 cpid 526 node 0 sec 223545 nsec 574400066 probe 1177
	bytes 452

  SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 35  CORR: 0003  CHAINED: y  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLSTT - SQL Statement
      LL: 29    CP: 2414   
      DATA:                              (ASCII)          (EBCDIC)
      000000001343414C 4C20544553545F4A  .....CALL TEST_J .......<<.....^[
      4156415350283F29 FF                AVASP(?).        ....&....
 ...
 ...
   SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 36  CORR: 0004  CHAINED: n  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLDTA - SQL Program Variable Data
      LL: 30    CP: 2412   
      NM: FDODSC - FD:OCA Data Descriptor
        LL: 16    CP: 0010   
         N-GDA Len: 06 Type: 76 ID: D0
            Var[00] Type: 0X03 Len: 0X0004
        Footer: Length: 6
        DATA:                              (ASCII)          (EBCDIC)
        0671E4D00001                       .q....           ..U}..
      NM: FDODTA - FD:OCA Data
        LL: 10    CP: 147A   
        DATA:                              (ASCII)          (EBCDIC)
        000009000000                       ......           ......

We see SEND (AR) which is the send buffer from the client. SQLDTA (SQL DATA structure) says we are putting in 9 for the parameter marker in CALL TEST_JAVASP(?)

Listing 28. DRDA trace for CALL TEST_JAVASP(10)
50460	data DB2 UDB DRDA Communication Manager sqljcSend fnc (3.3.54.5.0.1177)
	pid 2088 tid 2484 cpid 526 node 0 sec 223546 nsec 533380764 probe 1177
	bytes 174

	SEND BUFFER(AR):

            EXCSQLSTT RQSDSS                 (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0079D05100010073 200B004421135341   .y.Q...s ..D!.SA  .`}.............
  0010  4D504C4520202020 2020202020202020   MPLE              (&<.............
  0020  4E554C4C49442020 2020202020202020   NULLID            +.<<............
  0030  2020535953534832 3030202020202020     SYSSH200        ................
  0040  202020205359534C 564C303100040005       SYSLVL01....  .......<.<......
  0050  2105F100052111F1 0008211400007FFF   !....!....!.....  ..1....1......".
  0060  00062141FFFF0006 2140FFFF00052142   ..!A....!@....!B  ......... ......
  0070  C000081900800000 00                 .........         {........

            SQLDTA OBJDSS                    (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0024D0030001001E 2412001000100676   .$......$......v  ..}.............
  0010  D00300040671E4D0 0001000A147A0000   .....q.......z..  }.....U}.....:..
  0020  0A000000                            ....              ....

  SEND(AR) RQSDSS - Request Data Stream Structure
  LL: 121  CORR: 0001  CHAINED: y  CONT ON ERR: n  SAME CORR FOR NEXT DSS: y  

    NM: EXCSQLSTT - Execute SQL Statement
      LL: 115    CP: 200B   
      NM: PKGNAMCSN - RDB Pkg Name, Const Tkn & Sec Num
        LL: 68    CP: 2113   
        * RDBNAM - Relational Database Name
          ASCII: SAMPLE            
          EBCDIC: ..(&<.............
        * RDBCOLID - RDB Collection Identifier
          ASCII: NULLID            
          EBCDIC: +.<<..............
        * PKGID - RDB Package Identifier
          ASCII: SYSSH200          
          EBCDIC: ..................
        * PKGCNSTKN - RDB Package Consistency Token
          DATA:                              (ASCII)          (EBCDIC)
          5359534C564C3031                   SYSLVL01         ...<.<..
        * PKGSN - RDB Package Section Number
          DECIMAL:     4
          HEXADECIMAL: 0004
      NM: RDBCMTOK - RDB Commit Allowed
        LL: 5    CP: 2105   
        BOOLEAN: TRUE
      NM: OUTEXP - Output Expected
        LL: 5    CP: 2111   
        BOOLEAN: TRUE
      NM: QRYBLKSZ - Query Block Size
        LL: 8    CP: 2114   
        DECIMAL:     32767
        HEXADECIMAL: 00007FFF
      NM: MAXBLKEXT - Maximum Number of Extra Blocks
        LL: 6    CP: 2141   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: MAXRSLCNT - Maximum Result Set Count
        LL: 6    CP: 2140   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: RSLSETFLG - Result Set Flags
        LL: 5    CP: 2142   
        FLAG: 0XC0Return Names, Return Labels, 
      NM: MONITOR - Monitor
        LL: 8    CP: 1900   
        DECIMAL:     -2147483648
        HEXADECIMAL: 80000000

  SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 36  CORR: 0001  CHAINED: n  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLDTA - SQL Program Variable Data
      LL: 30    CP: 2412   
      NM: FDODSC - FD:OCA Data Descriptor
        LL: 16    CP: 0010   
         N-GDA Len: 06 Type: 76 ID: D0
            Var[00] Type: 0X03 Len: 0X0004
        Footer: Length: 6
        DATA:                              (ASCII)          (EBCDIC)
        0671E4D00001                       .q....           ..U}..
      NM: FDODTA - FD:OCA Data
        LL: 10    CP: 147A   
        DATA:                              (ASCII)          (EBCDIC)
        00000A000000                       ......           ......

Now it is 10 (decimal) or 0xA (hex). From the corresponding flow file (trace.flw) with timestamps we can see that we call sqlcctcpsend() which is a wrapper to the operating system's TCP/IP API to send data. This send took less than 1 second. If there is a network delay it should show up here.

Listing 29. trace.flw
50480         33:650976401   | | | | | clientCommCallback exit
50481         33:650984989   | | | | sqljcSend exit
50482         33:650989272   | | | | sqljrRecv entry
50483         33:650989982   | | | | | sqljcReceive entry
50484         33:650993253   | | | | | | clientCommCallback entry
50485         33:651003619   | | | | | | | CLI_utlGetInfo entry
50486         33:651005423   | | | | | | | CLI_utlGetInfo exit
50487         33:651008072   | | | | | | | sqlrxf2a entry
50488         33:651021647   | | | | | | | sqlrxf2a data [probe 4]
50489         33:651022705   | | | | | | | sqlrxf2a exit
50490         33:656536851   | | | | | | clientCommCallback exit
50491         33:656547857   | | | | | | sqlccrecv entry
50492         33:656549136   | | | | | | sqlccrecv data [probe 1]
50493         33:656551339   | | | | | | sqlccrecv data [probe 2]
50494         33:656551992   | | | | | | sqlccrecv data [probe 3]
50495         33:656552653   | | | | | | sqlccrecv data [probe 4]
50496         33:656553245   | | | | | | sqlccrecv data [probe 120]
50497         33:656554490   | | | | | | sqlccrecv data [probe 130]
50498         33:656556542   | | | | | | | sqlcctcprecv entry
50499         33:656557298   | | | | | | | sqlcctcprecv data [probe 1]
50500         33:656561269   | | | | | | | |  tcprecv entry 
50501         33:237234851   | | | | | | | | tcprecv data [probe 2] 
50502         33:237247868   | | | | | | | |  tcprecv exit 
50503         33:237256312   | | | | | | | sqlcctcprecv exit
50504         33:237258748   | | | | | | sqlccrecv data [probe 5]
50505         33:237259658   | | | | | | sqlccrecv exit
Listing 30. DRDA trace for CALL TEST_JAVASP(11)
 51714	data DB2 UDB DRDA Communication Manager sqljcSend fnc (3.3.54.5.0.1177)
	pid 2088 tid 2484 cpid 526 node 0 sec 223546 nsec 816354478 probe 1177
	bytes 174

	SEND BUFFER(AR):

            EXCSQLSTT RQSDSS                 (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0079D05100010073 200B004421135341   .y.Q...s ..D!.SA  .`}.............
  0010  4D504C4520202020 2020202020202020   MPLE              (&<.............
  0020  4E554C4C49442020 2020202020202020   NULLID            +.<<............
  0030  2020535953534832 3030202020202020     SYSSH200        ................
  0040  202020205359534C 564C303100040005       SYSLVL01....  .......<.<......
  0050  2105F100052111F1 0008211400007FFF   !....!....!.....  ..1....1......".
  0060  00062141FFFF0006 2140FFFF00052142   ..!A....!@....!B  ......... ......
  0070  C000081900800000 00                 .........         {........

            SQLDTA OBJDSS                    (ASCII)           (EBCDIC)
         0 1 2 3 4 5 6 7  8 9 A B C D E F   0123456789ABCDEF  0123456789ABCDEF
  0000  0024D0030001001E 2412001000100676   .$......$......v  ..}.............
  0010  D00300040671E4D0 0001000A147A0000   .....q.......z..  }.....U}.....:..
  0020  0B000000                            ....              ....

  SEND(AR) RQSDSS - Request Data Stream Structure
  LL: 121  CORR: 0001  CHAINED: y  CONT ON ERR: n  SAME CORR FOR NEXT DSS: y  

    NM: EXCSQLSTT - Execute SQL Statement
      LL: 115    CP: 200B   
      NM: PKGNAMCSN - RDB Pkg Name, Const Tkn & Sec Num
        LL: 68    CP: 2113   
        * RDBNAM - Relational Database Name
          ASCII: SAMPLE            
          EBCDIC: ..(&<.............
        * RDBCOLID - RDB Collection Identifier
          ASCII: NULLID            
          EBCDIC: +.<<..............
        * PKGID - RDB Package Identifier
          ASCII: SYSSH200          
          EBCDIC: ..................
        * PKGCNSTKN - RDB Package Consistency Token
          DATA:                              (ASCII)          (EBCDIC)
          5359534C564C3031                   SYSLVL01         ...<.<..
        * PKGSN - RDB Package Section Number
          DECIMAL:     4
          HEXADECIMAL: 0004
      NM: RDBCMTOK - RDB Commit Allowed
        LL: 5    CP: 2105   
        BOOLEAN: TRUE
      NM: OUTEXP - Output Expected
        LL: 5    CP: 2111   
        BOOLEAN: TRUE
      NM: QRYBLKSZ - Query Block Size
        LL: 8    CP: 2114   
        DECIMAL:     32767
        HEXADECIMAL: 00007FFF
      NM: MAXBLKEXT - Maximum Number of Extra Blocks
        LL: 6    CP: 2141   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: MAXRSLCNT - Maximum Result Set Count
        LL: 6    CP: 2140   
        DECIMAL:     -1
        HEXADECIMAL: FFFFFFFF
      NM: RSLSETFLG - Result Set Flags
        LL: 5    CP: 2142   
        FLAG: 0XC0Return Names, Return Labels, 
      NM: MONITOR - Monitor
        LL: 8    CP: 1900   
        DECIMAL:     -2147483648
        HEXADECIMAL: 80000000

  SEND(AR) OBJDSS - Object Data Stream Structure
  LL: 36  CORR: 0001  CHAINED: n  CONT ON ERR: n  SAME CORR FOR NEXT DSS: n  

    NM: SQLDTA - SQL Program Variable Data
      LL: 30    CP: 2412   
      NM: FDODSC - FD:OCA Data Descriptor
        LL: 16    CP: 0010   
         N-GDA Len: 06 Type: 76 ID: D0
            Var[00] Type: 0X03 Len: 0X0004
        Footer: Length: 6
        DATA:                              (ASCII)          (EBCDIC)
        0671E4D00001                       .q....           ..U}..
      NM: FDODTA - FD:OCA Data
        LL: 10    CP: 147A   
        DATA:                              (ASCII)          (EBCDIC)
        00000B000000                       ......           ......

In the last iteration (Listing 30) when calling the stored procedure with 11 (decimal) or B (hex) we find tracepoint 51714 in the DRDA trace which corresponds to the same tracepoint in the flow file. Inside we see that a send was performed but during tcprecv() (TCP/IP receive) there is a delay of ~7s between tracepoints 51754 and 51755. This indicates that the issue is external to DB2 and should be investigated by the network administrator. The issue could lie within the operating system's TCP/IP stack or a network device (i.e. firewall, load-balancing device, router, etc...) between the client and server.

Listing 31. trace.flw
51714         33:922051842   | | | | sqljcSend data [probe 1177]
...
51735         33:934285388   | | | | sqljcSend exit
51736         33:934290007   | | | | sqljrRecv entry
51737         33:934290717   | | | | | sqljcReceive entry
51738         33:934294324   | | | | | | clientCommCallback entry
51739         33:934304206   | | | | | | | CLI_utlGetInfo entry
51740         33:934306048   | | | | | | | CLI_utlGetInfo exit
51741         33:934309009   | | | | | | | sqlrxf2a entry
51742         33:934322190   | | | | | | | sqlrxf2a data [probe 4]
51743         33:934323299   | | | | | | | sqlrxf2a exit
51744         33:939817767   | | | | | | clientCommCallback exit
51745         33:939828871   | | | | | | sqlccrecv entry
51746         33:939830244   | | | | | | sqlccrecv data [probe 1]
51747         33:939832445   | | | | | | sqlccrecv data [probe 2]
51748         33:939833093   | | | | | | sqlccrecv data [probe 3]
51749         33:939833764   | | | | | | sqlccrecv data [probe 4]
51750         33:939834387   | | | | | | sqlccrecv data [probe 120]
51751         33:939835606   | | | | | | sqlccrecv data [probe 130]
51752         33:939837978   | | | | | | | sqlcctcprecv entry
51753         33:939838688   | | | | | | | sqlcctcprecv data [probe 1]
51754       33:939842723   | | | | | | | | tcprecv entry
51755      154:211882227   | | | | | | | | tcprecv data [probe 2]
51756        154:211896294   | | | | | | | | tcprecv exit
51757        154:211904245   | | | | | | | sqlcctcprecv exit
51758        154:211906988   | | | | | | sqlccrecv data [probe 5]
51759        154:211907763   | | | | | | sqlccrecv exit
...

Diagnosing authentication issues

When a user connects to a database or attaches to a DB2 instance, the authentication is performed by a security facility outside of DB2. The security facility is usually provided by the operating system on which DB2 resides. Depending on the configuration, the authentication can be done on server or client. DB2 supports various methods of authentication. Further authentication information can be found in the DB2 Information Center, from the link in the Resources section.

A user which is on the same system as the database can connect using an implicit connect in which no user id and password are required or explicit connect in which a user id and password must be used. Connections to remote databases will usually require an explicit connect unless the server was configured for client authentication. When troubleshooting authentication issues, do not use an implicit connect because this bypasses any authentication mechanisms.

Troubleshooting authentication issues should be performed from outside the Java application via the DB2 CLP. Assuming that authentication has been configured to take place on the server. If an implicit connect executes quickly but an explicit connect exhibits a slow connect then there is likely a performance issue with authentication. Another indication of an authentication performance issue is that the initial time needed to establish a connect takes a long time, but there is no query response degradation for subsequent queries.

Listing 32. Explicit versus implicit authentication
$ db2 "connect to sample user db2inst1 using mypassword"

   Database Connection Information

 Database server        = DB2/AIX64 8.2.7
 SQL authorization ID   = DB2INST1
 Local database alias   = SAMPLE

$ db2 "connect to sample"

   Database Connection Information

 Database server        = DB2/AIX64 8.2.7
 SQL authorization ID   = DB2INST1
 Local database alias   = SAMPLE

On the AIX platform, DB2 uses the OS API getpwnam_r to get the user attributes. The AIX OS API getpwnam_r is a thread safe version of getpwnam. Following sample C program demonstrates the getpwnam_r and getpwnam calls.

Listing 33. Sample program calling O/S authentication APIs
#include <stdio.h>
#include <sys/types.h>
#include <pwd.h>
#include <errno.h>
#include <stdlib.h>
#include <unistd.h>
int main(int argc, char *argv[]) 
{ 
	int err = 0; 
	int rc = 0; 
	struct passwd *pResult = NULL; 
	struct passwd passwordData; 
	char *pBuffer = (char *)malloc(256); 
	if (argc != 2) 
	{ 
		printf("Usage: %s <userid> \n", argv[0]); 
		exit (1); 
	} 
	pResult = getpwnam(argv[1]); 
	if (pResult == NULL) 
	{ 
		err = errno; 
		printf("\n1: err: %d", err);
	} 
	else 
	{ 
		printf("getpwnam returned OK. \n"); 
	} 

	rc = getpwnam_r(argv[1], 
	&passwordData, 
	pBuffer, 
	256, 
	&pResult); 
	if ((rc != 0) || (pResult == NULL)) 
	{ 
		err = errno; 
		printf("\n2: err: %d, rc: %d\n", err, rc); 
	} 
	else 
	{ 
		printf("getpwnam_r returned OK. \n");
	} 
}

Save the code above as testgetpwnam.C and compile it generating the executable a.out. The command runs the program a.out that looks up user bianca and writes the amount of real, user, and system time to standard error.

Listing 34. Executing testgetpwnam program
$ xlc testgetpwnam.C

$ time ./a.out bianca

getpwnam returned OK.
getpwnam_r returned OK.

real 0m0.80s 
user 0m0.01s 
sys 0m0.00s

The output of ./a.out bianca shows user bianca is found by operating system calls getpwnam() and getpwnam_r() in addition to the time spent during execution. If execution time appears to be excessive, the AIX admin should be engaged to investigate the cause of delay that occurred in AIX

On the Windows platform, DB2 supports access tokens. Because access tokens are cached, this increases authentication performance. The access token support is enabled by using by setting the DB2 registry variable DB2_GRP_LOOKUP to TOKEN, TOKENLOCAL or TOKENDOMAIN. Access token support can be enabled with all authentication types except CLIENT authentication.

Listing 35. Windows authentication DB2 registry variables
db2set DB2_GRP_LOOKUP=,TOKEN
db2set DB2_GRP_LOOKUP=LOCAL,TOKENLOCAL
db2set DB2_GRP_LOOKUP=DOMAIN,TOKENDOMAIN

More information on DB2 access tokens can be found DB2 Information Center. Link from the

Resources

section of this article.

Numerous applications making frequent short connections to DB2 server using SERVER_ENCRYPT authentication will experience performance degradation due to overhead associated with encryption/decryption. The obvious solution is to set authentication to SERVER, so that there is no need for decryption/encryption. However, if authentication cannot be set to SERVER due to security reasons, modify the applications to make less frequent long connections or utilize connection pooling

Conclusion

Application performance problem determination is not trivial and can be further complicated by complexity of the environment. As the complexity of the environment increases, so is the effort expended to isolate the problem. This article demonstrated numerous tools to help isolate the components causing a performance bottleneck. We've looked at test cases of Java applications, Java routines, and networks for determining the causes of performance issues. We have also discussed diagnosing authentication performance problems on various platforms.

There is more than one way to isolate an application performance problem. With the use of the trace facilities and test cases demonstrated in this article, the application developer and database administrator should be able to formulate plans to diagnose various types of performance problems.

Acknowledgements

Special thanks to John Chun, Christine Law, Paolo Cirone, and Shakeb Shere for reviewing this article.

Resources

Learn

Get products and technologies

Comments

developerWorks: Sign in

Required fields are indicated with an asterisk (*).


Need an IBM ID?
Forgot your IBM ID?


Forgot your password?
Change your password

By clicking Submit, you agree to the developerWorks terms of use.

 


The first time you sign into developerWorks, a profile is created for you. Information in your profile (your name, country/region, and company name) is displayed to the public and will accompany any content you post, unless you opt to hide your company name. You may update your IBM account at any time.

All information submitted is secure.

Choose your display name



The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerWorks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

Required fields are indicated with an asterisk (*).

(Must be between 3 – 31 characters.)

By clicking Submit, you agree to the developerWorks terms of use.

 


All information submitted is secure.

Dig deeper into Information management on developerWorks


static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=Information Management, Java technology
ArticleID=248880
ArticleTitle=Determining performance problems with DB2 Java applications
publish-date=08162007