HikariCP connection times out after 10 hits

Question

I recently upgraded to SpringBoot 2.0.2.RELEASE. The default connection pool has moved from Tomcat to HikariCP. I have changed my application.properties as follows

spring.datasource.type=com.zaxxer.hikari.HikariDataSource
spring.datasource.hikari.minimumIdle=5
spring.datasource.hikari.maximumPoolSize=10
spring.datasource.hikari.idleTimeout=20000
spring.datasource.hikari.poolName=CoffeeHikariCP
spring.datasource.hikari.maxLifetime=1800000
spring.datasource.hikari.connectionTimeout=30000
spring.jpa.open-in-view=false

I am using standard CrudRepository to operate on Oracle DB. I have built a sample controller to fetch the data from DB. After 10 hits, following error is reported and no query is getting executed after tha. Please let me know if I am missing anything in the setup. Everything was working fine with 1.5.10.

22-May-2018 16:02:06.710 [AsyncIPMSProc-2] WARN  o.h.e.j.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null
22-May-2018 16:02:06.710 [AsyncIPMSProc-2] ERROR o.h.e.j.spi.SqlExceptionHelper - HikariPool-1 - Connection is not available, request timed out after 30001ms.
22-May-2018 16:02:06.715 [AsyncIPMSProc-2] ERROR o.s.a.i.SimpleAsyncUncaughtExceptionHandler - Unexpected error occurred invoking async method 'public void org.coffeeshop.service.CommunicationService.processCommunicationRequest(java.lang.Long,java.lang.String)'.
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:450)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:474)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:289)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:135)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
    at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
    at com.sun.proxy.$Proxy152.findById(Unknown Source)
    at org.coffeeshop.service.CommunicationService.processCommunicationRequest(CommunicationService.java:297)
    at org.coffeeshop.service.CommunicationService$$FastClassBySpringCGLIB$$d205c5a.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48)
    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.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:109)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
    at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:524)
    at sun.reflect.GeneratedMethodAccessor105.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:223)
    at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:207)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle.doGetConnection(HibernateJpaDialect.java:391)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:154)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:400)
    ... 25 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:669)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
    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)
    ... 35 common frames omitted
22-May-2018 16:02:07.634 [AsyncIPMSProc-1] WARN  o.h.e.j.spi.SqlExceptionHelper
                - SQL Error: 0, SQLState: null
22-May-2018 16:02:07.634 [AsyncIPMSProc-1] ERROR o.h.e.j.spi.SqlExceptionHelper
                - HikariPool-1 - Connection is not available, request timed out after 30000ms.
22-May-2018 16:02:07.634 [AsyncIPMSProc-1] ERROR o.c.s.CommunicationService
                - Unhandled Error Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

Thanks in Advance

Answer 1

You need to checkout few things:

1. How many requests per seconds you are sending, did you send 10 requests/second?
2. How long a request take time to process, response time??
3. if you are sending 10 requests/second and requests processing is taking longer than all your connections are busy in processing requests so here case is of 10.

Increase connection pool size if you are closing connection after each request processing or check if there is any leak.

Enable the leakDetectionThreshold ... hikari.setLeakDetectionThreshold(60 * 1000) and watch the logs for leak messages. The stacktrace that is logged should lead you to the place in your code that borrowed but did not return a connection.

Enable DEBUG level logging in your logging framework for package com.zaxxer.hikari and watch the pool stats logged every 30 seconds:

DEBUG 2018-03-14 07:06:46 com.zaxxer.hikari.pool.HikariPool - Pool-0 - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
DEBUG 2018-03-14 07:06:46 com.zaxxer.hikari.pool.HikariPool - Pool-0 - After cleanup  stats (total=5, active=0, idle=5, waiting=0)

if it continue to increase then make sure your are closing connection after use.

Answer 2

I had the same kind of problem.

As @brettw said, you can enable the leakDetectionThreshold of Hikari.

In Spring-boot, you can add the following property in the application.properties:

spring.datasource.hikari.leakDetectionThreshold=2000

Hikari was throwing this useful stacktrace:

23:59:06.887 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for conn9: url=jdbc:h2:file:./src/main/resources/h2/schema-test.mv.db user=SA on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
    at xyz.testutils.DbUnitUtils.assertDatabaseEquals(DbUnitUtils.java:43)
    at xyz.controller.MyIntegrationTest.test(MyIntegrationTest.java:117)

In my case, I was using DbUnit and I was opening a Connection (to retrieve the content of my database) but didn't close it. After closing the connection (.close()), it was fixed.