记一次获取连接超时的排查过程Connection is not

2020-04-15  本文已影响0人  不着方寸

背景

之前在压测一个用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%'

image.png

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到,那么就会抛错了

这个时候真相呼之欲出了,什么情况会造成获取连接池连接超时?

本例排除了前两种可能,因此猜测是第三种原因。 并发数远大于连接池大小,导致有可能出现某些线程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

  1. 本地数据库复现
    无法复现????!!!!
    10个连接,500个并发都能完美处理过来!!!
    怀疑是因为本地通信太快了,500个并发可能还不足以看出来。(这里没有再往上调并发数,理论上应该调大也能复现,就是不知道得多大。。。)

  2. 远程数据库复现
    换成和java应用不在同一个内网的外网数据库
    ab刚启动没一会,java应用就抛出了这个可爱的错误!
    nice!

如何解决

既然问题是因为并发数远大于连接池大小导致的,那么有以下几个解决方案:

其实个人以为这个问题基本无解,要是并发数无限提高的话还是一样会出问题。

这个问题就和偶尔网络抽风一样,概率挺小的,感觉可以不用管~

后话

该错误的本质原因其实就是线程去borrow连接超时抛出的,超时的原因说白了就是超时时间内一直拿不到可用连接,因此可以从这方面下手去排查。

上一篇下一篇

猜你喜欢

热点阅读