Spring Data / HikariCP: Unable to acquire JDBC Connection on high load with MySQL database

[sdoeringNew]

The default pool size on HikariCP is ten. If an instant high load with more than ten threads occurs the connection pool can't acquire a connection in time. That's 30 seconds until it timeouts altough the request itself would take far less than a second.

I've created and attached an application with Spring Boot 2.2.6 and a SpringBootTest: demo.tar.gz

There are many errors during the test run:

2020-04-15 22:25:08.151  WARN 31173 --- [ool-1-thread-20] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2020-04-15 22:25:08.151 ERROR 31173 --- [pool-1-thread-4] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30000ms.

And this stacktrace is printed:

Caused by: 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:448)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:376)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:572)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:360)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:99)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at com.example.demo.DemoService$$EnhancerBySpringCGLIB$$71ec5fc0.saveDemo(<generated>)
    at com.example.demo.DemoApplicationTests.lambda$acquire_database_connection$0(DemoApplicationTests.java:40)
    at java.base/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)
    at java.base/java.util.stream.IntPipeline$Head.forEach(IntPipeline.java:593)
    at com.example.demo.DemoApplicationTests.lambda$acquire_database_connection$1(DemoApplicationTests.java:40)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
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:113)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:250)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:258)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246)
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:184)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402)
    ... 17 more
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:697)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161)
    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:38)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104)
    ... 24 more

I did some further tests...

The problem does not occur with tomcat-jdbc connection pool. The problem does not occur with a different database as H2 or PostgreSQL. The problem does not occur if the pool size is set higher.

[sdoeringNew]

I've used a Docker to provide a MySQL server for the test run:

docker run --name "mysql_demo" -e MYSQL_ROOT_PASSWORD=root -p 3306:3306 -d mysql/mysql-server:8.0.19
// wait a bit
docker exec -i "mysql_demo" mysql --user=root --password=root -e "CREATE DATABASE demo"
docker exec -i "mysql_demo" mysql --user=root --password=root -e "CREATE USER 'demo'@'%' IDENTIFIED BY 'demo'"
docker exec -i "mysql_demo" mysql --user=root --password=root -e "GRANT ALL PRIVILEGES ON *.* TO 'demo'@'%'"

[snicoll]

The problem does not occur with tomcat-jdbc connection pool. The problem does not occur with a different database as H2 or PostgreSQL.

Thanks for the report but given the the problem does not occur with another connection pool or another database, I don't see how it can be related to Spring Boot. Please consider reporting that problem to the HikariCP project or MySQL. I'd ask on StackOverflow first to see if someone in the community can help you.

[sdoeringNew]

Should the default connection pool be changed?

As MySQL and MariaDB are the most used databases and Spring Boot is fairly popular it is not good that the default pool is unstable on a bit of high load.

[snicoll]

I don’t think so. Let’s confirm the issue first and we can take it from there. Feel free to add a link of what you’ve reported so that we can follow along.

[sdoeringNew]

Isn't the provided test application confirmation enough? What else do you need for confirmation?

[snicoll]

This is the Spring Boot issue tracker and I've already indicated in my first comment what I'd recommend doing:

Please consider reporting that problem to the HikariCP project or MySQL. I'd ask on StackOverflow first to see if someone in the community can help you.

[sdoeringNew]

So you can confirm it's an HikariCP issue? I haven't been able to.

Currently I assume something about the ID generation. If I remove the @GeneratedValue and set the ID myself the provided test application works.

Edit: My amateurish opinion is now that all connections have been pulled from the pool. Thus leaving no possibility to get another connection to get and set the next value for the table-based HiLo sequence. That's the reason the other databases are not affected as they have a real sequence.

[snicoll]

So you can confirm it's an HikariCP issue? I haven't been able to.

No. If I did, I would have shared that information with you. Spring Boot is configuring the infrastructure and such an issue is too low-level for it to be involved.

Paging @mp911de in case that rings a bell on the Spring Data front.

[sdoeringNew]

Now that I know it's something ID generation related I can confirm the issue with the Tomcat JDBC pool, too. If I set the maxActive to ten (default: 50) the problem occurs with that pool, too.

So it's not necessary to change the default pool. ^^

[sdoeringNew]

It's a known Hibernate issue: https://hibernate.atlassian.net/browse/HHH-11825 Open for years and no real solution or workaround.

Thanks for your time. :+1:

[15pkzhaozhu]

How to solve this problem？

The problem occur with a database as MySQL. The problem does not occur with a database as Oracle.

code: Session openSession = entityManagerFactory.unwrap(SessionFactory.class).openSession(); openSession.setHibernateFlushMode(FlushMode.MANUAL); openSession.beginTransaction();

error: o.h.e.j.s.SqlExceptionHelper : SQL Error: 0, SQLState: null o.h.e.j.s.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms.

o.s.b.a.j.DataSourceHealthIndicator : DataSource health check failed org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82) ~[spring-jdbc-5.3.4.jar:5.3.4]

[snicoll]

@15pkzhaozhu please ask questions on StackOverflow.