kl个人博客 首页>>异常排查记录>>记阿里Druid数据连接池引发的线上血案

记阿里Druid数据连接池引发的线上血案

记阿里Druid数据连接池引发的线上血案

前言碎语

事件起因:项目使用了activiti工作流,系统是由老的spring mvc项目改造成的spring boot项目,数据库链接池从dbcp切换到druid,新系统上线后,同事多次系统隔一段时间后数据查询就很慢,基本出不来。由此开始了线上bug排查之路。这个问题从一开始就模糊定位到数据库层面的问题,因为只有和数据相关的操作会很慢,其他服务不受影响,并且在中午休息时没有问题,在下午刚上班后不就出现。

过程一:定位工作流

首先第一反应是看日志:日志一切正常,并没有任何异常信息抛出,然后将日志级别调整到debug,发现了一些问题,中午休息时,用户没有操作的情况下,日志一直在输出jpa的连接信息,最后定位是工作流的异步执行器在轮询,因为在spring boot环境下spring.activiti.async-executor-activate=true默认是true的,如果不需要使用可以设置为false,改完后情况依旧

过程二:定位JPA的OpenEntityManagerInViewInterceptor

使用OpenEntityManagerInViewInterceptor后服务端在接收到一个请求的时候开启EntityManager,在请求结束的时候才去关闭这个EntityManager,所以在用户数多,并发高,操作耗时的情况下会造成数据连接不够用的情况,而我们的业务有这个特征。在spring boot环境中,OpenEntityManagerInViewInterceptor默认是开启的,然而我们使用spring.jpa.open-in-view=false关闭后,问题依旧,不过比之前的间隔时间久一点了

过程三:定位Druid,真正的罪魁祸首

使用top定位到程序pid,然后使用jstack -l 2591 >>dump.out 拿到当前堆栈快照后发现如下

"http-nio-8080-exec-54" daemon prio=10 tid=0x0000000000e61000 nid=0xcc9 waiting on condition [0x00007f4a753d4000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007a143f230> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:1732)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1330)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1198)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4619)
所有的请求都被druid的获取连接操作阻塞了,最后看源码如下

因为数据链接没有释放,连接池中无可用连接,导致请求被阻塞了

到这里基本上就是真相了,最后换成spring boot自带的连接池tomcat jdbc后一切正常


后记:

定位到问题后,发现网上很多人遇到了连接泄露的情况,可见druid的官方issue,如https://github.com/alibaba/druid/issues/1160

不过druid也提供了相应的方案,如下

虽然官方说可能是应用自己导致连接未被释放导致连接泄露,但是为什么切换别家的连接池后就毛事都没有呢,元芳,你怎么看呢?

kl个人博客