I'm having a lot of troubles with a Java (tomcat) application using MySQL (Hibernate) and HikariCP as connection pool. I'm having troubles with connection leak, but I'm using Spring's @Transactional annotation in service's and DAO's layers, so I guess shouldn't be a problem.
What's happening: After a while, my application stops. And I can't perform anything that need a database connection. When that happened my logs show:
ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - HikariPool-1 - Connection is not available, request timed out after 30004ms.
javax.persistence.PersistenceException:
org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
The logs that warn leak detection dosn't show any useful tip (to me):
295269 [HikariPool-1 housekeeper] WARN com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@64f645d5 on thread http-nio-8080-exec-9, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85)
at org.hibernate.hikaricp.internal.HikariCPConnectionProvider.getConnection(HikariCPConnectionProvider.java:77)
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:109)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:47)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172)
at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.prepareQueryStatement(AbstractLoadPlanBasedLoader.java:241)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:185)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
at org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer.initialize(AbstractLoadPlanBasedCollectionInitializer.java:88)
at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:688)
at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:75)
at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2004)
at org.hibernate.collection.internal.AbstractPersistentCollection$4.doWork(AbstractPersistentCollection.java:567)
at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:249)
at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:563)
at org.hibernate.collection.internal.AbstractPersistentCollection.read(AbstractPersistentCollection.java:132)
at org.hibernate.collection.internal.AbstractPersistentCollection$1.doWork(AbstractPersistentCollection.java:161)
at org.hibernate.collection.internal.AbstractPersistentCollection$1.doWork(AbstractPersistentCollection.java:146)
at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:249)
at org.hibernate.collection.internal.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:145)
at org.hibernate.collection.internal.PersistentBag.size(PersistentBag.java:261)
at javax.faces.model.ListDataModel.isRowAvailable(ListDataModel.java:110)
at javax.faces.model.ListDataModel.setRowIndex(ListDataModel.java:185)
at javax.faces.model.ListDataModel.setWrappedData(ListDataModel.java:220)
at javax.faces.model.ListDataModel.<init>(ListDataModel.java:79)
at org.primefaces.component.api.UIData.getDataModel(UIData.java:583)
at javax.faces.component.UIData.isRowAvailable(UIData.java:343)
at org.primefaces.component.api.UIData.setRowModel(UIData.java:418)
at org.primefaces.component.api.UIData.setRowIndex(UIData.java:397)
at org.primefaces.component.api.UIData.visitTree(UIData.java:629)
at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
at javax.faces.component.UIForm.visitTree(UIForm.java:371)
at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
at javax.faces.component.UIComponent.visitTree(UIComponent.java:1623)
at com.sun.faces.context.PartialViewContextImpl.processComponents(PartialViewContextImpl.java:376)
at com.sun.faces.context.PartialViewContextImpl.processPartial(PartialViewContextImpl.java:297)
at javax.faces.context.PartialViewContextWrapper.processPartial(PartialViewContextWrapper.java:183)
at javax.faces.component.UIViewRoot.encodeChildren(UIViewRoot.java:981)
at javax.faces.component.UIComponent.encodeAll(UIComponent.java:1779)
at com.sun.faces.application.view.FaceletViewHandlingStrategy.renderView(FaceletViewHandlingStrategy.java:391)
at com.sun.faces.application.view.MultiViewHandler.renderView(MultiViewHandler.java:125)
at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:121)
at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)
at javax.faces.webapp.FacesServlet.service(FacesServlet.java:594)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
After a few days trying to fix it, I enabled the debug level for Hikari (I don't know why i didn't this before) and I saw when I perform a SELECT/INSERT/UPDATE:
54571 [http-nio-8080-exec-9] DEBUG com.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Executed rollback on connection com.mysql.jdbc.JDBC4Connection@64f645d5 due to dirty commit state on close().
My configurations:
hibernate.xml
<property name="hibernate.dialect" value="org.hibernate.dialect.MySQL5Dialect"/>
<property name="hibernate.connection.autocommit" value="false" />
<property name="hibernate.show_sql" value="false" />
<property name="hibernate.format_sql" value="false"/>
<property name="hibernate.connection.provider_class" value="org.hibernate.hikaricp.internal.HikariCPConnectionProvider" />
<property name="hibernate.hikari.dataSource.prepStmtCacheSize" value="350" />
<property name="hibernate.hikari.dataSource.prepStmtCacheSqlLimit" value="2048" />
<property name="hibernate.hikari.dataSource.cachePrepStmts" value="true" />
<property name="hibernate.hikari.dataSource.useServerPrepStmts" value="true" />
<property name="hibernate.hikari.dataSource.useLocalSessionState" value="true" />
<property name="hibernate.hikari.dataSource.useLocalTransactionState" value="true" />
<property name="hibernate.hikari.dataSource.rewriteBatchedStatements" value="true" />
<property name="hibernate.hikari.dataSource.cacheResultSetMetadata" value="true" />
<property name="hibernate.hikari.dataSource.cacheResultSetMetadata" value="true" />
<property name="hibernate.hikari.dataSource.cacheServerConfiguration" value="true" />
<property name="hibernate.hikari.dataSource.elideSetAutoCommits" value="true" />
<property name="hibernate.hikari.dataSource.maintainTimeStats" value="false" />
<!--
wait_timeout = 1800
idleTimeout, maxLifetime should be 1min less than wait_timeout = 1740s or 1740000ms
-->
<property name="hibernate.hikari.minimumIdle" value="5" />
<property name="hibernate.hikari.maximumPoolSize" value="200" />
<property name="hibernate.hikari.idleTimeout" value="740000" />
<property name="hibernate.hikari.maxLifetime" value="1740000" />
<property name="hibernate.hikari.connectionTestQuery" value="SELECT 1" />
<property name="hibernate.hikari.leakDetectionThreshold" value="60000" />
<property name="javax.persistence.jdbc.driver" value="com.mysql.jdbc.Driver" />
<property name="javax.persistence.jdbc.url" value="jdbc:mysql://localhost/DATABASE?autoReconnect=true&useSSL=false" />
<property name="javax.persistence.jdbc.user" value="root" />
<property name="javax.persistence.jdbc.password" value="root" />
MySQL
interactive_timeout = 7200
wait_timeout = 1800
max_connections = 200
My code:
Business Object layer
@Transactional(readOnly = true)
public List<Person> getPersons() {
if (persons == null) {
try {
persons = new PersonBO().listAll(Person.class);
} catch (Exception e) {
getLog().error("Erro", e);
}
}
return persons;
}
DAO layer
@Transactional(readOnly = true)
public List<E> listAll(Class<E> classEntity) throws Exception {
return list(createQuery("SELECT o FROM " + classEntity.getSimpleName() + " o"));
}
@Transactional(readOnly = true)
public List<E> list(Query query) throws Exception {
List<E> entities = null;
if (query != null) {
try {
entities = query.getResultList();
} catch (Exception e) {
throw new Exception(e);
}
}
return entities;
}
@Transactional(readOnly = false)
private Query createQuery(String jpql) {
Query query = null;
if (jpql != null && !jpql.isEmpty()) {
query = entityManager.createQuery(jpql);
}
return query;
}
After stops, I have to restart TOMCAT to start using my system again.
Any help? Thanks in advance!
