search

brettwooldridge / HikariCP

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

Number of waiting threads is always zero (PostgreSQL in minikube) #1702

Open JonasBRasmussen opened 3 years ago

JonasBRasmussen commented 3 years ago

I am experiencing a peculiar problem that seems to be related to the use of minikube.

I am running a PostgreSQL 13 pod (with no custom configuration) in minikube and connecting to it from my application in IntelliJ. After a while, no connections are created to replace the ones that are closed by Hikari, because Hikari feels that there are no waiting threads. I have tried running the same application, but connecting it to a PosgreSQL 13 Docker container instead (using Docker Desktop on Windows 10), and then the problem disappears.

I am hoping someone with Hikari (and possibly minikube, kubernetes and PostgreSQL) insight that can help me figure out what the problem is (Hikari configuration, minikube configuration, PostgreSQL configuration, etc.).

I have created a minimal Spring Boot application that reproduces the problem. It consists of the following two classes (I am using scheduling to avoid the application shutting down immediately):

@EnableScheduling
@SpringBootApplication
public class DemoApplication {
    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }
}
@Component
public class ScheduledJob {
    private final DataSource dataSource;

    public ScheduledJob(DataSource dataSource) {
        this.dataSource = dataSource;
    }

    @Scheduled(fixedDelay = 2000L)
    public void execute() {
        var template = new JdbcTemplate(this.dataSource);
        template.queryForObject("SELECT 1", Integer.class);
    }
}

The application.yaml looks like this (notice the low values - this is so the problem occurs in at most a few minutes):

spring:
  datasource:
    url: jdbc:postgresql://localhost:5432/postgres
    username: postgres
    password: postgres
    hikari:
      pool-name: my-pool
      max-lifetime: 30000
      connection-timeout: 5000
      validation-timeout: 5000
      leak-detection-threshold: 10000
logging:
  level:
    com.zaxxer.hikari: DEBUG

The build.gradle looks like this:

plugins {
    id 'org.springframework.boot' version '2.4.0'
    id 'io.spring.dependency-management' version '1.0.10.RELEASE'
    id 'java'
}

group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = '11'

repositories {
    mavenCentral()
}

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-jdbc'
    implementation 'org.postgresql:postgresql'
}

Running this application gives the following log messages:

2020-12-06 11:01:15.197  INFO 5536 --- [           main] com.example.demo.DemoApplication         : Starting DemoApplication using Java 11.0.8
2020-12-06 11:01:15.201  INFO 5536 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2020-12-06 11:01:15.708 DEBUG 5536 --- [           main] com.zaxxer.hikari.HikariConfig           : Driver class org.postgresql.Driver found in Thread context class loader jdk.internal.loader.ClassLoaders$AppClassLoader@368239c8
2020-12-06 11:01:15.811  INFO 5536 --- [           main] o.s.s.c.ThreadPoolTaskScheduler          : Initializing ExecutorService 'taskScheduler'
2020-12-06 11:01:15.845 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : my-pool - configuration:
2020-12-06 11:01:15.847  INFO 5536 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 1.083 seconds (JVM running for 2.569)
2020-12-06 11:01:15.848 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : allowPoolSuspension.............false
2020-12-06 11:01:15.848 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : autoCommit......................true
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : catalog.........................none
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : connectionInitSql...............none
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : connectionTestQuery.............none
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : connectionTimeout...............5000
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : dataSource......................none
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : dataSourceClassName.............none
2020-12-06 11:01:15.849 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : dataSourceJNDI..................none
2020-12-06 11:01:15.850 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : dataSourceProperties............{password=<masked>}
2020-12-06 11:01:15.850 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : driverClassName................."org.postgresql.Driver"
2020-12-06 11:01:15.850 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : exceptionOverrideClassName......none
2020-12-06 11:01:15.850 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : healthCheckProperties...........{}
2020-12-06 11:01:15.850 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : healthCheckRegistry.............none
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : idleTimeout.....................600000
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : initializationFailTimeout.......1
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : isolateInternalQueries..........false
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : jdbcUrl.........................jdbc:postgresql://localhost:5432/postgres
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : leakDetectionThreshold..........10000
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : maxLifetime.....................30000
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : maximumPoolSize.................10
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : metricRegistry..................none
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : metricsTrackerFactory...........none
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : minimumIdle.....................10
2020-12-06 11:01:15.851 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : password........................<masked>
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : poolName........................"my-pool"
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : readOnly........................false
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : registerMbeans..................false
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : scheduledExecutor...............none
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : schema..........................none
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : threadFactory...................internal
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : transactionIsolation............default
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : username........................"postgres"
2020-12-06 11:01:15.852 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariConfig           : validationTimeout...............5000
2020-12-06 11:01:15.852  INFO 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariDataSource       : my-pool - Starting...
2020-12-06 11:01:15.967 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@278f3b04
2020-12-06 11:01:15.969  INFO 5536 --- [   scheduling-1] com.zaxxer.hikari.HikariDataSource       : my-pool - Start completed.
2020-12-06 11:01:16.069 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Pool stats (total=1, active=0, idle=1, waiting=0)
2020-12-06 11:01:16.191 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@549a7be8
2020-12-06 11:01:16.255 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@5a5d9f0b
2020-12-06 11:01:16.307 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@5e621098
2020-12-06 11:01:16.359 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@1b609530
2020-12-06 11:01:16.424 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@1c22e88f
2020-12-06 11:01:16.492 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@2a3189c7
2020-12-06 11:01:16.548 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@6499aac9
2020-12-06 11:01:16.599 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@7b4f6a7f
2020-12-06 11:01:16.661 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@70228309
2020-12-06 11:01:16.662 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:01:45.448 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@549a7be8: (connection has passed maxLifetime)
2020-12-06 11:01:45.502 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@7c9cc368
2020-12-06 11:01:45.703 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@278f3b04: (connection has passed maxLifetime)
2020-12-06 11:01:45.753 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@725b328b
2020-12-06 11:01:45.803 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@5a5d9f0b: (connection has passed maxLifetime)
2020-12-06 11:01:45.850 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@1c22e88f: (connection has passed maxLifetime)
2020-12-06 11:01:45.855 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:01:45.901 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@7664a818
2020-12-06 11:01:45.961 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@336638b0
2020-12-06 11:01:45.961 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:01:46.071 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Pool stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:01:46.071 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Fill pool skipped, pool is at sufficient level.
2020-12-06 11:01:46.147 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@5e621098: (connection has passed maxLifetime)
2020-12-06 11:01:46.155 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:01:46.155 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@7b4f6a7f: (connection has passed maxLifetime)
2020-12-06 11:01:46.175 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 2
2020-12-06 11:01:46.175 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@1b609530: (connection has passed maxLifetime)
2020-12-06 11:01:46.209 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@297b2a37
2020-12-06 11:01:46.263 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@5349c7ff
2020-12-06 11:01:46.263 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=9, active=0, idle=9, waiting=0)
2020-12-06 11:01:46.316 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@23937533
2020-12-06 11:01:46.316 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:01:46.342 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@2a3189c7: (connection has passed maxLifetime)
2020-12-06 11:01:46.391 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@5da5ebfa
2020-12-06 11:01:46.405 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@6499aac9: (connection has passed maxLifetime)
2020-12-06 11:01:46.441 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:01:46.441 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@70228309: (connection has passed maxLifetime)
2020-12-06 11:01:46.488 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@4a6ca882
2020-12-06 11:01:46.538 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@5707f80f
2020-12-06 11:01:46.539 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:02:15.329 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@336638b0: (connection has passed maxLifetime)
2020-12-06 11:02:15.407 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:02:15.407 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@725b328b: (connection has passed maxLifetime)
2020-12-06 11:02:15.423 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@21147cd7
2020-12-06 11:02:15.438 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:02:15.438 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@7c9cc368: (connection has passed maxLifetime)
2020-12-06 11:02:15.466 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@7664a818: (connection has passed maxLifetime)
2020-12-06 11:02:15.466 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 2
2020-12-06 11:02:15.472 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@2fd38685
2020-12-06 11:02:15.472 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=8, active=0, idle=8, waiting=0)
2020-12-06 11:02:15.532 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@2bec17a7
2020-12-06 11:02:15.532 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=9, active=0, idle=9, waiting=0)
2020-12-06 11:02:15.578 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@6eee8cbe
2020-12-06 11:02:15.578 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:02:15.882 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@297b2a37: (connection has passed maxLifetime)
2020-12-06 11:02:15.947 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@6c9ea770
2020-12-06 11:02:15.999 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@5da5ebfa: (connection has passed maxLifetime)
2020-12-06 11:02:16.046 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@5f4ae3c8
2020-12-06 11:02:16.072 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Pool stats (total=10, active=0, idle=10, waiting=0)
2020-12-06 11:02:16.072 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Fill pool skipped, pool is at sufficient level.
2020-12-06 11:02:16.073 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@4a6ca882: (connection has passed maxLifetime)
2020-12-06 11:02:16.120 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@14d096a9
2020-12-06 11:02:16.140 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@5349c7ff: (connection has passed maxLifetime)
2020-12-06 11:02:16.196 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@ec173f1
2020-12-06 11:02:16.207 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@23937533: (connection has passed maxLifetime)
2020-12-06 11:02:16.255 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@17fdf07e
2020-12-06 11:02:16.293 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@5707f80f: (connection has passed maxLifetime)
2020-12-06 11:02:16.346 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@1fa115ea
2020-12-06 11:02:44.953 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@21147cd7: (connection has passed maxLifetime)
2020-12-06 11:02:45.008 DEBUG 5536 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : my-pool - Added connection org.postgresql.jdbc.PgConnection@525045b3
2020-12-06 11:02:45.325 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@2bec17a7: (connection has passed maxLifetime)
2020-12-06 11:02:45.412 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@2fd38685: (connection has passed maxLifetime)
2020-12-06 11:02:45.412 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:02:45.465 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 2
2020-12-06 11:02:45.465 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@6eee8cbe: (connection has passed maxLifetime)
2020-12-06 11:02:45.664 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 3
2020-12-06 11:02:45.664 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@1fa115ea: (connection has passed maxLifetime)
2020-12-06 11:02:45.779 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 4
2020-12-06 11:02:45.779 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@14d096a9: (connection has passed maxLifetime)
2020-12-06 11:02:45.794 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 5
2020-12-06 11:02:45.794 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@5f4ae3c8: (connection has passed maxLifetime)
2020-12-06 11:02:45.873 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@6c9ea770: (connection has passed maxLifetime)
2020-12-06 11:02:45.873 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 6
2020-12-06 11:02:46.020 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 7
2020-12-06 11:02:46.020 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@ec173f1: (connection has passed maxLifetime)
2020-12-06 11:02:46.044 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 8
2020-12-06 11:02:46.044 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@17fdf07e: (connection has passed maxLifetime)
2020-12-06 11:02:46.073 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Pool stats (total=1, active=0, idle=1, waiting=0)
2020-12-06 11:02:46.073 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Fill pool skipped, pool is at sufficient level.
2020-12-06 11:03:14.740 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 9
2020-12-06 11:03:14.741 DEBUG 5536 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : my-pool - Closing connection org.postgresql.jdbc.PgConnection@525045b3: (connection has passed maxLifetime)
2020-12-06 11:03:16.075 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Pool stats (total=0, active=0, idle=0, waiting=0)
2020-12-06 11:03:16.075 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Fill pool skipped, pool is at sufficient level.
2020-12-06 11:03:16.340 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 1, queue 10
2020-12-06 11:03:21.340 DEBUG 5536 --- [   scheduling-1] com.zaxxer.hikari.pool.HikariPool        : my-pool - Timeout failure stats (total=0, active=0, idle=0, waiting=0)

After which the application starts failing because no connections are available:

2020-12-06 11:03:21.345 ERROR 5536 --- [   scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: my-pool - Connection is not available, request timed out after 5001ms.
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:376) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:465) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:475) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:508) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:515) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at com.example.demo.Service.execute(Service.java:20) ~[main/:na]
    at jdk.internal.reflect.GeneratedMethodAccessor26.invoke(Unknown Source) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
    at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.3.1.jar:5.3.1]
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.3.1.jar:5.3.1]
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
    at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: java.sql.SQLTransientConnectionException: my-pool - Connection is not available, request timed out after 5001ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162) ~[HikariCP-3.4.5.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.5.jar:na]
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116) ~[spring-jdbc-5.3.1.jar:5.3.1]
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79) ~[spring-jdbc-5.3.1.jar:5.3.1]
    ... 17 common frames omitted

The interesting messages are these, where the number of waiting threads is always 0, while the queued threads just increase:

2020-12-06 11:02:45.412 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 1
2020-12-06 11:02:45.465 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 2
2020-12-06 11:02:45.664 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 3
2020-12-06 11:02:45.779 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 4
2020-12-06 11:02:45.794 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 5
2020-12-06 11:02:45.873 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 6
2020-12-06 11:02:46.020 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 7
2020-12-06 11:02:46.044 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 8
2020-12-06 11:03:14.740 DEBUG 5536 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : my-pool - Add connection elided, waiting 0, queue 9

When the application starts, Hikari is clearly able to add 10 connections without any issue. Hikari then (sometimes) add new connections when old connections are closed, but mostly not, because the addBag method is (almost) always called with the value 0. Thus it varies from run to run how long it takes for the pool to become empty. With the 30s max lifetime, it is never more than a couple of minutes though.

fdkuiper commented 3 years ago

Hi @JonasBRasmussen, I see similar behaviour on our environment but then with a Oracle DB. Did you ever found a root cause or something like that for this issue?

JonasBRasmussen commented 3 years ago

Hi @fdkuiper, Unfortunately not. I've had to learn to live with it.

adiospeds commented 2 years ago

Seeing the exact same issue with Azure SQL DB + Spring Boot App + HikariCP v3.4.5 which is running as a traditional service (not microservice) on a server.

marcopiccolo-atos commented 2 years ago

Hi all. I too am dealing with this issue at the moment but with Azure SQL DB. I even tryied setting the socketTimeout configuration on the connection string as suggested in another issue I can't find at the moment but the problem occurred again.

The project is running the following versions. Java 1.8 Spring Boot 2.3.4.RELEASE HikariCP 3.4.5 mssql-jdbc 7.4.1.jre8

Configuration: `spring: datasource: driver-class-name: com.microsoft.sqlserver.jdbc.SQLServerDriver

indirizzo database

url: jdbc:sqlserver://${DATABASE-URL};database=${DATABASE-NAME};user=${DATABASE-USER};password=${DATABASE-PASSWORD};encrypt=true;trustServerCertificate=false;hostNameInCertificate=*.database.windows.net;loginTimeout=30;authentication=ActiveDirectoryPassword;socketTimeout=60000
hikari:
  minimum-idle: 10
  maximum-pool-size: 50

jpa: show-sql: true default-schema: DL hibernate: dialect: org.hibernate.dialect.SQLServer2019Dialect ddl-auto: none default-schema: DL properties: hibernate.default_schema: DL`

The issue is happening randomly on one of 15 different microservices that continue working normally. The logs for when it happens 2022-09-27 06:04:48.052 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=10, active=0, idle=10, waiting=0) 2022-09-27 06:04:48.052 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection ConnectionID:28436 ClientConnectionId: ef2dcaa5-e667-4acd-8d2e-4aa1c99a09b1 2022-09-27 06:05:01.359 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0) 2022-09-27 06:05:01.359 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2022-09-27 06:05:13.369 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28427 ClientConnectionId: 51b982af-e019-4903-9394-ad3dd770569b: (connection has passed maxLifetime) 2022-09-27 06:05:14.004 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection ConnectionID:28437 ClientConnectionId: 08e710af-a1a5-4732-85af-afdb171274ed 2022-09-27 06:05:14.193 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28428 ClientConnectionId: d0dd9754-653f-4d51-81ee-68ca3ce52c38: (connection has passed maxLifetime) 2022-09-27 06:05:14.235 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 1 2022-09-27 06:05:14.235 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28429 ClientConnectionId: 0e7fc772-760e-48f8-9c27-75462e9ba0ab: (connection has passed maxLifetime) 2022-09-27 06:05:14.635 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection ConnectionID:28438 ClientConnectionId: 3ce42328-b375-4550-b8c0-397953872988 2022-09-27 06:05:14.756 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 1 2022-09-27 06:05:14.756 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28430 ClientConnectionId: ebd8ab1a-5937-49ed-bd93-c254dd6c26d3: (connection has passed maxLifetime) 2022-09-27 06:05:15.050 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28431 ClientConnectionId: 5789c582-f285-4a22-861a-473104e2d11e: (connection has passed maxLifetime) 2022-09-27 06:05:15.050 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 2 2022-09-27 06:05:15.953 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28432 ClientConnectionId: 08bc282b-38e6-406f-8843-2e6975a128e8: (connection has passed maxLifetime) 2022-09-27 06:05:15.953 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 3 2022-09-27 06:05:16.507 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 4 2022-09-27 06:05:16.507 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28433 ClientConnectionId: 4ea3be9b-74ed-458c-ae93-f0fa396b71fc: (connection has passed maxLifetime) 2022-09-27 06:05:17.034 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28434 ClientConnectionId: a92d34b5-4549-4ced-8549-63f5f704855d: (connection has passed maxLifetime) 2022-09-27 06:05:17.034 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 5 2022-09-27 06:05:17.038 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28435 ClientConnectionId: c395008c-733f-4132-93e1-c3be1ee706b1: (connection has passed maxLifetime) 2022-09-27 06:05:17.037 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 6 2022-09-27 06:05:17.374 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28436 ClientConnectionId: ef2dcaa5-e667-4acd-8d2e-4aa1c99a09b1: (connection has passed maxLifetime) 2022-09-27 06:05:17.374 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 7 2022-09-27 06:05:31.360 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2022-09-27 06:05:31.360 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=2, active=0, idle=2, waiting=0) 2022-09-27 06:05:43.431 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 8 2022-09-27 06:05:43.431 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28437 ClientConnectionId: 08e710af-a1a5-4732-85af-afdb171274ed: (connection has passed maxLifetime) 2022-09-27 06:05:44.097 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting 0, queue 9 2022-09-27 06:05:44.097 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:28438 ClientConnectionId: 3ce42328-b375-4550-b8c0-397953872988: (connection has passed maxLifetime) 2022-09-27 06:06:01.360 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0) 2022-09-27 06:06:01.360 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2022-09-27 06:06:31.360 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool is at sufficient level. 2022-09-27 06:06:31.360 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0)

slychops commented 2 years ago

@JonasBRasmussen How did you learn to live with it? This seems like an unliveable bug.. are you just implementing some health checks and restarts?

catalinbalasoiu commented 1 year ago

@slychops This is exactly what we did.. It is definitely not what we wanted, but we couldn't find any other solution.

For us is happening on version 5.0.0 while connecting to an Azure SQL Server.

ravibarkhani commented 1 year ago

Hello, We are also facing same issue :( Hi everyone, anybody solved this issue, we are facing with HikariCP v5.0.1

Connection pool settings minimumIdle: 5 maximumPoolSize: 30 maxLifetime: default 30 min connectionTimeout: 180000 idleTimeout : 600000

database : Azure SQL DB detailed Logs added in issue : https://github.com/brettwooldridge/HikariCP/issues/1710

ozzybil commented 4 months ago

Hi everyone! Are there any updates on this?

AmbujaAK commented 1 month ago

Any solution found for this issue ?? I'm facing similar kind of issue where connection are getting elided during high load and cpu usage reaches up to 98%.