踩坑DruidDataSource导致的服务卡死

在我们项目中,Druid提供了一个高效、功能强大、可扩展性好的数据库连接池。我们使用他来替代C3P0作为数据库的连接池;

翻车背景

平台私有化给一个三十人的小团队使用,某天有人反馈平台无响应,接口全部超时无响应;

排查过程
  1. 连上服务器,发现服务状态都健康,内存CPU等都很稳定;

  2. jstack查看线程状态,发现所有容器工作线程都是wait状态,如下:

    "XNIO-1 task-5" #178 prio=5 os_prio=0 tid=0x000000002a03e000 nid=0x350c waiting on condition [0x000000004013a000]
       java.lang.Thread.State: WAITING (parking)
            at sun.misc.Unsafe.park(Native Method)
            - parking to wait for  <0x00000006c4f36dd0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
            at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
            at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
            at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:2029)
            at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1557)
            at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1337)
            at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1317)
            at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1307)
            at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:109)
            at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158)
            at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116)
            at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79)
            at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:82)
            at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:68)
    
    

    可以看见所有线程都卡在了DruidDataSource.takeLast方法的2029行,我们查看源码找到这行代码:

        // maxWait是 获取连接等待超时时间 默认是-1,即不超时,此时会走到takeLast方法
    	if (maxWait > 0) {
            holder = pollLast(nanos);
        } else {
            holder = takeLast();
        }
    
    	DruidConnectionHolder takeLast() throws InterruptedException, SQLException {
            try {
                while (poolingCount == 0) {
                    emptySignal(); // send signal to CreateThread create connection
    
                    if (failFast && isFailContinuous()) {
                        throw new DataSourceNotAvailableException(createError);
                    }
    
                    notEmptyWaitThreadCount++;
                    if (notEmptyWaitThreadCount > notEmptyWaitThreadPeak) {
                        notEmptyWaitThreadPeak = notEmptyWaitThreadCount;
                    }
                    try {
                        // 因为数据库的连接都没有释放且被占用,连接池中无可用连接,导致请求被阻塞了
                        notEmpty.await(); // signal by recycle or creator
                    } finally {
                        notEmptyWaitThreadCount--;
                    }
                    notEmptyWaitCount++;
    
                    if (!enable) {
                        connectErrorCountUpdater.incrementAndGet(this);
                        throw new DataSourceDisableException();
                    }
                }
            } catch (InterruptedException ie) {
                notEmpty.signal(); // propagate to non-interrupted thread
                notEmptySignalCount++;
                throw ie;
            }
    
            decrementPoolingCount();
            DruidConnectionHolder last = connections[poolingCount];
            connections[poolingCount] = null;
    
            return last;
        }
    

找到问题所在后,我们找到服务排查为什么会出现这样的情景,发现服务里使用了多数据源,这就导致了必须自己创建DataSource,继续查看创建DataSource的地方

    @Bean("masterDataSource")
    @Primary
    @ConfigurationProperties(prefix = "spring.datasource.master")
    public DataSource masterDataSource() {
        return DataSourceBuilder.create().type(com.alibaba.druid.pool.DruidDataSource.class).build();
    }

这里创建的时候直接使用了DruidDataSource的默认配置,没有手动修改任何配置,而在DruidDataSource中maxwait默认值为-1:

    public final static int                            DEFAULT_MAX_WAIT                          = -1;
    protected volatile int                             maxActive                                 = DEFAULT_MAX_ACTIVE_SIZE;8个

这就会导致代码分叉到takeLast上,然后刚好如果所有线程都被使用且没有正常释放,那么就会导致一直await卡死;

场景复现

那么问题的发生场景就很明了了,需要两个条件,

  • maxWait使用默认值-1,即不会超时

  • poolingCount == 0,即线程池可用数量为0

    其余参数均使用默认值;

我们尝试使用Jmeter来复现问题;

Jmeter设置100个并发,在300秒内启动,观察服务;发现在并发13个左右(多次)线程就会导致服务卡死,此时Jstack查看线程发现所有线程均在wait;

因为maxActive默认值为8,所以超过8个后,一旦数据库连接不及时释放,则会导致poolingCount ==0,此时刚好maxWait为-1,则进入takeLast复现此问题

尝试解决

在网上搜索‘ druid的takeLast导致卡死’,可以看到很多人遇到了同样的问题;而且在官方的issue也可以查到相关的提交;如下:

https://github.com/alibaba/druid/issues/2376

https://github.com/alibaba/druid/issues/1160

可以看到里面的回复大多是贴上一两个配置,其实这样都是不可解决问题的;知其然知其所以然,我们必须弄明白问题的本事在哪里,才可以解决问题;

就此问题本身来说,看着代码思考,那么我设置下这个参数使得参数不为默认值(-1),让他避免这个问题不就可以了吗?

dataSource.setMaxWait(100);

我们设置超时时间(毫秒)为100,此时我们通过压测再来验证一下这个问题,结果发现继续报错,错误为获取不到连接;

因为连接默认只有8个,设置超时时间后,因为连接不能及时的释放,所以有可能拿不到连接;

### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 101, active 8, maxActive 8, creating 0
	at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:150)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
	at sun.reflect.GeneratedMethodAccessor268.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
	... 104 common frames omitted
Caused by: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 101, active 8, maxActive 8, creating 0

所以,我们还需要配置一下连接数来保证可用,以下为druid的配置说明,可以酌情使用:

属性 说明 建议值
url 数据库的jdbc连接地址。一般为连接oracle/mysql。示例如下:
mysql : jdbc:mysql://ip:port/dbname?option1&option2&…
oracle : jdbc:oracle:thin:@ip:port:oracle_sid
username 登录数据库的用户名
password 登录数据库的用户密码
initialSize 启动程序时,在连接池中初始化多少个连接 10-50已足够
maxActive 连接池中最多支持多少个活动会话
maxWait 程序向连接池中请求连接时,超过maxWait的值后,认为本次请求失败,即连接池 100
没有可用连接,单位毫秒,设置-1时表示无限等待
minEvictableIdleTimeMillis 池中某个连接的空闲时长达到 N 毫秒后, 连接池在下次检查空闲连接时,将回收该连接,要小于防火墙超时设置 见说明部分
net.netfilter.nf_conntrack_tcp_timeout_established的设置
timeBetweenEvictionRunsMillis 检查空闲连接的频率,单位毫秒, 非正整数时表示不进行检查
keepAlive 程序没有close连接且空闲时长超过 minEvictableIdleTimeMillis,则会执 true
行validationQuery指定的SQL,以保证该程序连接不会池kill掉,其范围不超过minIdle指定的连接个数
minIdle 回收空闲连接时,将保证至少有minIdle个连接. 与initialSize相同
removeAbandoned 要求程序从池中get到连接后, N 秒后必须close,否则druid 会强制回收该连接,不管该连接中是活动还是空闲, 以防止进程不会进行close而霸占连接。 false,当发现程序有未正常close连接时设置为true
removeAbandonedTimeout 设置druid 强制回收连接的时限,当程序从池中get到连接开始算起,超过此 应大于业务运行最长时间
值后,druid将强制回收该连接,单位秒。
logAbandoned 当druid强制回收连接后,是否将stack trace 记录到日志中 true
testWhileIdle 当程序请求连接,池在分配连接时,是否先检查该连接是否有效。(高效) true
validationQuery 检查池中的连接是否仍可用的 SQL 语句,drui会连接到数据库执行该SQL, 如果
正常返回,则表示连接可用,否则表示连接不可用
testOnBorrow 程序 申请 连接时,进行连接有效性检查(低效,影响性能) false
testOnReturn 程序 返还 连接时,进行连接有效性检查(低效,影响性能) false
poolPreparedStatements 缓存通过以下两个方法发起的SQL: true
public PreparedStatement prepareStatement(String sql)
public PreparedStatement prepareStatement(String sql,
int resultSetType, int resultSetConcurrency)
maxPoolPrepareStatementPerConnectionSize 每个连接最多缓存多少个SQL 20
filters 这里配置的是插件,常用的插件有: stat,wall,slf4j
监控统计: filter:stat
日志监控: filter:log4j 或者 slf4j
防御SQL注入: filter:wall
connectProperties 连接属性。比如设置一些连接池统计方面的配置。
druid.stat.mergeSql=true;druid.stat.slowSqlMillis=5000
比如设置一些数据库连接属性

了解了每个配置的作用,那么我们只需要合理的进行配置即可解决这个问题。以下为经过压测验证后的我们服务的配置,供参考:

// 初始连接数
dataSource.setInitialSize(10);
// 最小连接池数量
dataSource.setMinIdle(10);
// 最大连接池数量
dataSource.setMaxActive(100);
// 配置获取连接等待超时时间  毫秒
dataSource.setMaxWait(100);
//缓存通过以下两个方法发起的SQL:
dataSource.setPoolPreparedStatements(true);
//每个连接最多缓存多少个SQL
dataSource.setMaxPoolPreparedStatementPerConnectionSize(50);
//检查空闲连接的频率,单位毫秒, 非正整数时表示不进行检查
dataSource.setTimeBetweenEvictionRunsMillis(-1);
//池中某个连接的空闲时长达到 N 毫秒后, 连接池在下次检查空闲连接时,将回收该连接,要小于防火墙超时设置
dataSource.setMinEvictableIdleTimeMillis(300000);
//当程序请求连接,池在分配连接时,是否先检查该连接是否有效。(高效)
dataSource.setTestWhileIdle(true);
// 程序 申请 连接时,进行连接有效性检查(低效,影响性能)
dataSource.setTestOnBorrow(false);
//程序 返还 连接时,进行连接有效性检查(低效,影响性能)
dataSource.setTestOnReturn(false);
// 要求程序从池中get到连接后, N 秒后必须close,否则druid 会强制回收该连接,不管该连接中是活动还是空闲, 以防止进程不会进行close而霸占连接。
dataSource.setRemoveAbandoned(true);
// 设置druid 强制回收连接的时限,当程序从池中get到连接开始算起,超过此值后,druid将强制回收该连接,单位秒。
// 结合业务来看,存在jpa极大事务;不好设置 暂时为设置两分钟
dataSource.setRemoveAbandonedTimeout(120);
//当druid强制回收连接后,是否将stack trace 记录到日志中
dataSource.setLogAbandoned(true);

题外话:

对于此类问题,官方给的回复是我们没有正确的关闭连接,导致连接泄漏;

这样通过配置的方法虽然解决了问题,但是为什么其他连接池就没有此类问题;也不需要人为的来通过配置避免此'BUG'呢?不得而知

posted @ 2021-05-19 20:50  faylinn  阅读(14474)  评论(4编辑  收藏  举报
、、、