登录
  • 欢迎访问悠扬的技术博客,推荐使用最新版火狐浏览器和Chrome浏览器访问本网站😉

分库分表sharding-proxy使用druid链接池链接断开故障原因分析

ShardingSphere 悠扬 750次浏览 已收录 0个评论

(转)诡异的druid链接池链接断开故障经验总结

背景

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

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

第一反应肯定是因为这次的读库地址的变动引起的问题,觉得问题应该是 druid 链接池中的 connection 保活策略没起作用,只要做下配置修改应该就可以了。结果这个问题让我们排查了好几天,我们竟然踩到了千年难遇的深坑。

这个问题排查的很坎坷,一次次的吐血,最终我们定位到问题并且优雅的修复了,我们一起来体验下这个一次一次让你绝望一次一次打脸的过程。

症状

先说故障症状,经常出现如下错误:

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

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 方法。

作者:王清培(沪江网资深架构师)


版权所有丨如未注明 , 均为原创丨本网站采用BY-NC-SA协议进行授权 , 转载请注明分库分表sharding-proxy使用druid链接池链接断开故障原因分析
喜欢 (1)
支付宝[]
分享 (0)
悠扬
关于作者:
10年以上工作经验,从事2年微服务架构搭建工作,有大数据处理相关工作经验,使用spring全家桶包括:Spring,SpringBoot,SpringCloud 数据层组件服务使用SpringDataJpa,Mybatis以及其他第三方组件Sharding-JDBC,Sharding-Proxy分库分表。熟悉微服务,服务降级,限流,分流,做过项目源码修改,有cat,apollo,nacos使用经验,有Lostash,Elasticsearch,kibana,mysqlMHA生产实践经验,使用开源代码Apache Sarding项目,修改源码支持mysql分库分表使用年月日小时分库分表,docker做集群服务,Jekins做项目发布,GitLab做项目管理,使用docker容器部署,熟悉消息队列RabbitMQ,Kafka,ActiveMQ。RuoYi-Vue-Atomikos项目开源加入生态圈组件,项目支持分布式事务,界面添加多数据源,数据源动态配置,切面切换,多数据源事务支持,支持区域数据源配置,用于区域数据切分,数据层次分库。项目地址:https://gitee.com/zsiyang/ruoyi-vue-atomikos
发表我的评论
取消评论

表情 贴图 加粗 删除线 居中 斜体 签到

Hi,您需要填写昵称和邮箱!

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址