Saturday, October 05, 2013

Troubleshooting database connection leaks in JBOSS AS 7 or JBOSS EAP 6


JBOSS Database Connection Leak

Troubleshooting database connection leaks in JBOSS AS 7 or JBOSS EAP 6

  • Jboss connection pool not releasing the connection from pool
  • Connections to Oracle not released Java EE 6, JBoss EAP 6 
  • Detecting connection leaks in JBOSS
  • Detecting and closing leaked connections in JBoss 7.1 or EAP 6
  • JBOSS Database Connection Leak
  • JBoss run out of Connections
  • No ManagedConnections available within configured blocking timeout
  • Jboss leaked DB Connection
  • Detecting and closing leaked connections in JBoss 7.1


We deployed a web based application on JBOSS and we were getting the below error after the application was used for some time.
Unable to get managed connection for java:/jdbc/TST_MYDB”
Caused by: javax.resource.ResourceException: IJ000655: No managed connections available within configured blocking timeout (30000 [ms])

It was obvious that we were running out database connections. But it was hard to see where exactly the issue was. Jboss EAP6 or Jboss AS 7 has a good mechanism to trouble shoot database connection leaks in your code.
Then we logged in to oracle database and ran the below query to see how many connections were being used by this application. We had set a max limit of 20 for number of connections which is the default in Jboss.

select count(*),
machine from v$session  where username='MYDB_TST_USER' group by machine
-----------------------------
20          rama-local-host

By seeing the above query results it was obvious all 20 connections were being used though one or two users were using the app. This proved that we had issue in our code where we were not closing the connections.
Enable jdbc calls logging in Jboss
In standalone.xml or domain.xml (If you using domain mode. Note: In domain mode make the changes under the profile section that you are using)
Under you data source section set spy=”true”

<datasource
jta="false" jndi-name="java:/jdbc/TST_MYDB"
pool-name="TST_Datasource" enabled="true"
use-ccm="false" spy="true">

Also please enable “jboss.jdbc.spy” as shown below under section logging.
<subsystem xmlns="urn:jboss:domain:logging:1.1">

<!-- ************* Enabling Spy logging category ************ -->
<logger category="jboss.jdbc.spy">
<level name="TRACE"/>
</logger>

Once done re-start your servers. If in domain mode re-start the domain controller and servers.
Here is one thread I traced after it used up all 20 connections… See the highlighted parts

11:52:20,390 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ajp-/10.xx.xx.xxx:8018-9) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@454d1a2[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5c8ee4e6 connection handles=0 lastUse=1376581940388 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@677e7076 pool internal context=SemaphoreArrayListManagedConnectionPool@15de28a6[pool=TST_Datasource]]

11:52:20,390 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ajp-/10.10.204.167:8018-9) Got connection from pool: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@454d1a2[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5c8ee4e6 connection handles=0 lastUse=1376581940388 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@677e7076 pool internal context=SemaphoreArrayListManagedConnectionPool@1

Method: returnConnection(454d1a2, false)
ManagedConnectionFactory:
  Class: org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory
  Object: 52f841c3
ConnectionListenerFactory:
  Class: org.jboss.jca.core.connectionmanager.notx.NoTxConnectionManagerImpl
  Object: 28a593c3
Pool:
  Name: TST_Datasource
PoolConfiguration:
  MinSize: 1
  MaxSize: 30
  BlockingTimeout: 30000
  IdleTimeoutMinutes: 30
  BackgroundValidation: false
  BackgroundValidationMillis: 0
  StrictMin: false
  UseFastFail: false
Available (0):
InUse (20):
   39377d16 (NORMAL)
  239bd4f2 (NORMAL)
  286de44c (NORMAL)
  31ac0fe5 (NORMAL)
  2fa57790 (NORMAL)
  18b5a5ac (NORMAL)
  5c91f314 (NORMAL)
  2c08546f (NORMAL)
  74dc648a (NORMAL)
  4d5aab23 (NORMAL)
  17722dcc (NORMAL)
  37423505 (NORMAL)
  1ee6dffd (NORMAL)
  454d1a2 (NORMAL)==================è This connection is not released though a request was sent. Oops !!!
Statistics:
  ActiveCount: 20 ====è At this what happened…all 20 connections are held up.
  AvailableCount: 0 =è No more connections left out.
  AverageBlockingTime: 0
  AverageCreationTime: 113
  CreatedCount: 20
  DestroyedCount: 0
  MaxCreationTime: 346
  MaxUsedCount: 20
  MaxWaitCount: 0
  MaxWaitTime: 1
  TimedOut: 0
  TotalBlockingTime: 1
  TotalCreationTime: 3029


This additionally shows that the connections were are being held up.
So next we enabled logging for jboss jca as shown in standalone.xml or domain.xml ( Needless to say to re start the server)
<logger category="org.jboss.jca">
                    <level name="TRACE"/>
 </logger>
Also set use-ccm=true and spy=true and enabled=true

<subsystem xmlns="urn:jboss:domain:datasources:1.1">
       <datasources>
            
<datasource jta="false" jndi-name="java:/jdbc/TST_MYDB"
  pool-name="TST_Datasource"
enabled="true" spy="true"
use-ccm="true">

Under data source tag also add

<validation>
     <valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleValidConnectionChecker"/>
<stale-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleStaleConnectionChecker"/>
   <exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.oracle.OracleExceptionSorter"/>
</validation>

Also if you set  debug=true, error=false it will Show message :
<cached-connection-manager debug="true" error="false"/>
You can see the below lines in server log
 INFO  [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (http-/127.0.0.1:8080-1) IJ000100: Closing a connection for you. Please close them yourself: org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@6f1170a9: java.lang.Throwable: STACKTRACE    at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.registerConnection(CachedConnectionManagerImpl.java:269)    at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:495)    at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:

If you set debug=true, error=true
<cached-connection-manager debug="true" error="true"/>

It will throw exception showing where the connection leaks are occuring
See the stack trace below.
Error:

10:57:44,395 INFO [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (ajp-/10.10.204.166:8018-5) IJ000100: Closing a connection for you. Please close them yourself: org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@e24e94: java.lang.Throwable: STACKTRACE
   at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.registerConnection(CachedConnectionManagerImpl.java:269)        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:495)        at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139)
        at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81) [spring-orm-3.0.5.RELEASE.jar:3.0.5.RELEASE]
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417) [hibernate-3.1.3.jar:]        at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144) [hibernate-3.1.3.jar:]        at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:105) [hibernate-3.1.3.jar:]        at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1561) [hibernate-3.1.3.jar:]        at org.hibernate.loader.Loader.doQuery(Loader.java:661) [hibernate-3.1.3.jar:]
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224) [hibernate-3.1.3.jar:]
        at org.hibernate.loader.Loader.doList(Loader.java:2145) [hibernate-3.1.3.jar:]
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2029) [hibernate-3.1.3.jar:]
        at org.hibernate.loader.Loader.list(Loader.java:2024) [hibernate-3.1.3.jar:]
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:375) [hibernate-3.1.3.jar:]
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:308) [hibernate-3.1.3.jar:]
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:153) [hibernate-3.1.3.jar:]
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1106) [hibernate-3.1.3.jar:]
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79) [hibernate-3.1.3.jar:]


So by seeing the above stack trace we were able to trace the method that was not closing the connection.
eg: In our code we had something like

Query q=getHibernateTemplate().getSessionFactory().openSession().createQuery(…..)
q.list();

As you notice that someone was opening a session and never closed it.
Sadly someone forgot to close the hibernate session and over a period of time
we would run  out of all connections

So we fixed it by
Session session = getHibernateTemplate().getSessionFactory().openSession();
Query q=session.createQuery(…..)
q.list();
session.close();

With this fix we were able to fix the connection leaks in the code.



1 comment:

  1. Thanks! Very interesting / useful info for me atm. :)

    ReplyDelete