记一次HikariPool-1 - Connection is not available, request timed out after 60000ms异常排查过程

前言

     前几天把spring boot从1.5升级到2.X之后，项目出了一堆问题，然后调了几天bug。最后好不容易能正常打包运行了，周五晚上在家里又收到信息，服务器挂了！！！好吧，看下日志：

org.springframework.dao.DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
	at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:236) ~[spring-orm-5.0.12.RELEASE.jar!/:5.0.12.RELEASE]
	at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:223) ~[spring-orm-5.0.12.RELEASE.jar!/:5.0.12.RELEASE]
	......
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_232]
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
	at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48) ~[hibernate-core-5.2.17.Final.jar!/:5.2.17.Final]
	......
	at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139) ~[spring-tx-5.0.12.RELEASE.jar!/:5.0.12.RELEASE]
	... 133 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 60000ms.
	......
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:669) ~[HikariCP-2.7.9.jar!/:na]
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183) ~[HikariCP-2.7.9.jar!/:na]

一堆这个东西，什么意思不用说了吧，数据库连接超时。但是不知道为什么会出现这个问题，然后网上找找看，一堆让你改参数的，虽然感觉没用，但是死马当做活马医，反正没思路

spring:
  datasource:
    hikari:
      connection-timeout: 60000
      minimum-idle: 5
      maximum-pool-size: 10
      idle-timeout: 300000
      max-lifetime: 1200000
      auto-commit: true
      connection-test-query: SELECT 1
      validation-timeout: 3000
      read-only: false
      login-timeout: 5

放上去看看有没有效果吧，当然了，当时看不出来什么效果，第二天再看吧，结果不出意外，还是报这个错，然后网上再查好像还是只能找到让你改上面这些参数的，调大点啊，小点啊什么的，好吧，不搜了，自己看。

分析

     既然是获取不到连接，无非就是数据库自身的问题，网络问题，连接池关闭，或者连接池满了（连接没释放）。这里先排除数据库和网络等问题，其实我一直猜是哪里使用的连接没有释放导致的问题，但是没法定位。先来看下数据库连接状态

没看出来什么问题，接着来吧。

     上面已经说了，最近刚把spring boot升级到2.X，问题也是升级后才出现的，那么版本升级后变过哪些东西呢？数据库连接池，也就是hikari，spring boot 2默认采用了hikari连接池，这个和之前不一样，那会不会是连接池的问题呢？hikari好像是号称最快的连接池，本来是不想换的，这里没办法，换吧，这里又换成了之前的druid

<dependency>
     <groupId>com.alibaba</groupId>
     <artifactId>druid-spring-boot-starter</artifactId>
     <version>1.1.10</version>
</dependency>

配置改一改

spring:
  datasource:
    type: com.alibaba.druid.pool.DruidDataSource
    druid:
      initial-size: 1
      min-idle: 5
      max-active: 10
      max-wait: 60000
      test-while-idle: true
      time-between-eviction-runs-millis: 60000
      min-evictable-idle-time-millis: 30000
      validation-query: SELECT 'x'
      test-on-borrow: false
      test-on-return: false
      pool-prepared-statements: true
      max-pool-prepared-statement-per-connection-size: 20

然后呢？放上去继续等吧，等错，该干嘛干嘛去。果然还是报错了，意料之中，错误和上面差不多，连接超时。

     现在只能从自身找问题了，那到底是谁占着连接不放呢？druid配置中有如下几个参数

# 连接在多少秒后应该考虑弃用
spring.datasource.druid.remove-abandoned-timeout-millis: 180
# 被弃用的连接在到达弃用超时后是否应该被移除
spring.datasource.druid.remove-abandoned: true
# 程序在回收连接的同时会打印日志
spring.datasource.druid.log-abandoned: true

注意：removeAbandoned是连接池的高级功能，理论上这中配置不应该出现在实际的生产环境，因为有时应用程序执行长事务，可能这种情况下，会被连接池误回收。我这里主要是为了定位连接泄漏的具体代码位置，生产环境中连接的关闭应该靠程序自己保证。

     加上上面参数后，再来看看错误日志：

2019-12-07 18:59:19.269 ERROR 4189 --- [troy-1832973792] com.alibaba.druid.pool.DruidDataSource   : abandon connection, owner thread: http-nio-8999-exec-8, connected at : 1575716348048, open stackTrace
	at java.lang.Thread.getStackTrace(Thread.java:1559)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1313)

	at com.sun.proxy.$Proxy168.findAll(Unknown Source)
	at com.mq.portal.service.impl.ArticleServiceImpl.findBriefShow(ArticleServiceImpl.java:198)
	at com.mq.portal.service.impl.ArticleServiceImpl$$FastClassBySpringCGLIB$$5901d7ef.invoke(<generated>)

	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
ownerThread current state is WAITING, current stackTrace

	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
	at com.mq.portal.stats.StatsQueue.put(StatsQueue.java:22)
	at com.mq.portal.interceptor.StatsInterceptor.postHandle(StatsInterceptor.java:47)

	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

2019-12-07 18:59:19.271 ERROR 4189 --- [troy-1832973792] com.alibaba.druid.pool.DruidDataSource   : abandon connection, owner thread: http-nio-8999-exec-11, connected at : 1575716357218, open stackTrace
	at java.lang.Thread.getStackTrace(Thread.java:1559)

	at com.sun.proxy.$Proxy161.findByDescription(Unknown Source)
	at com.mq.portal.service.impl.DictionaryServiceImpl.portalList(DictionaryServiceImpl.java:76)
	at com.mq.portal.service.impl.DictionaryServiceImpl$$FastClassBySpringCGLIB$$fb3b5daf.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)

	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
ownerThread current state is RUNNABLE, current stackTrace
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

	at com.mq.portal.stats.StatsQueue.put(StatsQueue.java:22)
	at com.mq.portal.interceptor.StatsInterceptor.postHandle(StatsInterceptor.java:47)

看ownerThread current state is WAITING, current stackTrace后面的，出现了我的东西（StatsQueue.put），这是一个内存队列，大致意思是上面的操作放弃了连接，原因是线程都在队列的put操作上等待（估计是整个服务器线程都用来在这卡着了，数据库连接池线程应该也没法用了）。

     终于找到病根了，既然是队列put一直在等待，那么肯定是take有问题了，看消费线程

public class StatsProcessorThread implements Runnable {
    @Override
    public void run() {
        StatsQueue queue = StatsQueue.getInstance();

        RedisUtil redisUtil = (RedisUtil) SpringContextUtil
                .getApplicationContext().getBean("redisUtil");

        while (true) {
            try {

                StatsModel model = queue.take();
                //......

                }

            } catch (Exception e) {
                e.printStackTrace();
            }
        }
    }
}

既然加了异常处理，那么没道理因为消费异常就导致take不出来啊？？？没走到take这一步来？前面就注入了一下redisUtil，有问题那也就是这一块有问题了，拿spring上下文出错了（为啥日志里面没有呢，不清楚）。最后在项目的初始化部分发现了问题

public class InitListener implements ServletContextListener {


    @Override
    public void contextInitialized(ServletContextEvent sce) {

        //初始化工作线程池和内存队列
        SolrUpdProcessorThreadPool.init();
        new Thread(new StatsProcessorThread()).start();
        new Thread(new TokenThread()).start();

        //获取spring上下文
        ServletContext sc = sce.getServletContext();
        ApplicationContext context = WebApplicationContextUtils.getWebApplicationContext(sc);
        SpringContextUtil.setApplicationContext(context);
    }
}

启动上面那个线程的时候spring 上下文还没获取呢，那么问题来了，谁动我代码了？这个可不是一个新功能啊！然后我到git上翻了一下之前的代码，神奇的发现之前好像也是这样写的。。。或许是指令重排序问题了，至于为什么spring boot升级后这块的指令排序就不一样了，我就不清楚了，总不至于再把项目改到之前版本试试吧。

解决方案

     问题分析出来了，然后怎么解决呢？简单啊，上面代码那块的顺序调整一下就ok了啊

public class InitListener implements ServletContextListener {


    @Override
    public void contextInitialized(ServletContextEvent sce) {

        //操作1：获取spring上下文
        ServletContext sc = sce.getServletContext();
        ApplicationContext context = WebApplicationContextUtils.getWebApplicationContext(sc);
        SpringContextUtil.setApplicationContext(context);

        //操作2：初始化工作线程池和内存队列
        SolrUpdProcessorThreadPool.init();
        new Thread(new StatsProcessorThread()).start();
        new Thread(new TokenThread()).start();

    }
}

这次放上去后，果然好了，至少目前为止还没报错。但是如果真是指令重排序问题，以后可能还会出现这个问题，因为这里其实是没法确定操作1和操作2的执行顺序（根据happens-before规则）。怎么处理这块呢？可以考虑采用volatile，其实也就是考虑volatile的可见性：对一个volatile变量的读，总是能看到（任意线程）对这个volatile变量最后的写入。

     说白了，这里涉及到的也就两个线程，InitListener和StatsProcessorThread，它们共用的变量是SpringContextUtil里面的applicationContext。其中InitListener写，StatsProcessorThread读，这样懂了吧，我们只要applicationContext用volatile修饰一下就可以了。

public class SpringContextUtil {
    private static volatile ApplicationContext applicationContext;

    public static ApplicationContext getApplicationContext() {
        return applicationContext;
    }

    public static void setApplicationContext(ApplicationContext applicationContext) {
        SpringContextUtil.applicationContext = applicationContext;
    }
}

总结

     总结了也没有什么用，大家碰到的问题可能一样，但是原因就不好说了。其实一个bug出现了，你网上搜个10分钟还是解决不了你的问题，基本上就可以放弃搜索了。网上的帖子虽然多，但是吧，

     第一，重复的太多，来来回回没几个不一样的（最近发现一个百度搜索结果里面去csdn的方法，就是“你要搜索的内容 -csdn”，然后搜索结果里面就没有csdn的东西了，可以试试）；

     第二，你的bug和网上的bug可能报的错一样，但是解决办法可能就未必了，别人的问题未必是你的问题，盲目从别人的方案里面找自己的办法不可取。