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

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.