Hikaricp: Timeout on dead connection connecting to Postgres

Created on 31 Mar 2016 · 12Comments · Source: brettwooldridge/HikariCP

I am getting timeout exceptions when connecting to an Amazon RDS instance:

2016-03-30 12:11:40,520 [debug] Before cleanup pool stats HikariPool-0 (total=10, inUse=0, avail=10, waiting=0)
2016-03-30 12:11:40,521 [debug] After cleanup pool stats HikariPool-0 (total=10, inUse=0, avail=10, waiting=0)
2016-03-30 12:11:40,785 [debug] Before cleanup pool stats HikariPool-1 (total=5, inUse=0, avail=5, waiting=0)
2016-03-30 12:11:40,785 [debug] After cleanup pool stats HikariPool-1 (total=5, inUse=0, avail=5, waiting=0)
2016-03-30 12:11:41,139 [debug] Before cleanup pool stats HikariPool-2 (total=4, inUse=0, avail=4, waiting=0)
2016-03-30 12:11:41,143 [debug] After cleanup pool stats HikariPool-2 (total=4, inUse=0, avail=4, waiting=0)
2016-03-30 12:11:41,250 [debug] Closing connection org.postgresql.jdbc4.Jdbc4Connection@2fa511df
2016-03-30 12:11:41,289 [debug] After fill pool stats HikariPool-2 (total=4, inUse=0, avail=4, waiting=0)
2016-03-30 12:11:41,370 [debug] Before cleanup pool stats HikariPool-3 (total=2, inUse=1, avail=1, waiting=0)
2016-03-30 12:11:41,371 [debug] After cleanup pool stats HikariPool-3 (total=2, inUse=1, avail=1, waiting=0)
2016-03-30 12:11:41,408 [debug] Closing connection org.postgresql.jdbc4.Jdbc4Connection@2162ea5b
2016-03-30 12:11:41,606 [debug] Before cleanup pool stats HikariPool-4 (total=1, inUse=0, avail=1, waiting=0)
2016-03-30 12:11:41,607 [debug] After cleanup pool stats HikariPool-4 (total=0, inUse=0, avail=0, waiting=0)
2016-03-30 12:11:41,607 [debug] Closing connection org.postgresql.jdbc4.Jdbc4Connection@1d6d338
2016-03-30 12:11:41,771 [debug] After fill pool stats HikariPool-4 (total=1, inUse=0, avail=1, waiting=0)
2016-03-30 12:11:48,163 [warn]  Exception during keep alive check, that means the connection (org.postgresql.jdbc4.Jdbc4Connection@e681374) must be dead.
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:283) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:570) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:406) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:286) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at com.zaxxer.hikari.pool.HikariPool.isConnectionAlive(HikariPool.java:120) ~[com.zaxxer.HikariCP-2.3.7.jar:na]
    at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:207) [com.zaxxer.HikariCP-2.3.7.jar:na]
    at com.zaxxer.hikari.pool.BaseHikariPool.getConnection(BaseHikariPool.java:182) [com.zaxxer.HikariCP-2.3.7.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:93) [com.zaxxer.HikariCP-2.3.7.jar:na]
    at scala.slick.jdbc.JdbcBackend$DatabaseFactoryDef$$anon$3.createConnection(JdbcBackend.scala:47) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.JdbcBackend$BaseSession.conn$lzycompute(JdbcBackend.scala:397) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.JdbcBackend$BaseSession.conn(JdbcBackend.scala:397) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.JdbcBackend$SessionDef$class.prepareStatement(JdbcBackend.scala:152) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.JdbcBackend$BaseSession.prepareStatement(JdbcBackend.scala:389) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.StatementInvoker.results(StatementInvoker.scala:32) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.StatementInvoker.iteratorTo(StatementInvoker.scala:22) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.Invoker$class.foreach(Invoker.scala:64) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.StatementInvoker.foreach(StatementInvoker.scala:16) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.Invoker$class.firstOption(Invoker.scala:29) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
    at scala.slick.jdbc.StatementInvoker.firstOption(StatementInvoker.scala:16) [com.typesafe.slick.slick_2.11-2.1.0.jar:na]
(...)
Caused by: java.net.SocketException: Connection timed out
    at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_74]
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_74]
    at java.net.SocketInputStream.read(SocketInputStream.java:170) ~[na:1.8.0_74]
    at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_74]
    at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:143) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:112) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:71) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:282) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1803) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    ... 99 common frames omitted
2016-03-30 12:11:48,175 [debug] Timeout failure pool stats HikariPool-3 (total=1, inUse=0, avail=1, waiting=0)
2016-03-30 12:11:48,175 [debug] Closing connection org.postgresql.jdbc4.Jdbc4Connection@e681374
2016-03-30 12:11:48,206 [error] Caught exception: Timeout after 951945ms of waiting for a connection.

This happens every hour or so under intensive usage. From what I understand, when hikari tries to use a connection from the pool it hangs for 15 min and then throws a timeout exception. I do not have a 900s timeout anywhere on the code so I don't know where that number comes from.

On the server side I have a few logs with "could not receive data from client: Connection timed out", don't know if it is related. I enabled Postgres server keepalives using tcp_keepalives_interval, tcp_keepalives_idle and tcp_keepalives_count. I checked with tcpdump on the client and there are keep alive packets coming from the DB host.

Here is the Hikari pool configuration:

2016-03-30 11:18:41,348 [info]  Creating Pool for datasource 'default'
2016-03-30 11:18:41,349 [debug] HikariCP pool HikariPool-3 configuration:
2016-03-30 11:18:41,349 [debug] allowPoolSuspension.............false
2016-03-30 11:18:41,350 [debug] autoCommit......................true
2016-03-30 11:18:41,350 [debug] catalog.........................
2016-03-30 11:18:41,350 [debug] connectionCustomizer............com.zaxxer.hikari.AbstractHikariConfig$1@66eb985d
2016-03-30 11:18:41,351 [debug] connectionCustomizerClassName...
2016-03-30 11:18:41,351 [debug] connectionInitSql...............
2016-03-30 11:18:41,351 [debug] connectionTestQuery.............SELECT 1;
2016-03-30 11:18:41,351 [debug] connectionTimeout...............30000
2016-03-30 11:18:41,352 [debug] dataSource......................
2016-03-30 11:18:41,352 [debug] dataSourceClassName.............
2016-03-30 11:18:41,352 [debug] dataSourceJNDI..................
2016-03-30 11:18:41,353 [debug] dataSourceProperties............{password=<masked>}
2016-03-30 11:18:41,353 [debug] driverClassName.................org.postgresql.Driver
2016-03-30 11:18:41,353 [debug] healthCheckProperties...........{}
2016-03-30 11:18:41,353 [debug] healthCheckRegistry.............
2016-03-30 11:18:41,354 [debug] idleTimeout.....................600000
2016-03-30 11:18:41,354 [debug] initializationFailFast..........true
2016-03-30 11:18:41,354 [debug] isolateInternalQueries..........false
2016-03-30 11:18:41,355 [debug] jdbc4ConnectionTest.............false
2016-03-30 11:18:41,355 [debug] jdbcUrl.........................jdbc:postgresql://XXXXX
2016-03-30 11:18:41,355 [debug] leakDetectionThreshold..........0
2016-03-30 11:18:41,355 [debug] maxLifetime.....................1800000
2016-03-30 11:18:41,356 [debug] maximumPoolSize.................5
2016-03-30 11:18:41,356 [debug] metricRegistry..................
2016-03-30 11:18:41,356 [debug] minimumIdle.....................1
2016-03-30 11:18:41,357 [debug] password........................<masked>
2016-03-30 11:18:41,357 [debug] poolName........................HikariPool-3
2016-03-30 11:18:41,357 [debug] readOnly........................false
2016-03-30 11:18:41,357 [debug] registerMbeans..................false
2016-03-30 11:18:41,358 [debug] threadFactory...................
2016-03-30 11:18:41,358 [debug] transactionIsolation............
2016-03-30 11:18:41,359 [debug] username........................XXXX
2016-03-30 11:18:41,359 [debug] validationTimeout...............5000
2016-03-30 11:18:41,359 [debug] HikariCP pool HikariPool-3 configuration:
2016-03-30 11:18:41,360 [debug] allowPoolSuspension.............false
2016-03-30 11:18:41,360 [debug] autoCommit......................true
2016-03-30 11:18:41,361 [debug] catalog.........................
2016-03-30 11:18:41,361 [debug] connectionCustomizer............com.zaxxer.hikari.AbstractHikariConfig$1@66eb985d
2016-03-30 11:18:41,361 [debug] connectionCustomizerClassName...
2016-03-30 11:18:41,361 [debug] connectionInitSql...............
2016-03-30 11:18:41,362 [debug] connectionTestQuery.............SELECT 1;
2016-03-30 11:18:41,362 [debug] connectionTimeout...............30000
2016-03-30 11:18:41,362 [debug] dataSource......................
2016-03-30 11:18:41,362 [debug] dataSourceClassName.............
2016-03-30 11:18:41,363 [debug] dataSourceJNDI..................
2016-03-30 11:18:41,363 [debug] dataSourceProperties............{password=<masked>}
2016-03-30 11:18:41,363 [debug] driverClassName.................org.postgresql.Driver
2016-03-30 11:18:41,364 [debug] healthCheckProperties...........{}
2016-03-30 11:18:41,364 [debug] healthCheckRegistry.............
2016-03-30 11:18:41,364 [debug] idleTimeout.....................600000
2016-03-30 11:18:41,364 [debug] initializationFailFast..........true
2016-03-30 11:18:41,365 [debug] isolateInternalQueries..........false
2016-03-30 11:18:41,365 [debug] jdbc4ConnectionTest.............false
2016-03-30 11:18:41,365 [debug] jdbcUrl.........................jdbc:postgresql://XXXXX?tcpKeepAlive=true
2016-03-30 11:18:41,365 [debug] leakDetectionThreshold..........0
2016-03-30 11:18:41,366 [debug] maxLifetime.....................1800000
2016-03-30 11:18:41,366 [debug] maximumPoolSize.................5
2016-03-30 11:18:41,366 [debug] metricRegistry..................
2016-03-30 11:18:41,367 [debug] minimumIdle.....................1
2016-03-30 11:18:41,367 [debug] password........................<masked>
2016-03-30 11:18:41,367 [debug] poolName........................HikariPool-3
2016-03-30 11:18:41,367 [debug] readOnly........................false
2016-03-30 11:18:41,368 [debug] registerMbeans..................false
2016-03-30 11:18:41,368 [debug] threadFactory...................
2016-03-30 11:18:41,368 [debug] transactionIsolation............
2016-03-30 11:18:41,368 [debug] username........................XXX
2016-03-30 11:18:41,369 [debug] validationTimeout...............5000
2016-03-30 11:18:41,369 [info]  HikariCP pool HikariPool-3 is starting.
2016-03-30 11:18:41,537 [debug] HikariPool-3 - Connection.setNetworkTimeout() not supported
2016-03-30 11:18:41,556 [debug] After fill pool stats HikariPool-1 (total=5, inUse=0, avail=5, waiting=0)
2016-03-30 11:18:41,581 [info]  Database [default] connected at jdbc:postgresql://XXXX

I tried to change maxLifetime and idleTimeout to 300 seconds, but it did not help. I am using play 2.4.3 with jdbc 9.4-1201-jdbc41 connecting to postgres 9.4.

Source

nmatpt

All 12 comments

Check stackoverflow. I believe that RDS has its own Postgres driver.

brettwooldridge on 31 Mar 2016

@brettwooldridge That's Amazon Redshift. RDS is a standard Postgres instance, the examples they show use JDBC. What do you mean about checking stackoverflow? The issue happens consistently for some time now, the application hangs when it needs a connection. Looks like Hikari isn't fetching idle connections correctly from the pool, or isn't closing dead connections.

nmatpt on 1 Apr 2016

Googling HikariCP Amazon Postgres yields quite a few results.

http://stackoverflow.com/questions/34933325/how-to-make-play-2-scala-work-with-remote-postgresql-db-server

https://groups.google.com/forum/#!topic/hikari-cp/O-L015dAk_g

https://groups.google.com/forum/#!topic/hikari-cp/fl5IWveW1l8

brettwooldridge on 1 Apr 2016

Those links are completely unrelated to my problem.

The first link is about a user who cannot connect to the Postgres instance ever. If you read my issue description you can see that I only have occasional timeouts. I also have my connectionTestQuery set as SELECT 1; which was the solution to his problem (again, you can read this in the debug logs from Hikari that I posted above). The other 2 links are from Amazon Redshift which has nothing to do with the case.

nmatpt on 1 Apr 2016

Maybe a little creative googling? "Amazon RDS postfgresql timeout".

http://stackoverflow.com/questions/22696745/timeouts-connecting-to-a-postgres-database-on-amazon-rds-from-azure

You can see from your log that your driver does not support network timeouts:

2016-03-30 11:18:41,537 [debug] HikariPool-3 - Connection.setNetworkTimeout() not supported

PostgreSQL or something in between is dropping the connection. At that point you are going to run into the OS level TCP timeout, which in your case is likely 900 seconds.

brettwooldridge on 2 Apr 2016

👎1

Yes, I read that answer, that was what led me to tune the postgres server settings, like I described. But even with the server keepalives the connection is being dropped somehow.

Shouldn't Hikari detect that the connection was dropped and close it? I wouldn't mind handling this exception in the code (I am actually doing that at the moment), the problem is that it takes 15 minutes for the exception to be thrown so my thread just hangs waiting for this. I would expect Hikari to be a little smarter detecting dead connections before retrieving them from the pool. Am I missing some setting that I can use to make Hikari validate the connections?

EDIT: Also, my case differs from the question in the sense that I don't get the timeouts when I use psql. This probably indicates that the problem lies in the client and not the server, right?

nmatpt on 2 Apr 2016

@nmatpt This is where HikariCP is at the mercy of the OS. If the driver supported network timeout, HikariCP would quickly detect the issue.

Without support for network timeout, if the PostgreSQL server drops the TCP connection from its side, any packet sent from the application on that TCP connection will block in the OS network layer until the timeout configured at the OS-level (on the application server) is triggered.

You can see in this stacktrace that HikariCP tried to check the connection:

[warn]  Exception during keep alive check, that means the connection (org.postgresql.jdbc4.Jdbc4Connection@e681374) must be dead.
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:283) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:570) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:406) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:286) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at com.zaxxer.hikari.pool.HikariPool.isConnectionAlive(HikariPool.java:120) ~[com.zaxxer.HikariCP-2.3.7.jar:na]

but it was blocked at the OS level...

Caused by: java.net.SocketException: Connection timed out
    at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_74]
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_74]
    at java.net.SocketInputStream.read(SocketInputStream.java:170) ~[na:1.8.0_74]
    at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_74]
    at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:143) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:112) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:71) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:282) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1803) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[org.postgresql.postgresql-9.4-1201-jdbc41.jar:9.4]

There is nothing that HikariCP can do at this point. To try to avoid the issue, you can shorten the maxLifeTime to something like 5 or 10 minutes. Basically, you want HikariCP to kill connections before the server does it. If the server kills it first, you are going to run into the OS-level timeout (because the driver does not support network timeouts).

Also, I would recommend running the latest HikariCP (2.4.5), there have been so many fixes since 2.3.7.

brettwooldridge on 2 Apr 2016

👍1

OK, that makes sense, thanks for explaining. I actually tried to lower the maxLifeTime parameter, but the problem kept happening. I guess I have to try to find out the root cause of the timeouts. I will also update Hikari and the JDBC driver to the latest versions, that might help.

nmatpt on 2 Apr 2016

@brettwooldridge I was reading Hikari's isConnectionAlive method and I noticed that when networkTimeout is not supported you set a query timeout on the validation statement:

try (Statement statement = connection.createStatement()) {
   if (isNetworkTimeoutSupported != TRUE) {
      setQueryTimeout(statement, (int) MILLISECONDS.toSeconds(Math.max(1000L, validationTimeout)));
   }
   statement.execute(config.getConnectionTestQuery());
}

Shouldn't this throw a SQLTimeoutException after validationTimeout even if the connection is dead?

EDIT: I eventually resolved this issue by replacing Hikari with Tomcat and adding a custom tomcat validator to force the timeout on the validation query.

nmatpt on 5 Apr 2016

I had similar symptom (Java/Tomcat web app deployed on EBS with AWS RDS Postgres)
I would get connection timeout under load tests.
I resolved this case by replacing Hikari with Vibur DBCP. By default, it uses Connection.isValid() to validate JDBC connection, and has useNetworkTimeout bolean config parameter, set to false by default (http://www.vibur.org/#connection-timeouts)