诡异的druid连接池连接断开故障经验总结

时间  2019-11-05
标签 诡异 druid 连接 断开 故障 经验总结 栏目 Java开源 繁體版
原文   原文链接
  • 背景
  • 症状
  • 排查
  • 修复

背景

最近在陆续作机房升级相关工做，配合DBA对产线数据库连接方式作个调整，将原来直接连接读库的地址切换到统一的读负载均衡的代理 haproxy 上，方便机柜和服务器的搬迁。
切换以后线上时不时的会发生 discard connection 错误，致使程序报 500 错误，但不是每次都必现的。mysql

开发框架: spring boot+mybatis+druid+shardingJDBC
网络架构:
appserver->mysql(master) 写
appserver->haproxy->mysql(slave)/n 读git

第一反应确定是由于此次的读库地址的变更引发的问题，以为问题应该是 druid 连接池中的 connection 保活策略没起做用，只要作下配置修改应该就能够了。结果这个问题让咱们排查了好几天，咱们居然踩到了千年难遇的深坑。github

这个问题排查的很坎坷，一次次的吐血，最终咱们定位到问题而且优雅的修复了，咱们一块儿来体验下这个一次一次让你绝望一次一次打脸的过程。redis

症状

先说故障症状，常常出现以下错误：spring

discard connection
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failuresql

The last packet successfully received from the server was 72,557 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.数据库

根据错误日志初步判断确定是与 db 之间的连接已经断开，尝试使用了一个已经断开的连接才会引发这个错误发生。可是根据咱们对 druid 了解，druid 有连接检查功能，按理不会拿到一个无效连接才对，带着这个线索咱们上路了。后端

排查

为了准确的知道 db 的连接的存活时间，了解到 haproxy 对转发的 db tcp 连接空闲时间在 1m 以内，超过 1m 不活动就会被关掉。也就说咱们与 db 之间的原来的长连接在 1m 以内会被断开。咱们先无论这个时间设置的是否符合全部的大并发场景，至少在 druid 的连接池里会有有效连接检查，应该不会拿到无效连接才对，咱们作了配置调整。服务器

咱们看下 druid 跟连接时间相关的配置：网络

datasource.druid.validationQuery=SELECT 1
datasource.druid.validationQueryTimeout=2000
datasource.druid.testWhileIdle=true
datasource.druid.minEvictableIdleTimeMillis=100000
datasource.druid.timeBetweenEvictionRunsMillis=20000

配置的每项的意思这里就不解释了。
咱们启用了 testWhileIdle 配置，让每次拿取连接的时候发起检查。根据 timeBetweenEvictionRunsMillis 的配置只有大于这个时间 druid 才会发起检查，因此可能的场景是拿到一个即将过时的连接，根据这个线索咱们调整这个时间为 20000ms，也就是超过 20s 会检查当前拿取的连接肯定是否有效，检查的方式应该是使用 validationQuery 配置的 sql 语句才对，可是发现咱们并找不到任何有关于 SELECT 1 的痕迹。

为何你死活找不到 SELECT 1

首先要搞清楚 validationQuery 为何没起做用，带着这个疑问开始 debug druid 源码。

if (isTestWhileIdle()) {
                    final long currentTimeMillis = System.currentTimeMillis();
                    final long lastActiveTimeMillis = poolableConnection.getConnectionHolder().getLastActiveTimeMillis();
                    final long idleMillis = currentTimeMillis - lastActiveTimeMillis;
                    long timeBetweenEvictionRunsMillis = this.getTimeBetweenEvictionRunsMillis();
                    if (timeBetweenEvictionRunsMillis <= 0) {
                        timeBetweenEvictionRunsMillis = DEFAULT_TIME_BETWEEN_EVICTION_RUNS_MILLIS;
                    }

                    if (idleMillis >= timeBetweenEvictionRunsMillis) {
                        boolean validate = testConnectionInternal(poolableConnection.getConnection());
                        if (!validate) {
                            if (LOG.isDebugEnabled()) {
                                LOG.debug("skip not validate connection.");
                            }

                            discardConnection(realConnection);
                            continue;
                        }
                    }
                }
            }

闲置时间确定会有大于 timeBetweenEvictionRunsMillis 时间的，会发起 testConnectionInternal 方法检查。咱们继续跟进去看，

protected boolean testConnectionInternal(DruidConnectionHolder holder, Connection conn) {
   boolean valid = validConnectionChecker.isValidConnection(conn, validationQuery, validationQueryTimeout);

内部会使用 validConnectionChecker 检查对象发起检查。

public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) throws Exception {
        if (conn.isClosed()) {
            return false;
        }

        if (usePingMethod) {
            if (conn instanceof DruidPooledConnection) {
                conn = ((DruidPooledConnection) conn).getConnection();
            }

            if (conn instanceof ConnectionProxy) {
                conn = ((ConnectionProxy) conn).getRawObject();
            }

            if (clazz.isAssignableFrom(conn.getClass())) {
                if (validationQueryTimeout < 0) {
                    validationQueryTimeout = DEFAULT_VALIDATION_QUERY_TIMEOUT;
                }

                try {
                    ping.invoke(conn, true, validationQueryTimeout * 1000);
                } catch (InvocationTargetException e) {
                    Throwable cause = e.getCause();
                    if (cause instanceof SQLException) {
                        throw (SQLException) cause;
                    }
                    throw e;
                }
                return true;
            }
        }

        String query = validateQuery;
        if (validateQuery == null || validateQuery.isEmpty()) {
            query = DEFAULT_VALIDATION_QUERY;
        }

        Statement stmt = null;
        ResultSet rs = null;
        try {
            stmt = conn.createStatement();
            if (validationQueryTimeout > 0) {
                stmt.setQueryTimeout(validationQueryTimeout);
            }
            rs = stmt.executeQuery(query);
            return true;
        } finally {
            JdbcUtils.close(rs);
            JdbcUtils.close(stmt);
        }

    }

debug 这里才发现，druid 默认采用的是 mysql.ping 来作连接有效性检查。

druid 默认采用msyql.ping 协议检查

那是否是用 msyql.ping 协议并不会让 mysql 从新滑动 session 闲置时间，带着这个问题打开 information_schema.processlist 进程列表查看会不会刷新会话时间，经过 debug发现是会刷新时间的，说明没有问题，这条线索算是断了。

haproxy tiemout主动close上下游连接

调整方向，开始怀疑是否是 haproxy 的一些策略致使连接失效，开始初步怀疑 haproxy 的轮训转发后端连接是否是有相关会话保持方式，是否是咱们配置有误致使 haproxy 的连接和 mysql 连接篡位了。

固然这个猜测有点夸张，可是没办法，技术人员就要有怀疑一切的态度。

为了还原产线的网络路线，我在本地搭了一个 haproxy，了解下他的工做原理和配置，图方便我就用了yum顺手装了一个，版本是 HA-Proxy version 1.5.18 不知道是我本地环境问题仍是这个版本的 bug，咱们配置的 mode tcp 活动检查一直不生效。

listen service 127.0.0.1:60020
  mode tcp
  balance roundrobin
  option tcplog
  server server1 192.168.36.66:3306 check inter 2000 rise 2 fall 3
  server server2 192.168.36.66:3306 check inter 2000 rise 2 fall 3

因为 haproxy 活动检查一直不经过，因此没法转发个人连接，搞了半天我只能手动装了一个低版本的 haproxy HA-Proxy version 1.4.14 。
完整的配置：

defaults
        mode tcp               
        retries 3              
        option redispatch      
        option abortonclose    
        maxconn 32000          
        timeout connect 2s 
        timeout client 5m 
        timeout server 5m 


listen test1
        bind 0.0.0.0:60000
        mode tcp
        balance roundrobin
        server s1 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s
        server s2 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s
        server s3 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s

1.4 的版本顺利完成活动检查。
我使用 haproxy 进行debug，调试下来也都没有问题，也翻了下 haproxy 如何转发连接的，内部经过会话的方式保持两个连接的关系，若是是 tcp 长连接应该不会出现什么问题。haproxy 在 http 模式下有会话保持方式，tcp 应该是直接捆绑的方式，一旦到 timeout 时间会主动 close 和 mysql 的连接，并且没有出现篡位的问题。到这里线索又断了。

自定义 ValidConnectionChecker 埋点日志

没有办法，只能试着埋点 druid 的检查日志，排查内部上一次的 check和报错之间的时间差和 connectionId 是否是一致的。

public class MySqlValidConnectionCheckerDebug extends MySqlValidConnectionChecker {

    @Override
    public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) {
        
            Long connId = 0L;
            try {
                Field connField = ConnectionImpl.class.getDeclaredField("connectionId");
                connField.setAccessible(true);
                connId = (Long) connField.get(((ConnectionProxyImpl) conn).getConnectionRaw());
            } catch (Exception e) {
                log.error("valid connection error", e);
            } finally {
                log.info("valid connection ok. conn:" + connId);
            }

            return true;
}

为了拿到 connectionId 只能反射获取，在本地debug下没问题，能正常拿到 connectionId，可是发到验证环境进行验证的时候报错了，以为奇怪，仔细看了下原来开发环境的配置和验证和生产的不同，开发环境没有走读写分离。

验证和生产都是使用了 mysql 的 replication 的机制，因此致使我反射获取的代码报错。

datasource.druid.url=jdbc:mysql:replication

经过debug发现，原来 __druid__的 connection 是 JDBC4Connection ，变成了 ReplicationConnection ，并且里面包装了两个 connection ，一个 masterconnection ，一个 slaveconnection ，彷佛问题有点浮现了。

经过debug发现 druid 的检查仍是会正常走到，当走到 ReplicationConnection 内部的时候 ReplicationConnection 有一个 currentConnection ，这个连接是会在 masterConnection 和 slaveConnection 之间切换，切换的依据是 readOnly 参数。

在检查的时候因为 druid 并不感知上层的参数，readOnly 也就不会设置。因此走的是 masterConnection ，可是在程序里用的时候经过 spring 的 TransactionManager 将 readOnly 传播到了 ShardingJDBC ， ShardingJDBC 在设置到 ReplicationConnection 上，最后致使真正在使用的时候其实使用的是 slaveConnection。

找到这个问题以后去 druid github Issues 搜索了下果真有人提过这个问题，在高版本的 druid 中已经修复这个问题了。

修复

修复这个问题有两个方法，第一个方法，建议升级 druid，里面已经有 MySqlReplicationValidConnectionChecker 检查器专门用来解决这个问题。第二个方法就是本身实现 ValidConnectionChecker 检查器，可是会有在未来出现bug的可能性。

因为时间关系文章只讲了主要的排查路线，事实上咱们陆续花了一周多时间，再加上周末连续趴上十几个小时才找到这根本问题。

这个问题之因此难定位的缘由主要是牵扯的东西太多，框架层面、网络连接层面、mysql服务器层面，haproxy代理等等，固然其中也绕了不少弯路。。

下面分享在这个整个排查过程当中的一些技术收获。

相关技术问题

1.mysqlConenction提供了ping方法用来作活动检查，默认MySqlValidConnectionChecker使用的是pinginternal。

ping = clazz.getMethod("pingInternal", boolean.class, int.class);

2.低版本的druid不支持自定义 ValidConnectionChecker 来作个性化的检查。

3.druid 的test方法使用注意事项，testOnBorrow 在获取连接的时候进行检查，与testWhileIdle是护持关系。

if (isTestOnBorrow()) {
            } else {
                if (isTestWhileIdle()) {

3.kill mysql processlist 进程会话到连接端tcp状态有延迟，这是tcp的四次断开延迟。

4.haproxy 1.5.18 版本 mode tcp check不执行，健康检查设置无效。

5.mysql replication connection master/slave切换逻辑须要注意，会不会跟上下油的连接池组合使用出现bug，尤为是分库不表、读写分离、自定义分片。

6.排查mysql服务器的问题时，打开各类日志，操做日志，binlog日志。

7.springtransactionmanagenent 事务传播特性会影响下游数据源的选择，setreadonly、setautocommit。

8.低版本的 druid MySqlValidConnectionChecker 永远执行不到 ReplicationConnection ping 方法。

做者：王清培(沪江网资深架构师)

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程