druid连接池因数据库故障导致主线程挂起停止响应的优化

最新推荐文章于 2024-01-16 23:02:53 发布

forgetmetoo

最新推荐文章于 2024-01-16 23:02:53 发布

阅读量4.7k

点赞数 3

分类专栏：性能调优问题排查文章标签：数据库 java nginx mysql

本文链接：https://blog.csdn.net/forgetmetoo/article/details/115010296

版权

问题排查同时被 2 个专栏收录

8 篇文章 0 订阅

订阅专栏

性能调优

2 篇文章 0 订阅

订阅专栏

快速翻看

一、问题背景
二、问题排查
三、问题原因
四、问题解决
五、总结

一、问题背景

某天晚上，突然收到运维同事反馈说系统告警，A系统调用B系统出现大量超时，通过日志分析，B系统中出现了大量的mysql连接报错信息，但是却没有收到任何http请求，怀疑是线程阻塞，运维人员进行了线上的重启操作，系统恢复，开始了问题的追溯。

二、问题排查

查看日志中的数据库报错，首先确定问题的源头是出在数据库上面，相关报错日志如下（已屏蔽敏感信息）：

2021-03-09 20:57:29,058 ERROR [] com.alibaba.druid.pool.DruidDataSource.run:2471 [Druid-ConnectionPool-Create-1453384899] [B系统] - create connection SQLException, url: jdbc:mysql://xx.xx.xx.xx:xxxx/b?useUnicode=yes&characterEncoding=UTF8&useSSL=false&serverTimezone=Asia/Shanghai, errorCode 0, state 08S01
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
	at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:172)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:862)
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:444)
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:230)
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:226)
	at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:156)
	at com.alibaba.druid.filter.stat.StatFilter.connection_connect(StatFilter.java:218)
	at com.alibaba.druid.filter.FilterChainImpl.connection_connect(FilterChainImpl.java:150)
	at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1560)
	at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1623)
	at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2468)
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
	at sun.reflect.GeneratedConstructorAccessor250.newInstance(Unknown Source)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:59)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:103)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:149)
	at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:165)
	at com.mysql.cj.protocol.a.NativeSocketConnection.connect(NativeSocketConnection.java:92)
	at com.mysql.cj.NativeSession.connect(NativeSession.java:152)
	at com.mysql.cj.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:982)
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:852)
	... 9 common frames omitted
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
	at java.net.Socket.connect(Socket.java:589)
	at com.mysql.cj.protocol.StandardSocketFactory.connect(StandardSocketFactory.java:173)
	at com.mysql.cj.protocol.a.NativeSocketConnection.connect(NativeSocketConnection.java:66)
	... 12 common frames omitted

数据库查询是通过mybatis实现，而数据库连接使用的是druid，默认开启10个连接，最大连接数为50，该系统连接了3个数据源，出问题的是其中的一个，按理来说，应该不至于导致整个系统不可用。
日志中没有任何的请求信息，而且由于系统已经进行了重启，且环境部署在kubernets容器环境，无法获取到现场的一些线程栈信息了，这给问题排查增加了一定的难度。
不过我们还有一个排查利器：链路监控pinpoint。于是进一步查看pinpoint，看看在出故障的时间段是不是有资源异常，首先是发现了一个有意思的现象，在请求的热力分布图上，该系统存在一段空白的区域：
在这里插入图片描述
这意味着什么？
开发的同学很自然的就会说，你看，这段时间我的系统都没有收到请求，一定是请求方问题，要么是系统A的问题，没有将数据发出来，要么是网络问题导致数据丢失。
然而，事情的真相真是这样吗？
带着这样的疑问，我进一步排查系统的各项指标：堆内存正常、堆外内存正常、CPU正常、事务正常、响应时间正常、活跃线程……
等等，活跃线程怎么出现了一大片黄色区域，仔细查看活跃线程，发现从某个时间点开始呈现陡峭的上升趋势，一直到200的时候变成了一条横线，说明此时线程池已经撑爆，和运维确认了故障时间段，与图形吻合。
在这里插入图片描述
由于系统使用的springboot+内嵌tomcat的框架，在springboot的源码中：org.springframework.boot.autoconfigure.web包下的ServerProperties中默认主线程的上限就是200，如下：

/**
 * Maximum amount of worker threads.
 */
private int maxThreads = 200;

到此时，已经基本确定问题就出在服务端系统，也就是B系统，虽然从日志和热力图的现象都表明B系统没有收到任何请求，但是从线程池的表现来看，这是进入了排队等待的状态，当活跃线程数量达到上限时，系统就停止响应了。

三、问题原因

虽然问题已经查到，是B系统由于线程池占满导致系统停止响应，但是问题的根源到底在哪里呢，我们需要进一步的排查得到深层次的结论。
我们需要得到一些线程栈信息的现场信息才能进一步确定线程到底是阻塞在什么地方，主线程阻塞，一定是在等待什么条件，我们需要获取这个重要的信息，于是想到通过在测试环境模拟故障的方式进行验证
我使用的方式是：本机启动一个nginx，nginx通过配置tcp的4层转发将数据转发到数据库地址，当nginx启动时，则为数据库正常，相反nginx停止时则说明数据库故障。
先简单试验了一下说明该方法有效，将系统的jdbc连接串修改为本地nginx监听的地址和端口，添加tcp代理转发到远程，具体的nginx配置如下（nginx.conf的http后面添加内容）：

stream {
    server {	
        listen 6100;	#此处为本地监听端口
		#echo_sleep 20;
        proxy_pass xx.xx.xx.xx:xxxx;	#此处为实际连接的数据库ip和端口

    # 也支持socket
    # proxy_pass unix:/var/lib/mysql/mysql.socket;
    }
}

然后使用jemeter模拟客户端向系统不停的发送请求，jemeter中的线程数量不需要设置太大，20以内足够。
刚开始的时候数据库连接正常，启动系统正常，本地我是通过jconsole连接系统进程来实现线程监测，线程数量保持在比较低的水平，日志中能够显示正常的请求日志、响应日志。
然后将数据库连接断开（关闭本地nginx），则开始出现线程堆积，系统响应缓慢，当活跃线程数量达到上限时，系统停止响应，日志中只有不停刷新的数据库连接失败，没有输出任何的请求日志。
通过jstack将线程栈输出到文件中，发现了关键的信息。
通过堆栈信息可以发现，当执行到数据库查询时，通过mybatis的selectOne方法会最终调用druid的getConnection方法，该方法就是从连接池中获取可用连接，此时主线程一直在等待（await），说明连接池中已经没有可用的连接了，于是发生了线程阻塞：

"http-nio-8080-exec-56" #22665 daemon prio=5 os_prio=0 tid=0x00007f2f34017000 nid=0x586a waiting on condition [0x00007f2f2a7ec000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000074a5d0648> (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:1899)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1460)
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1255)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5007)
	at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:680)
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5003)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1233)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1225)
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90)
	at org.springframework.jdbc.datasource.lookup.AbstractRoutingDataSource.getConnection(AbstractRoutingDataSource.java:169)
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:151)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115)
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78)
	at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:82)
	at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:68)
	at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:338)
	at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:84)
	at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62)
	at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:326)
	at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
	at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:108)
	at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
	at com.sun.proxy.$Proxy245.query(Unknown Source)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
	at sun.reflect.GeneratedMethodAccessor232.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)
	at com.sun.proxy.$Proxy159.selectOne(Unknown Source)
	at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:166)

我们很自然的想到为什么此处不会超时呢，作为老牌开源数据库连接池框架druid，不应该会有如此的问题啊，带着这样的疑问，我也搜索了一些资料，但是都没有得到很好的答案，不过倒是受到社区里面的一些启发。
通过堆栈信息再对照查看druid的源码，我们很容易发现getConnection有一个重要的参数maxWait，此参数的默认值为-1：

public final static int                            DEFAULT_MAX_WAIT                          = -1;

进一步分析代码，发现当maxWait为初始值是会执行takeLast方法，该方法会调用线程的await方法获取可用连接，而数据库可用连接为0则会导致该操作一直lock住，从而使得线程挂起。

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 && failContinuous.get()) {
                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;
}

看到此处，是不是已经豁然开朗，那么我们解决问题的思路也就有了。

四、问题解决

只要问题分析清楚了，解决问题有时候其实是一件很容易的事情，通过上面的分析我们得知，druid在获取不到可用连接时，会有一个超时时间，这个超时时间就是maxWait，也就是说，只需要将maxWait设置为一个值，那么我们就可以在数据库出现故障时，快速的失败返回，由于使用的springboot的starter方式引入，我们可以直接在springboot的yml配置（笔者所在公司使用的携程apollo配置中心，且统一框架内嵌druid默认配置）中添加如下参数即可：

spring.datasource.druid.maxWait = 7500

注意：该超时时间单位为毫秒，并且druid第一次获取连接超时后，会默认进行一次重试，对外表现的超时时间是maxWait*2,，如笔者的配置总体超时时间则为15秒。
需要根据具体的业务场景来进行设置，最好不要超系统间调用超时时间，否则没有意义。
加上了该参数后，通过进一步的测试验证，发现在数据库断开连接的情况下也不会导致主线程阻塞，问题解决。

五、总结

1、数据库故障导致druid连接池中没有可用的连接；
2、没有设置maxWait参数导致druid使用默认参数-1，无可用连接时无限等待；
3、tomcat主线程同步调用mybatis的数据库查询语句（其他语句也一样），通过druid获取可用连接，陷入等待，导致主线程阻塞；
4、主线程达到线程池最大上限，系统停止响应；
5、调优druid连接池参数，增加maxWait，问题圆满解决。

感谢社区的文章提供的一些思路：
1、线程卡死在druiddatasource上#1160
https://github.com/alibaba/druid/issues/1160
2、数据库连接池Druid配置调优：
https://blog.csdn.net/java821643/article/details/103778537