4

I recently started getting error on my project which calls a third party api which usually takes 40sec. Looks like db connection from hikaripool is hijacked by the parent thread and is not available for other concurrent requests

Here is the overview of the implemention

  1. DB insert (business logic)
  2. Restemplate call (40 sec)
  3. DB update (business logic)

Some errors on high concurrency

java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30005ms.

I tried to mimic this locally and found theses error same as production

Hikari Configs

hikari:
      maximumPoolSize: 2
      idleTimeout: 60000
      minimumIdle: 2
      maxLifetime: 120000
      leak-detection-threshold: 1000

Service method to mimic the production logic


public void insertComment() throws InterruptedException {
        Load load =  new Load();
        load.setComment("new comment "+System.currentTimeMillis());
        repo.save(load);
        Thread.sleep(60000); // mocking restemplate long i/o
        load =  new Load();
        load.setComment("new comment "+System.currentTimeMillis());
        repo.save(load);
    }

Edit 1:

Now firing 3 concurrent requests to api (2 connection in hikari-cp + 1) invoking this service method

Stack Trace -1

2021-01-01 22:50:01.309  WARN 6599 --- [l-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask     : Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@462abec3 on thread http-nio-8080-exec-1, stack trace follows

java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:273) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:281) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174) ~[spring-data-jpa-2.4.2.jar:2.4.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.2.jar:5.3.2]
    at com.sun.proxy.$Proxy77.save(Unknown Source) ~[na:na]
    at com.example.demo.Service.insertComment(Service.java:89) ~[classes/:na]

Stack Trace - 2


java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30002ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:273) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:281) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.4.25.Final.jar:5.4.25.Final]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421) ~[spring-orm-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137) ~[spring-tx-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174) ~[spring-data-jpa-2.4.2.jar:2.4.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.2.jar:5.3.2]
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.2.jar:5.3.2]
    at com.sun.proxy.$Proxy77.save(Unknown Source) ~[na:na]
    at com.example.demo.Service.insertComment(Service.java:89) ~[classes/:na]

Stack Trace -3


2021-01-01 22:50:51.411  INFO 6599 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.ProxyLeakTask     : Previously reported leaked connection com.mysql.jdbc.JDBC4Connection@462abec3 on thread http-nio-8080-exec-1 was returned to the pool (unleaked)

How deal with this problem?

EDIT 2:

Found this post. Setting this config spring.jpa.open-in-view=false seems to solve the issue. Any leads on what this config does. Is it safe?

pranav prashant
  • 307
  • 1
  • 3
  • 13

3 Answers3

3

This is late reply but hopefully it will help others:

My hunch is that if you have OSIV filter enabled (i.e. when spring.jpa.open-in-view is true or not set) then Session is open for the whole flow (for 40+ seconds) and connection is returned to the pool only after session is closed. This way if you have 2 such flows active there will be no connections available for other logic for 40seconds and those will timeout.

On the other hand if you disable OSIV like you did and if you don't have a transaction that spans between first and last DB operation, then connection will be returned to the pool for the time of the 40s rest call.

See excellent explanation of OSIV by Vlad here

Domaru
  • 31
  • 2
2

You told that you have :

Some errors on high concurrency

And you get :

java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30005ms.

That means that the DB connection pool (Hikari) didn't manage to provide a connection in 30 secs max.
You configured the max number of connection of the pool to 2 :

  maximumPoolSize: 2

It is few and moreover, if your queries are quite long processing and that your application has high concurrency, that parameter looks really under-estimate.
Increase it to a higher number such as 10 or more and watch the behavior. You can also play with the connectionTimeout parameter but as a result, it will slow down your app if client requests wait for connection.

The Hikari pool size documentation could give you some information about the way to tweak the configuration.

As alternative, you could rethink your datasource. For example define two datasources : one for long connections (for long queries) and another one for sort connections (for short queries) and use the datasources that fits better according to the case.

As a side note Spring Boot provides an actuator focused on datasource connections : DataSourceHealthIndicator that checks that a connection to DataSource can be obtained.
Joined to a monitoring system tool (Prometheus or any other), these may be helpful to diagnostic that kind of issues.

davidxxx
  • 125,838
  • 23
  • 214
  • 215
  • Hi @davidxxx this was just a mock.... on prod i do have set it to 10 but for 10 concurrent request its fine, but for 11th request its the same story. – pranav prashant Jan 01 '21 at 18:04
  • Hi pranav, I had some doubts when I read your question. You can increase above 10. 15 or 20 may improve things. I edited my answer with an additional idea. – davidxxx Jan 01 '21 at 18:21
  • Sure. Is there any other way as well to deal with this or is this by design. one thread one db connection. – pranav prashant Jan 01 '21 at 18:24
  • That is by design. A database connection is stateful : it contains specific information related to which the caller and the database sends. You cannot share it without taking the risk of breaking its state. – davidxxx Jan 01 '21 at 18:27
  • 1
    Hi David, on setting this value `spring.jpa.open-in-view=false` in .yml, Connections are getting returned back to hikari pool and available for concurrent requests... Load tested the same scenario with 15 concurrent requests and 2 hikari pool connection. No issues observed. Can you share your thoughts here.... No connection leak detected as well ...Thanks. – pranav prashant Jan 05 '21 at 09:06
1

You can increase a connection timeout by setting the corresponding property:

hikari:
  connectionTimeout: 60000        #30000 (or 30 sec) by default

However, it's better not to hold the connection while calling 3rd party API but to make DB calls with separate connections in this case.

amseager
  • 5,795
  • 4
  • 24
  • 47