HikariCP Idle connections staying in connection pool as active

Saif picture Saif · May 27, 2018 · Viewed 20.4k times · Source

I am using Spring Boot (1.5.6), Hibernate, Postgres, Hikari (2.7.8) . My configuration is :

spring.datasource.hikari.minimumIdle=1
spring.datasource.hikari.maximumPoolSize=20
spring.datasource.hikari.idleTimeout=30000
spring.datasource.hikari.poolName=SpringBootJPAHikariCP
spring.datasource.hikari.maxLifetime=50000
spring.datasource.hikari.connectionTimeout=30000

What I expect is, Idle connections should be released after 30000 ms/ 30 sec of idleness.
The problem is with every request new connection being made leaving all the idle connection as it is. So after some times I end up with 20 idle connection and with a new request Hikari try to gain a new connection and get SpringBootJPAHikariCP - Connection is not available, request timed out after 30001ms.

So, What I am doing wrong.? Or Have the misunderstood the configuration?

Hikari initialization Log:

SpringBootJPAHikariCP - configuration:
 allowPoolSuspension.............false
 autoCommit......................true
 catalog.........................none
 connectionInitSql...............none
 connectionTestQuery.............none
 connectionTimeout...............30000
 dataSource......................none
 dataSourceClassName.............none
 dataSourceJNDI..................none
 dataSourceProperties............{password=<masked>}
 driverClassName................."org.postgresql.Driver"
 healthCheckProperties...........{}
 healthCheckRegistry.............none
 idleTimeout.....................30000
 initializationFailFast..........true
 initializationFailTimeout.......1
 isolateInternalQueries..........false
 jdbc4ConnectionTest.............false
 jdbcUrl.........................jdbc:postgresql://localhost:5432/dbname
 leakDetectionThreshold..........0
 maxLifetime.....................50000
 maximumPoolSize.................20
 metricRegistry..................none
 metricsTrackerFactory...........none
 minimumIdle.....................1
 password........................<masked>
 poolName........................"SpringBootJPAHikariCP"
 readOnly........................false
 registerMbeans..................false
 scheduledExecutor...............none
 scheduledExecutorService........internal
 schema..........................none
 threadFactory...................internal
 transactionIsolation............default
 username........................"postgres"
 validationTimeout...............5000

Update: In last 24 hour I have tried several solution from different thread and none of them fixed my issue. So here is the observations that might be important.

  1. SpringBootJPAHikariCP - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@1344bbf1 found this log. studied Reset (autoCommit) on connection in HikariCP this thread. tried to set auto commit same (true) at both side (hibernate and Hikari) and tried with false at both side also. still no luck.
  2. Enables leakDetectionThreshold, got leak detection exception. So tried to understand if hibernate/spring transaction manager releasing connections. From bellow Logs it looks like hibernate working fine.

    28 22:19:35- DEBUG - o.s.orm.jpa.JpaTransactionManager-371 ::  Opened new EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@4212be39] for JPA transaction
    28 22:19:35- DEBUG - o.h.e.t.internal.TransactionImpl-51 ::  begin
    28 22:19:35- DEBUG - o.s.orm.jpa.JpaTransactionManager-403 ::  Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@243e942]
    2com.someentity.MyEntity#ac918eed-345f-4a6c-8539-fe14e7fc41e2
    28 22:19:35- DEBUG - o.h.r.j.i.LogicalConnectionManagedImpl-137 ::  Initiating JDBC connection release from afterTransaction
    28 22:19:35- DEBUG - c.zaxxer.hikari.pool.ProxyConnection-242 ::  SpringBootJPAHikariCP - Executed rollback on connection org.postgresql.jdbc.PgConnection@1344bbf1 due to dirty commit state on close().
    28 22:19:35- DEBUG - o.h.e.i.AbstractFlushingEventListener-132 ::  Processing flush-time cascades
    28 22:19:35- DEBUG - o.h.e.i.AbstractFlushingEventListener-174 ::  Dirty checking collections
    
    28 22:19:35- DEBUG - org.hibernate.internal.SessionImpl-508 ::  Disconnecting session
    28 22:19:35- DEBUG - o.s.orm.jpa.JpaTransactionManager-759 ::  Initiating transaction commit
    28 22:19:35- DEBUG - o.s.orm.jpa.JpaTransactionManager-512 ::  Committing JPA transaction on EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@4212be39]
    28 22:19:35- DEBUG - o.h.e.t.internal.TransactionImpl-62 ::  committing
    28 22:19:35- DEBUG - o.h.r.j.i.LogicalConnectionManagedImpl-137 ::  Initiating JDBC connection release from afterTransaction
    28 22:19:35- DEBUG - o.h.r.j.i.LogicalConnectionManagedImpl-137 ::  Initiating JDBC connection release from afterTransaction
    28 22:19:35- DEBUG - o.s.orm.jpa.JpaTransactionManager-600 ::  Closing JPA EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@4212be39] after transaction
    28 22:19:35- DEBUG - o.s.o.jpa.EntityManagerFactoryUtils-435 ::  Closing JPA EntityManager
    
  3. All the idle connectiona are idle form postgres point of view and active form Hikari point of view. So when there are 5 idle connection from database, there are toatal = 5, active=4, idle = ,waiting=0 in Hikari log.

Note:

  1. may be I am having this exact issue https://github.com/brettwooldridge/HikariCP/issues/109 in my case active connection increasing with every transaction.

  2. HikariCP - connection is not available this is also a same issue. but nobody provide clear solution to this. btw I was using @Transactional from the begging as suggested by the accepted answer.

Answer

Saif picture Saif · Oct 30, 2018

This was not any Hikari issue, there was a mistake in my end. Still posting the details of how this occurred, in case it helps someone.

I was using spring boot 1.5.6 (This was the latest version when I start working). This version included spring-orm 4.3.1. This version of spring-orm included support for three versions of hibernate, Hibernate5, Hibernate4 and Hibernate3.

So I configured spring boot with bellow configuration for current_session_context_class.

spring.jpa.properties.hibernate.current_session_context_class=org.springframework.orm.hibernate4.SpringSessionContext

Everything was working fine until it comes to connection management of Hikari. What happened is spring-boot-starter-jpa for 1.5.6 included Hibernate5 (I mean hibernate core) .

So, After performing any DB operation spring loosing control of that connection (most possibility for this version mismatch). Hence the problem.

After changing

org.springframework.orm.hibernate4.SpringSessionContext

to

org.springframework.orm.hibernate5.SpringSessionContext

the problem was solved immediately.

My current configuration is

spring.jpa.properties.hibernate.current_session_context_class=org.springframework.orm.hibernate5.SpringSessionContext
spring.jpa.properties.hibernate.dialect=org.hibernate.dialect.PostgreSQL95Dialect

FYI, after solving the problem is switched to Spring Boot 2.