Apache Druid连接回收引发的血案

news2024/11/24 1:03:49

问题

线上执行大批量定时任务，发现SQL执行失败的报错：

CommunicationsException, druid version 1.1.10, 
jdbcUrl : jdbc:mysql://xxx?useUnicode=true&characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull,
 testWhileIdle true, idle millis 658108, minIdle 2, poolingCount 1,
  timeBetweenEvictionRunsMillis 60000, lastValidIdleMillis 658108, 
  driver com.mysql.jdbc.Driver, exceptionSorter com.alibaba.druid.pool.vendor.MySqlExceptionSorter

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 658,107 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
	at sun.reflect.GeneratedConstructorAccessor60.newInstance(Unknown Source)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
	at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:981)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3465)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3365)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3805)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
	at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
	at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_executeQuery(FilterChainImpl.java:3188)
	at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_executeQuery(FilterEventAdapter.java:465)
	at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_executeQuery(FilterChainImpl.java:3185)
	at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.executeQuery(PreparedStatementProxyImpl.java:181)
	at com.alibaba.druid.pool.DruidPooledPreparedStatement.executeQuery(DruidPooledPreparedStatement.java:228)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
	at org.hibernate.loader.Loader.getResultSet(Loader.java:2304)

追查

从错误日志看来，是连接MySQL超时，但是这个超时时间感觉有点离谱，查看了一下执行的SQL，是非常简单的SQL，理论上不可能造成超时。
联系DBA，看看MySQL的日志能否发现什么蛛丝马迹。

原因

经过DBA排查，确认是MySQL的空闲连接清理参数配置，MySQL的interactive_timeout参数指定了连接空闲多久后会被回收掉，缺省配置为600秒。
在这里插入图片描述

问题初步定位，是因为数据库连接池Druid持有的数据库连接，已经被MySQL回收，此时有SQL执行时，已经被回收掉的连接再此被分配，就会导致这个报错。
那么问题来了，为什么数据库连接池没有感知到这个连接已经被回收了呢？

连接池是怎么判断一条连接是Idle状态的？

带着疑问，翻找Druid文档，发现两个配置：

minEvictableIdleTimeMillis：最小空闲时间，默认30分钟，如果连接池中非运行中的连接数大于minIdle，并且那部分连接的非运行时间大于minEvictableIdleTimeMillis，则连接池会将那部分连接设置成Idle状态并关闭；也就是说如果一条连接30分钟都没有使用到，并且这种连接的数量超过了minIdle，则这些连接就会被关闭了。
maxEvictableIdleTimeMillis：最大空闲时间，默认7小时，如果minIdle设置得比较大，连接池中的空闲连接数一直没有超过minIdle，这时那些空闲连接是不是一直不用关闭？当然不是，如果连接太久没用，数据库也会把它关闭，这时如果连接池不把这条连接关闭，系统就会拿到一条已经被数据库关闭的连接。为了避免这种情况，Druid会判断池中的连接如果非运行时间大于maxEvictableIdleTimeMillis，也会强行把它关闭，而不用判断空闲连接数是否小于minIdle。

原来Druid是根据这两个配置来确认什么时候回收空闲的连接，为了验证是否如此，看一下源码中如何使用这两个配置。

我们使用的Druid版本是1.1.10。

com.alibaba.druid.pool.DruidDataSource

    public class DestroyTask implements Runnable {

        @Override
        public void run() {
            shrink(true, keepAlive);

            if (isRemoveAbandoned()) {
                removeAbandoned();
            }
        }

    }

追踪源码，定位到DruidDataSource，*DestroyTask shrink()*负责释放连接：

public void shrink(boolean checkTime, boolean keepAlive) {
        try {
            lock.lockInterruptibly();
        } catch (InterruptedException e) {
            return;
        }

        int evictCount = 0;
        int keepAliveCount = 0;
        try {
            if (!inited) {
                return;
            }

            final int checkCount = poolingCount - minIdle;
            final long currentTimeMillis = System.currentTimeMillis();
            for (int i = 0; i < poolingCount; ++i) {
                DruidConnectionHolder connection = connections[i];

                if (checkTime) {
                    if (phyTimeoutMillis > 0) {
                        long phyConnectTimeMillis = currentTimeMillis - connection.connectTimeMillis;
                        if (phyConnectTimeMillis > phyTimeoutMillis) {
                            evictConnections[evictCount++] = connection;
                            continue;
                        }
                    }

                    long idleMillis = currentTimeMillis - connection.lastActiveTimeMillis;

                    if (idleMillis < minEvictableIdleTimeMillis) {
                        break;
                    }

                    if (checkTime && i < checkCount) {
                        evictConnections[evictCount++] = connection;
                    } else if (idleMillis > maxEvictableIdleTimeMillis) {
                        evictConnections[evictCount++] = connection;
                    } else if (keepAlive) {
                        keepAliveConnections[keepAliveCount++] = connection;
                    }
                } else {
                    if (i < checkCount) {
                        evictConnections[evictCount++] = connection;
                    } else {
                        break;
                    }
                }
            }
			.........
			
    }

在*shrink()*方法中我们找到了minEvictableIdleTimeMillis和maxEvictableIdleTimeMillis，等等，好像哪里不对？

		if (idleMillis < minEvictableIdleTimeMillis) {
          	break;
         }

         if (checkTime && i < checkCount) {
             evictConnections[evictCount++] = connection;
         } else if (idleMillis > maxEvictableIdleTimeMillis) {
             evictConnections[evictCount++] = connection;
         } else if (keepAlive) {
             keepAliveConnections[keepAliveCount++] = connection;
         }