一个MySQL JDBC驱动bug引起的血案

1.1  问题背景

公司是做电商系统的,整个系统搭建在华为云上。系统设计的时候,考虑到后续的用户和订单数量比较大,需要使用一些大数据库的组件。关系型数据库这块,考虑到后续数据量的快速增长,不是直接写入MySQL,而是使用了华为云的分布式数据库中间件(DDM)。

DDM华为云连接:https://www.huaweicloud.com/product/ddm.html

      image.png


使用了DDM之后,可以在业务不感知的情况下,直接增加MySQL读实例的个数,线性提升读性能。也支持中间件层面的分库分表,提供海量关系型数据库的操作。简直是为电商系统贴身定制的。

DDM自身是以集群形式提供服务的,对业务开放的是多个连接IP地址。需要有一层负载均衡。如果使用传统的加LB的形式做负载均衡,会多一层中转,有性能损耗。所以,直接使用了MySQL-JDBC提供的客户端负载均衡能力。逻辑结构如下图所示:

 

           2.PNG



业务通过MySQL-JDBCLoadbalance能提访问多个DDM节点。MySQL-JDBC提供负载均衡能力。

 

1.2  问题说明

使用MySQL客户端负载均衡力能,一直运行得好好,性能嗷嗷叫。可是前一阵子,无故出现了业务请求失败。我是负责电商订单模块的,涉及到真实的Money,这个问题吓了宝宝一身冷汗。。赶紧查看后台日志,发现是访问DDM出现了异常,二话不说直接提了工单给华为云DDM服务。


[WARN] [2018-07-08 23:11:29] [MySqlValidConnectionChecker:isValidConnection()] [DubboServerHandler-172.31.0.146:8080-thread-64-txId=00000000657615aa] Unexpected error in ping
java.lang.reflect.InvocationTargetException
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.lang.reflect.Method.invoke(Method.java:498)
         at com.alibaba.druid.pool.vendor.MySqlValidConnectionChecker.isValidConnection(MySqlValidConnectionChecker.java:98)
         at com.alibaba.druid.pool.DruidAbstractDataSource.testConnectionInternal(DruidAbstractDataSource.java:1252)
         at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:981)

 

不得不说,华为云的服务还是很好的,不到半个小时就联系了我,还跟我一起排查问题。

将我们业务的日志取下来,和DDM的支撑人员一起分析,发现报错如下:

根本原因竟然是MySQL驱动的bug,导致StackOverflow本地栈溢出导致,真是误会了DDM服务,抱歉了。

Caused by: java.lang.StackOverflowError
         at com.mysql.jdbc.StringUtils.getBytes(StringUtils.java:2360)
         at com.mysql.jdbc.StringUtils.getBytes(StringUtils.java:2344)
         at com.mysql.jdbc.StringUtils.getBytes(StringUtils.java:568)
         at com.mysql.jdbc.StringUtils.getBytes(StringUtils.java:626)
         at com.mysql.jdbc.Buffer.writeStringNoNull(Buffer.java:670)
         at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2636)
         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2483)
         at com.mysql.jdbc.ConnectionImpl.setReadOnlyInternal(ConnectionImpl.java:4961)
         at com.mysql.jdbc.ConnectionImpl.setReadOnly(ConnectionImpl.java:4954)
         at com.mysql.jdbc.MultiHostConnectionProxy.syncSessionState(MultiHostConnectionProxy.java:381)
         at com.mysql.jdbc.MultiHostConnectionProxy.syncSessionState(MultiHostConnectionProxy.java:366)
         at com.mysql.jdbc.LoadBalancedConnectionProxy.pickNewConnection(LoadBalancedConnectionProxy.java:344)
         at com.mysql.jdbc.LoadBalancedAutoCommitInterceptor.postProcess(LoadBalancedAutoCommitInterceptor.java:104)
         at com.mysql.jdbc.MysqlIO.invokeStatementInterceptorsPost(MysqlIO.java:2885)
         at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2808)
         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2483)
         at com.mysql.jdbc.ConnectionImpl.setReadOnlyInternal(ConnectionImpl.java:4961)
         at com.mysql.jdbc.ConnectionImpl.setReadOnly(ConnectionImpl.java:4954)
         at com.mysql.jdbc.MultiHostConnectionProxy.syncSessionState(MultiHostConnectionProxy.java:381)
         at com.mysql.jdbc.MultiHostConnectionProxy.syncSessionState(MultiHostConnectionProxy.java:366)
         at com.mysql.jdbc.LoadBalancedConnectionProxy.pickNewConnection(LoadBalancedConnectionProxy.java:344)
         at com.mysql.jdbc.LoadBalancedAutoCommitInterceptor.postProcess(LoadBalancedAutoCommitInterceptor.java:104)
         at com.mysql.jdbc.MysqlIO.invokeStatementInterceptorsPost(MysqlIO.java:2885)
。。。 此处省略10000行。。



从堆栈可以看出来,某个异常,触发了MySQL-JDBCbug,导致循环调用,直至栈溢出。

在华为DDM支撑人员的建议下,对驱动代码进行了反编译,从反编译的情况下,可以看到,的确是存在循环嵌套的可能。

Loadbalance轮询连接 –>同步新老连接的状态 ->发送sql给服务端 -> Loadbalance轮询连接。

相关代码如下:


com/mysql/jdbc/LoadBalancedConnectionProxy.javapickNewConnection()函数

for (int hostsTried = 0, hostsToTry = this.hostList.size(); hostsTried < hostsToTry; hostsTried++) {
    ConnectionImpl newConn = 
null;
    
try {
        newConn = 
this.balancer.pickConnection(this, Collections.unmodifiableList(this.hostList), Collections.unmodifiableMap(this.liveConnections),
                
this.responseTimes.clone(), this.retriesAllDown);

        
if (this.currentConnection != null) {
            
if (pingBeforeReturn) {
                
if (pingTimeout == 0) {
                    newConn.ping();
                } 
else {
                    newConn.pingInternal(
true, pingTimeout);
                }
            }

            
syncSessionState(this.currentConnection, newConn);
        }

        
this.currentConnection = newConn;
        
return;

    } 
catch (SQLException e) {
        
if (shouldExceptionTriggerConnectionSwitch(e) && newConn != null) {
            
// connection error, close up shop on current connection
            
invalidateConnection(newConn);
        }
    }
}

syncSessionState()函数,在执行完SQL之后,又会调用postProcess()函数,如此嵌套循环就来了。

if (!this.conn.getAutoCommit()) {
   
this.matchingAfterStatementCount = 0;
   
// auto-commit is enabled:
} else {

   
if (this.proxy == null && this.conn.isProxySet()) {
        MySQLConnection lcl_proxy =
this.conn.getMultiHostSafeProxy();
       
while (lcl_proxy != null && !(lcl_proxy instanceof LoadBalancedMySQLConnection)) {
            lcl_proxy = lcl_proxy.getMultiHostSafeProxy();
        }
       
if (lcl_proxy != null) {
           
this.proxy = ((LoadBalancedMySQLConnection) lcl_proxy).getThisAsProxy();
        }

    }

   
if (this.proxy != null) {
       
// increment the match count if no regex specified, or if matches:
       
if (this.matchingAfterStatementRegex == null || sql.matches(this.matchingAfterStatementRegex)) {
           
this.matchingAfterStatementCount++;
        }
    }
   
// trigger rebalance if count exceeds threshold:
   
if (this.matchingAfterStatementCount >= this.matchingAfterStatementThreshold) {
       
this.matchingAfterStatementCount = 0;
       
try {
           
if (this.proxy != null) {
               
this.proxy.pickNewConnection();
            }

        }
catch (SQLException e) {
           
// eat this exception, the auto-commit statement completed, but we could not rebalance for some reason.  User may get exception when using
            // connection next.
       
}
    }
}


 

 

这么明显的bug,不太相信MySQL会没有发现。当前我们使用的是5.1.44版本的驱动,查看了下最新的5.1.66的代码,发现的确是修复了这个问题的,代码如下:

public ResultSetInternalMethods postProcess(String sql, Statement interceptedStatement, ResultSetInternalMethods originalResultSet, Connection connection,
                                            
int warningCount, boolean noIndexUsed, boolean noGoodIndexUsed, SQLException statementException) throws SQLException {

   
// Don't count SETs neither SHOWs. Those are mostly used internally and must not trigger a connection switch.
   
if (!this.countStatements || StringUtils.startsWithIgnoreCase(sql, "SET") || StringUtils.startsWithIgnoreCase(sql, "SHOW")) {
       
return originalResultSet;
    }


通过过滤掉SETSHOW语句,避免了循环嵌套的发生。

但是5.1.66又引入了新的bug,由于并不是每个调用postProcess的地方都有SQL,这里的代码会抛空指针异常。MySQL JDBC的开发者都不做测试的吗。。。

 

没办法,分析了下5.1.44的代码,发现通过适当的调整loadBalanceAutoCommitStatementThreshold这个参数的数值,也可以避免循环嵌套的发生。我们的环境改成了5,修改之后,平稳运行1周,没再出现过问题。

 

1.3  修改方案

loadBalanceAutoCommitStatementThreshold修改成了5,但是引入的问题是,如果业务包含一些比较耗时的SQL,可能会DDM的负载不均衡。不过,目前看来还好,DDM性能比较强劲。

 

最后告诉大家一个小福利,华为云数据库年中钜惠活动正在火热进行中,分布式数据库中间件DDM等多款产品免费体验!点击:https://activity.huaweicloud.com/dcs_midyear/index.html?forum

,发现更多精彩!



欢迎扫码查看更多精彩:

中间件小哥.jpg