*The Problem*
Recently I started experiencing issues with our connection pool (Apache DBCP2) in several production applications . Every certain amount of time I was forced to restart different applications because they run out of connections in the database pool.
After some investigation I discovered that the problem happened after a number of long running queries that had issued socket time outs.
By inspecting our runtime environments using Java Mission Control, we could see that the JMX bean of our connection pool showed that all the connections in the pool were active and they were never been released.
Upon application restart everything would go back to normal operation.
*Investigation Discoveries*
After further investigation I managed to reproduce the scenario. All we needed to do was to force a socket timeout during a Hibernate transaction to cause that a connection in our DBCP2 pool got affected by the issue.
It seems Hibernate does not close the affected connection and the pool keeps it as active forever eventually (and gradually) consuming all connections in the pool until it starts rejecting new requests because the pool is full.
I also discovered that by forcing {{hibernate.connection.release_mode}} to {{after_statement}} the problem go solved, however, it is my intention that we use {{after_transaction}} mode.
*Testing Scenario*
I use Spring to configure my {{DataSource}}. I defined a single connection in the pool to make the test easier.
{code:xml}
<bean id="dataSource" class="org.apache.commons.dbcp2.BasicDataSource" destroy-method="close">
<property name="driverClassName" value="org.postgresql.Driver"/>
<property name="url" value="jdbc:postgresql://batcave.dalorzo.com:5432/bcs"/>
<property name="username" value="edalorzo"/>
<property name="password" value="edalorzo"/>
<property name="validationQuery" value="SELECT 1"/>
<property name="testOnBorrow" value="true"/>
<property name="initialSize" value="0"/>
<property name="maxTotal" value="1"/>
<property name="maxIdle" value="0"/>
<property name="minIdle" value="0"/>
<property name="maxWaitMillis" value="10000"/>
<property name="connectionProperties" value="tcpKeepAlive=true;socketTimeout=15"/>
</bean>
{code}
I use Spring ORM to bootstrap my {{EntityManagerFactory}}.
{code:xml}
<bean id="entityManagerFactory" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean">
<property name="dataSource" ref="dataSource"/>
<property name="jpaVendorAdapter">
<bean class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter">
<property name="database" value="POSTGRESQL"/>
<property name="showSql" value="true"/>
</bean>
</property>
<property name="jpaDialect">
<bean class="org.springframework.orm.jpa.vendor.HibernateJpaDialect">
<property name="prepareConnection" value="true"/>
</bean>
</property>
<property name="jpaProperties">
<props>
<prop key="hibernate.dialect">org.hibernate.dialect.PostgreSQL9Dialect</prop>
<prop key="hibernate.temp.use_jdbc_metadata_defaults">false</prop>
</props>
</property>
<property name="persistenceUnitName" value="test-bug"/>
<property name="packagesToScan">
<list>
<value>com.dalorzo.domain</value>
</list>
</property>
</bean>
{code}
And this is how test it the issue:
* First I open a database console and get a lock of a record and keep that transaction open.
* Then I debug my code below step by step. I make a first invocation of my {{processRequest}} method where I try to run a native query that will attempt to get a lock on that exact same record. Since it is already held by the transaction I started in the previous step, the query will eventually cause the socketTimeout.
* The {{processRequest}} method rollbacks the transaction, print the stack trace and close the entity manager.
* At this point I should have my connection back in the DBCP2 pool, right?.
* So, from the command line console I release the record I had obtained in the first step above.
* And then continue debugging in my IDE by moving into my second method invocation of {{processRequest}}. It should succeed this time, since I was supposed to have 1 connection in the pool and the record is no longer locked. However, I get an error reporting that my pool is full.
You can see the code I used to testing here:
{code:java}
import org.springframework.context.ConfigurableApplicationContext;
import org.springframework.context.support.ClassPathXmlApplicationContext;
import javax.persistence.EntityManager;
import javax.persistence.EntityManagerFactory;
import javax.persistence.EntityTransaction;
import javax.persistence.Query;
import java.util.List;
public class TestDriveOfHibernate {
//debug step by step such that you can control when database locks get released
public static void main(String[] args) {
try (ConfigurableApplicationContext context = new ClassPathXmlApplicationContext("classpath:application-context.xml")) {
EntityManagerFactory emf = context.getBean(EntityManagerFactory.class);
System.out.println(emf.getProperties());
try {
//before running this get a lock on the record by running the following on the pgslq console
//>
//pgsql> begin;
//pgsql> select tote_id from totes where facility = 'SLCW' and tote_id = '70005' FOR UPDATE;
//>
//don't commit the transaction just yet
//now proceed to the first method invocation to force the socket timeout
processRequest(emf);
//now end the transaction you started in the console before you run this second method invocation
//>
// end;
//
//at this point the record is free to be taken and I should have one connection in the pool.
processRequest(emf);
//however, you will notice that the connection we used in the first invocation never got back to the pool
//and this second method reports the pool is full, and fails.
}
finally {
emf.close();
}
}
}
private static void processRequest(EntityManagerFactory emf) {
EntityManager em = emf.createEntityManager();
try {
EntityTransaction tx = em.getTransaction();
tx.begin();
try {
Query query = em.createNativeQuery("select tote_id from totes where facility = 'SLCW' and tote_id = '70005' FOR UPDATE");
List<Object> totes = query.getResultList();
System.out.println(totes);
tx.commit();
}
catch (Exception e) {
try {
tx.rollback();
} catch (Exception ex) {
ex.printStackTrace();
}
e.printStackTrace();
}
}
finally {
em.close();
}
}
}
{code}
*The Exceptions*
When the socket timeout kicks in, this is what I see in the stack trace
{code}
Nov 28, 2017 9:27:12 PM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
WARN: SQL Error: 0, SQLState: 08006
Nov 28, 2017 9:27:12 PM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
ERROR: An I/O error occured while sending to the backend.
org.hibernate.TransactionException: Unable to rollback against JDBC Connection
at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.rollback(AbstractLogicalConnectionImplementor.java:121)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.rollback(JdbcResourceLocalTransactionCoordinatorImpl.java:250)
at org.hibernate.engine.transaction.internal.TransactionImpl.rollback(TransactionImpl.java:100)
at com.backcountry.fulfillment.TestDriveOfHibernate.processRequest(TestDriveOfHibernate.java:58)
at com.backcountry.fulfillment.TestDriveOfHibernate.main(TestDriveOfHibernate.java:29)
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:822)
at org.postgresql.jdbc2.AbstractJdbc2Connection.rollback(AbstractJdbc2Connection.java:839)
at org.apache.commons.dbcp2.DelegatingConnection.rollback(DelegatingConnection.java:492)
at org.apache.commons.dbcp2.DelegatingConnection.rollback(DelegatingConnection.java:492)
at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.rollback(AbstractLogicalConnectionImplementor.java:116)
... 4 more
javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: could not extract ResultSet
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:149)
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:157)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1423)
at org.hibernate.query.Query.getResultList(Query.java:146)
at com.backcountry.fulfillment.TestDriveOfHibernate.processRequest(TestDriveOfHibernate.java:52)
at com.backcountry.fulfillment.TestDriveOfHibernate.main(TestDriveOfHibernate.java:29)
Caused by: org.hibernate.exception.JDBCConnectionException: could not extract ResultSet
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:115)
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:69)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2168)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1931)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1893)
at org.hibernate.loader.Loader.doQuery(Loader.java:938)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341)
at org.hibernate.loader.Loader.doList(Loader.java:2692)
at org.hibernate.loader.Loader.doList(Loader.java:2675)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2507)
at org.hibernate.loader.Loader.list(Loader.java:2502)
at org.hibernate.loader.custom.CustomLoader.list(CustomLoader.java:335)
at org.hibernate.internal.SessionImpl.listCustomQuery(SessionImpl.java:2162)
at org.hibernate.internal.AbstractSharedSessionContract.list(AbstractSharedSessionContract.java:1016)
at org.hibernate.query.internal.NativeQueryImpl.doList(NativeQueryImpl.java:152)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1414)
... 3 more
Caused by: org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:281)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:559)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:302)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:83)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
... 17 more
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:143)
at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:112)
at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:71)
at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:269)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1700)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
... 23 more
{code}
But in the second method invocation, when the connection should be available and record should be free I get the following:
{code}
Nov 28, 2017 9:29:04 PM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
WARN: SQL Error: 0, SQLState: null
Nov 28, 2017 9:29:04 PM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
ERROR: Cannot get a connection, pool error Timeout waiting for idle object
[main] INFO org.springframework.context.support.ClassPathXmlApplicationContext - Closing org.springframework.context.support.ClassPathXmlApplicationContext@31ef45e3: startup date [Tue Nov 28 21:26:54 CST 2017]; root of context hierarchy
[main] INFO org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit 'test-api'
Exception in thread "main" org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:109)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:254)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:262)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:214)
at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:56)
at com.backcountry.fulfillment.TestDriveOfHibernate.processRequest(TestDriveOfHibernate.java:49)
at com.backcountry.fulfillment.TestDriveOfHibernate.main(TestDriveOfHibernate.java:35)
Caused by: java.sql.SQLException: Cannot get a connection, pool error Timeout waiting for idle object
at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:142)
at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:106)
... 7 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:449)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
... 11 more
{code}
I tested the exact same scenario using EclipseLink 2.5.0 and it worked just fine. |
|
