剧本杀 :《若不是SkyWalking,MySQL的这个锅都没人背了》-终章

数据库 MySQL
无论是 5.6 还是 5.7 + ,从逻辑看只是概率不同,监听 binlog 的方案始终是无法避免这类问题的。因无法确认 MySQL 的最大延迟时间,你的 canal 也无法使用 MQ 定时延迟消息的机制,因为延迟时间设大设小都不合适,你给出可行的 2 个建议:异常重试 :异常时借助 MQ 的 delay 重试机制多试几次。采用新的实现架构:从根本上规避再去查询 DB。

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

本剧本杀分上下两章:

首章:《​​若不是SkyWalking,MySQL的这个锅都没人背了-首章​​》​

终章:《​​若不是SkyWalking,MySQL的这个锅都没人背了-终章​​》(本篇)

请按需回顾前情,方便你尽快融入角色(戏精上身)。

一、前情回顾

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

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

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

应用 B 消费这个 MQ,收到这条消息后,处理流程中会再调用应用 A 的 Dubbo 服务,查询一些信息

应用 A 响应 Dubbo 请求时,处理逻辑中还会从 MySQL 中查询这条 x 订单记录,但是!!!读出的状态字段居然还是老数据 ccc

DB 是 MySQL ,采用读写分离架构,主从采用异步同步

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

图片

数据流转图

通过这个数据流转图可以看出读数据有如下 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 信息截图

图片

非原截图

因为剧情所需,作为本章主角的你,此时已很熟悉 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 请求返回

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

图片

读写流程时序

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

图片

来自网络

通过你给出的解释和资料,除了老张的表情看起来是还在纠结着什么,其他众人皆表示此瓜香甜可口、回味无穷,经过学习思考后对此情况基本达成共识,开始考虑如何应对这个小概率事件。

图片

七、新的疑虑和答案

第二天下班后,老张又找到你探讨为什么应用 A 的服务逻辑并未变更,而是升级 8.x 之后这个问题才开始出现(虽然概率不高);据老张讲,昨夜他查阅了好多资料,其中有一个关键信息是写 engine 后更新才能被查到,但是 5.7 开始,写 engine 的时机被调整了:

5.6 版本中是先写 engine 再同步,由于写 engine 的时机较早,产生问题的概率就更低。

5.7 提供的默认逻辑是先同步,再写 engine,由于同步前置了就可能带来更多的具有不确定性的耗时

图片

MySQL 5.7 默认同步机制的变化

八、建议

总结来看,无论是 5.6 还是 5.7 + ,从逻辑看只是概率不同,监听 binlog 的方案始终是无法避免这类问题的。因无法确认 MySQL 的最大延迟时间,你的 canal 也无法使用 MQ 定时延迟消息的机制,因为延迟时间设大设小都不合适,你给出可行的 2 个建议:

异常重试 :异常时借助 MQ 的 delay 重试机制多试几次。

采用新的实现架构:从根本上规避再去查询 DB。

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

责任编辑:武晓燕 来源: 架构染色
相关推荐

2022-11-26 10:36:30

MySQLSkyWalking应用性能

2017-09-12 16:18:22

ICO区块链互联网+

2020-02-20 16:21:46

远程办公

2019-06-03 14:38:11

AWS挖掘机光缆

2019-12-03 13:57:38

CIO背锅IT

2021-08-28 10:58:15

MySQL备份数据库

2017-08-23 17:11:40

WI-FI流量路由器

2021-04-16 09:20:34

黑客DDoS网络攻击

2022-12-09 09:43:41

前端测试

2019-07-10 06:08:33

IT运维网络故障故障排除

2021-04-13 17:38:38

区块链比特币安全

2018-06-09 23:18:25

2017-09-25 10:52:27

2018-12-26 17:36:37

开发者技能阿里

2022-05-11 18:22:51

元宇宙大会剧本杀

2019-09-17 10:31:51

岗位产品程序员

2021-11-26 07:02:37

数据库

2015-12-09 13:51:21

Intelskylake散热器

2019-01-04 10:13:22

苹果中国市场iPhone

2019-01-16 18:11:28

程序员技能开发者
点赞
收藏

51CTO技术栈公众号