Hikaricp: Intermittent Timeouts from Pool at High Load

Created on 29 Nov 2018 · 4Comments · Source: brettwooldridge/HikariCP

Environment

HikariCP version: 3.1.0
JDK version     : 1.8.0_91
Database        : MySQL
Driver version  : 8.0.11

We are getting intermittent timeout failures on connection pool to our master DB. These failure are coming on our performance environment at higher traffic. These timeouts occur every few minutes and last for around few milliseconds to upto a few seconds. The database health seems to be fine at this time and also, these timeouts happen on various app servers at different times.

Hikari Configuration:

Below are the Hikari logs:

28 Nov 2018 16:10:19,011 -[]- DEBUG HikariPool-1 - Pool stats (total=40, active=2, idle=38, waiting=0)
28 Nov 2018 16:10:49,011 -[]- DEBUG HikariPool-1 - Pool stats (total=40, active=3, idle=37, waiting=0)
28 Nov 2018 16:10:55,322 -[1012752031:3]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,324 -[1012752379:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,326 -[1012752173:2]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,327 -[1012752336:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,328 -[1012752347:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,329 -[1012752186:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,329 -[1012752335:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=85)
28 Nov 2018 16:10:55,330 -[1012751860:5]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,330 -[1012752308:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,331 -[1012751595:2]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,332 -[1354258828:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,332 -[1354258953:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=84)
28 Nov 2018 16:10:55,332 -[1012751826:5]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=84)
28 Nov 2018 16:10:55,333 -[1012751731:2]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
28 Nov 2018 16:10:55,334 -[1012752306:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=86)
]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=52)
28 Nov 2018 16:10:55,610 -[1012752216:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=56)
28 Nov 2018 16:10:55,646 -[1012752217:1]- WARN HikariPool-1 - Connection com.mysql.cj.jdbc.ConnectionImpl@286bcb03 marked as broken because of SQLSTATE(08003), ErrorCode(0)
28 Nov 2018 16:10:55,766 -[1012752217:1]- DEBUG HikariPool-1 - Closing connection com.mysql.cj.jdbc.ConnectionImpl@286bcb03: (connection is broken)
28 Nov 2018 16:10:55,838 -[1012752365:1]- DEBUG HikariPool-1 - Added connection com.mysql.cj.jdbc.ConnectionImpl@3f955f7e
28 Nov 2018 16:10:55,865 -[1012752365:1]- DEBUG HikariPool-1 - After adding stats (total=40, active=5, idle=35, waiting=0)
28 Nov 2018 16:10:56,187 -[1354258816:2]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=95)
28 Nov 2018 16:10:56,189 -[1012752321:2]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=95)
28 Nov 2018 16:10:56,197 -[1012752602:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=97)
28 Nov 2018 16:10:56,199 -[1012752460:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=97)
28 Nov 2018 16:10:56,199 -[1354259060:1]- DEBUG HikariPool-1 - Timeout failure stats (total=40, active=40, idle=0, waiting=97)
28 Nov 2018 16:10:56,483 -[1012752554:2]- DEBUG HikariPool-1 - Timeout failure stats (total=38, active=37, idle=1, waiting=56)
28 Nov 2018 16:11:19,011 -[]- DEBUG HikariPool-1 - Pool stats (total=40, active=5, idle=35, waiting=0)

We have ruled out any issues with the server or GC like issues effecting performance. I have taken the thread dump of the application during the time and it seems like only 5-10 of the application threads are actually waiting on db response or connection. All other threads are busy performing non-db operations. Attaching threaddump as well.

My guess is that at high throughput, hikari is not able to lease connection to application at high throughput. Please give your inputs on this and how to investigate this further.

12036.txt

Have you searched the CLOSED issues already? How about checking stackoverflow?

Source

mkathuria

Most helpful comment

@rodripf Wow, I hate to say it, but most of the advice in that post is pretty bad.

One piece of advice:

idleTimeout: 10000ms
This modification will reduce the time to mark a connection as idle. In other word, to free connection faster and that helps reduce the chance that Hikari’s pool is full.

Incorrect. First, the author does not recommend any minimumIdle, which means that idleTimeout will be ignored (and a warning logged at startup).

Assuming minimumIdle _is_ also specified, setting idleTimeout=10000 does not "free a connection faster" in any meaningful sense. It _would_ cause a connection to be _closed_ faster, and removed from the pool. But this is actually less efficient than a pool that is "full" of idle connections ready to go. It has nothing to do with the _"Connection is not available, request timed out after 30000ms"_ exception.

The author recommends maxLifetime: 1800000ms. This is already the default and does not need to be set explicitly. Again, it has nothing to do with the timeout exception.

Finally, the author recommends maximumPoolSize: 200. This is fine, assuming your database server has _96 CPU cores_.

The _"Connection is not available, request timed out after 30000ms"_ exception is reflective of one of several issues:

The application or database server CPUs are overloaded, and pegged at 100% for more than 30 seconds.
The server is a virtual machine, and the VM was suspended for more than 30 seconds.
The application has some long-running queries (> 30 seconds).
The number of application threads _vastly_ outnumbers the maximumPoolSize (like by nearly 10x) combined with somewhat slow queries.

In order to illustrate this last case, imagine a pool with a single connection. Imagine 20 application threads. And imagine each query takes 2 seconds. Clearly, if 20 theads queue up to run a query, and each query takes 2 seconds, only the first 15 theads will succeed. At that point, theads 16-20 will have been waiting for 30 seconds for a connection, and will all encounter the timeout.

The only credit to be given to the above recommendations is that maximumPoolSize likely _is_ too small for the given application. More accurately, it is _more_ likely that the application queries are inefficient -- lacking indexes etc. My company has a database with hundreds of millions of rows on average, and potentially over a billion rows for some customers, and yet most of our queries have been optimized to return in less than 2ms. A "long" query for us might be 20ms.

But if the application will not be fixed, or time is needed while it is being fixed, you can _try_ a "quick fix" to increase maximumPoolSize. The default pool size is 10 connections, so by "increase" I do _not_ mean 200 connections. Try doubling to 20 connections to see if the timeout issues go away.

But also monitor CPU/memory on the application and database. Do connection timeout issues correlate with CPU/memory spikes?

Monitor query transaction times. Possibly most queries run fast most of the time, but occassionally _a combination_ of inserts/updates/selects runs into severe lock contention, jamming the pool and causing timeouts until the lock contention naturally clears. Such issues are hard to track down, and the only solution is to collect as much data as possible. Throwing connections at the problem is a rather poor "solution".

Update: One issue I left out is a very short connectionTimeout. The default is 30 seconds, but it can be set as low as 250ms. The lower you go, the more you risk sporadic timeouts caused by unrelated OS activity suspending threads, or CPU contention with other theads. Some OS such as Windows have a notoriously high scheduler "quantum" (timeslice) -- something like 30ms resolution -- which can result in _jerky_ thread execution leading to sporadic timeouts.

brettwooldridge on 15 Dec 2019

❤2 🚀1

All 4 comments

Hi, your connectionTimeout is configured to the very shortest value allowed by HikariCP, from the docs:
"...the maximum number of milliseconds that a client (that's you) will wait for a connection from the pool ... Lowest acceptable connection timeout is 250 ms. Default: 30000 (30 seconds)"

Basically, try changing that setting to e.g. 5000 msec

As I understand the logs, your 40 connections are often all checked out of the pool, leaving some threads waiting. That's normal. Bear in mind a thread might hold a connection, but not be running a query on it at the point you took a thread dump.

I think the problem lies with the 250 msec connectionTimeout. Each thread will only be allowed to wait a quarter of a second in the pool queue before being kicked out with a timeout exception. Considering you have almost 100 connection requests waiting, your average checked-out time needs to be max 100 msec to keep up, using those 40 connections. Realistically, 100 msec is too short for network-routed database queries.

Increasing the connectionTimeout to 5000 msec would allow 2 seconds per checkout in the scenario shown.

nunnr on 30 Nov 2018

Hi We have the similar problem and our parameters are as follows; We are using postgresql 9.6, hikari 3.1

2019-03-27 10:40:55.554 WARN 7 --- [ 2019-03-27 10:40:55.557 DEBUG 7 --- [ 2019-03-27 10:40:55.561 DEBUG 7 --- [ 2019-03-27 10:40:55.561 DEBUG 7 --- [ 2019-03-27 10:40:55.562 DEBUG 7 --- [ 2019-03-27 10:40:55.562 DEBUG 7 --- [ 2019-03-27 10:40:55.563 DEBUG 7 --- [ 2019-03-27 10:40:55.564 DEBUG 7 --- [ 2019-03-27 10:40:55.564 DEBUG 7 --- [ 2019-03-27 10:40:55.565 DEBUG 7 --- [ 2019-03-27 10:40:55.565 DEBUG 7 --- [ 2019-03-27 10:40:55.567 DEBUG 7 --- [ 2019-03-27 10:40:55.568 DEBUG 7 --- [ 2019-03-27 10:40:55.568 DEBUG 7 --- [ 2019-03-27 10:40:55.568 DEBUG 7 --- [ 2019-03-27 10:40:55.569 DEBUG 7 --- [ 2019-03-27 10:40:55.569 DEBUG 7 --- [ 2019-03-27 10:40:55.570 DEBUG 7 --- [ 2019-03-27 10:40:55.571 DEBUG 7 --- [ 2019-03-27 10:40:55.571 DEBUG 7 --- [ 2019-03-27 10:40:55.572 DEBUG 7 --- [ 2019-03-27 10:40:55.572 DEBUG 7 --- [ 2019-03-27 10:40:55.573 DEBUG 7 --- [ 2019-03-27 10:40:55.573 DEBUG 7 --- [ 2019-03-27 10:40:55.574 DEBUG 7 --- [ 2019-03-27 10:40:55.575 DEBUG 7 --- [ 2019-03-27 10:40:55.575 DEBUG 7 --- [ 2019-03-27 10:40:55.576 DEBUG 7 --- [ 2019-03-27 10:40:55.577 DEBUG 7 --- [ 2019-03-27 10:40:55.577 DEBUG 7 --- [ 2019-03-27 10:40:55.578 DEBUG 7 --- [ 2019-03-27 10:40:55.579 DEBUG 7 --- [ 2019-03-27 10:40:55.580 DEBUG 7 --- [ 2019-03-27 10:40:55.580 DEBUG 7 --- [ 2019-03-27 10:40:55.581 DEBUG 7 --- [ main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - idleTimeout has been set but has no effect because the pool is operating as a fixed size pool.
main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - configuration:
main] com.zaxxer.hikari.HikariConfig : allowPoolSuspension.............false
main] com.zaxxer.hikari.HikariConfig : autoCommit......................true
main] com.zaxxer.hikari.HikariConfig : catalog.........................none
main] com.zaxxer.hikari.HikariConfig : connectionInitSql...............none
main] com.zaxxer.hikari.HikariConfig : connectionTestQuery............."SELECT 1"
main] com.zaxxer.hikari.HikariConfig : connectionTimeout...............30000
main] com.zaxxer.hikari.HikariConfig : dataSource......................none
main] com.zaxxer.hikari.HikariConfig : dataSourceClassName.............none
main] com.zaxxer.hikari.HikariConfig : dataSourceJNDI..................none
main] com.zaxxer.hikari.HikariConfig : dataSourceProperties............{password=}
main] com.zaxxer.hikari.HikariConfig : driverClassName.................none
main] com.zaxxer.hikari.HikariConfig : healthCheckProperties...........{}
main] com.zaxxer.hikari.HikariConfig : healthCheckRegistry.............none
main] com.zaxxer.hikari.HikariConfig : idleTimeout.....................20000
main] com.zaxxer.hikari.HikariConfig : initializationFailTimeout.......1
main] com.zaxxer.hikari.HikariConfig : isolateInternalQueries..........false
main] com.zaxxer.hikari.HikariConfig : .................
main] com.zaxxer.hikari.HikariConfig : leakDetectionThreshold..........60000
main] com.zaxxer.hikari.HikariConfig : maxLifetime.....................1800000
main] com.zaxxer.hikari.HikariConfig : maximumPoolSize.................10
main] com.zaxxer.hikari.HikariConfig : metricRegistry..................none
main] com.zaxxer.hikari.HikariConfig : metricsTrackerFactory...........none
main] com.zaxxer.hikari.HikariConfig : minimumIdle.....................10
main] com.zaxxer.hikari.HikariConfig : password........................
main] com.zaxxer.hikari.HikariConfig : poolName........................"HikariPool-1"
main] com.zaxxer.hikari.HikariConfig : readOnly........................false
main] com.zaxxer.hikari.HikariConfig : registerMbeans..................false
main] com.zaxxer.hikari.HikariConfig : scheduledExecutor...............none
main] com.zaxxer.hikari.HikariConfig : schema..........................none
main] com.zaxxer.hikari.HikariConfig : threadFactory...................internal
main] com.zaxxer.hikari.HikariConfig : transactionIsolation............default
main] com.zaxxer.hikari.HikariConfig : username........................none
main] com.zaxxer.hikari.HikariConfig : validationTimeout...............5000

the error is

2019-03-27 10:52:21.650 DEBUG 7 --- [o-8080-exec-198] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=97)
2019-03-27 10:52:21.652 DEBUG 7 --- [o-8080-exec-232] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=96)
2019-03-27 10:52:21.652 DEBUG 7 --- [o-8080-exec-228] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=95)
2019-03-27 10:52:21.652 DEBUG 7 --- [o-8080-exec-225] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=94)
2019-03-27 10:52:21.652 DEBUG 7 --- [o-8080-exec-259] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=93)
2019-03-27 10:52:21.671 ERROR 7 --- [o-8080-exec-194] Controller : HikariPool-1 - Connection is not available, request timed out after 30780ms.; nested exception is org.apache.openjpa.persistence.PersistenceException: HikariPool-1 - Connection is not available, request timed out after 30780ms.

org.springframework.orm.jpa.JpaSystemException: HikariPool-1 - Connection is not available, request timed out after 30780ms.; nested exception is org.apache.openjpa.persistence.PersistenceException: HikariPool-1 - Connection is not available, request timed out after 30780ms.
at org.springframework.orm.jpa.EntityManagerFactoryUtils.convertJpaAccessExceptionIfPossible(EntityManagerFactoryUtils.java:418)
at org.springframework.orm.jpa.DefaultJpaDialect.translateExceptionIfPossible(DefaultJpaDialect.java:122)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:488)
at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:59)
at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:213)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:147)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:133)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:57)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)

mehmetekici on 27 Mar 2019

This link helped me understand and fix this error:
https://oraerr.com/database/oracle/understanding-hibernate-database-connection-pool-and-fix-sqltransientconnectionexception-hikaripool-1-connection-is-not-available-request-timed-out-after-30000ms/

rodripf on 11 Dec 2019

👎1