刚更新的数据居然查不到，MySQL你到底在做什么妖-下-阿里云开发者社区

你用忙碌送走白昼，笑迎安静的深夜

并非贪恋繁星的闪耀，而是钟爱默默地拼搏

欢迎关注【架构染色】交流学习

本篇尝试悬疑推理风剧本杀，剧情纯属虚构（若有雷同实属巧合)：应用 A 更新了 MySQL 数据 -> canal 监听 binlog ，发给 MQ -> 应用 B 消费 MQ，并向 A 发起 Dubbo 请求 -> 应用 A 处理时却查到了更新前的数据。这个情况多数人都没遇到过，但提前了解并规避是必要的。

本剧本杀分上下两章：

首章：《刚更新的数据居然查不到，MySQL你到底在做什么妖-上》
终章：《刚更新的数据居然查不到，MySQL你到底在做什么妖-下》（本篇）

请按需回顾前情，方便你尽快融入角色（戏精上身）。

一、前情回顾

在首章剧情中你在技术部门负责链路追踪系统和数据库中间件等，在一次日常技术支持中，遇到了神奇的现象：

应用 A 将 MySQL 中 x 订单记录里的 y 字段从 ccc 变成了 ddd
canal 监听 DB 中的订单表，从 binlog 中感知到 x 记录变更信息后，发到 MQ
应用 B 消费这个 MQ，收到这条消息后，处理流程中会再调用应用 A 的 Dubbo 服务，查询一些信息
应用 A 响应 Dubbo 请求时，处理逻辑中还会从 MySQL 中查询这条 x 订单记录，但是！！！读出的状态字段居然还是老数据 ccc
DB 是 MySQL ，采用读写分离架构，主从采用异步同步

你梳理的数据流转图如下：

数据流转图.png

通过这个数据流转图可以看出读数据有如下 3 种途径：

6.1 读缓存
6.2 读 slave-DB
6.3 读 master-DB

你反复思索之后推测 6.1 或 6.2 这两种途径很可能会读取到旧值，但经梳理排查将各方信息整合后，似乎并没有执行 6.1 的读缓存，也没有执行 6.2 的读 slave-DB，你也认定不会是数据库中间件的路由机制有漏洞，而 DBA 也不认为 master-DB 有问题，应用 A 也不认为他指定读 master-DB 的代码有问题，老王也不认为他的 canal 读到的 binlog 有问题。但由于没有 trace 信息提供直接有效的证据，各方只能保留意见，不乱猜疑。

面面相觑好久，大家心照不宣地望向了导演，作为主角的你去问导演接下来怎么演。

导演也着急，把编剧叫来朝他怒吼：“那谁，这都演完了，你剧本还没写出来嘛？”

只见编剧不慌不忙的把剧本递给导演，导演定睛一看，剧本上写着"没有有效的观测数据，又没有办法复现，可能只有上帝视角知道是哪个环节有问题，要不问问上帝？”。

此时有人自称上帝的站出来说：”应用 A、应用 B、canal 都接入 SkyWalking，等下次复现时，根据链路信息来寻找线索“。

二、终章剧本

因剧情所需，这次你在技术部门负责 canal 和 MQ 等，情节延续上一次的排障经历...

突然，导演大喊：男主请就位... 预备 ! Action!

你：我去，咋的这就又开始演了？

三、心中的疑虑

当听完上帝让接 SkyWalking 后，你必须开始心中有疑虑，疑虑些什么呢？终章剧本要求作为主角的你，要好好想一想为什么接入 SkyWalking 后就能准确定位问题，帮助定位问题的信息 SkyWalking 是提供的？因为不擅长这个领域，你很头疼；倘若刚好你很熟悉 SkyWalking ，这里也需要假装不熟悉且头疼一下，导演要求就这么演。。。

头疼了一会儿，你突然想到隔壁老张，在首章中是主角，负责 SkyWalking ，于是你去咨询 SkyWalking 能提供哪些有效的信息，老张拿出之前梳理的图，指着其中几个关键环节：

应用 A 什么时候开始更新记录，什么时候结束更新记录
应用 B 什么时候消费 MQ，什么时候请求应用 A，应用 A 什么时候开始执行的查询，查询的是哪里？用缓存没？如果没用缓存，访问的又是哪个 DB？

这些关键信息 SkyWalking 的 trace 中都有记录，且在界面中清晰可见，

老张继续解释说，虽然当前的 MySQL 没有传递 traceId 信息，会导致链路断开成更新和查询这两条 trace，但是可以通过关键字从日志中检索出这两条 trace 的 traceId(下文用 TID) 。

听完老张的讲解，你了解并相信了 SkyWalking 的能力。原本你也推测查询的是 slave-DB 或缓存，所以当时下意识的决策就是等到复现后用 trace 信息来印证你的推测；不过老张在下班时又向你抛出一个疑虑：会不会真有当 canal 读到 binlog 时 MySQL 事务还未完成提交的可能呢？

从你以往的经验看是没有这个情况的，但被老张这么一问却不自信了。难道当前版本的 canal 同步 binlog 的机制有问题？“到底有没有问题呢，到底有没有呢？”这个声音一直在你耳边萦绕，莫名感让你觉得很不踏实，于是之后便在空闲时搜集学习 MySQL 同步机制的更多内幕。

四、问题再现

大约两周后，问题排查群突然出现@全员的消息，想到可能是问题再现，你赶紧点开查看；只见在群聊窗口中已经发出了把 x 记录的 y 字段从 ccc 更新成 ddd 这个过程的 TID 以及 trace 信息截图

非原截图.png

因为剧情所需，作为本章主角的你，此时已很熟悉 SkyWalking 了，当看到这个截图后，亲自在 SkyWalking 的 web 页中通过此 TID 查看 trace 信息，点击Mysql/JDBI/Connection/commit，看到 commit 的具体信息如下：

Key	value	描述解释
服务	serviceA	应用 A 的服务名称
服务实例	111.111.111.222	执行本次操作的实例 IP
端点	Mysql/JDBI/Connection/commit	commit操作的名称信息
跨度类型	Exit	Exit 表示访问了外部资源，如此处的MySQL
组件	mysql-connector-java	表明此 trace 信息是 JDBC 插件提供的
Peer	serviceA-xxxx:3311	db 实例的域名\ip 信息
失败	false	false 表示本次操作没有异常
db.type	sql	表示本次操作的 DB 是 SQL 类型
db.instance	serviceA	表示应用 A 的 DB 实例
db.statement	xxx	sql 语句

五、铁证如山

你从 trace 信息中筛选出应用 A 将 x 订单记录里 y 字段从 ccc 变成了 ddd操作的关键信息是：

事务发生在 MySQL 实例 serviceA-xxxx 中（这是 master-DB）
事务 commit 的开始是 09:58:54 的第 72 毫秒（后边都只显示毫秒)
事务 commit 的结束是在第 123 毫秒

之后又快速从 SkyWalking 的 web 页中查看核实应用 A 查询数据的 trace 信息，没有读 Mybatis 缓存、没有读 slave-DB，真儿真儿的是从 master-DB 中查询数据。至此， trace 信息提供的信息有效证明了 应用 A 更新记录和查询记录都发生在 master-DB serviceA-xxxx 中。

剧本提醒，拥有主角光环的你，此时已淡定、娴熟的把两条 trace 信息中关键事项的时间节点结合 mysql 和 canal 日志（canal 系统还未接 SkyWalking，只能看日志信息）整理了出来，情况如下：

第 72 毫秒：应用 A 更新事务 commit 开始
第 73 毫秒：MySQL 服务端开始写 Binlog
第 77 毫秒：canal 同步到 Binlog 后发送到 MQ
第 78 毫秒：应用 B 拉取到 canal 消息后，向应用 A 发起 Dubbo 调用
第 88 毫秒：应用 A 查询 Mysql
第 123 毫秒：应用 A 的事务 commit 结束返回

剧本提醒：作为主角的你，绝对不能表现出惊讶，但其他群演看完你整理的信息后，必需配合表演出下图中的表情（导演强调，怎么夸张怎么演）。

六、揭开玄机

因两周前隔壁老张提出疑虑后，你就已经开始查阅资料学习 MySQL 8（今年是从 5.6 升级了）的同步机制，大脑知识库中的资料显示 MySQL 是分两阶段处理事物请求的，其中跟剧情密切相关的是第二阶段的 3 个核心步骤：

写 binlog
当写完 biblog 后，事务已经提交并持久化了，若发生崩溃，重启之后就能正确恢复
同步 binlog
各种同步机制有差异
写 engine
会处理释放锁，释放 mvcc 相关的 read view 等；注意只有写完 engine 之后，事务中的变更才能被查询到
客户端 commit 请求返回

综合上述的信息，你将整个流程整理成下图:

读写流程时序.png

并在图中指出，这两次异常的情况的发生，全是因为在读 x 记录的时候，master-DB 中写 engine 尚未完成，你之所以在上图中使用2.谜之操作的名称，是因为 MySQL 并不确定这个同步耗时是多长；而且在强同步、半同步的机制下实现逻辑更复杂，可能出现此问题的概率会比异步同步模式更高，因细节和剧情的关系不那么密切，本剧本里并没有过多的描述，只提供了下边这个更为细致的流程图：