HikariCP
HikariCP copied to clipboard
brettwooldridge
Randomly HikariPool pool becomes zero and HikariCP is not renewing/creating new connections
A couple times this year our production servers crashed because of a bug in Hikari that it runs out of connections. It never creates new connections to move from min size to max size. Our setting is 20 min and 100 max. We have not changed any OS related timeouts. We do not have firewall issues, or TLS issues.
Environment
HikariCP version: which ever comes with Spring Boot 2.0.3.RELEASE (spring-boot-starter-data-jpa)
JDK version : 1.8.0_111
Database : MySQL
Driver version : 5.1.46
First time it was a process running that we had a few users start around the same time. This last time this week was a longer running process by one user. The use cases have the correct transactionality and thread settings on them. We do not have any special logs turned on, and luckily these are rare as we only had it happen twice this year so far. So trying to even replicate it will be difficult.
I have the same issue. In my case, a PostgreSQL database. For some reasons, not related to TLS or OS, HikariCP cannot get connections in some random moments. Instead of throwing away such bad connections, it does not renew the pool, and gets stuck until the application is restarted. After that, we can work some weeks without issues, but eventually Hikari will get stuck, unable to get connections until the application is restarted.
I apologize, and think this ticket should stay open, but I have moved on. We have switched back to Tomcat's CP implementation.
We are also facing the same issues, and it's random. We are using Azure MySQL Database. our Mysql Wait_Timeout is 30min.
and below is Hikari Configuration
connectionTimeout=30000 idleTimeout=600000 maximumPoolSize=100 maxLifetime=1795000 minimumIdle=25
below is snippet of error.
2020-04-23 13:57:08.315 DEBUG [HikariPool-1 housekeeper][HikariPool:389] HikariPool-1 - Before cleanup stats (total=26, active=1, idle=25, waiting=0)
2020-04-23 13:57:08.316 DEBUG [HikariPool-1 housekeeper][HikariPool:389] HikariPool-1 - After cleanup stats (total=26, active=1, idle=25, waiting=0)
2020-04-23 13:57:09.947 DEBUG [HikariPool-2 housekeeper][HikariPool:389] HikariPool-2 - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2020-04-23 13:57:09.947 DEBUG [HikariPool-2 housekeeper][HikariPool:389] HikariPool-2 - After cleanup stats (total=0, active=0, idle=0, waiting=0)
Can you please provide some input, how and what are the possible reasons of this and how we can reproduce. Once we restart the application it's work normally.
@haresh1288 What I see in the log above is two pools: HikariPool-1 and HikariPool-2. What I need to see is a longer log segment that includes two or more housekeeping cycles for HikariPool-2. For example:
2020-04-23 13:56:09.947 DEBUG ... HikariPool-2 - Before cleanup stats ???
2020-04-23 13:56:09.947 DEBUG ... HikariPool-2 - After cleanup stats ???
2020-04-23 13:56:39.947 DEBUG ... HikariPool-2 - Before cleanup stats ???
2020-04-23 13:56:39.947 DEBUG ... HikariPool-2 - After cleanup stats ???
2020-04-23 13:57:09.947 DEBUG ... HikariPool-2 - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2020-04-23 13:57:09.947 DEBUG ... HikariPool-2 - After cleanup stats (total=0, active=0, idle=0, waiting=0)
Finally, that version of HikariCP are you using, and what version of the MySQL driver?
To @bytor99999 and others experiencing any of these kinds of connection issues, one of the first things to check is for changes in the JDBC driver. Every pool and every driver interact differently especially in terms of connection acquisition and termination.
Taking the MySQL Connector/J driver 5.1.46 as an example, the following fix in subsequent version is potentially determinative of connection issues and the ability to establish connection on an ongoing basis:
v5.1.48 bug fix
For an SSL connection, after a client disconnected from a server by calling Connection.close(), the TCP connection remained in the TIME_WAIT state on the server side. With this fix, the connection remains in the TIME_WAIT state on the client side instead, in most cases. (Bug #29054329, Bug #93590)
If you are using MySQL Server 5.6 or later, you should be using the Connector/J 8.x.
Having said that, I am continuing to investigate this issue. Any data, especially logs (both HikariCP and database server) immediately preceding and up to the zeroing of the pool would be extremely helpful.
@brettwooldridge , Thanks for quick replay. I had two datasource connected using Hikari. HikariCP : 2.6.3 MySQL Connector: 5.1.23 MySQL : 5.6 Java:1.8.0_221 Please find the attached logs connections.log
I have the same issue. In my case, a PostgreSQL database. For some reasons, not related to TLS or OS, HikariCP cannot get connections in some random moments. Instead of throwing away such bad connections, it does not renew the pool, and gets stuck until the application is restarted. After that, we can work some weeks without issues, but eventually Hikari will get stuck, unable to get connections until the application is restarted.
Hi @Ryaryu , Did you found any solution to this ?? we are stuck badly with this issue, i tried many things but no success yet for this..
@Hpatel-eic You need to be running the latest version of HikariCP available for the version of Java that you are using. On Java 8, that would be HikariCP v3.4.3. I cannot support back-level versions, too many changes and fixes have been made.
Also, upgrade your Connector/J driver to v5.1.48.
I thought Java 8 has the highest percentage of users. Are you saying all of us still using it are SOL in getting this major issue fixed?
On May 2, 2020, at 11:09 PM, Brett Wooldridge [email protected] wrote:
@Hpatel-eic You need to be running the latest version of HikariCP available for the version of Java that you are using. On Java 8, that would be HikariCP v3.4.3. I cannot support back-level versions, too many changes and fixes have been made.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.
I have the same issue, please help. My version: HikariCP : 3.4.5 MySQL Connector: 8.0.24 Java:1.8.0_232
My Hikari Config:
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1066] HikariPool-3 - configuration:
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] allowPoolSuspension.............false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] autoCommit......................true
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] catalog.........................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] connectionInitSql...............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] connectionTestQuery............."SELECT 1"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] connectionTimeout...............60000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSource......................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSourceClassName.............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSourceJNDI..................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSourceProperties............{password=<masked>}
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] driverClassName................."com.mysql.cj.jdbc.Driver"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] exceptionOverrideClassName......none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] healthCheckProperties...........{}
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] healthCheckRegistry.............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] idleTimeout.....................500000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] initializationFailTimeout.......1
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] isolateInternalQueries..........false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] jdbcUrl.........................jdbc:mysql://xxxx:3306/xxx?serverTimezone=UTC&allowPublicKeyRetrieval=true&characterEncoding=utf-8&socketTimeout=60000&connectTimeout=30000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] leakDetectionThreshold..........60000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] maxLifetime.....................540000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] maximumPoolSize.................50
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] metricRegistry..................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] metricsTrackerFactory...........none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] minimumIdle.....................20
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] password........................<masked>
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] poolName........................"HikariPool-3"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] readOnly........................false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] registerMbeans..................false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] scheduledExecutor...............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] schema..........................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] threadFactory...................internal
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] transactionIsolation............default
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] username........................"xxx"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] validationTimeout...............5000
there are no logs at 17:36:03 to 17:47:00 , and then timeout occurred.
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:517] HikariPool-3 - Fill pool skipped, pool is at sufficient level.
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:47:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
Same issue, tried everything I've found here. Sadly it heavily impacts production environment.
Java: jdk1.8.0_192 DB: Azure hosted - PostgreSQL 10.11, compiled by Visual C++ build 1800, 64-bit Driver: postgresql-42.2.14 Pool: HikariCP-3.4.5
Our appliaction has actually two pools pointing to the exact same database, the only difference is sizing. Both pools have leakDetectionTreshold configured and socketTimeout as dataSource parameter. There is no leak warning in logs, yet few days ago one pool just stopped working, unable to create new connection due to timeout, while the second pool is OK. Again, both pools point to the exact same database with same username and timeout configuration.
[2021-05-25 13:20:58,568] [DEBUG] [wso2 connection closer] com.zaxxer.hikari.pool.PoolBase - wso2 - Closing connection org.postgresql.jdbc.PgConnection@3fdbc150: (connection has passed maxLifetime)
[2021-05-25 13:20:58,744] [DEBUG] [wso2 connection adder] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@288501e4
[2021-05-25 13:21:00,001] [DEBUG] [DefaultQuartzScheduler_Worker-5] com.zaxxer.hikari.pool.HikariPool - monitoring - Add connection elided, waiting 4, queue 5
[2021-05-25 13:21:00,002] [DEBUG] [DefaultQuartzScheduler_Worker-8] com.zaxxer.hikari.pool.HikariPool - monitoring - Timeout failure stats (total=0, active=0, idle=0, waiting=3)
Also I noticed really weird behaviour. How can completely empty pool be at "sufficient level"?
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Before cleanup stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - After cleanup stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Fill pool skipped, pool is at sufficient level.
Cannot provide configuration from logs, so here is at least JMX.
Same issue, tried everything I've found here. Sadly it heavily impacts production environment.
Java: jdk1.8.0_192 DB: Azure hosted - PostgreSQL 10.11, compiled by Visual C++ build 1800, 64-bit Driver: postgresql-42.2.14 Pool: HikariCP-3.4.5
Our appliaction has actually two pools pointing to the exact same database, the only difference is sizing. Both pools have leakDetectionTreshold configured and socketTimeout as dataSource parameter. There is no leak warning in logs, yet few days ago one pool just stopped working, unable to create new connection due to timeout, while the second pool is OK. Again, both pools point to the exact same database with same username and timeout configuration.
[2021-05-25 13:20:58,568] [DEBUG] [wso2 connection closer] com.zaxxer.hikari.pool.PoolBase - wso2 - Closing connection org.postgresql.jdbc.PgConnection@3fdbc150: (connection has passed maxLifetime) [2021-05-25 13:20:58,744] [DEBUG] [wso2 connection adder] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@288501e4 [2021-05-25 13:21:00,001] [DEBUG] [DefaultQuartzScheduler_Worker-5] com.zaxxer.hikari.pool.HikariPool - monitoring - Add connection elided, waiting 4, queue 5 [2021-05-25 13:21:00,002] [DEBUG] [DefaultQuartzScheduler_Worker-8] com.zaxxer.hikari.pool.HikariPool - monitoring - Timeout failure stats (total=0, active=0, idle=0, waiting=3)Also I noticed really weird behaviour. How can completely empty pool be at "sufficient level"?
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Before cleanup stats (total=0, active=0, idle=0, waiting=3) [2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - After cleanup stats (total=0, active=0, idle=0, waiting=3) [2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Fill pool skipped, pool is at sufficient level.Cannot provide configuration from logs, so here is at least JMX.
@bytor99999 Thanks for the sarcasm. No good deed goes unpunished, I guess. I asked several times for more logs, but none were provided. Reproducing a bug that happens "couple times [per] year" is difficult when all you have is an anecdotal account. So far as the issue having never been assigned, it's just little old me, so I don't bother using the assignment feature.
Enjoy your retirement.
Yeah, I finally figured it all out, right after I posted that I couldn't figure it out. Go figure. But good luck with this one.
Funny, too is it looks like if you unsubscribe, but then are mentioned in the issue, you get re-subscribed. ;)
@TomasTokaMrazek Although it is contradictory to docs, I'm setting minimumIdle to 0 so HikariCP is always forced to create new connections. So far (~2 weeks of testing in production) I haven't got this connection issue. Or at least at a noticeable rate. Since it still seems to be random, I cannot say that it is the better approach for now (and since it forces the pool to constantly create connections, it certainly's not the better approach).
@TomasTokaMrazek Thank you for the logs. This log is particularly useful:
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - After cleanup stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Fill pool skipped, pool is at sufficient level.
Can you try PostgeSQL driver v4.2.20? They have fixed a number of key issues in the past few releases, including these since v4.2.14 that you are using:
Fixed
isValid() timeout should not be blocked #1943 Cherry-picked #2076 The usage of
setQueryTimeout();with the same value as thesetNetworkTimeout();is blocking the current transaction timeout. The timeouts are blocking each other with this approach.Fix: properly set cancel socket timeout (#2044)
Fix Connnection.isValid() to not wait longer than existing network timeout PR #2040
Make sure socketTimeout is enforced PR 1831 210b27a6
If the issue is semi-reproducible or occurring frequently enough, and you are running on Linux, the output of lsof from the application server where HikariCP and PostgreSQL is deployed would be useful -- captured when the pool is dead.
Any logs from PostgreSQL from just before until just after the pool stats go to zero could also prove useful. Documentation on enabling debug logging levels as well as log format strings can be found here.
@brettwooldridge I've read the changelogs for pgjdbc, obviously not carefully enough as I missed the timeout fixes. I will update the driver as soon as possible.
I've enabled Hikari debug logs before server restart, so I should be able to provide as much info as possible when the next draining occurs. I'll keep in mind to lsof, for now I can only tell you the OS version centos-release-7-9.2009.1.el7.centos.x86_64. I don't know, if it is the factor, but ulimit is set to unlimited for basically everything.
As for PostgreSQL logs and lsof, I'm afraid I will not be able to provide them. We have PostgreSQL as PaaS in Azure, and while that might not be a blocker, I don't have direct access to that service either. I could escalate the request, if the issue persists after driver update.
I have to ask tho, I still find it weird, that the hikari logs report empty pool while reporting that it is at sufficient level. While the root cause might be in jdbc driver itself, I think that the report should indicate, that there actually are connections, be it still in active state or for example blocked state.
@TomasTokaMrazek Re: your last statement, I agree, and that is why I said those particular log messages are particularly useful. None of the other reports in this issue included that message when the pool was in fact empty. I am hoping that through careful dissection of the code, I can figure out how that can occur. I strongly suspect a race condition that leaves internal state inconsistent.
EDIT: One commonality that I notice is that all of the reported configurations have a minimumIdle that is lower than the maximumPoolSize. That is a certainly a clue. My company always runs with a fixed size pool (the default), which may be why in the +5 years we have been running it we have never encountered this issue. I'll let you know if I can come up with a reproduction scenario.
@brettwooldridge One pool got depleted just moments ago. Here's pool configuration from logs after a restart.
[2021-05-31 13:18:23,571] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - Driver class org.postgresql.Driver found in Thread context class loader org.eclipse.core.runtime.internal.adaptor.ContextFinder@7a2d3f94
[2021-05-31 13:18:23,578] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - wso2 - configuration:
[2021-05-31 13:18:23,581] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
[2021-05-31 13:18:23,582] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - autoCommit......................true
[2021-05-31 13:18:23,582] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - catalog.........................none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTimeout...............10000
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSource......................none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
[2021-05-31 13:18:23,587] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
[2021-05-31 13:18:23,587] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, socketTimeout=30}
[2021-05-31 13:18:23,587] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - driverClassName................."org.postgresql.Driver"
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:postgresql://<masked>
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........30000
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maximumPoolSize.................100
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricRegistry..................none
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - minimumIdle.....................100
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - password........................<masked>
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - poolName........................"wso2"
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - readOnly........................false
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - registerMbeans..................true
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - schema..........................none
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - threadFactory...................internal
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - transactionIsolation............default
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - username........................"<masked>"
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
[2021-05-31 13:18:23,597] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - wso2 - Starting...
[2021-05-31 13:18:23,804] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@1da0e3dd
[2021-05-31 13:18:23,808] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - wso2 - Start completed.
[2021-05-31 13:18:23,908] [DEBUG] [wso2 housekeeper] com.zaxxer.hikari.pool.HikariPool - wso2 - Pool stats (total=1, active=0, idle=1, waiting=0)
[2021-05-31 13:18:23,955] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - Driver class org.postgresql.Driver found in Thread context class loader org.eclipse.core.runtime.internal.adaptor.ContextFinder@7a2d3f94
[2021-05-31 13:18:23,955] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - monitoring - configuration:
[2021-05-31 13:18:23,956] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
[2021-05-31 13:18:23,956] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - autoCommit......................true
[2021-05-31 13:18:23,956] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - catalog.........................none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTimeout...............10000
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSource......................none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, socketTimeout=30}
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - driverClassName................."org.postgresql.Driver"
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:postgresql://<masked>
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........30000
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maximumPoolSize.................5
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricRegistry..................none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - minimumIdle.....................1
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - password........................<masked>
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - poolName........................"monitoring"
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - readOnly........................false
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - registerMbeans..................true
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - schema..........................none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - threadFactory...................internal
[2021-05-31 13:18:23,959] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - transactionIsolation............default
[2021-05-31 13:18:23,959] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - username........................"<masked>"
[2021-05-31 13:18:23,959] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
[2021-05-31 13:18:23,959] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - monitoring - Starting...
[2021-05-31 13:18:24,085] [DEBUG] [wso2 connection adder] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@4a8a57b0
[2021-05-31 13:18:24,134] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.pool.HikariPool - monitoring - Added connection org.postgresql.jdbc.PgConnection@12b1d73c
[2021-05-31 13:18:24,135] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - monitoring - Start completed.
And here are Hikari logs during pool exhaustion and lsof from application server. hikari.log lsof.txt
We also switched to newest PG driver 42.2.20
EDIT: We didn't change pool configuration and this time "wso2" pool got depleted. Pool with the same minimumIdle and maximumPoolSize.
@huangyayu What is happening with these logs? Did you remove some?
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:517] HikariPool-3 - Fill pool skipped, pool is at sufficient level.
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:47:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
I see the housekeeper run at 17:35:33, and then 30 seconds later at 17:36:03, which is correct (every 30s). But then there is a 4-minute skip to 17:47:00. And then a 3-minute skip to 17:50:00. This should not be possible.
@TomasTokaMrazek Are you really running a pool with 100 connections? Did you read About pool sizing?
@brettwooldridge I do run a pool with 100 connections, I did read about pool sizing, several times actually. I am planning to lover it slowly, but we've encountered a lot of pool exhaustion issues (not related to HikariCP per se, there's Tomcat Pool for appliation server internals). Higher connection pool helped a lot, even at the price of slightly worse performance. Now we have about 5 minutes to act, when pool does not create new connections. Besides our Postgres subscription in Azure allows currently 7500 simultaneous connections and CPU barely hits 20%. Active connections are in 95% cases under 5, sometimes it jumps to 10, and there is one time (in our metrics) in the last two days, when it was above 40. It's more of a buffer of connections, we do not actrively use all of them.
@brettwooldridge FYI so far so good, no pool exhaustion with newest PG jdbc.
Hello there, I have the same, although, as far as I can tell, it's only happened once, on 1 server out of 6, and in over a year.
Spring 2.2.7.RELEASE, HikariCP 3.4.3, Postgres driver 42.2.18.
We'll upgrade to the latest driver, and hope that we never see this again, but hoping info here can help troubleshoot the issue.
spring.datasource.hikari.minimum-idle=10
spring.datasource.hikari.maximum-pool-size=20
There was absolutely no traffic on this server at the time; a few anomalies pointing to possibly a network issue, which might explain why database connections could not be established (although no trace of errors there).
The pool remained at 0 for several hours (until the server was restarted)
A couple of hours after the pool depleted, traffic picked up, and requests were then timing out after the default 30 seconds: java.sql.SQLTransientConnectionException: HikariCP-Pool - Connection is not available, request timed out after 30001ms.; as expected with an empty pool...
The logs:
2021-06-29T01:00:09.49957714Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:09.499628265Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:09.499645469Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:00:39.500073285Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:39.50014193Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:39.500153115Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:01:09.500430648Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:09.500476543Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:09.500506514Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:01:39.500917543Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:39.500969329Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:39.500976971Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:02:09.501257526Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:09.501347133Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:09.501358873Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:02:39.501673118Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:39.501746493Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:39.501757056Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:03:09.502149824Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:09.502239242Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:09.50225113Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:03:39.502513634Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:39.502577477Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:39.502586818Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:03:51.301645809Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@77ee65c3: (connection has passed maxLifetime)
2021-06-29T01:03:51.378162954Z --- [onnection adder] class=HikariPool method=call HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@6b03c51
2021-06-29T01:04:09.502926235Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:09.502976534Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:09.502984864Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:04:39.503374865Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:39.503439295Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:39.50345082Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:05:09.503792364Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:09.503898772Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:09.503910288Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:05:39.50431245Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:39.504381693Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:39.50447626Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:06:09.504914021Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:09.504990971Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:09.505003689Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:06:39.505361102Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:39.505425864Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:39.505454275Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:06:48.468215048Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@2c57dec8: (connection has passed maxLifetime)
2021-06-29T01:06:48.511801881Z --- [onnection adder] class=HikariPool method=call HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@54c76d75
2021-06-29T01:07:06.569838289Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@2c2f9b47: (connection has passed maxLifetime)
2021-06-29T01:07:06.58737191Z --- [onnection adder] class=HikariPool method=call HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@709a149c
2021-06-29T01:07:09.505913315Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:09.506067032Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:09.506087933Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:07:39.506576515Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:39.506624414Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:39.506632485Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:07:46.740513308Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@26d6d5ba: (connection has passed maxLifetime)
2021-06-29T01:07:46.794847705Z --- [onnection adder] class=HikariPool method=call HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@235f7b70
2021-06-29T01:08:09.506940981Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:08:09.506991341Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:08:09.507000331Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:08:18.28318327Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@2129067d: (connection has passed maxLifetime)
2021-06-29T01:08:18.363369171Z --- [onnection adder] class=HikariPool method=call HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@6f156098
2021-06-29T01:08:20.151587209Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@4c4cc607: (connection has passed maxLifetime)
2021-06-29T01:08:39.507316652Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=9, active=0, idle=9, waiting=0)
2021-06-29T01:08:39.507365809Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=9, active=0, idle=9, waiting=0)
2021-06-29T01:08:39.507374499Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:08:56.927597178Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 1
2021-06-29T01:08:56.928889001Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@28c635c5: (connection has passed maxLifetime)
2021-06-29T01:09:05.942431229Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 2
2021-06-29T01:09:05.942510543Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@788b0207: (connection has passed maxLifetime)
2021-06-29T01:09:08.319300363Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 3
2021-06-29T01:09:08.319524591Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@7cb48949: (connection has passed maxLifetime)
2021-06-29T01:09:09.507762761Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:09.50786155Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:09.508270457Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:09:39.508292778Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:39.508351035Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:39.508411535Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:10:09.508863811Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:10:09.508936933Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:10:09.508949202Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:10:24.003927023Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 4
2021-06-29T01:10:24.004640073Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@6d01ce23: (connection has passed maxLifetime)
2021-06-29T01:10:39.509278991Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:10:39.509328959Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:10:39.509350526Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:11:09.509761952Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:09.50983824Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:09.509851454Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:11:39.510290608Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:39.51034942Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:39.51035739Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:12:09.510650825Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:09.510707035Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:09.510718653Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:12:39.511157062Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:39.511205324Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:39.511213435Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:13:09.511609779Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:09.511666268Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:09.511746067Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:13:39.512067169Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:39.51215596Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:39.512205084Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:14:09.512559362Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:09.512609493Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:09.512618157Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:14:39.513180797Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:39.513241737Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:39.513250501Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:15:09.513515045Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:09.513577992Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:09.513597052Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:15:39.513841408Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:39.513889186Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:39.513964944Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:16:09.514291971Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:09.514348694Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:09.514360069Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:16:39.514774739Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:39.514850311Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:39.514954256Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:17:09.515316585Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:09.515373943Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:09.515382199Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:17:39.515865467Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:39.515956812Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:39.515969071Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:18:09.516253452Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:09.516308871Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:09.51631763Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:18:39.516509215Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:39.516575373Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:39.516588366Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:19:09.517159524Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:09.517235574Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:09.517247644Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:19:39.517455051Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:39.518628897Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:39.519209522Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:20:09.517881635Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:09.517936623Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:09.517946308Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:20:39.518350225Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:39.518405452Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:39.518414191Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:21:09.518837812Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:09.518894729Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:09.518903179Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:21:39.519335494Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:39.519426571Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:39.519473398Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:22:09.519796614Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:09.519885103Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:09.519894573Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:22:39.520244203Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:39.520368613Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:39.520386302Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:23:09.520596045Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:09.520645563Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:09.520656771Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:23:39.521190075Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:39.521270343Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:39.521284373Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:24:09.521499449Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:09.521558434Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:09.52156739Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:24:39.52188109Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:39.52201449Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:39.522075882Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:25:09.522444725Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:09.522542199Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:09.522556085Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:25:39.52273193Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:39.522782444Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:39.522790339Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:26:09.523218806Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:09.523277074Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:09.523285777Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:26:39.523546817Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:39.523659005Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:39.523700401Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:27:09.524115564Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:09.524171598Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:09.524180265Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:27:39.524503071Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:39.524567885Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:39.52458053Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:28:09.524999005Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:09.52509318Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:09.525129636Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:28:39.525410395Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:39.525471877Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:39.525480293Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:29:09.525889203Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:09.525947083Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:09.525955797Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:29:39.526215978Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:39.526299654Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:39.526315465Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:30:09.526582797Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:09.526628154Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:09.526660111Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:30:39.527122193Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:39.527192555Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:39.527214937Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:31:09.527553499Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:09.52760292Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:09.527610362Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:31:39.528067675Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:39.528118977Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:39.528127087Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:32:09.528483697Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:09.528540421Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:09.528549088Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:32:39.528743219Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:39.528796679Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:39.528813139Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:33:07.453472655Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 5
2021-06-29T01:33:07.453567154Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@6b03c51: (connection has passed maxLifetime)
2021-06-29T01:33:09.529342826Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:09.529404025Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:09.529430415Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:33:39.529638727Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:39.529691038Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:39.529700583Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:34:09.530121403Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:09.530197531Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:09.530206232Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:34:39.530431809Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:39.530505529Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:39.5305207Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:35:09.530791571Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:09.530879886Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:09.530890606Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:35:39.531218851Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:39.531297708Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:39.531312217Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:36:09.531769424Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:36:09.531872485Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:36:09.531886214Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:36:21.819081062Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 6
2021-06-29T01:36:21.819233355Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@54c76d75: (connection has passed maxLifetime)
2021-06-29T01:36:26.981083206Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 7
2021-06-29T01:36:26.981164912Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@709a149c: (connection has passed maxLifetime)
2021-06-29T01:36:39.532479584Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2021-06-29T01:36:39.532536753Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=2, active=0, idle=2, waiting=0)
2021-06-29T01:36:39.532544952Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:37:08.892000145Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 8
2021-06-29T01:37:08.892060929Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@235f7b70: (connection has passed maxLifetime)
2021-06-29T01:37:09.532683903Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=1, active=0, idle=1, waiting=0)
2021-06-29T01:37:09.532737619Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=1, active=0, idle=1, waiting=0)
2021-06-29T01:37:09.532744965Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:37:33.710740649Z --- [ool housekeeper] class=HikariPool method=addBagItem HikariCP-Pool - Add connection elided, waiting 0, queue 9
2021-06-29T01:37:33.710927581Z --- [nnection closer] class=PoolBase method=quietlyCloseConnection : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@6f156098: (connection has passed maxLifetime)
2021-06-29T01:37:39.533289121Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:37:39.533361054Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:37:39.533373058Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:38:09.533570366Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:09.533627264Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:09.533636121Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:38:39.534016165Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:39.534148709Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:39.534187612Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:39:09.534634757Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:09.534716188Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:09.534731419Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:39:39.53497712Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:39.535031822Z --- [ool housekeeper] class=HikariPool method=logPoolState HikariCP-Pool - After cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:39.535040161Z --- [ool housekeeper] class=HikariPool method=fillPool HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
@brettwooldridge The issue occurs with a fixed sized pool too. This error occurs randomly in any of the pods.
HikariCP:3.4.5 Spring Boot: 2.3.4-RELEASE JDBC Driver: Microsoft SQL Server
The logs are very similar to the previous one posted here.
I see that you've added a fix for the issue in the latest version 5.0.0.
@brettwooldridge
Used the version 5.0.0 but still pool size becomes zero and no new connections are added. Only solution we see for now is to keep monitoring and restart the POD as soon as the POOL drains out.
HikariCP:5.0.0
Spring Boot: 2.3.4-RELEASE
JDBC Driver: Microsoft SQL Server
spring.datasource.hikari.maximum-pool-size=20
spring.datasource.hikari.leak-detection-threshold=20000
spring.datasource.hikari.max-lifetime=30000
Looks like your recent fix also didn't solve the issue.
logs:
2021-10-16 20:31:45.669 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=13 2021-10-16 20:31:45.669 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68700 ClientConnectionId: 1a185b9a-6fec-4fe4-b269-332f277b1fe0: (connection has passed maxLifetime) 2021-10-16 20:31:45.698 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=14 2021-10-16 20:31:45.698 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68701 ClientConnectionId: 5469f543-f26b-4f13-85b0-d92202658cc6: (connection has passed maxLifetime) 2021-10-16 20:31:46.545 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=15 2021-10-16 20:31:46.545 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68702 ClientConnectionId: fb7b6930-1b40-4fc0-9314-30706727b766: (connection has passed maxLifetime) 2021-10-16 20:31:46.760 INFO 1 --- [nio-8080-exec-8] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:31:47.087 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0) 2021-10-16 20:31:47.199 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68703 ClientConnectionId: cbfcdbe4-b47e-433a-bc91-c02e77a33960: (connection has passed maxLifetime) 2021-10-16 20:31:47.199 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:47.488 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68704 ClientConnectionId: 4eef9b94-8e1c-4d92-8d2f-a351bbdc6185: (connection has passed maxLifetime) 2021-10-16 20:31:47.488 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:47.648 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:47.648 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68705 ClientConnectionId: 9649835b-2d1c-49b2-a5eb-f99459b99fcb: (connection has passed maxLifetime) 2021-10-16 20:31:48.898 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:48.898 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68707 ClientConnectionId: 78dc2f69-d4bc-4a99-912f-5f9ef17d2e2d: (connection has passed maxLifetime) 2021-10-16 20:31:48.960 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:48.960 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68706 ClientConnectionId: eb60394a-9e49-4321-b551-efe6a1a9557b: (connection has passed maxLifetime) 2021-10-16 20:31:51.760 INFO 1 --- [nio-8080-exec-9] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:31:56.760 INFO 1 --- [io-8080-exec-10] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:01.760 INFO 1 --- [nio-8080-exec-1] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:06.760 INFO 1 --- [nio-8080-exec-2] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:11.760 INFO 1 --- [nio-8080-exec-3] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:16.760 INFO 1 --- [nio-8080-exec-4] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:17.087 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0) 2021-10-16 20:32:21.760 INFO 1 --- [nio-8080-exec-5] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:26.760 INFO 1 --- [nio-8080-exec-6] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:31.760 INFO 1 --- [nio-8080-exec-7] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:36.760 INFO 1 --- [nio-8080-exec-8] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:41.760 INFO 1 --- [nio-8080-exec-9] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:46.760 INFO 1 --- [io-8080-exec-10] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:47.087 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0)
HikariCP: 3.4.5 PostgreSQL JDBC: 42.2.18
We're now also upgrading to the latest HikariCP version (5.0.x) and PostgreSQL JDBC version hoping this will be the cure. But because @krandhir has mentioned that this issue may not be entirely resolved with the new version, I've decided to also share our story. Will keep you posted when it occurs again with 5.0.x.
We've had multiple outages due to this issue which required a manual restart of the app to recover - yesterday it even happened twice. Once just at the end of business hours and once during the night after which it stayed in this broken state for many hours as we only page operators during business hours.
Edit 2: It turned out, that this was actually a problem with RHEL. A system admin restarted the firewalld service which cut our java application running within a podman container entirely off from the network. Using a heap dump we've figured out HikariCP correctly continued trying to connect, so that part kept working.
HikariCP:5.6.5.Final
Postgresql driver: 42.4.0
Hello @brettwooldridge , I think that I have a similar error. A few times per day one of our pods is facing issue that has a lot of connections in a WAITING state, this problem mostly disappears after 1 minute, but it is blocking customers to use API over that period of time. Here are Hikari logs from that period of time hikarilogs.csv
@davidvuletas It seems clear to me that the issue is on the PostgreSQL-side. This has been a most elusive issue to nail down. It is clear from the logs that HikariCP is trying its best to establish new connections, but ultimately PostgreSQL refuses. If this is happening frequently, you are in the best position of anyone I've spoken with to help resolve this once and for all. What would be really useful would be PostgreSQL logging.
Logging is documented here. In particular, if you can enable log_connections, log_disconnections, log_error_verbosity=VERBOSE, and configure log_line_prefix using your best judgement.
@davidvuletas If you encounter the pool going to zero, can you run this query in psql against your server?
select pid as process_id,
usename as username,
datname as database_name,
client_addr as client_address,
application_name,
backend_start,
state,
state_change
from pg_stat_activity;
@davidvuletas If you encounter the pool going to zero, can you run this query in
psqlagainst your server?
It's hard to execute this query at the time of losing connection because it happens at a random period of the day and it takes 1 minute. I executed the query right now. And this is the result. pg_stat_activity.csv