executeupdate不执⾏_解Bug之路-中间件SQL重复执⾏
前⾔
我们的分库分表中间件在线上运⾏了两年多，到⽬前为⽌还算稳定。在笔者将精⼒放在处理各种灾难性事件(例如中间件物理机宕机/数据库
宕机/⽹络隔离等突发事件)时。竟然发现还有⼀些奇怪的corner case。现在就将排查思路写成⽂章分享出来。
Bug现场
应⽤拓扑
应⽤通过中间件连后端多个数据库,sql会根据路由规则路由到指定的节点，如下图所⽰:
错误现象
应⽤在做某些数据库操作时，会发现有⽐较⼤的概率失败。他们的代码逻辑是这样:
int count = updateSql(sql1);...// 伪代码int count = updateSql("update test set value =1 where id in ("100","200") and status = 1;if( 0 == count ){throw new RuntimeE
即每做⼀次update之后都检查下是否更新成功，如果不成功则回滚并抛异常。 在实际测试的过程中，发现经常报错，更新为0。⽽实际那
条sql确实是可以更新到的(即报错回滚后，我们⼿动执⾏sql可以执⾏并update count>0)。
中间件⽇志
笔者根据sql去中间件⽇志⾥⾯搜索。发现了⾮常奇怪的结果,⽇志如下:
2020-03-13 11:21:01:440 [NIOREACTOR-20-RW] frontIP=>ip1;sqlID=>12345678;rows=>0;sql=>update test set value =1 where id in ("1","2") and status =
由于中间件对每条sql都标识了唯⼀的⼀个sqlID，在⽇志表现看来就好像sql执⾏了两遍!由于sql中有⼀个in，很容易想到是否被拆成了两条执
⾏了。如下图所⽰:
下载mysql为什么下载不了
这条思路很快被笔者否决了，因为笔者explain并⼿动执⾏了⼀下，这条sql确实只路由到了⼀个节点。真正完全否决掉这条思路的是笔者在
⽇志⾥⾯还发现，同样的SQL会打印三遍！即看上去像执⾏了三次，这就和仅仅只in了两个id的sql在思路上相⽭盾了。
数据库⽇志
那到底数据真正执⾏了多少条呢？DBA去捞⼀下其中的sql⽇志，由于线下环境没有⽇志切割，⽇志量巨⼤，搜索时间太慢。没办法，就
按照现有的数据进⾏分析吧。
⽇志如何被触发
由于当前没有任何思路，于是笔者翻看中间件的代码，发现在update语句执⾏后，中间件会在收到mysql okay包后打印上述⽇志。如下图所⽰:
注意到所有出问题的update出问题的时候都是同⼀个NIOREACTOR线程先后打印了两条⽇志，所以笔者推断这两个okay⼤概率是同⼀个
后端连接返回的。
什么情况会返回多个okay?
这个问题笔者思索了很久，因为在笔者的实际重新执⾏出问题的sql并debug时，永远只有⼀个okay返回。于是笔者联想到，我们中间件有
个状态同步的部分,⽽这些状态同步是将set auto_commit=0等sql拼接到应⽤发送的sql前⾯。即变成如下所⽰:
sql可能为set auto_commit=0;set charset=gbk;>update test set value =1 where id in ("1","2") and status = 1;
于是笔者细细读了这部分的代码，发现处理的很好。其通过计算出前⾯拼接出的sql数量，再在接收okay包的时候进⾏递减，最后将真正执
⾏的那条sql处理返回。其处理如下图所⽰:
但这⾥确给了笔者⼀个灵感，即⼀条sql⽂本确实是有可能返回多个okay包的。
真相⼤⽩
在笔者发现(sql1;sql2;)这样的拼接sql会返回多个okay包后，就⽴刻联想到，该不会业务⾃⼰写了这样的sql发给中间件，造成中间件的sql 处理逻辑错乱吧。因为我们的中间件只有在对⾃⼰拼接(同步状态)的sql做处理，明显是⽆法处理应⽤传过来即为拼接sql的情况。 由于看上去有问题的那条sql并没有拼接，于是笔者凭借这条sql打印所在的reactor线程往上搜索，发现其上⾯真的有拼接sql!
2020-03-1311:21:01:040[NIOREACTOR-20RW]frontIP=>ip1;sqlID=>12345678;rows=>1;sql=>update test_2 set value =1 where id=1 and status = 1;update
如上图所⽰，(update1;update2)中update1的okay返回被驱动认为是所有的返回。然后应⽤⽴即发送了update3。前脚刚发送,update2
的okay返回就回来了⽽其刚好是0，应⽤就报错了(要不是0，这个错乱逻辑还不会提前暴露)。那三条"重复执⾏"也很好解释了，就是之前的
拼接sql会有三条。
为何是概率出现
但奇怪的是，并不是每次拼接sql都会造成update3"重复执⾏"的现象，按照笔者的推断应该前⾯只要是多条拼接sql就会必现才对。于是笔
者翻了下jdbc驱动源码，发现其在发送命令之前会清理下接收buffer，如下所⽰:
MysqlIO.javafinal Buffer sendCommand(......){......// 清理接收buffer，会将残存的okay包清除掉clearInputStream();......send(this.sendPacket, Pos
正是由于clearInputStream()使得错误⾮必现(暴露)，如果okay(update2)在应⽤发送第三条sql前先到jdbc驱动会被驱动忽略！ 让我们再
看⼀下不会让update3"重复执⾏"的时序图:
即根据okay(update2)返回的快慢来决定是否暴露这个问题，如下图所⽰:
同时笔者观察⽇志，确实这种情况下"update1;update2"这条语句在中间件⾥⾯⽇志有两条。
临时解决⽅案
让业务开发不⽤这些拼接sql的写法后，再也没出过问题。
为什么不连中间件是okay的
业务开发这些sql是就在线上运⾏了好久，⽤了中间件后才出现问题。 既然不连中间件是okay的，那么jdbc必然有这⽅⾯的完善处理，笔者
去翻了下mysql-connect-java(5.1.46)。由于jdbc⾥⾯存在⼤量的兼容细节处理，笔者这边只列出⼀些关键代码路径:
MySQL JDBC 源码MySQLIOstack;executeUpdate|->executeUpdateInternel|->executeInternal|->execSQL|->sqlQueryDirect|->readAllResults (MysqlIO.java)readA
正确的处理流程如下图所⽰:
⽽我们中间件的源码确实这么处理的:
@Overridepublic void okResponse(byte[] data, BackendConnection conn) {......// 这边仅仅处理了autocommit的状态，没有处理SERVER_MORE_RESULTS_EXIST
select也"重复执⾏"了
解决完上⾯的问题后，笔者在⽇志⾥竟然发现select尽然也有重复的，这边并不会牵涉到okay包的处理，难道还有问题？⽇志如下所⽰:
2020-03-13 12:21:01:040[NIOREACTOR-20RW]frontIP=>ip1;sqlID=>12345678;rows=>1;select abc;2020-03-13 12:21:01:045[NIOREACTOR-21RW]frontIP
从不同的REACTOR线程号(20RW/21RW)和不同的frontIP(ip1,ip2)来看是两个连接执⾏了同样的sql，但为何sqlID是⼀样的？任何⼀个诡
异的现象都必须⼀查到底。于是笔者登录到应⽤上看了下应⽤⽇志，确实应⽤有两个不同的线程运⾏了同⼀条sql。 那肯定是中间件显⽰的
问题了，笔者很快就想通了其中的关窍，我们中间件有个对同样sql缓存其路由节点结构体的功能(这样下⼀次同样sql就不必解析，降低了
CPU)，⽽sqlID信息正好也在那个路由节点结构体⾥⾯。如下图所⽰:
这个缓存功能感觉没啥⽤(因为线上基本是没有相同sql的)，于是笔者在笔者优化的闪电模式下(⼤幅度提⾼中间件性能)将这个功能禁⽤掉
了，没想到为了排查问题⽽开启的详细⽇志碰巧将这个功能开启了。
总结
任何系统都不能说百分之百稳定可靠，尤其是不能⽴flag。在线上运⾏了好⼏年的系统也是如此。只有对所有预料外的现象进⾏细致的追查
与深⼊的分析并解决，才能让我们的系统越来越可靠。

版权声明：本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系QQ:729038198，我们将在24小时内删除。