brettwooldridge / HikariCP

光 HikariCP・A solid, high-performance, JDBC connection pool at last.
Apache License 2.0
20.01k stars 2.93k forks source link

HikariPool-1 - Connection is not available, request timed out after 30096ms. #1111

Closed yooniks closed 6 years ago

yooniks commented 6 years ago

Environment

HikariCP version: 2.7.8
JDK version     : 1.8.0_111
Database        : MySQL|

Hey, since long time I have big problem with my database, when I'm doing something I got this: (HikariPool-1 - Connection is not available, request timed out after 30000ms. | ) [09:26:26] [Craft Scheduler Thread - 2/WARN]: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. [09:26:26] [Craft Scheduler Thread - 2/WARN]: at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:667) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at xyz.yooniks.something.subpackage.SomeCommand$1.run(SomeCommand.java:74) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:59) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at org.github.paperspigot.ServerSchedulerReportingWrapper.run(ServerSchedulerReportingWrapper.java:23) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [09:26:26] [Craft Scheduler Thread - 2/WARN]: at java.lang.Thread.run(Thread.java:748) How can I fix that?

brettwooldridge commented 6 years ago

Not enough information. Please post your configuration, and report your version of HikariCP. How often does it happen? Does it only happen under load? etc. Please provide as much detail as possible, otherwise nobody can help you.

yooniks commented 6 years ago

HikariCP version: 2.7.8 Sometimes I get it: https://hastebin.com/adujexiqad.md 'Does it only happen under load?' -This happens when I'm spamming with method which executes something to mysql, or 'two users' are using over 2 methods, in 3-5 seconds (i think so)

Example:

final String updateString = "UPDATE `users` SET `group`=? WHERE UUID=?";
try (final Connection con = CorePlugin.getInst().getHikari().getConnection();
      final PreparedStatement update = con.prepareStatement(updateString)) {
   update.setString(1, args[1]);
   update.setString(2, uuid.toString());
   update.executeUpdate();
}

(https://hastebin.com/peyudexedu.swift)

hikari = new HikariDataSource();
hikari.setDataSourceClassName("com.mysql.jdbc.jdbc2.optional.MysqlDataSource");
hikari.addDataSourceProperty("serverName", getConfig().getString("mysql.host"));
hikari.addDataSourceProperty("port", getConfig().getString("mysql.port"));
hikari.addDataSourceProperty("databaseName", getConfig().getString("mysql.database"));
hikari.addDataSourceProperty("user", getConfig().getString("mysql.user"));
hikari.addDataSourceProperty("password", getConfig().getString("mysql.password"));
hikari.addDataSourceProperty("autoReconnect",true);
hikari.addDataSourceProperty("tcpKeepAlive", true);
hikari.setMaximumPoolSize(100);
hikari.setMinimumIdle(0);
hikari.setIdleTimeout(1);
brettwooldridge commented 6 years ago
yooniks commented 6 years ago

@brettwooldridge hikari = new HikariDataSource(); hikari.setDataSourceClassName("com.mysql.jdbc.jdbc2.optional.MysqlDataSource"); hikari.addDataSourceProperty("serverName", getConfig().getString("mysql.host")); hikari.addDataSourceProperty("port", getConfig().getString("mysql.port")); hikari.addDataSourceProperty("databaseName", getConfig().getString("mysql.database")); hikari.addDataSourceProperty("user", getConfig().getString("mysql.user")); hikari.addDataSourceProperty("password", getConfig().getString("mysql.password")); hikari.addDataSourceProperty("autoReconnect",true); hikari.addDataSourceProperty("cachePrepStmts",true); hikari.addDataSourceProperty("prepStmtCacheSize",250); hikari.addDataSourceProperty("prepStmtCacheSqlLimit",2048); hikari.addDataSourceProperty("useServerPrepStmts",true); hikari.addDataSourceProperty("cacheResultSetMetadata",true); hikari.addDataSourceProperty("maxReconnects",5); hikari.addDataSourceProperty("tcpKeepAlive", true); hikari.setMaximumPoolSize(20); hikari.setMinimumIdle(0); hikari.setIdleTimeout(30000); https://hastebin.com/lesojopizu.scala

final String insertString = "INSERT INTO users VALUES(?,?,?,?,?,?,?,?,?)"; try (final Connection con = CorePlugin.getInst().getHikari().getConnection(); final PreparedStatement insert = con.prepareStatement(insertString)) { insert.setString(1, uuid.toString()); insert.setString(2, p.getName()); insert.setString(3, args[1]); //group insert.setInt(4, 0); insert.setInt(5, 0); insert.setInt(6, 500); insert.setInt(7, 0); insert.setInt(8, 0); insert.setString(9, ""); insert.execute(); } https://hastebin.com/sotezidiji.swift

and

final String updateString = "UPDATEusersSETgroup=? WHERE UUID=?"; try (final Connection con = CorePlugin.getInst().getHikari().getConnection(); final PreparedStatement update = con.prepareStatement(updateString)) { update.setString(1, args[1]); update.setString(2, uuid.toString()); update.executeUpdate(); } https://hastebin.com/uqeguqeyec.swift

still not working ;/

[12:30:34] [Craft Scheduler Thread - 1/WARN]: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms. [12:30:34] [Craft Scheduler Thread - 1/WARN]: at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:667) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at xyz.yooniks.pvpcore.commands.SetRankCommand$1.run(SetRankCommand.java:69) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftTask.run(CraftTask.java:59) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at org.bukkit.craftbukkit.v1_8_R3.scheduler.CraftAsyncTask.run(CraftAsyncTask.java:53) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at org.github.paperspigot.ServerSchedulerReportingWrapper.run(ServerSchedulerReportingWrapper.java:23) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [12:30:34] [Craft Scheduler Thread - 1/WARN]: at java.lang.Thread.run(Thread.java:748) https://hastebin.com/odiwiviniv.md

Don't use autoReconnect, it is not meant for pools.'

How can I replace this?

brettwooldridge commented 6 years ago

Remove: hikari.addDataSourceProperty("autoReconnect",true); Remove: hikari.addDataSourceProperty("maxReconnects",5);

Enable the leakDetectionThreshold ... hikari.setLeakDetectionThreshold(60 * 1000) and watch the logs for leak messages. The stacktrace that is logged should lead you to the place in your code that borrowed but did not return a connection.

Enable DEBUG level logging in your logging framework for package com.zaxxer.hikari and watch the pool stats logged every 30 seconds:

DEBUG 2018-03-14 07:06:46 com.zaxxer.hikari.pool.HikariPool - Pool-0 - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
DEBUG 2018-03-14 07:06:46 com.zaxxer.hikari.pool.HikariPool - Pool-0 - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
...

If the active count keeps going up until it hits the total, and then waiting starts piling up, again an indication of a leak.

yooniks commented 6 years ago

@brettwooldridge A lot of thanks! I fixed it.

apoguy commented 6 years ago

@yooniks how exactly did you fix it?

yooniks commented 6 years ago

@apoguy I don't remember exactly, but I think i was not closing datasource (yes, it is autocloseable, but it helped me) That is what i changed:

        hikari.setDataSourceClassName("com.mysql.jdbc.jdbc2.optional.MysqlDataSource");
        hikari.addDataSourceProperty("serverName", getConfig().getString("mysql.host"));
        hikari.addDataSourceProperty("port", getConfig().getString("mysql.port"));
        hikari.addDataSourceProperty("databaseName", getConfig().getString("mysql.database"));
        hikari.addDataSourceProperty("user", getConfig().getString("mysql.user"));
        hikari.addDataSourceProperty("password", getConfig().getString("mysql.password"));
        hikari.addDataSourceProperty("autoReconnect", true);
        hikari.addDataSourceProperty("cachePrepStmts", true);
        hikari.addDataSourceProperty("prepStmtCacheSize", 250);
        hikari.addDataSourceProperty("prepStmtCacheSqlLimit", 2048);
        hikari.addDataSourceProperty("useServerPrepStmts", true);
        hikari.addDataSourceProperty("cacheResultSetMetadata", true);

        hikari.setMaximumPoolSize(16);
        hikari.setConnectionTimeout(30000);

it is very old code, but it is working fine now and i had try/catch in try/catch, i removed it and cleaned my code.

            hikari.close();
kaushik1979 commented 6 years ago

Do we know now exactly how to fix this error?

@yooniks Why use hikari.close();? Should it not be conn.close() in the finally after the execution?

apoguy commented 6 years ago

I have identified the issue on our end, and it was a connection leak. Detected by using logging and setting the connection leak detection threshold.

We solved it by making all methods that used the DB @Transacted, and returning the connection to the pool with the close() method.

solankivaibhav789 commented 5 years ago

Update properties spring.datasource.hikari.connection-timeout = 500000, Is it valid solution?

yooniks commented 5 years ago

I am not sure but i think i just didn't close the statement (in another methods)

pon., 11 mar 2019, 13:59 użytkownik solanki vaibhav < notifications@github.com> napisał:

Update properties spring.datasource.hikari.connection-timeout = 500000, Is it valid solution?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/brettwooldridge/HikariCP/issues/1111#issuecomment-471528286, or mute the thread https://github.com/notifications/unsubscribe-auth/AcooWjocN6wU77yv3n7nBMEQxA5nHcJCks5vVlMngaJpZM4SlsOR .

skydh commented 5 years ago

how to use hikari.close(); to fix problem

Dhanapalva commented 5 years ago

i am getting the -SpringBootJPAHikariCP - Connection is not available, request timed out after *****. intermediately. please advice This is my Hikari CP stetting

HIKARI SETTINGS

spring.datasource.type=com.zaxxer.hikari.HikariDataSource

spring.datasource.hikari.minimumIdle=20

spring.datasource.hikari.maximumPoolSize=100

spring.datasource.hikari.idleTimeout=300000

spring.datasource.hikari.poolName=SpringBootJPAHikariCP

spring.datasource.hikari.maxLifetime=200000

spring.datasource.hikari.connectionTimeout=20000

spring.datasource.hikari.registerMbeans=true

ERROR Message:

8760b748-662d-4434-9c79-15cf8dc44b82 1 Fri Jun 21 2019 07:24:27.261 at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:190) ~[HikariCP-3.2.0.jar!/:na] 8760b748-662d-4434-9c79-15cf8dc44b82 1 Fri Jun 21 2019 07:24:27.261 at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:676) ~[HikariCP-3.2.0.jar!/:na] 8760b748-662d-4434-9c79-15cf8dc44b82 1 Fri Jun 21 2019 07:24:27.261 Caused by: java.sql.SQLTransientConnectionException: SpringBootJPAHikariCP - Connection is not available, request timed out after 20000ms.

brettwooldridge commented 5 years ago

I recommend setting the leakDetectionThreshold and watching the log file. Also, enable debug level logging and monitor the pool stats.

Dhanapalva commented 5 years ago

i have enabled the debug log, this what i can see with pool state. Line 480: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:09.517 2019-06-24 11:07:09.517 DEBUG 16 --- [ XNIO-2 task-96] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=11, active=11, idle=0, waiting=2) Line 3286: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:08.179 2019-06-24 11:07:08.179 DEBUG 16 --- [ XNIO-2 task-24] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=12, active=12, idle=0, waiting=2) Line 5983: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:06.502 2019-06-24 11:07:06.502 DEBUG 16 --- [ XNIO-2 task-48] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=30, active=30, idle=0, waiting=5) Line 6472: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:06.077 2019-06-24 11:07:06.077 DEBUG 16 --- [XNIO-2 task-100] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=30, active=30, idle=0, waiting=5) Line 7368: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:06.060 2019-06-24 11:07:06.060 DEBUG 16 --- [ XNIO-2 task-8] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=16, active=16, idle=0, waiting=3) Line 7369: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:06.059 2019-06-24 11:07:06.059 DEBUG 15 --- [ XNIO-2 task-1] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=24, active=24, idle=0, waiting=5) Line 7507: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:06.049 2019-06-24 11:07:06.049 DEBUG 16 --- [ XNIO-2 task-60] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=16, active=16, idle=0, waiting=4) Line 7710: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:05.815 2019-06-24 11:07:05.815 DEBUG 16 --- [ XNIO-2 task-84] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=11, active=11, idle=0, waiting=1) Line 8495: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:05.148 2019-06-24 11:07:05.148 DEBUG 16 --- [ XNIO-2 task-41] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=30, active=30, idle=0, waiting=6) Line 9620: 17c57c5b-b561-4293-ba2c-da13a3da5a71 1 Mon Jun 24 2019 16:37:02.536 2019-06-24 11:07:02.536 DEBUG 15 --- [ XNIO-2 task-5] com.zaxxer.hikari.pool.HikariPool : SpringBootJPAHikariCP - Timeout failure stats (total=24, active=24, idle=0, waiting=5)

tianhao-au commented 5 years ago

Hi guys, I have same issues, not sure what's the proper fix for this. Also I can confirm that my connection has been closed properly.

stolario commented 5 years ago

same issue

ChaminW commented 5 years ago

Hi, I'm getting same issue with error code "java.sql.SQLTransientConnectionException / -hikari-pool - Connection is not available, request timed out after " This is getting randomly and doesn't have relation with heavy load. Also what do you mean by leak?

yooniks commented 5 years ago

make sure that you close a connection and statement, when i close only statement and the connection stays i get this error after some time

śr., 23 paź 2019, 07:40 użytkownik Chamin Wickramarathna < notifications@github.com> napisał:

Hi, I'm getting same issue with error code "java.sql.SQLTransientConnectionException / -hikari-pool - Connection is not available, request timed out after " This is getting randomly and doesn't have relation with heavy load. Also what do you mean by leak?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/brettwooldridge/HikariCP/issues/1111?email_source=notifications&email_token=AHFCQWTCJXXX7PYQC6QSYALQP7PTRA5CNFSM4EUWYOI2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOECAD6QI#issuecomment-545275713, or unsubscribe https://github.com/notifications/unsubscribe-auth/AHFCQWTUNGXBCFUPOCXN24TQP7PTRANCNFSM4EUWYOIQ .

CambodianCoder commented 5 years ago

Got the same error today

   :message db_pool - Connection is not available, request timed out after 30003ms.
   :at [com.zaxxer.hikari.pool.HikariPool createTimeoutException HikariPool.java 697]}

Environment:

Postgresql database, clojure project
:dependancies {[hikari-cp "2.9.0"]}
Leiningen 2.9.1 on Java 1.8.0_222 OpenJDK 64-Bit Server VM
openjdk version "1.8.0_222"
OpenJDK Runtime Environment (build 1.8.0_222-8u222-b10-1ubuntu1~18.04.1-b10)
OpenJDK 64-Bit Server VM (build 25.222-b10, mixed mode)

How do I get to the properties

Remove: hikari.addDataSourceProperty("maxReconnects",5);

? Are these in my env/dev/resources/config.edn?

mrbuddypal commented 4 years ago

I have been seeing this issue occasionally in a low-activity application, and thanks to debug logging I was able to catch it in the act. The log didn't indicate a cause, unfortunately.

The application had been running for 116 days, and then the pool mysteriously ran out of connections. It simply began to not reopen them after they had expired. The application wasn't even in use at the time; it was not performing any database operations.

Normally, the connections would expire and be reopened, with log entries like this:

HikariPool-1 - Closing connection oracle.jdbc.driver.T4CConnection@ea16de1: (connection has passed maxLifetime) HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@71a66e81

This time, they were not reopened and the Pool stats' total value gradually went down to zero:

Pool stats (total=10, active=0, idle=10, waiting=0) Closing connection oracle.jdbc.driver.T4CConnection@730229a3: (connection has passed maxLifetime) Pool stats (total=9, active=0, idle=9, waiting=0) Closing connection oracle.jdbc.driver.T4CConnection@439ae1f9: (connection has passed maxLifetime) Closing connection oracle.jdbc.driver.T4CConnection@796607cc: (connection has passed maxLifetime) Pool stats (total=7, active=0, idle=7, waiting=0) ... Pool stats (total=0, active=0, idle=0, waiting=0)

Two days later someone tried to use the application and the "Connection is not available, request timed out..." error occurred. We restarted it and it began to operate normally as always. I did not have an opportunity to test the database or its network connection while our pool was dying, but I will set up a monitor on our log for next time.

There were 23001 log entries for "Added connection ...".

saschabrockel commented 4 years ago

I faced the same problem. For me the solution seems to be to change the dataSource if you use one. I'm using Spring Boot and switched from DataSourceto HikariDataSource

    @Autowired
    protected HikariDataSource dataSource;
shuchi-ag commented 4 years ago

Hi, I am getting almost the same ERROR ->

o.h.engine.jdbc.spi.SqlExceptionHelper : IO Error: Socket read timed out o.h.engine.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms.

The application is running fine for few days but suddenly sometimes it shows this error. After restarting application it again works fine. Could not trace the issue.

Properties defined are:- server.connection-timeout=10000 spring.mvc.async.request-timeout=10000ms

spring.datasource.url=jdbc:oracle:thin:@hostname/databasename spring.datasource.username=username spring.datasource.password=password spring.jpa.show-sql=true spring.jpa.hibernate.ddl-auto=none

spring.datasource.driver-class-name=oracle.jdbc.driver.OracleDriver

spring.jpa.hibernate.naming.physical-strategy=org.hibernate.boot.model.naming.PhysicalNamingStrategyStandardImpl spring.jpa.properties.hibernate.dialect=org.hibernate.dialect.Oracle10gDialect spring.jpa.hibernate.naming-strategy=org.hibernate.cfg.DefaultNamingStrategy spring.jpa.properties.hibernate.id.new_generator_mappings=false

spring.datasource.connection-test-query=SELECT 1 spring.datasource.test-while-idle=true spring.datasource.test-on-borrow=true

mindit-beatrice-luca commented 4 years ago

I have been seeing this issue occasionally in a low-activity application, and thanks to debug logging I was able to catch it in the act. The log didn't indicate a cause, unfortunately.

The application had been running for 116 days, and then the pool mysteriously ran out of connections. It simply began to not reopen them after they had expired. The application wasn't even in use at the time; it was not performing any database operations.

Normally, the connections would expire and be reopened, with log entries like this:

HikariPool-1 - Closing connection oracle.jdbc.driver.T4CConnection@ea16de1: (connection has passed maxLifetime) HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@71a66e81

This time, they were not reopened and the Pool stats' total value gradually went down to zero:

Pool stats (total=10, active=0, idle=10, waiting=0) Closing connection oracle.jdbc.driver.T4CConnection@730229a3: (connection has passed maxLifetime) Pool stats (total=9, active=0, idle=9, waiting=0) Closing connection oracle.jdbc.driver.T4CConnection@439ae1f9: (connection has passed maxLifetime) Closing connection oracle.jdbc.driver.T4CConnection@796607cc: (connection has passed maxLifetime) Pool stats (total=7, active=0, idle=7, waiting=0) ... Pool stats (total=0, active=0, idle=0, waiting=0)

Two days later someone tried to use the application and the "Connection is not available, request timed out..." error occurred. We restarted it and it began to operate normally as always. I did not have an opportunity to test the database or its network connection while our pool was dying, but I will set up a monitor on our log for next time.

There were 23001 log entries for "Added connection ...".

@mrbuddypal I have the same error with an application that is live for over a year, and in last month it crashes (the pool ran out of connections) mostly in the night (when there are no users in the application).

Did you manage to find a solution?

mrbuddypal commented 4 years ago

@mindit-beatrice-luca I did not find a solution. I was able to capture a thread dump when it happened again on June 8. paddock-pool-empty.log

ravi-b-m commented 4 years ago

@mrbuddypal , @mindit-beatrice-luca I am having the same issue.. I recently switched myBattis to use HikariCP from BoneCP.. and I notice the same issue that you guys were seeing..

Is it possible to reopen this issue ?

stianrincon commented 4 years ago

I am using spring boot and I was facing the same problem, and my solution was to get the connection like this "DataSourceUtils.getConnection(dataSource)".

So I change from dataSource.getConnection() to DataSourceUtils.getConnection(dataSource).

sanjaybsm commented 4 years ago

Hello Team,

Is this issue still being tracked? and also is there a way I can check/compare fixes done on different releases? release document/notes available?

Basically we have similar issue mentioned in this thread. Versions used:

2.7.6 **Exception stack trace:** `org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection at org.springframework.orm.hibernate5.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:542) at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) 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) Caused by: java.sql.SQLTransientConnectionException: lxb2capa02.db-pool - Connection is not available, request timed out after 932300ms. at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:548) at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:186) Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Connection timed out (Read failed) at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1667) at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1654)` **configuration:** public static final int DB_CONN_POOL_SIZE = 50; public static final int DB_INIT_FAIL_TIME_OUT = 10000; public static final long CONN_LEAK_THRESHOLD_IN_MILLS = 240000; //4 min public static final long CONN_IDLE_TIMEOUT_IN_MILLS = 900000; //15 min public static final long CONN_MAX_LIFE_IN_MILLS = 1800000; //30 min public static final int CONN_TIMEOUT_IN_MILLS = 10000; //10 sec public static final int QUERY_TIMEOUT_IN_SECS = 30; //30 secs ` config.setMaximumPoolSize(DB_CONN_POOL_SIZE); config.setLeakDetectionThreshold(CONN_LEAK_THRESHOLD_IN_MILLS); //4 mins config.setConnectionTestQuery("SELECT 1"); config.setValidationTimeout(CONN_TIMEOUT_IN_MILLS); config.setIdleTimeout(CONN_IDLE_TIMEOUT_IN_MILLS); config.setMaxLifetime(CONN_MAX_LIFE_IN_MILLS); config.setConnectionTimeout(CONN_TIMEOUT_IN_MILLS); //10 secs DataSource dataSource = new HikariDataSource(config);` To add some more information, we do set 'QUERY_TIMEOUT_IN_SECS ' for most of the GET calls and not to the save/update calls. My question is why connection was released/timed out after **932300ms**(15mins) the only correlation i see for this behaviour is 'CONN_IDLE_TIMEOUT_IN_MILLS ' configuration. I'm enabling the debug logs for hikari cp to check connection leak, just in case if this information helps and someone can throw some light on this topic would be helpful.
wolongjie commented 3 years ago

I have been seeing this issue occasionally in a low-activity application, and thanks to debug logging I was able to catch it in the act. The log didn't indicate a cause, unfortunately. The application had been running for 116 days, and then the pool mysteriously ran out of connections. It simply began to not reopen them after they had expired. The application wasn't even in use at the time; it was not performing any database operations. Normally, the connections would expire and be reopened, with log entries like this:

HikariPool-1 - Closing connection oracle.jdbc.driver.T4CConnection@ea16de1: (connection has passed maxLifetime) HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@71a66e81

This time, they were not reopened and the Pool stats' total value gradually went down to zero:

Pool stats (total=10, active=0, idle=10, waiting=0) Closing connection oracle.jdbc.driver.T4CConnection@730229a3: (connection has passed maxLifetime) Pool stats (total=9, active=0, idle=9, waiting=0) Closing connection oracle.jdbc.driver.T4CConnection@439ae1f9: (connection has passed maxLifetime) Closing connection oracle.jdbc.driver.T4CConnection@796607cc: (connection has passed maxLifetime) Pool stats (total=7, active=0, idle=7, waiting=0) ... Pool stats (total=0, active=0, idle=0, waiting=0)

Two days later someone tried to use the application and the "Connection is not available, request timed out..." error occurred. We restarted it and it began to operate normally as always. I did not have an opportunity to test the database or its network connection while our pool was dying, but I will set up a monitor on our log for next time. There were 23001 log entries for "Added connection ...".

@mrbuddypal I have the same error with an application that is live for over a year, and in last month it crashes (the pool ran out of connections) mostly in the night (when there are no users in the application).

Did you manage to find a solution?

I face the same issue. the problem appears every 6 days. And my solution was to replace "getSessionFactory().openSession" to “getSessionFactory().getCurentSession” . It never been appears.

BoinaRamesh commented 3 years ago

Currently, we are also facing the same issue and the issue remains for 5 mins then automatically settles down to normal. During this point in time noticed that high latencies and Hikari timeouts and Hikari cp pending.

JDK - 11 Hikari version - 3.4.1 Spring boot - 2.2.1 PG driver - 42.2.8 Hibernate - 5.4.8

Please share your solutions, what works to eliminate this issue.

brettwooldridge commented 3 years ago

@BoinaRamesh Do you have debug logs? Have you enabled Java GC (garbage collection) logging? You might try upgrading to HikariCP v4.0.3 and enabling the new keepaliveTime setting.

Lastly, the latest PG driver, v4.2.20, has a critical fix. The change log says:

isValid() timeout should not be blocked #1943 Cherry-picked #2076 The usage of setQueryTimeout(); with the same value as the setNetworkTimeout(); is blocking the current transaction timeout. The timeouts are blocking each other with this approach.

v4.2.15 also has a relavent fix:

Make sure socketTimeout is enforced

BoinaRamesh commented 3 years ago

@brettwooldridge Please find the logs here :

{ "thread": "http-nio-127.0.0.1-8080-exec-1581", "level": "ERROR", "loggerName": "com.demo.common.exception.handler.GlobalExceptionHandler", "message": "op=GlobalExceptionHandler:RuntimeException, status=KO, desc=exception stack trace: ", "timeMillis": 1620787669601, "thrown": { "commonElementCount": 0, "localizedMessage": "Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection", "message": "Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection", "name": "org.springframework.dao.DataAccessResourceFailureException", "cause": { "commonElementCount": 103, "localizedMessage": "Unable to acquire JDBC Connection", "message": "Unable to acquire JDBC Connection", "name": "org.hibernate.exception.JDBCConnectionException", "cause": { "commonElementCount": 103, "localizedMessage": "HikariPool-1 - Connection is not available, request timed out after 10000ms.", "message": "HikariPool-1 - Connection is not available, request timed out after 10000ms.", "name": "java.sql.SQLTransientConnectionException", "cause": { "commonElementCount": 103, "localizedMessage": "This connection has been closed.", "message": "This connection has been closed.", "name": "org.postgresql.util.PSQLException", "extendedStackTrace": "org.postgresql.util.PSQLException: This connection has been closed.\n\tat org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:782) ~[postgresql-42.2.8.jar:42.2.8]\n\tat org.postgresql.jdbc.PgConnection.setNetworkTimeout(PgConnection.java:1560) ~[postgresql-42.2.8.jar:42.2.8]\n\tat com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:552) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:168) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:185) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.1.jar:?]\n\tat org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat }, "extendedStackTrace": "java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10000ms.\n\tat com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:697) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161) ~[HikariCP-3.4.1.jar:?]\n\tat com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.1.jar:?]\n\tat org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2104) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2034) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2012) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doQuery(Loader.java:953) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doList(Loader.java:2815) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doList(Loader.java:2797) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2629) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.list(Loader.java:2624) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:396) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219) ~ }, "extendedStackTrace": "org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection\n\tat org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2104) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2034) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2012) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doQuery(Loader.java:953) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doList(Loader.java:2815) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.doList(Loader.java:2797) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2629) ~[hibernate-core-5.4.8.Final.jar:5.4.8.Final]\n\tat org.hibernate.loader.Loader.list(Loader.java:2624) ~[hibernate-core- }, "extendedStackTrace": "org.springframework.dao.DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection\n\tat org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:277) ~[spring-orm-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:255) ~[spring-orm-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:528) ~[spring-orm-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61) ~[spring-tx-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242) ~[spring-tx-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:153) ~[spring-tx-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:149) ~[spring-data-jpa-2.2.1.RELEASE.jar:2.2.1.RELEASE]\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat com.sun.proxy.$Proxy191.findAllByLocationId(Unknown Source) ~[?:?]\n\tat com.demo.dao.impl.DriveupEventDAOImpl.searchByLocationId(DriveupEventDAOImpl.java:42) ~[driveup_events-v1-0.0.1-SNAPSHOT.jar:?]\n\tat com.demo.dao.impl.DriveupEventDAOImpl$$FastClassBySpringCGLIB$$cd61917d.invoke() ~[driveup_events-v1-0.0.1-SNAPSHOT.jar:?]\n\tat org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88) ~[spring-aop-5.2.1.RELEASE.jar:5.2.1.RELEASE]\n\tat io.micrometer.core.aop.TimedAspect.processWithTimer(TimedAspect.java:105) ~[micrometer-core-1.3.1.jar:1.3.1]\n\tat io.micrometer.core.aop.TimedAspect.timedMethod(TimedAspect.java:94) ~[micrometer-core- }

I have enabled metrics for GC (G1GC) and most of the time latency is 0.4ms even during this issue. I have reached out to our DBA's and as per them something might be blocking at the DB side and that is cascading to other symptoms at the app layer but as per DB logs 4~5 blockers at that point in time. I do not really understand 5 blockers how 200 connections(in my cluster I have a total of 200 connections) got impacted. Usually, my service responses ~30ms but when this occurred saw 10s about 10minutes window after that it go back to normal automatically.

Not sure of any issues with DB(confirmed there are no firewall rules in the network) or planning to configure with socket timeout values with DB URL string. Pls, advise me If am missing anything.

cleophusper commented 3 years ago

Dear Sir,

I ma using following version of Hikari hibernate-hikaricp -> 4.3.8.Final HikariCP-java7 -> 2.4.9 JDK 1.8

Following property configuration hibernate.connection.provider_class=org.hibernate.hikaricp.internal.HikariCPConnectionProvider hibernate.hikari.maximumPoolSize=75 hibernate.hikari.initializationFailFast=true hibernate.hikari.connectionTimeout=300000 hibernate.hikari.dataSource.driverType=thin hibernate.naming_strategy=org.hibernate.cfg.DefaultNamingStrategy hibernate.hikari.dataSourceClassName=oracle.jdbc.pool.OracleDataSource hibernate.hikari.dataSource.serviceName=DBSERVICE hibernate.hikari.minimumIdle=30 com.zaxxer.hikari.HikariConfig:allowPoolSuspension.............false com.zaxxer.hikari.HikariConfig:autoCommit......................true com.zaxxer.hikari.HikariConfig:catalog.........................null com.zaxxer.hikari.HikariConfig:connectionInitSql...............null com.zaxxer.hikari.HikariConfig:connectionTestQuery.............null com.zaxxer.hikari.HikariConfig:connectionTimeout...............300000 com.zaxxer.hikari.HikariConfig:dataSource......................null com.zaxxer.hikari.HikariConfig:dataSourceClassName............."oracle.jdbc.pool.OracleDataSource" com.zaxxer.hikari.HikariConfig:dataSourceJNDI..................null com.zaxxer.hikari.HikariConfig:dataSourceProperties............{user=xxxx, password=xxxxxx, serviceName=DBSERVICE, driverType=thin, portNumber=1521, serverName=x.x.x.x} com.zaxxer.hikari.HikariConfig:driverClassName.................null com.zaxxer.hikari.HikariConfig:healthCheckProperties...........{} com.zaxxer.hikari.HikariConfig:healthCheckRegistry.............null com.zaxxer.hikari.HikariConfig:idleTimeout.....................600000 com.zaxxer.hikari.HikariConfig:initializationFailFast..........true com.zaxxer.hikari.HikariConfig:isolateInternalQueries..........false com.zaxxer.hikari.HikariConfig:jdbc4ConnectionTest.............false com.zaxxer.hikari.HikariConfig:jdbcUrl.........................null com.zaxxer.hikari.HikariConfig:leakDetectionThreshold..........0 com.zaxxer.hikari.HikariConfig:maxLifetime.....................1800000 com.zaxxer.hikari.HikariConfig:maximumPoolSize.................75 com.zaxxer.hikari.HikariConfig:metricRegistry..................null com.zaxxer.hikari.HikariConfig:metricsTrackerFactory...........null com.zaxxer.hikari.HikariConfig:minimumIdle.....................30 com.zaxxer.hikari.HikariConfig:poolName........................"HikariPool-1" com.zaxxer.hikari.HikariConfig:readOnly........................false com.zaxxer.hikari.HikariConfig:registerMbeans..................true com.zaxxer.hikari.HikariConfig:scheduledExecutorService........null com.zaxxer.hikari.HikariConfig:threadFactory...................null com.zaxxer.hikari.HikariConfig:transactionIsolation............null com.zaxxer.hikari.HikariConfig:validationTimeout...............5000

This application has not been changed for long time . I suddenly observed following Error, suddenly after 2 years in live production i see below error. Don't know is it because of leak or what. As code has not changed for quite long time dont suspect leak. It goes on adding connection and suddenly all db connection get exhausted. Even if it is a leak i would have preferred single few db connection leak. It suddenly after adding 100 db connection exhausting all 75 database connection dont understand. Why though?

Logs---- com.zaxxer.hikari.pool.HikariPool:HikariPool-1 - Pool stats (total=75, active=75, idle=0, waiting=27) java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 300000ms.

Need your help to resolve the issue.

KarthikVCO commented 3 years ago

Team, Even we are running into same issue with connection. Application becomes unresponsive in span of 20 to 30 days and not recovering

Version

Connection pool configuration

{"time": "2021-09-30 10:01:49,206", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "HikariPool-1 - configuration:"} {"time": "2021-09-30 10:01:49,211", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "allowPoolSuspension.............false"} {"time": "2021-09-30 10:01:49,212", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "autoCommit......................false"} {"time": "2021-09-30 10:01:49,213", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "catalog.........................none"} {"time": "2021-09-30 10:01:49,213", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "connectionInitSql...............none"} {"time": "2021-09-30 10:01:49,213", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "connectionTestQuery.............none"} {"time": "2021-09-30 10:01:49,213", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "connectionTimeout...............30000"} {"time": "2021-09-30 10:01:49,213", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "dataSource......................none"} {"time": "2021-09-30 10:01:49,214", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "dataSourceClassName.............none"} {"time": "2021-09-30 10:01:49,214", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "dataSourceJNDI..................none"} {"time": "2021-09-30 10:01:49,215", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "dataSourceProperties............{password=, oracle.jdbc.implicitStatementCacheSize=100}"} {"time": "2021-09-30 10:01:49,215", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "driverClassName................."oracle.jdbc.OracleDriver""} {"time": "2021-09-30 10:01:49,216", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "exceptionOverrideClassName......none"} {"time": "2021-09-30 10:01:49,216", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "healthCheckProperties...........{}"} {"time": "2021-09-30 10:01:49,216", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "healthCheckRegistry.............none"} {"time": "2021-09-30 10:01:49,216", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "idleTimeout.....................600000"} {"time": "2021-09-30 10:01:49,216", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "initializationFailTimeout.......1"} {"time": "2021-09-30 10:01:49,217", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "isolateInternalQueries..........false"} {"time": "2021-09-30 10:01:49,217", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "jdbcUrl.........................jdbc:oracle:thin:@***/**"} {"time": "2021-09-30 10:01:49,217", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "leakDetectionThreshold..........2000"} {"time": "2021-09-30 10:01:49,218", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "maxLifetime.....................1800000"} {"time": "2021-09-30 10:01:49,218", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "maximumPoolSize.................20"} {"time": "2021-09-30 10:01:49,218", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "metricRegistry..................none"} {"time": "2021-09-30 10:01:49,218", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "metricsTrackerFactory...........none"} {"time": "2021-09-30 10:01:49,219", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "minimumIdle.....................5"} {"time": "2021-09-30 10:01:49,219", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "password........................"} {"time": "2021-09-30 10:01:49,219", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "poolName........................"HikariPool-1""} {"time": "2021-09-30 10:01:49,219", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "readOnly........................false"} {"time": "2021-09-30 10:01:49,220", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "registerMbeans..................false"} {"time": "2021-09-30 10:01:49,220", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "scheduledExecutor...............none"} {"time": "2021-09-30 10:01:49,220", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "schema..........................none"} {"time": "2021-09-30 10:01:49,220", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "threadFactory...................internal"} {"time": "2021-09-30 10:01:49,220", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "transactionIsolation............default"} {"time": "2021-09-30 10:01:49,221", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "username........................"wm""} {"time": "2021-09-30 10:01:49,221", "level": "DEBUG", "thread": "main", "correlation-id": "", "transaction-reference": "", "facility-id": "", "invoice-batch": "", "source": "com.zaxxer.hikari.HikariConfig", "message": "validationTimeout...............5000"}

Failure logs: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection\n at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48)\n at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)\n at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)\n at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)\n at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107)\n at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134)\n at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)\n at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)\n at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)\n at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)\n at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2104)\n at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2034)\n at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2012)\n at org.hibernate.loader.Loader.doQuery(Loader.java:953)\n at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)\n at org.hibernate.loader.Loader.doList(Loader.java:2838)\n at org.hibernate.loader.Loader.doList(Loader.java:2820)\n at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2652)\n at org.hibernate.loader.Loader.list(Loader.java:2647)\n at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506)\n at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:396)\n at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)\n at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1404)\n at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1565)\n at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1533)\n at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1581)\n at org.hibernate.query.criteria.internal.compile.CriteriaQueryTypeQueryAdapter.getSingleResult(CriteriaQueryTypeQueryAdapter.java:111)\n at jdk.internal.reflect.GeneratedMethodAccessor89.invoke(Unknown Source)\n at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n at java.base/java.lang.reflect.Method.invoke(Method.java:566)\n at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:409)\n at com.sun.proxy.$Proxy157.getSingleResult(Unknown Source)\n at org.springframework.data.jpa.repository.query.JpaQueryExecution$SingleEntityExecution.doExecute(JpaQueryExecution.java:196)\n at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:88)\n at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:154)\n at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:142)\n at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor$QueryMethodInvoker.invoke(QueryExecutorMethodInterceptor.java:195)\n at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:152)\n at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:130)\n at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)\n at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:80)\n at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)\n at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:366)\n at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:118)\n at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)\n at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)\n ... 28 more\nCaused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.\n at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695)\n at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)\n at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)\n at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)\n at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)\n at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)\n at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104)\n ... 69 more\nCaused by: java.sql.SQLRecoverableException: IO Error: Invalid Operation, NOT Connected\n at oracle.jdbc.driver.T4CConnection.doSetNetworkTimeout(T4CConnection.java:7689)\n at oracle.jdbc.driver.PhysicalConnection.setNetworkTimeout(PhysicalConnection.java:9408)\n at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:560)\n at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:173)\n at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:186)\n ... 74 more\nCaused by: oracle.net.ns.NetException: Invalid Operation, NOT Connected\n at oracle.net.nt.TcpNTAdapter.setOption(TcpNTAdapter.java:344)\n at oracle.net.ns.NSProtocol.setOption(NSProtocol.java:501)\n at oracle.net.ns.NSProtocol.setSocketReadTimeout(NSProtocol.java:748)\n at oracle.jdbc.driver.T4CConnection.doSetNetworkTimeout(T4CConnection.java:7686)\n ... 78 more\n""}