Connection Acquisition Hangs After Network Disturbance. #754

@liamchristopher

Description

Hello,
This is a follow-up to [https://github.com/ /issues/602 ](Issue #602 ). I closed the issue after upgrading and doing some more investigation, but I'd like to see if you have any suggestions for how to deal with this issue.

Same stack: Spring, HIbernate 4, Tomcat 7, Java 8, MySql 5.5. We're using the latest version of hikari (Currently 2.5.1), and still having intermittent failures.

I don't believe that this is a bug in the connection pool, but in our corporate environment, we've had a recurring problem where the network has some intermittent "blips". This is not a failure of the App or of MySql, but somehow the connection is momentarily lost.

So, what happens is that the Runnable in addBagItem

@Override public Future<Boolean> addBagItem() { return addConnectionExecutor.submit(POOL_ENTRY_CREATOR); }

Is that the thread can't make a connection and sits and hangs while the idle threads expire and are evicted. Since the addConnection process is a single blocking queue, the thread never acquires a connection and the fillPool() method just sits there. This eventually results in having a total connection of 0 and the app crashes, because its unable to get a DB connection.

This has proven very difficult to replicate (there is a thread dump in the prior ticket), and since the issues seem to be rooted in some mysterious behavior on the ops side of things, it seems like there isn't too much we can actually do on the app side. At first we thought it was a connection issue on the VIP that sits in front of our Read-Only / Slave boxes, but it has also happened on our direct connection to the RW / master. The other difficulty is that since the starvation doesn't happen until AFTER the existing DB threads timeout / are evicted, then we can't really pinpoint when the network issue happened.

So, in addition to the configuration as listed, I added a scheduled job to poll the MX Beans and perform a softEvict() if the Working / Idle threads drop to 0/0, but we're still having issues of eventually running out of connections.

My next course of action was to inject a ScheduledExecutor to enforce a timeout at the thread level. That seems a little extreme, but I'm honestly not sure where to go forward with this.

Below is a log of what the debug during one of these incidents. Both pools have the same config of Min/Max: 10/50 connections. In this case you can see that our Read-Only pool started dying at 4 connections:

Any thoughts?

2016-10-21 04:29:02,975 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:02,975 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=2) 2016-10-21 04:29:03,084 [http-apr-7305-exec-38] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=1) 2016-10-21 04:29:03,084 [http-apr-7305-exec-38] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:03,084 [http-apr-7305-exec-38] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:03,674 [http-apr-7305-exec-7] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=0) 2016-10-21 04:29:03,674 [http-apr-7305-exec-7] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:03,674 [http-apr-7305-exec-7] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:05,363 [Read-Only-Pool housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=0) 2016-10-21 04:29:05,363 [Read-Write-Pool housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:12,976 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:12,976 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=1) 2016-10-21 04:29:19,504 [http-apr-7305-exec-5] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=0) 2016-10-21 04:29:19,504 [http-apr-7305-exec-5] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:19,504 [http-apr-7305-exec-5] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:22,977 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:22,977 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=0) 2016-10-21 04:29:32,978 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:32,978 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=4) 2016-10-21 04:29:35,084 [http-apr-7305-exec-46] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=4) 2016-10-21 04:29:35,084 [http-apr-7305-exec-46] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:35,084 [http-apr-7305-exec-46] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:35,363 [Read-Only-Pool housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=4) 2016-10-21 04:29:35,363 [Read-Write-Pool housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:35,685 [http-apr-7305-exec-17] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=3) 2016-10-21 04:29:35,685 [http-apr-7305-exec-17] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:35,685 [http-apr-7305-exec-17] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:40,083 [http-apr-7305-exec-24] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=3) 2016-10-21 04:29:40,083 [http-apr-7305-exec-24] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:40,083 [http-apr-7305-exec-24] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:40,695 [http-apr-7305-exec-4] DEBUG com.zaxxer.hikari.pool.HikariPool - Read-Only-Pool - Timeout failure stats (total=4, active=4, idle=0, waiting=2) 2016-10-21 04:29:40,695 [http-apr-7305-exec-4] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: null 2016-10-21 04:29:40,695 [http-apr-7305-exec-4] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Read-Only-Pool - Connection is not available, request timed out after 10000ms. 2016-10-21 04:29:43,062 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Write-Pool - Pool stats (total=10, active=0, idle=10, waiting=0) 2016-10-21 04:29:43,062 [pool-6-thread-1] INFO <redacted>.api.v3.util.HikariPoolRestartController - Read-Only-Pool - Pool stats (total=4, active=4, idle=0, waiting=2)