Nov 8, 2009

How to troubleshoot J2CA0045E connection pooling problems

Part 1:
Enable a diagnostic trace on the server.
It is best to enable a 'Runtime' trace instead of a 'Configuration' trace. This is so that the trace can be
disabled once the diagnostic data has been retrieved from the server.
1. Start the application server.
2. Immediately after starting the server, enable a Runtime trace:
a. In the WebSphere Application Server administrative console, expand the
Troubleshooting section and click Logs and Trace.
b. Click the link for your server.
c. Click Diagnostic Trace.
d. Click the Runtime tab.
e. Click on Change Log Level Details.
f. Click the Runtime tab.
g. In Trace Specification, enter the following string:
ConnLeakLogic=all
Click OK.
h. Trace has now been dynamically enabled on the server.
It is important to enable the trace immediately after the server is started and BEFORE any connections
are obtained from the connection pool.
NOTE: A trace.log will be created, however, it will only contain messages similar in nature to what is
logged to the SystemOut.log. It will not log continuous messages like a WAS.j2c=all trace and causes
only slight performance impact.
Part 2:
Collect diagnostic data.
Let the system run and watch the SystemOut.log. If J2CA0045E messages are occurring or if
connections appear to be stuck in the connection pool, then it is time to invoke wsadmin.
The following wsadmin commands can be used to dump the contents of the connection pool at any
given time:
wsadmin>set ds [$AdminControl queryNames "*:name=,process=,node=,*"]
wsadmin>$AdminControl invoke $ds showPoolContents
For example, the Plants By WebSphere Samples datasource is configured with these properties:
The wsadmin commands to view the pool contents for this datasource would be the following:
wsadmin>set ds [$AdminControl queryNames
"*:name=PLANTSDB,process=server1,node=TREESNode04,*"]
"WebSphere:name=PLANTSDB,process=server1,platform=dynamicproxy,node=TREESNode04,
JDBCProvider=Samples Derby JDBC Provider (XA),diagnosticProvider=true,j2eeType=J
DBCDataSource,J2EEServer=server1,Server=server1,version=6.1.0.25,type=DataSource
,mbeanIdentifier=cells/TREESNode02Cell/nodes/TREESNode04/servers/server1/resourc
es.xml#DataSource_1243527981250,JDBCResource=Samples Derby JDBC Provider (XA),ce
ll=TREESNode02Cell,spec=1.0"
wsadmin>$AdminControl invoke $ds showPoolContents
Your output of the showPoolContents will display the stack trace of connections currently in use. The
output will be similar to this (note: the below output does not match the above datasource example):
WASX7209I: Connected to process "server1" on node TREESNode04 using SOAP connector; The type
of process is: UnManagedProcess
PoolManager name:jdbc/sample
PoolManager object:28487215
Total number of connections: 5 (max/min 5/0, reap/unused/aged 180/1800/0, connectiontimeout/purge
180/EntirePool)
(testConnection/inteval false/0, stuck timer/time/threshold 0/0/0, surge time/connections 0/­1)
The waiter count is 4
The mcWrappers in waiter queue []
Shared Connection information (shared partitions 300)
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@e07499;SUSPENDED; MCWrapper id 1fd7c23
Managed connection WSRdbManagedConnectionImpl@e11f7a
State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000003e Thread Name: WebContainer : 3
Handle count 0 Start time inuse Wed Sep 02 21:03:13 EDT 2009 Time inuse 157 (seconds)
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@157e52e;SUSPENDED; MCWrapper id 11b78de
Managed connection WSRdbManagedConnectionImpl@9c5f65
State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000003e Thread Name: WebContainer : 4
Handle count 0 Start time inuse Wed Sep 02 21:03:13 EDT 2009 Time inuse 157 (seconds)
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@7ba4b2;SUSPENDED; MCWrapper id 86332d
Managed connection WSRdbManagedConnectionImpl@89ef6c
State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000003e Thread Name: WebContainer : 5
Handle count 0 Start time inuse Wed Sep 02 21:03:12 EDT 2009 Time inuse 158 (seconds)
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@1d68191;SUSPENDED; MCWrapper id 15e5933
Managed connection WSRdbManagedConnectionImpl@1322b26
State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000003e Thread Name: WebContainer : 6
Handle count 0 Start time inuse Wed Sep 02 21:03:12 EDT 2009 Time inuse 158 (seconds)
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@81e7e9;SUSPENDED; MCWrapper id 1cbd4ee
Managed connection WSRdbManagedConnectionImpl@1087b1b
State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000003e Thread Name: WebContainer : 7
Handle count 0 Start time inuse Wed Sep 02 21:03:13 EDT 2009 Time inuse 157 (seconds)
Total number of connection in shared pool: 5
Free Connection information (free distribution table/partitions 3/1)
No free connections
UnShared Connection information
No unshared connections
Connection Leak Logic Information:
It is also possible to put the commands into a script which can be invoked at a regular interval to check
the status of the connection pool over time. The following is a sample which can be used or modified:
date >> ; wsadmin.sh ­c "\$AdminControl invoke
[\$AdminControl queryNames "*:name=,*"] showPoolContents" ­user ­password >>

Resolving the problem Interpreting the Data:
The showPoolContents data contains several pieces of useful data.
1. Total number of connections ­ this is the sum of the connections in the Shared, UnShared and
Free Connection Pools
2. waiter count ­ the number of connection requests which are waiting for free connection to be
returned from the connection pool
3. Total number of connections in [ shared | unshared | free ] pool ­ the number of connections
which are currently in the various pools
4. Connection Leak Logic Information ­ if a connection has been in use for more than 10 seconds,
then the stack trace of the code which obtained the connection will appear in this list.
5. Shared Connection information ­ let's look at the relevant parts of this output individually:
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@e07499;SUSPENDED; MCWrapper id
1fd7c23 Managed connection WSRdbManagedConnectionImpl@e11f7a
State:STATE_TRAN_WRAPPER_INUSE Thread Id: 0000003e Thread Name: WebContainer :
3 Handle count 0 Start time inuse Wed Sep 02 21:03:13 EDT 2009 Time inuse 157 (seconds)
com.ibm.ws.LocalTransaction.LocalTranCoordImpl@e07499;SUSPENDED ­­> The
transactional scope under which the connection was obtained. This connection was obtained
inside a LocalTrasnactionContainment (LTC). If the connection was obtained in a global
transaction, the output would look like this:
com.ibm.ws.Transaction.JTA.TransactionImpl@24c17ad2#tid=812
State:STATE_TRAN_WRAPPER_INUSE ­­> Transactional state of the connection
Thread Id: 0000003e Thread Name: WebContainer : 3 ­­> The thread id and the thread name on
which the connection was used. This can be useful when correlating data from javacores taken
at the same time.
Handle count ­­> When this value is 1, it means that the application has not yet issued a
connection.close(). When this value is 0, the application has already issued a connection.close().
Start time inuse ­­> The time and date of when the connection was first obtained from the
connection pool by this thread.
Time inuse ­­> The amount of time the connection has been in use.

No comments:

Post a Comment