记一次获取连接超时的排查过程Connection is not
背景
之前在压测一个用java写的应用时,偶尔会报如下的错误:
org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30002ms.
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:305)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:474)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:289)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
at com.quantil.cm.api.service.PurgeTaskService$$EnhancerBySpringCGLIB$$b4db5835.create(<generated>)
排查过程
1. MySQL最大连接数排查
show variables like '%conn%'
MySQL设置的最大连接数为32768,API开启的连接池也只有100个,因此排除这个原因
2. MySQL连接池泄露
百度找了一下相关资料,发现有可能是因为MyBatis自定义拦截器没有释放连接的原因。
因为这个java应用也自定义了一个拦截器用来分页,但是连接本地数据库进行压测的时候并没有出现这个错误,因此也排除了连接池泄露的原因
3. 源码研究
直接在IDEA查找关键字Connection is not available
,发现只有在HikariPool.java的方法getConnection
里面会抛错throw createTimeoutException(startTime)
方法代码如下:
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) > ALIVE_BYPASS_WINDOW_MS && !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();
}
}
大概看了一下这个方法做的事情,其实就是从连接池里面去borrow
一个连接,然后返回。如果borrow
了30s还没borrow
到,那么就会抛错了。
这个时候真相呼之欲出了,什么情况会造成获取连接池连接超时?
- 连接泄露
某些线程拿到了连接后没有归还,持续久了就出问题 - 连接归还连接池太慢
极端点,数据库响应时间要花1s,10个连接池1秒也只能处理10个请求。这个时候如果有500个并发那得50s才能处理完,这不就超时了 - 连接归还连接池很快,但是借的线程太多
数据库响应很快,无奈并发太高,远超连接池大小。假设连接池只有10个连接,但是有100个线程在borrow
连接的话,是不是有可能会出现某些倒霉的线程30s一直borrow
不到连接的情况?
本例排除了前两种可能,因此猜测是第三种原因。 并发数远大于连接池大小,导致有可能出现某些线程30s内一直获取不到连接,从而抛错
bug本地复现
既然是怀疑并发数大于连接池大小大致的,那我们将hikari的线程数设置成10(设置小点避免引入数据库的干扰),然后开500并发来测试本地java应用
spring.datasource.hikari.maximum-pool-size=10
ab压测命令
ab -c 500 -n 50000 -p body.json http://127.0.0.1:8080/api/test
-
本地数据库复现
无法复现????!!!!
10个连接,500个并发都能完美处理过来!!!
怀疑是因为本地通信太快了,500个并发可能还不足以看出来。(这里没有再往上调并发数,理论上应该调大也能复现,就是不知道得多大。。。) -
远程数据库复现
换成和java应用不在同一个内网的外网数据库
ab刚启动没一会,java应用就抛出了这个可爱的错误!
nice!
如何解决
既然问题是因为并发数远大于连接池大小导致的,那么有以下几个解决方案:
- 增加连接池大小
简单暴力,如果你可以预见并发数的上限的话 - 数据库和api部署在同一个内网
加快单个请求的响应速度,较少线程等待时间
其实个人以为这个问题基本无解,要是并发数无限提高的话还是一样会出问题。
这个问题就和偶尔网络抽风一样,概率挺小的,感觉可以不用管~
后话
该错误的本质原因其实就是线程去borrow
连接超时抛出的,超时的原因说白了就是超时时间内一直拿不到可用连接,因此可以从这方面下手去排查。