记一次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可能报的错一样,但是解决办法可能就未必了,别人的问题未必是你的问题,盲目从别人的方案里面找自己的办法不可取。

  • 29
    点赞
  • 43
    收藏
    觉得还不错? 一键收藏
  • 打赏
    打赏
  • 7
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论 7
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包

打赏作者

盡盡

你的鼓励将是我创作的最大动力

¥1 ¥2 ¥4 ¥6 ¥10 ¥20
扫码支付:¥1
获取中
扫码支付

您的余额不足,请更换扫码支付或充值

打赏作者

实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值