MTS 性能监控你知道多少

前言

说到 MySQL 的 MTS，相信很多同学都不陌生，从 5.6 开始基于 schema 的并行回放，到 5.7 的 LOGICAL_CLOCK 支持基于事务的并行回放，这些内容都有文章讲解，在本篇文章不再赘述。今天要讲的是，你知道如何查看并行回放是否存在性能瓶颈吗，是由于主库事务行为导致无法并行回放，还是由于 worker 线程不足，限制了并行回放的天花板？这都得从一个 Note 信息说起。

MY-010559

在开启了多线程回放的从库 error log，我们经常能看到 Note 级别的日志信息 MY-010559

让我们来看看这些日志的含义

Seconds elapsed：当前时间与上次输出日志时间的间隔秒数

Events assigned：自 slave 协调线程启动后，累计处理分发给 worker 线程的 event 数量。简单理解为 slave 启动后处理的 event 数量。

Worker queues filled over overrun level：worker 线程处理的 event 队列长度超过最大队列数(目前代码硬编码 16384)的 90%的次数，如果 0 则说明未发生该情况。

Waited due to worker queue full：worker 线程处理的 event 队列长度达到最大(目前代码硬编码 16384)的次数，如果为 0 则说明未发生该情况，是前面Worker queues filled over overrun level的情况升级。

Waited due to the total size：协调线程分发 event 大小达到 replica_pending_jobs_size_max 或者 slave_pending_jobs_size_max 限制而产生等待的次数。前面两个参数是限制 worker 线程处理 event 队列能够申请的最大内存(即大事务)。如果遇到此种大事务，在回放该大事务之前，会等待其他 worker 线程处理完已分配 event，然后再进行该大事务的回放，回放过程中，后续的 event 回放，也会进入等待状态。总之，大事务回放特别影响并行回放的性能，只能串行回放。

Waited at clock conflicts：由于不能并行回放的累计等待时间，单位纳秒。如果并行回放策略设置的是 DATABASE 而不是 LOGICAL_CLOCK，该值一直为 0。

Waited (count) when workers occupied：协调线程休眠次数。有两种情况会累加此状态值：1、worker 线程达到最大队列数(目前代码硬编码 16384)的 90%，此种情况协调线程最多休眠 1 毫秒；2、并行回放策略设置为 LOGICAL_CLOCK 时，由于没有空闲的 worker 线程导致无法分配事务的第一个 event 而产生的等待，此种情况协调线程会一直处于等待状态直到有空闲的 worker 线程能够处理回放。

Waited when workers occupied：等待空闲的 worker 线程累计时间，单位纳秒，对应Waited (count) when workers occupied的第二种等待情况。

代码分析

在 8.0.26 版本的代码中，我们通过错误信息关键字waited at clock conflicts查找，发现信息记录在变量 ER_RPL_MTS_STATISTICS 中，

继续按变量查找，发现其使用在 rpl_replica.cc 文件的 apply_event_and_update_pos 函数中，主要逻辑代码如下

可以看到，满足如下几个条件，日志信息就会输出

1. 并行回放为开启状态

2. 并行回放的累计 event 数量对 1024 取模余 1

3. 当前时间减去上次日志时间间隔大于 mts_online_stat_period(硬编码 120)秒

4. error log 日志级别为 info(log_error_verbosity=3)

上述几个条件，和并行回放的事务繁忙程度并没有太大的关系，满足条件即会记录日志。假如一个事务有 4 个 event，参数设置正常，每两分钟执行 256 个事务，就会输出一条日志信息，一秒钟 3 个事务不到。

日志解析观察

在我的日志文件中，取了如下两条连续的信息

2023-07-09T08:58:01.001019+08:00 909 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'group_replication_applier': seconds elapsed = 180; events assigned = 11515905; worker queues filled over overrun level = 8314; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 136628031500 waited (count) when Workers occupied = 242457 waited when Workers occupied = 22232543519002023-07-09T09:00:01.648124+08:00 909 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'group_replication_applier': seconds elapsed = 120; events assigned = 11518977; worker queues filled over overrun level = 8314; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 136644607700 waited (count) when Workers occupied = 242491 waited when Workers occupied = 2223755727800

第一条解析信息如下：

. 本次日志输出时间点为2023-07-09T08:58:01.001019. 与上次日志输出间隔时间为180秒. 累计处理event数量为11515905. worker线程处理的event队列长度超过最大队列数(目前代码硬编码16384)的90%的累计次数8314次. worker线程处理的event队列长度达到最大队列数(目前代码硬编码16384)的累计次数为0次. 回放event大小达到replica_pending_jobs_size_max或者slave_pending_jobs_size_max的次数为0. 由于不能并行回放而产生的累计等待时间为136628031500纳秒(约136.62秒). 协调线程累计休眠242457次. 累计等待空闲worker线程的时间为2223254351900纳秒(约2223.33秒)

第二条解析信息如下：

. 本次日志输出时间点为2023-07-09T09:00:01.648124. 与上次日志输出间隔时间为120秒. 累计处理event数量为11518977，新增处理event数量3072(为1024的3倍). worker线程处理的event队列长度超过最大队列数(目前代码硬编码16384)的90%的累计次数8314次，新增0次. worker线程处理的event队列长度达到最大队列数(目前代码硬编码16384)的累计次数为0次. 回放event大小达到replica_pending_jobs_size_max或者slave_pending_jobs_size_max的次数为0. 由于不能并行回放而产生的累计等待时间为136644607700纳秒(约136.64秒，新增等待约0.02秒). 协调线程累计休眠242457次，新增34次. 累计等待空闲worker线程的时间为2223755727800纳秒(约2223.38，新增等待约0.05秒)

通过上述信息，可以看出，在日志阶段，系统处于空闲状态，处理事务数不多。 对比各个参数，在系统繁忙时，因为不能并行回放产生的等待时间为 136.64 秒，等待空闲的 worker 线程累计时间为 2223.38，因此增大 slave_parallel_workers 的参数值，可以提升并行回放性能。

总结

[Note] [MY-010559]在我刚开始接触时，以为是系统出现了异常产生的日志，待真正了解其内容后，才发现通过该日志可以帮助我们了解 MTS 运行情况，针对性的做优化调整。

参考链接https://dev.mysql.com/doc/refman/8.0/en/replication-threads-monitor-worker.html