
本文将以数据库实际使用中的某典型案例来分析造成主从延迟的原因。
主从延迟的原因
1、某用户在使用数据库过程中,出现主从延迟很大的情况,show slave status\G,已经差了 60 多个 binlog 了。

2、观察发现,应该是卡在一个大事物上面(Retrieved_Gtid_Set 一直在上升,但是 Executed_Gtid_Set 卡在一个点不动了),通过分析 relay_log 找到这个大事物:是对表 A 进行删除操作的一个事物。

看到这里,感觉又是一例在 ROW 模式下表没有主键,引起的主从延迟。看看表结构确认一下,发现这张表不小,字段有上百个,有主键,且是一张分区表,分区很多。这就有意思了!并不是我们碰到过多次的由于 ROW 模式下没有主键,DML 引起的主从延迟(PS:为什么这种情况下会引起延迟?而是有主键,且走了二级索引,那为什么回放还会这么慢呢?)。

后来了解到用户是在存储过程里面调用 detele 语句来进行归档数据清理,看了一下存储过程,现在的问题就可以简化为:在存储过程中调用 delete 语句,走了二级索引删除有主键的分区表,从机回放延迟。

这个时候,我们需要拆解一下问题,控制好变量,一个一个的查:
1、直接执行 delete,SQL 会以 statement 的格式出现,且不会产生主从延迟。


2、调用 procedure,该 delete 语句在 procedure 中执行的时候会变成 ROW 格式,且会导致延迟。
OK,有以上两个测试,我们的问题可以聚焦为:
1、为什么同样 delete 语句,直接执行和在 procedure 里面执行记录的 binlog 格式不一样(ROW 格式的 binlog 导致回放慢,全局设置在 mixed 模式下,这条 SQL 应该走的是 statement 格式,为什么在 procedure 里执行就变成了 ROW 格式,怎么样才能让这条 SQL 再 procedure 里执行变成 statement 记录到 binlog 里面)。

通过 show processlist,可以看到这条 delete 在 procedure 内部执行的时候,被 MySQL 自动加上了 NAME_CONST 函数,所以导致了以 ROW 模式记录 binlog 格式。那为什么在 procedure 中会被改写成这样的 SQL 呢?怎么样才能让这条 SQL 记录为 statement 的格式呢?

看了 MySQL 官方在 procedure 里面的限制描述,MySQL 会自动加上 NAME_CONST 主要是为了从机可以识别到 B_DATE 这个 SP 的 Local vairable,不至于从机回放的时候报错。
2、为什么 ROW 模式的 binlog 在从库回放的时候,即使 delete 的这张表有主键也很慢。
我们先看一下 SQL 线程回放是卡在哪里了?为什么会慢?
通过 pstack 抓取堆栈,找到 SQL_thread 线程对应的 thread 15,再结合 perf 信息,可以看到从机回放慢是卡在了 bitmap_get_next_set()。


看一下 bitmap_get_next_set()的代码。
bitmap_get_next_set()都是一些位运算,速度按理来说应该很快。所以不应该是程序卡在了这个函数中,大概率是因为多次调用了这个函数。所以我们再往上层继续看代码。

get_next_used_partition(uint part_id) 直接调用了 bitmap_get_next_set(),继续往上看。

try_semi_consistent_read() 这个函数中出现了可疑的循环,这里会调用 m_tot_parts 次 get_next_used_partition。看了一下定义 m_tot_parts 是分区表的总分区数!!!
看到这里,就真相大白了。
这个 delele 的 SQL 变更的行数大约在 300W 行左右,总共的分区表数是 7200 个。那么这里调用 bitmap_get_next_set 的次数就被放大成了 216 亿次!


对比以 statement 格式回放,从机的堆栈信息,并不会进入 bitmap_get_next_set。

解决方案
分析了这么久,怎么处理这么问题呢?
方案 1:我们最后在 SP 中强制制定了 session 的 binlog_format=statement,让这条 delete 在从机以 statement 的模式回放,这样就避免触发 MySQL 中的这个 bug。
方案 2:修复内核。
方案 3:在 shell 里面去调度,而不使用存储过程。
作者介绍:
张松坡,腾讯云数据库架构师,主要负责腾讯云数据库 MySQL、Redis 等数据库架构设计、数据库运维、运营开发等工作。曾就职于腾讯新闻、腾讯视频。
原文链接:
评论