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。
- 遇到问题不要紧张,不要乱猜,一定要看源码,看源码,硬着头皮看源码。
更多推荐
HikariPool-1 - Connection is not available, request timed out after 6000ms
发布评论