How to Debug connection leaks in c3p0
We saw below exception stack-trace which was randomly appearing on our Glassfish application server logs. The application was randomly being sluggish and not responding to requests.
Stacktrace
[#|2010-11-05T02:21:06.076-0700|WARNING|sun-appserver9.1|javax.enterprise.system.stream.err|_ThreadID=21;_ThreadName=DefaultQuartzScheduler_Worker-5;_RequestID=00530e25-f5e7-4a12-8ee6-7c0d00d649ed;| org.hibernate.exception.GenericJDBCException: could not insert: [com.fromdev.AlertRecordImpl] at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140) at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2436) at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2856) at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79) at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:273) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:265) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184) at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216) at com.fromdev.AlertJob.execute(ProductAlertJob.java:83) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:276) at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:260) at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86) at org.quartz.core.JobRunShell.run(JobRunShell.java:203) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520) Caused by: java.sql.SQLException: Closed Connection at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208) at oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:868) at oracle.jdbc.driver.PhysicalConnection.prepareStatement(PhysicalConnection.java:787) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.mchange.v2.c3p0.stmt.GooGooStatementCache$1StmtAcquireTask.run(GooGooStatementCache.java:542) at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547) |#] [#|2010-11-05T02:21:06.076-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=21;_ThreadName=DefaultQuartzScheduler_Worker-5;|02:21:06,076 WARN NewPooledConnection :486 [c3p0] A PooledConnection that has already signalled a Connection error is still in use! |#] [#|2010-11-05T02:21:06.091-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=21;_ThreadName=DefaultQuartzScheduler_Worker-5;|02:21:06,076 WARN NewPooledConnection :487 [c3p0] Another error has occurred [ java.sql.SQLException: Closed Connection ] which will not be reported to listeners! java.sql.SQLException: Closed Connection at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208) at oracle.jdbc.driver.PhysicalConnection.setAutoCommit(PhysicalConnection.java:1057) at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) at org.hibernate.transaction.JDBCTransaction.toggleAutoCommit(JDBCTransaction.java:224) at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:216) at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:192) at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:625) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:800) at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:777) at com.fromdev.UnitOfWork.rollback(UnitOfWork.java:45) at com.fromdev.AlertJob.execute(ProductAlertJob.java:84) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:276) at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:260) at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86) at org.quartz.core.JobRunShell.run(JobRunShell.java:203) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520) |#] [#|2010-11-05T02:21:06.122-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=21;_ThreadName=DefaultQuartzScheduler_Worker-5;|02:21:06,122 ERROR JobRunShell :212 Job DEFAULT.methodInvokingJobDetail threw an unhandled Exception: org.springframework.scheduling.quartz.JobMethodInvocationFailedException: Invocation of method 'execute' on target class [class com.fromdev.AlertJob] failed; nested exception is org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: JDBC rollback failed at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:269) at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86) at org.quartz.core.JobRunShell.run(JobRunShell.java:203) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520) Caused by: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: JDBC rollback failed at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:628) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:800) at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:777) at com.fromdev.UnitOfWork.rollback(UnitOfWork.java:45) at com.fromdev.AlertJob.execute(ProductAlertJob.java:84) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:276) at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:260) ... 3 more Caused by: org.hibernate.TransactionException: JDBC rollback failed at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:200) at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:625) ... 13 more Caused by: java.sql.SQLException: Closed Connection at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208) at oracle.jdbc.driver.PhysicalConnection.rollback(PhysicalConnection.java:1161) at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:855) at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:213) at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:192) ... 14 more |#] [#|2010-11-05T02:21:06.122-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=21;_ThreadName=DefaultQuartzScheduler_Worker-5;|02:21:06,122 ERROR ErrorLogger :2015 Job (DEFAULT.methodInvokingJobDetail threw an exception. org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: org.springframework.scheduling.quartz.JobMethodInvocationFailedException: Invocation of method 'execute' on target class [class com.fromdev.AlertJob] failed; nested exception is org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: JDBC rollback failed] at org.quartz.core.JobRunShell.run(JobRunShell.java:214) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520) * Nested Exception (Underlying Cause) --------------- org.springframework.scheduling.quartz.JobMethodInvocationFailedException: Invocation of method 'execute' on target class [class com.fromdev.AlertJob] failed; nested exception is org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: JDBC rollback failed at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:269) at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86) at org.quartz.core.JobRunShell.run(JobRunShell.java:203) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520) Caused by: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: JDBC rollback failed at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:628) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:800) at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:777) at com.fromdev.UnitOfWork.rollback(UnitOfWork.java:45) at com.fromdev.AlertJob.execute(ProductAlertJob.java:84) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:276) at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:260) ... 3 more Caused by: org.hibernate.TransactionException: JDBC rollback failed at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:200) at org.springframework.orm.hibernate3.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:625) ... 13 more Caused by: java.sql.SQLException: Closed Connection at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146) at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208) at oracle.jdbc.driver.PhysicalConnection.rollback(PhysicalConnection.java:1161) at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:855) at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:213) at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:192) ... 14 more |#]
About our application
Our Web Application is regular JEE app using Glassfish v2/Spring/Hibernate with c3p0 connection pooling. We have used quartz scheduler for running our background jobs. One of our background job runs every night and does some intensive data processing which involves getting bulk data from database and processing it and then updating the database for each of the affected records.
How we used c3p0 Connection pooling
We have used c3p0 for connecting to our Oracle database connection pooling. As a added caution to not leak any connections we used one c3p0 config parameter, which allows us to clean unreturned connection for long time. The c3p0 pool has a configuration parameter unreturnedConnectionTimeout.
unreturnedConnectionTimeout defines a limit (in seconds) to how long a Connection may remain checked out. If set to a nozero value, unreturned, checked-out Connections that exceed this limit will be summarily destroyed, and then replaced in the pool. Obviously, you must take care to set this parameter to a value large enough that all intended operations on checked out Connections have time to complete. You can use this parameter to merely workaround unreliable client apps that fail to close() Connections. The Default value for this parameter is 0 Seconds. If set, if an application checks out but then fails to check-in [i.e. close()] a Connection within the specified period of time, the pool will unceremoniously destroy() the Connection. This permits applications with occasional Connection leaks to survive, rather than eventually exhausting the Connection pool. And that’s a shame. Zero means no timeout, applications are expected to close() their own Connections. Obviously, if a non-zero value is set, it should be to a value longer than any Connection should reasonably be checked-out. Otherwise, the pool will occasionally kill Connections in active use, which is bad. This is basically a bad idea, but it’s a commonly requested feature. Fix your applications so they don’t leak Connections!
In our application the “unreturnedConnectionTimeout” value was set to 300 seconds (5 minutes), which is enough time for any web request to be processed. Infact most of our background jobs also completed within this limit. The problem started coming in when we had some enhancements added to the background job and it started taking more then 5 minutes. It was really difficult to debug this issue. Server was randomly not responding or being sluggish and getting OutOfMemory errors. Whenver we restarted the server and problem disappeared but hit us back after few days.
How to Debug this issue
To debug this we used a parameter in c3p0 config called “debugUnreturnedConnectionStackTraces”
If you set debugUnreturnedConnectionStackTraces to true, then a stack trace will be captured each time a Connection is checked-out. Whenever an unreturned Connection times out, that stack trace will be printed, revealing where a Connection was checked out that was not checked in promptly. debugUnreturnedConnectionStackTraces is intended to be used only for debugging, as capturing a stack trace can slow down Connection check-out.
After setting this parameter, we found below exception stacktrace in our logs and realized what could be the problem.
New Stacktrace
[#|2010-11-05T02:21:04.623-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=20;_ThreadName=Timer-9;| 02:21:04,623 INFO BasicResourcePool :1392 A checked-out resource is overdue, and will be destroyed: com.mchange.v2.c3p0.impl.NewPooledConnection@1ee23c7 |#] [#|2010-11-05T02:21:04.623-0700|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=20;_ThreadName=Timer-9;|02:21:04,623 INFO BasicResourcePool :1395 Logging the stack trace by which the overdue resource was checked-out. java.lang.Exception: DEBUG ONLY: Overdue resource check-out stack trace. at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:506) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128) at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:82) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161) at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1700) at org.hibernate.loader.Loader.doQuery(Loader.java:801) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274) at org.hibernate.loader.Loader.doList(Loader.java:2533) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276) at org.hibernate.loader.Loader.list(Loader.java:2271) at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452) at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363) at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196) at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268) at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102) at com.fromdev.alerts.AlertJob.execute(AlertJob.java:51) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:276) at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:260) at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86) at org.quartz.core.JobRunShell.run(JobRunShell.java:203) at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520) |#]
The root causes
There were multiple issues in our application:
1. First root cause was poor performance of code. There was a code which was causing the background job to run slower. Due to this the job started taking more 300 seconds, which was greater than unreturnedConnectionTimeout value we had configured.
2. Second reason was not using finally block for releasing resources The root cause for Server being sluggish and going OutOfMemory (at times) was connection leaks. The leak was happening due to the session.close() not being called in a finally block.
I have seen this as most common cause of resource leaks in many java application. Releasing a resource at the end of the method does not gaurantee that it will always be called. Many developers make that mistake (like one of our teammates).
The resolution
We took following steps to resolve this issue
1. We Moved the session.close() call to finally block.
2. As a short term fix, we had to increase the value of unreturnedConnectionTimeout. We had set it to 600 seconds (10 mins).
3. The long term fix, was to identify the code which is taking longer time and split our jobs into shorter tasks. We used VisualVM CPU profiling to identify the bad performing methods and improved them. This also required us to make changes to the background processing logic.
References
Configuring Connection Testing
Hibernate: How To configure C3P0
Hope this helps you in debugging similar issues.