本文试杀悬疑推理风格的剧本杀，剧情纯属虚构（如有雷同纯属巧合）：申请A更新MySQL数据->运河监控binlog，发送给MQ->应用B消费MQ并向A发起Dubbo请求->应用A在处理过程中发现更新前的数据。大多数人没有遇到过这种情况，但有必要提前了解并避免。本剧本分为两章：第一章：《??若不是SkyWalking，MySQL的这个锅都没人背了-首章??》终章：?（本章）请根据需要回顾前面的故事，以便尽快融入角色（演员上半身).一、过往回顾第一章剧情中，你在技术部负责链??接跟踪系统和数据库中间件。在一次日常技术支持中，遇到了一个神奇的现象：应用A将MySQL中x订单记录中的y字段从ccc更改为dddcanal来监控DB中的订单表，从binlog中感知到x记录的变化信息后，将其发送给MQ应用程序B以消费此MQ。收到这条消息后，应用A的Dubbo在处理过程中会再次调用Service，查询一些信息当应用A响应Dubbo请求时，处理逻辑也会从MySQL中查询这条x订单记录，但是！！！读出的status字段其实是旧数据。cccDB即MySQL，采用读写分离架构，主从采用异步同步。:6.1读缓存6.2读slave-DB6.3读master-DB想了想，你推测6.1或者6.2这两种方式很可能是读旧值，但是经过整理整合各方信息后，好像没有执行6.1的readcache，也没有执行6.2的readslave-DB。你也相信数据库中间件的路由机制没有漏洞，DBA也不认为master-DB有问题，applicationA也不认为他指定的read有问题master-DB的代码，老王不认为他管读取的binlog有问题。但由于没有痕迹信息提供直接有效的证据，各方只能保留意见，避嫌。众人对视许久，默契的看向导演。作为主角，你问导演下一步怎么演。导演也着急了，把编剧叫了过来呵斥道：“那谁，都完了，剧本还没写好吗？”编剧不动声色的把剧本递给了导演。上面写着“没有有效的观测数据，也没有办法复现，可能只有上帝的视角才知道是哪个环节错了，你问问上帝好吗？”。这时候，一个自称是神的人站了出来，说道：“应用A、应用B、运河都连接到了SkyWalking，等下次它再次出现的时候，根据链接信息寻找线索。”2.最终章的剧本是剧情需要的。这次你在技术部负责canal和MQ。剧情延续之前的排查经验……突然，导演喊道：男主，请就位……准备！行动！你：我去，什么鬼又开始演戏了？3.心中的疑惑听了大神准许参加SkyWalking后，心里一定开始疑惑了。你有什么疑问？剧本的最后一章需要你作为主角思考为什么连接SkyWalking后可以准确定位问题。SkyWalking是否提供信息帮助定位问题？因为你不擅长这个领域，所以你会头疼；如果恰好你熟悉SkyWalking，你也需要假装不熟悉，头疼到这里，导演就要求这样演。..头疼了一会儿，你突然想到隔壁老张，他是第一章的主角，负责SkyWalking，于是你去问问SkyWalking能提供什么有效信息。应用A什么时候开始更新记录，什么时候结束更新记录？应用B什么时候消费MQ，什么时候请求应用A，应用A什么时候开始执行查询，查询在哪里？你用缓存了吗？如果不使用缓存，访问哪个DB？这些关键信息都记录在SkyWalking的轨迹中，在界面中清晰可见。老张继续解释，虽然现在的MySQL没有传递traceId信息，会导致链接断开，变成update和query两个trace，但是可以检索这两个trace的traceId（以下简称TID）通过关键字从日志中。听完老张的讲解，你就明白了，也相信了SkyWalking的能力。本来你也推测query是slave-DB或者cache，所以当时下意识的决定是等到重现再用trace信息来证实你的推测；canal读取binlog时MySQL事务还没有完成commit的可能性怎么办？以你以往的经验来看，并不是这样，只是被老张问起，你不自信。是不是canal当前版本同步binlog的机制有问题？“有什么问题吗？有什么问题吗？”这个声音一直在你耳边萦绕，莫名的感觉让你心里很不安，所以你会在空闲时间收集和学习更多关于MySQL同步机制的知识。4.问题再次出现后大约两周，问题排查群里突然出现@全员的消息。想到问题可能重现，赶紧点击查看；我在群聊窗口看到x记录的y字段是ccc发来的更新到ddd过程中的TID和trace信息的截图，因为剧情需要，不是原截图。作为本章的主角，您对SkyWalking已经很熟悉了。看到这个截图后，可以在SkyWalking网页上通过这个TID查看trace信息，点击Mysql/JDBI/Connection/commit，可以看到commit的具体信息如下：Keyvalue说明说明serviceserviceAApplication服务名称serviceinstance111.111.111.222执行该操作的实例IP端点Mysql/JDBI/Connection/commitcommit操作的名称信息span类型ExitExit表示访问外部资源。比如这里的MySQL组件mysql-connector-java表示这个trace信息是JDBC插件提供的PeerserviceA-xxxx:3311db实例的域名\ip信息。Failurefalse表示本次操作无异常db.typesql表示本次操作的DB为SQL类型db.instanceserviceA表示应用A的DB实例db.statementxxxsqlStatement5.证据确凿。你从trace信息中过滤掉应用A，将x订单记录中的y字段从ccc改为成为ddd操作的关键信息是：事务发生在MySQL实例serviceA-xxxx（这是master-DB）事务提交的开始是09:58:54的第72毫秒（后面只显示毫秒）事务提交的结束123毫秒后，我快速查看了验证应用程序的跟踪信息来自SkyWalkingweb的查询数据page，没有读Mybatis缓存，没有读slave-DB，真正从master-DB查询数据。至此，trace信息提供的信息有效证明了应用A的更新记录和查询记录均发生在master-DBserviceA-xxxx中。脚本提醒，有主角光环的你，结合mysql和canal日志（canal系统还没有连接SkyWalking，所以只能看到日志信息）。情况如下：72毫秒：应用A开始更新事务提交。73毫秒：MySQL服务器开始写入Binlog。77毫秒：Canal同步到Binlog并发送到MQ。A在第88毫秒发起Dubbo调用：应用A在第123毫秒查询Mysql：应用A的事务提交结束并返回脚本提醒：作为主角，你不能表现出惊讶，但其他群演者必须阅读你的信息已编译。配合下图表情的表现（导演强调，怎么夸怎么演）。六、揭开谜底在隔壁老张两周前提出疑惑后，你已经开始查阅资料学习MySQL8（今年从5.6升级而来）的同步机制。大脑知识库中的信息显示，MySQL是分两个阶段处理Things请求的，而第二阶段的三个核心步骤与剧情密切相关：写入binlog。写完biblog，事务已经提交并持久化。如果发生crash，重启后可以正确恢复同步binlog。同步机制存在差异。写引擎会处理锁的释放，释放mvcc相关的读视图等；注意，只有写好引擎后，才能向客户端查询事务的变化。Commit请求返回以上信息，你把整个过程组织成下图：读写过程的时序，图中指出这两种异常情况的发生都是因为写读取x记录时，master-DB中的引擎尚未完成。之所以用2.神秘操作的名称是因为MySQL不确定同步需要多长时间；并且在强同步和半同步机制下实现逻辑更加复杂，出现这个问题的概率可能比异步同步模式要高，所以细节与剧情关系不大。这个脚本没有太多的描述，下面只提供更详细的流程图：从你给的解释和网上的资料来看，除了老张的表情好像还在挣扎，其他人都说这个冬瓜香甜可口，回味无穷。经过研究和思考，他们对这种情况基本达成了共识，开始考虑如何应对这种小概率事件。7、新的疑惑解答第二天下班老张又找你讨论为什么应用A的服务逻辑没有变，但是升级到8.x后开始出现这个问题（虽然概率不高）;据老张张说，他昨晚查了很多资料。其中一个关键信息是更新只能在引擎写入后才能找到。不过从5.7开始，对写引擎的时机做了调整：5.6版本是先写引擎，再同步。时间越早，出问题的概率越低。5.7默认提供的逻辑是先同步，再写引擎。因为同步是预先配置的，所以可能会在MySQL5.7默认的同步机制中带来更多不确定和耗时的变化。5.7+，从逻辑上来说，只是概率不同而已，监控binlog的解决方案总是免不了的。因为MySQL的最大延迟时间无法确定，所以你的渠道不能使用MQ定时延迟消息的机制，因为延迟时间设置大或小都不合适。你给出两个可行的建议：异常重试：出现异常时使用MQ延迟重试机制，多试几次。采用新的实现架构：从根本上避免查询数据库。本文转载自微信公众号“结构染”，可通过以下二维码关注。转载本文请联系【结构染】公众号作者。
