一次druid连接池获取连接错误的排查分析

admin • • 未归属

问题描述

之前的上一篇文章 keepAlive解决druid空闲连接socket timeout 15分钟解决了防火墙导致的空闲连接socket timeout的问题，而这一次在另外一个没有防火墙策略的内部环境却又出现了另外一个情况，进程偶发数据库操作报错，并且个别进程一段时间后始终无法获取数据库连接一直处于宕机状态。

问题分析

通过对错误日志分析，发现前期数据库报错的日志四个进程出现的时间点基本一致，因此怀疑是外部因素网络或者数据库导致。部分进程维持着偶发报错的情况下工作，而有的进程则在一段时间后彻底无法工作，一直出现无法创建数据库连接。于是首先对无法工作的进程分析排查。
首先，查看进程与数据库连接状态，发现存在ESTABLISHED状态连接

1
2
3
4
 
netstat -anp|grep 1521
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)            
tcp6       0      0 172.16.72.25:18704      172.16.71.13:1521       ESTABLISHED 9229/java

而错误日志显示

1
2
3
4
5
6
 
org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException: 
 Error querying database.  Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 20, creating 1 
 .......
 Caused by: java.sql.SQLRecoverableException: IO Error: Connection reset
        at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:498)
        at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:553)

可以看到当前数据库连接池中没有可用连接，druid在创建新连接的时候出现异常。
查看druid创建连接相关源码

1
2
3
4
5
 
if (maxWait > 0) {
    holder = pollLast(nanos); 
} else {
    holder = takeLast();
}
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
 
private DruidConnectionHolder pollLast(long nanos) throws InterruptedException, SQLException {
    long estimate = nanos;
    for (;;) {
        if (poolingCount == 0) {
            emptySignal(); // send signal to CreateThread create connection

            if (failFast && failContinuous.get()) {
                throw new DataSourceNotAvailableException(createError);
            }
            ......
            try {
                long startEstimate = estimate;
                estimate = notEmpty.awaitNanos(estimate); // signal by
                                                          // recycle or
                                                          // creator
              ......  
               return last;
        }
    }

可以知道druid的连接获取是通过notEmpty和empty两个变量协调线程的同步，执行pollLast方法发现没可用连接时，就会notEmpty.awaitNanos(),同时empty.signal()去唤醒CreateConnectionThread这个线程去创建连接。

因此，查看当前进程的堆栈信息，找到CreateConnectionThread线程。
发现如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
 
"Druid-ConnectionPool-Create-523528914" #83 daemon prio=5 os_prio=0 tid=0x00007f6d1d8d4800 nid=0x26fb runnable [0x00007f6db3ffd000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:170)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
   ......
        at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
        at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
        at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
    ....
        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)

而当前工作线程

1
2
3
4
5
6
7
8
9
 
"http-nio-8212-exec-7" #72 daemon prio=5 os_prio=0 tid=0x00007f6d46caa800 nid=0x26ea waiting on condition [0x00007f6db90ea000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000006c23e65c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at com.alibaba.druid.pool.DruidDataSource.pollLast(DruidDataSource.java:1946)
        at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1458)
        at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1255)

可以看到，工作线程执行pollLast方法去唤醒Druid-ConnectionPool-Create线程，Druid-ConnectionPool-Create线程开始尝试连接数据库，但是线程一直出现了 socketRead0阻塞，导致无法创建连接，因此工作线程会一直waiting直到获取连接超时报错。而 Druid-ConnectionPool-Create线程通过jdbc连接数据库是使用Socket通信的，Socket没有办法探测到网络错误，因此应用也无法主动发现连接错误，它的超时是由Socket Timeout控制的，如果没有设置Socket Timeout在没有返回的情况下会一直等待下去,所以当数据库或者网络突然出现故障，就可能会发生socket阻塞，而如果没有socket timeout设置，那么阻塞将一直持续下去。这样始终无法创建连接，所以进程不可用。（一般来说Linux服务器会有系统级别的socket timeout，由于没有权限查看不了，从上面信息推测设置的可能较长）

那么为什么有的进程只是偶发故障，而后恢复呢？通过日志查看，发现这种情况的情况在报错的时候，连接池当前还存在着一个连接，即使连接池创建新的连接报错，但是并不会影响该连接，所以网络恢复后，该连接仍然可用，只是无法再创建新的连接而已，所以进程体现在偶发报错，但是仍然可用。而当这个连接空闲很长时间或者因为其他原因死亡后，那么连接池将再无连接可用，也无法创建新的连接，进程变成了不可用状态。
以上就是基于日志分析、进程堆栈和连接信息排查做出的推测。

问题解决

基于上面推测，问题主要出现在socket阻塞，因此解决方案就是尽量避免socket阻塞过长时间，导致长时间不可用。

临时应急操作

如果发生阻塞，只需要重启进程即可临时解决问题，如果不想要进程重启，那么我们可以通过杀掉阻塞的socket来重连数据库。

首先通过lsof 命令找到进程的所有文件描述符，并且找到阻塞的socket的连接，然后gdb连接进程，call close掉这个socket连接，这样Druid-ConnectionPool-Create线程可以再重新创建连接。

设置jdbc级别的timeout防止长时间阻塞

长久的解决思路肯定是设置一个合适的socket timeout来避免socket阻塞，一般会有系统环境相关设置，为了预防系统socket timeout过长或者没有设置，还是有必要设置一个jdbc级别的timeout。

上一篇文章中是通过开启keepAlive来解决问题的，其中我也提到不建议通过修改 socket timeout 去解决。而这次的这个问题就必须要通过设置一个合理的 socket timeout 参数来保证当出现异常网路情况下服务不会宕机太久，但是这个时间又不能过小，否则会导致一些耗时较长的数据库操作被超时终止，配置参考如下。

oracle：

1
 
connectionProperties: oracle.net.CONNECT_TIMEOUT=60000;oracle.jdbc.ReadTimeout=300000

mysql：

1
 
url: jdbc:mysql://ip:port/db?connectTimeout=60000&socketTimeout=300000

版权声明：
作者：admin
链接：https://www.techfm.club/p/178.html
来源：TechFM
文章版权归作者所有，未经允许请勿转载。

THE END
分享
二维码
< <上一篇
下一篇>>