MySQL复制从库延迟原因深入分析

背景介绍

近来一套业务系统，从库一直处于延迟状态，无法追上主库，导致业务风险较大。

从资源上看，从库的CPU、IO、网络使用率较低，不存在服务器压力过高导致回放慢的情况；从库开启了并行回放；在从库上执行 SHOW PROCESSLIST 看到没有回放线程阻塞，回放一直在持续；解析relay log日志文件，发现其中并没大事务回放。

过程分析

现象确认

收到运维同事的反馈，有一套从库延迟的非常厉害，提供了SHOW SLAVE STATUS
延迟的截图信息

持续观察了一阵SHOW SLAVE STATUS
的变化，发现pos点位信息在不停的变化，Seconds_Behind_master 也是不停的变化的，总体趋势还在不停的变大。

资源使用

观察了服务器资源使用情况，可以看到占用非常低

观察从库进程情况，基本上只能看到有一个线程在回放工作

并行回放参数说明

在主库设置了binlog_transaction_dependency_tracking = WRITESET

在从库设置了slave_parallel_type = LOGICAL_CLOCK
和slave_parallel_workers = 64

error log日志对比

从error log中取并行回放的日志进行分析

$ grep 010559 100werror3306.log | tail -n 3
2024-01-31T14:07:50.172007+08:00 6806 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'cluster': seconds elapsed = 120; events assigned = 3318582273; worker queues filled over overrun level = 207029; waite
d due a Worker queue full = 238; waited due the total size = 0; waited at clock conflicts = 348754579743300 waited (count) when Workers occupied = 34529247 waited when Workers occupied = 76847369713200

2024-01-31T14:11:50.060510+08:00 6806 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'cluster': seconds elapsed = 120; events assigned = 3319894017; worker queues filled over overrun level = 207029; waite
d due a Worker queue full = 238; waited due the total size = 0; waited at clock conflicts = 348943740455400 waited (count) when Workers occupied = 34542790 waited when Workers occupied = 76890229805500


上述信息的详细解释，可以参考 MTS性能监控你知道多少

去掉了发生次数比较少的统计，显示了一些关键数据的对比

可以发现自然时间120，回放的协调线程有90多秒由于无法并行回放而进入等待，有近20秒是由于没有空闲的work线程进入等待，折算下来协调线程工作的时间只有10秒左右。

并行度统计

众所周知，MySQL 从库并行回放主要依赖于 binlog 中的  last_commmitted 来做判断，如果事务的 last_commmitted 相同，则基本上可以认为这些事务可以并行回放，下面从环境中获取一个relay log进行并行回放的大概统计

$ mysqlsqlbinlog --no-defaults mysql-bin.046638 |grep -o 'last_committed.*' | sed 's/=/ /g' | awk '{print $2}' |sort -n | uniq -c |awk 'BEGIN {print "last_commited group_count Percentage"} {count[$2]=$1
; sum+=$1} END {for (i in count) printf "%d %d %.2f%%\n", i, count[i], (count[i]/sum)*100|"sort -k 1,1n"}' | awk '{if($2>=1 && $2 10){sum+=$2}} END {print sum}'
314694


上述第一条命令，是统计 last_commmitted 相同的事务数量在1-10个，即并行回放程度较低或者是无法并行回放，这些事务总数量为235703，占43%，详细解析并行回放度比较低的事务分布，可以看出这部分 last_commmitted 基本上都是单条的，都需要等待先序事务回放完成后，自己才能进行回放，这就会造成前面日志中观察到的协调线程等待无法并行回放而进入等待的时间比较长的情况

$ mysqlbinlog --no-defaults mysql-bin.046638 |grep -o 'last_committed.*' | sed 's/=/ /g' | awk '{print $2}' |sort -n | uniq -c |awk 'BEGIN {print "last_commited group_count Percentage"} {count[$2]=$1; sum+=$1} END {for (i in count) printf "%d %d %.2f%%\n", i, count[i], (count[i]/sum)*100|"sort -k 1,1n"}' | awk '{if($2>=1 && $2 11){print $0}}' | column -t
last_commited  group_count  Percentage
1              7340         1.33%
11938          7226         1.31%
23558          7249         1.32%
35248          6848         1.24%
46421          7720         1.40%
59128          7481         1.36%
70789          7598         1.38%
82474          6538         1.19%
93366          6988         1.27%
104628         7968         1.45%
116890         7190         1.31%
128034         6750         1.23%
138849         7513         1.37%
150522         6966         1.27%
161989         7972         1.45%
175599         8315         1.51%
189320         8235         1.50%
202845         8415         1.53%
218077         8690         1.58%
234248         8623         1.57%
249647         8551         1.55%
264860         8958         1.63%
280962         8900         1.62%
297724         8768         1.59%
313092         8620         1.57%
327972         9179         1.67%
344435         8416         1.53%
359580         8924         1.62%
375314         8160         1.48%
390564         9333         1.70%
407106         8637         1.57%
422777         8493         1.54%
438500         8046         1.46%
453607         8948         1.63%
470939         8553         1.55%
486706         8339         1.52%
503562         8385         1.52%
520179         8313         1.51%
535929         7546         1.37%


last_committed 机制介绍

主库的参数binlog_transaction_dependency_tracking
用于指定如何生成其写入二进制日志的依赖信息，以帮助从库确定哪些事务可以并行执行，即通过该参数控制 last_commmitted 的生成机制，参数可选值有 COMMIT_ORDER、WRITESET、SESSION_WRITESET。从下面这段代码，很容易看出来三种参数关系：

1. 基础算法为 COMMIT_ORDER。
2. WRITESET 算法是在 COMMIT_ORDER 基础上再计算一次。
3. SESSION_WRITESET 算法是在 WRITESET 基础上再计算一次。

由于当前数据库实例设置的是WRITESET，因此只需关注 COMMIT_ORDER 算法和 WRITESET 算法即可。

COMMIT_ORDER

COMMIT_ORDER 计算规则：如果两个事务在主节点上是同时提交的，说明两个事务的数据之间没有冲突，那么一定也是可以在从节点上并行执行的，理想中的典型案例如下面的例子

但对于 MySQL 来说，group_commit 是内部行为，只要 session-1 和 session-2 是同时执行 commit，不管内部是否合并为 group_commit，两个事务的数据本质上都是没有冲突的；再退一步来讲，只要 session-1 执行 commit 之后，session-2 没有新的数据写入，两个事务依旧没有数据冲突，依然可以并行复制。

对于更多并发线程的场景，可能这些线程不能同时并行复制，但部分事务却可以。以如下一个执行顺序来说，在 session-3 提交之后，session-2 没有新的写入，那么这两个事务是可以并行复制的；而 session-3 提交后，session-1 又插入了一条新的数据，此时无法判定数据冲突，所以 session-3 和 session-1 的事务无法并行复制；但 session-2 提交后，session-1 之后没有新数据写入，所以 session-2 和 session-1 又可以并行复制。因此，这个场景中，session-2 分别可以和 session-1、session-3 并行复制，但3个事务无法同时并行复制。

WRITESET

实际上是 commit_order + writeset 的组合，会先通过 commit_order 计算出一个last_commmitted 值，然后再通过 writeset 计算一个新值，最后取两者间的小值作为最终事务 GTID 的 last_commmitted。

在 MySQL 中，writeset 本质上是对 schema_name + table_name + primary_key/unique_key 计算的hash值，在DML执行语句过程中，通过 binlog_log_row 生成 row_event 之前，会将DML语句中所有的主键/唯一键都单独计算hash值，并加入到事务本身的 writeset 列表中。而如果存在无主键/唯一索引的表，还会对事务设置 has_missing_keys=true。

参数设置为 WRITESET，但是并不一定就能使用上，其限制如下

1. 非DDL语句或者表具有主键或者唯一键或者空事务。
2. 当前session使用的hash算法与hash map中的一致。
3. 未使用外键。
4. hash map的容量未超过 binlog_transaction_dependency_history_size 的设置
   以上4个条件均满足时，则可以使用 WRITESET 算法，如果有任意一个条件不满足，则会退化为 COMMIT_ORDER 计算方式。

具体 WRITESET 算法如下，事务提交时：

1. last_commmitted 设置为 m_writeset_history_start，此值为 m_writeset_history 列表中最小的 sequence_number。

2. 遍历事务的 writeset 列表

   a 如果某个 writeset 在全局 m_writeset_history 中不存在，构建一个 pair