HikariPool-1 - Connection is not available, request timed out after 6000ms

最新推荐文章于 2023-11-07 13:49:09 发布

skyline_wx

最新推荐文章于 2023-11-07 13:49:09 发布

阅读量1.6w

点赞数 15

分类专栏：问题排查 Hikari 文章标签： java 后端连接池

本文链接：https://blog.csdn.net/WX10301075WX/article/details/121277257

版权

问题排查同时被 2 个专栏收录

12 篇文章 2 订阅

订阅专栏

Hikari

2 篇文章 0 订阅

订阅专栏

Connection is not available, request timed out after 6000ms

问题
排查
论证
通过demo重现问题
总结

问题

今天项目上频繁出现了大量的这样的报错

Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 6000ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
	... 75 more

百度了一下，很多都说需要把spring.datasource.hikari.connection-timeout的值调大就行。但是我们试了一下之后发现效果并不明显，然后我们调大了spring.datasource.hikari.maximum-pool-size的大小，这下有效果了。这是为什么呢?

排查

一直以来，我都以为这个报错是hikari连接数据库时，创建数据库连接超时抛出的异常，但是翻了一下抛出异常的源码之后发现并不是这样的，简单的贴一下代码：

public Connection getConnection(final long hardTimeout) throws SQLException
   {
      suspendResumeLock.acquire();
      final long startTime = currentTime();

      try {
         long timeout = hardTimeout;
         do {
            PoolEntry poolEntry = connectionBag.borrow(timeout, MILLISECONDS);
            if (poolEntry == null) {
               break; // We timed out... break and throw exception
            }

            final long now = currentTime();
            if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > aliveBypassWindowMs && !isConnectionAlive(poolEntry.connection))) {
               closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE);
               timeout = hardTimeout - elapsedMillis(startTime);
            }
            else {
               metricsTracker.recordBorrowStats(poolEntry, startTime);
               return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry), now);
            }
         } while (timeout > 0L);

         metricsTracker.recordBorrowTimeoutStats(startTime);
         throw createTimeoutException(startTime);
      }
      catch (InterruptedException e) {
         Thread.currentThread().interrupt();
         throw new SQLException(poolName + " - Interrupted during connection acquisition", e);
      }
      finally {
         suspendResumeLock.release();
      }
   }

里面的代码虽然没有细究，但是从意思上看，应该是如果在hardTimeout时间内没有从连接池中获取到有效的连接，那就抛出异常，而抛出的正是日志中大量打印的那个异常。

论证

从上面的源码中看，增加spring.datasource.hikari.connection-timeout的值应该确实是有效的，最起码可以降低异常率，但是总连接数依然不足，所以看起来的现象应该是日志中的报错少了，但是系统会卡的要命。增加spring.datasource.hikari.maximum-pool-size之后整个系统可用的最大连接数变多了，自然就不卡不报错了。

通过demo重现问题

为了验证我的想法，我写了一个demo
数据库相关配置文件：

#5个最小空闲连接，我把它理解为coreSize
spring.datasource.hikari.minimum-idle=5
#最大生命周期60s，测试用
spring.datasource.hikari.max-lifetime=60000
#一个连接空闲10s后，将会被回收
spring.datasource.hikari.idle-timeout=10
#连接池中的最大连接数
spring.datasource.hikari.maximum-pool-size=10
#获取连接的等待时长5s
spring.datasource.hikari.connection-timeout=5000
#判断连接是否有效
spring.datasource.hikari.connection-test-query=select 1

demo源码：

@SpringBootApplication(scanBasePackages = "com.example.juc.hikari")
public class Main {
    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        ConfigurableApplicationContext applicationContext = SpringApplication.run(Main.class, args);
        DataSource dataSource = applicationContext.getBean(DataSource.class);
        logger.info("{}", dataSource);
        //先获取10个连接，就获取，不释放
        int maxConnectionCount = 10;
        List<Connection> connections = new ArrayList<>();
        for (int i = 0; i < maxConnectionCount; i++) {
            try {
                Connection connection = dataSource.getConnection();
                connections.add(connection);
            } catch (SQLException e) {
                e.printStackTrace();
            }
        }
        //起一个新的
        Thread thread = new Thread(() -> {
            Connection connection = null;
            do {
                try {
	                //开始尝试获取连接
                    connection = dataSource.getConnection();
                } catch (SQLException e) {
                    logger.error("连接获取失败:[{}]", e.getMessage());
                }
                //如果获取失败，就再来一次
            } while (connection == null);
            logger.info("获取到新的连接了！");
            try {
                connection.close();
            } catch (SQLException e) {
                e.printStackTrace();
            }
            logger.info("链接归还了！");
        }, "test");
        thread.start();
        try {
            logger.info("主线程休眠10s");
            TimeUnit.SECONDS.sleep(10);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        //主线程休眠10秒之后，开始归还连接
        connections.forEach(connection -> {
            try {
                connection.close();
                logger.info("归还了");
            } catch (SQLException e) {
                e.printStackTrace();
            }
        });
    }
}

先看结论：

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.4.6)

21:42:11.251 [main       ] INFO  c.e.j.h.Main - Starting Main using Java 1.8.0_261 on DESKTOP-5R7UHQH with PID 15948 (D:\code\myCode\out\production\classes started by w123x in D:\code\myCode)
21:42:11.253 [main       ] INFO  c.e.j.h.Main - No active profile set, falling back to default profiles: default
21:42:12.086 [main       ] INFO  o.s.b.w.e.t.TomcatWebServer - Tomcat initialized with port(s): 8080 (http)
21:42:12.092 [main       ] INFO  o.a.c.h.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-8080"]
21:42:12.093 [main       ] INFO  o.a.c.c.StandardService - Starting service [Tomcat]
21:42:12.093 [main       ] INFO  o.a.c.c.StandardEngine - Starting Servlet engine: [Apache Tomcat/9.0.46]
21:42:12.164 [main       ] INFO  o.a.c.c.C.[.[.[/] - Initializing Spring embedded WebApplicationContext
21:42:12.165 [main       ] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 873 ms
21:42:12.453 [main       ] INFO  o.a.c.h.Http11NioProtocol - Starting ProtocolHandler ["http-nio-8080"]
21:42:12.467 [main       ] INFO  o.s.b.w.e.t.TomcatWebServer - Tomcat started on port(s): 8080 (http) with context path ''
21:42:12.474 [main       ] INFO  c.e.j.h.Main - Started Main in 1.581 seconds (JVM running for 2.601)
21:42:12.475 [main       ] INFO  c.e.j.h.Main - HikariDataSource (null)
21:42:12.476 [main       ] WARN  c.z.h.HikariConfig - HikariPool-1 - idleTimeout is less than 10000ms, setting to default 600000ms.
21:42:12.476 [main       ] INFO  c.z.h.HikariDataSource - HikariPool-1 - Starting...
21:42:12.595 [main       ] INFO  c.z.h.HikariDataSource - HikariPool-1 - Start completed.
21:42:12.636 [main       ] INFO  c.e.j.h.Main - 主线程休眠10s
21:42:17.640 [test       ] ERROR c.e.j.h.Main - 连接获取失败:[HikariPool-1 - Connection is not available, request timed out after 5003ms.]
21:42:22.647 [test       ] ERROR c.e.j.h.Main - 连接获取失败:[HikariPool-1 - Connection is not available, request timed out after 5006ms.]
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [main       ] INFO  c.e.j.h.Main - 归还了
21:42:22.650 [test       ] INFO  c.e.j.h.Main - 获取到新的连接了！
21:42:22.650 [test       ] INFO  c.e.j.h.Main - 链接归还了！

从日志看到test线程一开始确实没有获取到连接，每次获取连接的最大等待时长为spring.datasource.hikari.connection-timeout，也就是5秒，所以一共失败了2次。10秒之后，主线程开始归还连接，test线程就获取到连接了。

总结

这个报错跟spring.datasource.hikari.connection-timeout和spring.datasource.hikari.maximum-pool-size都有关系。
连接是一种非常宝贵的资源，获取到connection之后，马上就应该开始执行SQL，执行完SQL之后马上就应该close。一定要尽快归还connection，这样也不影响其他业务的操作。
同一个线程中多次getConnection，获取到的是不同的connection。
遇到问题不要紧张，不要乱猜，一定要看源码，看源码，硬着头皮看源码。

skyline_wx

关注

15
点赞
踩
34

收藏

觉得还不错? 一键收藏
0
评论
HikariPool-1 - Connection is not available, request timed out after 6000ms

Connection is not available, request timed out after 6000ms问题排查论证通过demo重现问题总结问题今天项目上频繁出现了大量的这样的报错Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 6000ms. at com.zaxxer.hikari.pool.
复制链接

扫一扫