剧本杀 ：《若不是SkyWalking，MySQL的这个锅都没人背了》-首章

​剧本

因剧情所需，剧本显示你在技术部门负责链路追踪系统和数据库中间件等，剧情为你日常工作中的一次排障经历...

刚看这么多，导演大喊：男主请就位... 预备 ! Action!

你：哇喔，我这就开始演了？

一、问题首现

记得那是一个风和日丽的下午...突然你被拉到一个临时工作群里，只见窗口中快速弹出一条消息：@老张 binlog 中的字段更新，读 db 时却读不到。记住作为男主的你在剧本的这个章节里叫老张，看到这个消息后，你的大脑便开始拆解这些关键字：

• 应用 A 将 MySQL 中 x 记录中的 y 字段更新了
• canal（canal 是啥，下边有介绍）监听 DB 中订单记录变更事件，发到 MQ
• 应用 B 消费这个 MQ, 收到这个消息后，从 MySQL 中查询这个 x 记录
• 但是！！！没读到 y 字段更新后的值

同时，在你大脑的另一个区域也勾勒出如下数据流转的画面：

对此问题有了初步画像后，你的大脑中条件反应式的冒出了一连串问题，赶紧在群里发出：

• 有严重的业务影响嘛？
• 最近系统有变更嘛？
• 这是个别记录现象嘛？
• 以前发生过嘛？
• traceId 是什么？

得到的回复是：

• 问题不严重。
• 最近没变更。
• 这是个别记录现象。
• 以前好像没遇到过。
• 还没有接入 SkyWalking（SkyWalking 是啥，下边会介绍），现有的日志里也都看不出什么猫腻。

看完前 4 个回答后得知没有严重影响，你松了一口气，紧张的情绪缓和了下来；但同时也意识到没有直观的链路追踪数据，要理清楚这个问题就有点麻烦了。

1.1 canal 知识补充：

官方这么介绍：canal [kə'næl] ，译意为水道/管道/沟渠，主要用途是基于 MySQL 数据库增量日志解析，提供增量数据订阅和消费。

早期阿里巴巴因为杭州和美国双机房部署，存在跨机房同步的业务需求，实现方式主要是基于业务 trigger 获取增量变更。从 2010 年开始，业务逐步尝试数据库日志解析获取增量变更进行同步，由此衍生出了大量的数据库增量订阅和消费业务。

canal官网图示.png

github 地址：https://github.com/alibaba/canal

1.2 SkyWalking 知识补充：

SkyWalking 是一个可观测性平台（Observability Analysis Platform 简称 OAP）和应用性能管理系统（Application Performance Management 简称 APM）。提供分布式链路追踪、服务网格（Service Mesh）遥测分析、度量（Metric）聚合和可视化一体化解决方案。

下图即其链路追踪的展示效果，通过它能够直观看出一次请求完整的执行轨迹，经过了哪些应用、访问了哪些中间件、请求的关键信息是什么、各环节的执行耗时是多少、是否异常等。

github 地址：https://skywalking.apache.org/

二、询问排查

2.1 梳理数据流转

因为应用没有接入 SkyWalking，缺少直观完整 trace 信息的帮助，你只能通过低效的、人工询问的方式梳理有哪些应用、DB 什么类型、数据流转情况，经过一番沟通后才了解到情况如下：

应用 A 将 MySQL 中 x 订单记录中 y 字段从 ccc 变成了 ddd

canal 监听 DB 中订单表，从 binlog 中感知到 x 记录变更信息后，发到 MQ

应用 B 消费这个 MQ，收到这条消息后，处理流程中会再请求应用 A 的 Dubbo 接口，查询一些信息

应用 A 收到 Dubbo 请求后，处理逻辑中还会从 MySQL 中查询这个 x 订单记录，但是！！！读出的状态字段居然还是 ccc

DB 是读写分离，MySQL 主从同步采用的异步同步模式

2.2 锁定可疑环节

基于前边掌握的情况，你在大脑中快速勾勒出如下这个数据流传图：

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

• 6.1 读缓存
• 6.2 读从库
• 6.3 读主库

你反复思索之后推测 6.1 或 6.2 这两种途径很可能会读取到旧值，于是开始排查。

2.3 排查 Mybatis 缓存

你依据经验推测， 6.1 最有可能读不到新数据，缓存通常有进程内缓存、Redis 缓存，Mybatis 缓存这几种。进一步沟通后，你确认了应用 A 并没有使用内存缓存和 Redis 缓存，同事甚至有怀疑数据库中间件中是否有缓存，这个怀疑被你直接排除了（数据库中间件中没有缓存），那就剩下 Mybatis 缓存这一处嫌疑了，于是你快速从大脑的知识库中翻出 Mybatis 两级缓存的机制原理。

2.3.1 排除一级缓存的嫌疑

一级缓存默认是开启的，是否一级缓存的问题呢？你继续分析：

• 按照现有 mapper 的用法，一个请求中所有的 CRUD 操作都是在同一个 sqlSession 里面
• 一个 sqlSession 内的所有查询操作都会保存到这个 sqlSession 内缓存中，即每个请求都有一个专属于自己的一级缓存
• 每个请求的一级缓存隔离，彼此互不干扰
• 应用 A 在 x 记录更新前，查询请求中的一级缓存数据，不会被应用 A 在 x 记录更新后的查询请求访问到。

如此梳理分析后，你排除了 Mybatis 一级缓存造成此问题的可能。

2.3.2 排除二级缓存的嫌疑

然后你继续开始排查是否由二级缓存导致的，你的知识库显示：二级缓存在 sqlSession 之外，被 sqlSession 共享，即多个请求可以共用同一个二级缓存，一、二级缓存的协作机制如下：

sqlSession 缓存的数据是先放在一级缓存中，当 sqlSession 会话提交或者关闭时会将一级缓存数据同步到二级缓存中

用户查询时，会先去二级缓存中查找，若找不到才去一级缓存中查找

读二级缓存.png

这么看来如果时差吻合，二级缓存的嫌疑很大，那是不是二级缓存的问题呢？此时一个知识点在使劲的敲击你的大脑【二级缓存需要手动开启】 ，于是你抓紧咨询应用 A 是否开启了二级缓存，但同事一时间又搞不清楚这个开关的知识，于是你把开启二级缓存的方式描述发出：

单个 mapper 开启在需要开启二级缓存的 XXXmapper.xml 文件中加入以下配置

<!-- 开启单个mapper的二级缓存-->
<cache />

所有 mapper 都开启

在 mybatis.xml 中加入以下配置

<settings>
    <!--  开启所有mapper的二级缓存 -->
    <!--<setting name="cacheEnabled" value="true" />-->
</settings>

应用 A 对照结论，没有开启 Mybatis 的二级缓存。

如此梳理分析后，你又排除了 Mybatis 二级缓存造成此问题的可能。

2.4 排查 binlog 同步

依据上图你继续排查，此时怀疑到了 6.2 读从库这个环节，跟 DBA 核实得知，这个 MySQL 主从同步采用了异步同步方案；此刻你的知识库表示很尴尬：MySQL 异步同步机制并不熟悉，于是找到隔壁老王（canal、MQ 专家）请教，老王解释到：异步同步的机制中，master-DB 写 binlog 后执行提交，不等待 slave-DB 的同步状态；既然 canal 和 slave-DB 都是读取 binlog 数据之后再做处理，且无顺序管控，那就有可能当应用 A 从 slave-DB 读 x 记录时，slave-DB 还未完成 x 记录的同步，情况如下图：

同步延迟.png

同时老王还补充，刚才已经排查过 canal 和 MQ 的工作状态，DBA 也看过 DB 的监控信息，这几个系统的指标都很平稳没有抖动，如果有抖动的话，那出问题的应该也不只是这一条记录。

当掌握了这些信息后，你基本认定应用 A 是读了 slave-DB，因为你的数据库中间件，在读写分离的场景中，默认情况下读请求是自动路由到 slave-DB 的，除非...，突然你跟应用 A 核实，这个读请求有没有指定强制读master-DB...，应用 A 的回复跟你的预期相差很大，这个请求中他指定了读master-DB。

为什么为什么读 master-DB，还能读到的是老数据，难道是数据库中间件的路由机制有漏洞了？导演让你马上配合表演出了上图中的表情...OH MY GOD ！！！

2.5 新的困境

过了好一会儿，你冷静了下来，凭借你的坚强的灵魂，你认定不是数据库中间件的路由机制有漏洞，而此时 DBA 也不认为 master-DB 有问题，应用 A 也不认为他指定读 master-DB 的代码有问题，老王也不认为他的 canal 读到的 binlog 有问题。

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

三、接入 SkyWalking

导演着急的大吼：“那谁，这都演完了，你剧本还没写出来嘛？”

只见编剧不慌不忙的走来后把剧本递给导演，导演照着剧本认真的读了起来： "缺失有效的可观测trace数据，又没有办法快速复现，可能只有上帝知道是哪个环节有问题，要不问问上帝？” 。

此时突然有人站起来说：”我演的是上帝，应用 A、应用 B 接下来接一下 SkyWalking 吧，等下次复现时，大家就能根据链路信息来快速揭秘问题真相“。

于是你在群里发出接入 SkyWalking 的文档，两个点很简单：

• 应用配置中心勾选接入 SkyWalking
• 日志配置文件中调整加入 traceId 占位符​

梳理分析至此，众人没了方向，也都保留了各自的怀疑，期待接入 SkyWalking 后再遇到，依据精确的信息来定位。

四、终章剧透

在下一章（终章）的剧本中，你是主角老王；上边这种尴尬的状况把你那股较真儿的劲头给激活了，之后你查阅了许多资料，进一步学习了 MySQL 的同步机制，在问题复现后，给出了 MySQL 同步机制有缺陷的根因...。敬请期待终章，关键剧情如下：

• 应用 A、应用 B 之后接入了 SkyWalking
• 两周后，这个问题又出现了
• SkyWalking 中 trace 信息表明应用 A 的确是读了 master-DB
• 老王通过进一步搜集研究发现，这是 MySQL 工作机制中天然存在的缺陷
• 众人商定了后续的改进和规范调整，以应对这个缺陷

本文转载自微信公众号「架构染色」，可以通过以下二维码关注。转载本文请联系联系【架构染色】公众号作者。