为什么在MySQL双主单写的情况下主库偶尔出现大量延迟

共计 4678 个字符，预计需要花费 12 分钟才能阅读完成。

为什么在 MySQL 双主单写的情况下主库偶尔出现大量延迟，相信很多没有经验的人对此束手无策，为此本文总结了问题出现的原因和解决方法，通过这篇文章希望你能解决这个问题。

我们是双主单写，这里约定写入的库为主库，没有写入的库为从库。我们的 falcon 偶尔会进行报警如下（频率很低）：

这是非常奇怪的，按理说我是单写的从库没有做任何操作（除了应用 Event 以外），主库哪来的延迟，并且延迟这么大。在我映像中有朋友问过这个问题，当时没有细细研究。

二、延迟计算的规则

我们还是要看看主从计算延迟的伪代码：

/*
 The pseudo code to compute Seconds_Behind_Master:
 if (SQL thread is running)
// 如果 SQL 线程启动了
 { if (SQL thread processed all the available relay log)
// 如果 SQL 线程已经应用完了所有的 IO 线程写入的 Event
 { if (IO thread is running)
// 如果 IO 线程启动了
 print 0;
// 设置延迟为 0
 else
 print NULL;
// 否则为空值
 }
 else
 compute Seconds_Behind_Master;
// 如果 SQL 线程没有应用完所有的 IO 线程写入的 Event，那么需要计算延迟。 }
 else
 print NULL;
// 如果连 SQL 线程也没有启动则设置为空值
 */

计算延迟的公式为：

long time_diff= ((long)(time(0)
 - mi- rli- last_master_timestamp)
 - mi- clock_diff_with_master);
服务器当前时间 -Event header 中的 timestamp -  主从服务器时间差

出现延迟的必要条件：

如果 SQL 线程没有应用完了所有的 IO 线程写入的 Event，也就是 Read_Master_Log_Pos 和 Exec_Master_Log_Pos 存在一定的差值。判定标准为

(mi- get_master_log_pos() == mi- rli- get_group_master_log_pos())  
 (!strcmp(mi- get_master_log_name(), mi- rli- get_group_master_log_name()))

抛开文件名，也就是通过 IO 线程读取到主库 binary log 的位置 和 SQL 线程应用到的主库 binary log 位置进行比较来进行 判断，只要他们出现差值就会进入延迟计算环节。

服务器当前时间 -Event header 中的 timestamp – 主从服务器时间差 这个公式必须出现差值。

好了接下来带着这两个产生延迟的必要条件来寻求原因。

三、产生延迟的原因

1. 主库：首先主库写到从库的 Event，从库会写入到 binlog（log_slave_updates 开启），并且从库的 DUMP 线程会发送给主库，但是主库的 IO 线程通过 SERVER_ID 进程判定，将 Event 进行过滤，不写入主库的 relay log，同时会更新主库 IO 线程读取的位置（Read_Master_Log_Pos），并且更新忽略到的位置（rli- ign_master_log_name_end[0]）。代码如下：

 if (!(s_id == ::server_id   !mi- rli- replicate_same_server_id) ||
 (event_type != binary_log::FORMAT_DESCRIPTION_EVENT  
 event_type != binary_log::ROTATE_EVENT  
 event_type != binary_log::STOP_EVENT))
 { mi- set_master_log_pos(mi- get_master_log_pos() + inc_pos);// 增加 Read_Master_Log_Pos 位点，为当前位置  
 memcpy(rli- ign_master_log_name_end, mi- get_master_log_name(), FN_REFLEN); // 进行拷贝
 DBUG_ASSERT(rli- ign_master_log_name_end[0]); // 断言存在
 rli- ign_master_log_pos_end= mi- get_master_log_pos(); // 忽略到位点
 }

主库：SQL 线程会通过 rli- ign_master_log_name_end[0]判定是否有需要跳过的 Event，如果有则构建一个 Rotate_log_event 来跳过这个 Event，代码如下：

if (rli- ign_master_log_name_end[0]) // 如果跳过的 Event 存在
 {
 /* We generate and return a Rotate, to make our positions advance */
 DBUG_PRINT(info ,( seeing an ignored end segment));
 ev= new Rotate_log_event(rli- ign_master_log_name_end,
 0, rli- ign_master_log_pos_end, exec_relay_log_event 
 Rotate_log_event::DUP_NAME); // 构建一个 Rotate Event，位置为
 rli- ign_master_log_name_end[0]= 0; //rli- ign_master_log_pos_end，执行这个 Event 就可以
 mysql_mutex_unlock(log_lock);exec_relay_log_event // 来更新 Exec_Master_Log_Pos 位点
 if (unlikely(!ev))
 {
 errmsg=  Slave SQL thread failed to create a Rotate event  
  (out of memory?), SHOW SLAVE STATUS may be inaccurate 
 goto err;
 }
 ev- server_id= 0; // don t be ignored by slave SQL thread
 DBUG_RETURN(ev);
 }

好了到这里我们知道了 Event 在主库是如何跳过的，但是注意 IO 线程和 SQL 线程在处理 Read_Master_Log_Pos 和 Exec_Master_Log_Pos 的时候可能有一定的时间差，那么 Read_Master_Log_Pos 和 Exec_Master_Log_Pos 存在一定的差值 的条件就可能会满足，则进入延迟计算环节。

主库的 SQL 线程平时并没有读取到 Event，因为所有的 Event 都被 IO 线程过滤掉了。因此
Event 的 header 中的 timestamp 不会更新（MTS）。但是如果从库 binlog 切换的时候，从库至少会传送 ROTATE_EVENT 给主库，这个时候主库会拿到这个实际的 Event，因此 Event 的 header 中的 timestamp 更新了。如果刚好遇到主库的 IO 线程的 Read_Master_Log_Pos 和 Exec_Master_Log_Pos 有差值，
那么 falcon 去查看延迟就会得到一个延迟很大的假象，延迟的计算公式就会变为如下：

主库当前的时候 – 从库上次 binlog 切换的时间 – 主从时间的差值

MTS 和单线程的不同

上面的第 3 点只适用于 MTS，单 SQL 线程不同，会去将 last_master_timestamp 设置为 0，代码如下：

 if (!rli- is_parallel_exec())
 rli- last_master_timestamp= 0;

言外之意单 SQL 线程计算延迟的公式为：

主库当前的时间 – 1970 年 1 月 1 日 0 点 – 主从时间的差值

因此看起来计算出来的延迟会更大。

最后需要注意的是实际上这种情况的延迟并没有问题，完全是一种偶尔出现的计算上的问题，是一种假象，如果主库的压力越大出现这种情况的可能性就会越大，因为 IO 线程和 SQL 线程在处理 Read_Master_Log_Pos 和 Exec_Master_Log_Pos 的出现时间差的可能性就会越大。

四、MTS 下的延迟 debug

其实知道了原理就很容易 debug 了，因为我们可以将断点放到主库的 show_slave_status_send_data 函数上，那么就能看出来了，做的操作如下：

从库 flush binary logs

主库执行一些 insert 操作

主库 show slave status

这个时候我们可以跳过（Read_Master_Log_Pos 和 Exec_Master_Log_Pos 存在一定的差值）这个条件，直接通过公式去计算，得到如下结果：

(gdb) p (long)(time(0)- mi- rli- last_master_timestamp)- mi- clock_diff_with_master
$6 = 37

延迟就是 37 秒，因此我们的理论得到了验证。

下面一个 debug 结果是单 SQL 线程的，可以看到延迟更是大得离谱。

(gdb) p (long)(time(0)- mi- rli- last_master_timestamp)- mi- clock_diff_with_master
$7 = 1592672402

五、其他问题

额外的问题：

如果双主双写

S1S2
T1T2

T3

如果按照上面的理论那么 T3 的更新的位置可能会被，T2 事务的位点重置。因为主库的 SQL 线程通过构建的 Rotate_log_event 可能会出现 Exec_Master_Log_Pos 倒退的可能性，这显然是不行的。但是代码中构建 Rotate_log_event 的逻辑包裹在如下逻辑下面。

if (!cur_log- error) /* EOF */ // 当前 relay log  已经读取完了
 {
 /*
 On a hot log, EOF means that there are no more updates to
 process and we must block until I/O thread adds some and
 signals us to continue
 */
 if (hot_log) // 如果是   当前 relay log

我们可以看到只有在当前 relay log 读取完成后才会进行 Rotate_log_event 的构建。因此不存在此问题。

问题如上虽然不构建 Rotate_log_event，但是如果 rli- ign_master_log_name_end[0]如果一直保留那么当 relay log 应用完成后，依旧会去构建 Rotate_log_event 导致 Exec_Master_Log_Pos 倒退，实际上这个问题也不会出现，因为在每次 IO 线程 Event 写入到 relay log 后会重置，如下：

 rli- ign_master_log_name_end[0]= 0; // last event is not ignored

看完上述内容，你们掌握为什么在 MySQL 双主单写的情况下主库偶尔出现大量延迟的方法了吗？如果还想学到更多技能或想了解更多相关内容，欢迎关注丸趣 TV 行业资讯频道，感谢各位的阅读！