MySQL 双主单写，主库偶尔出现大量延迟的原因

作者：高鹏（网名八怪），《深入理解MySQL主从原理32讲》系列的作者。系列链接：https://www.jianshu.com/nb/43148932
版本：5.7.29
水平有限有误请谅解
一、问题来源这是来自我们线上数据库的一个问题。我们是双主单写，这里约定写入的库为主库，没有写入的库为从库。我们的falcon偶尔会进行报警如下（频率很低）：
这是非常奇怪的，按理说我是单写的从库没有做任何操作（除了应用Event以外），主库哪来的延迟，并且延迟这么大。在我映像中有朋友问过这个问题，当时没有细细研究。二、延迟计算的规则我们还是要看看主从计算延迟的伪代码：
/*ThepseudocodetocomputeSeconds_Behind_Master:if(SQLthreadisrunning)//如果SQL线程启动了{if(SQLthreadprocessedalltheavailablerelaylog)//如果SQL线程已经应用完了所有的IO线程写入的Event{if(IOthreadisrunning)//如果IO线程启动了print0;//设置延迟为0elseprintNULL;//否则为空值}elsecomputeSeconds_Behind_Master;//如果SQL线程没有应用完所有的IO线程写入的Event，那么需要计算延迟。}elseprintNULL;//如果连SQL线程也没有启动则设置为空值*/计算延迟的公式为：
longtime_diff=((long)(time(0)-mi->rli->last_master_timestamp)-mi->clock_diff_with_master);也就是：服务器当前时间-Eventheader中的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 – 主从服务器时间差 这个公式必须出现差值。
好了接下来带着这两个产生延迟的必要条件来寻求原因。关于更多延迟计算的细节参考：https://www.jianshu.com/p/033f83314619
三、产生延迟的原因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存在{/*WegenerateandreturnaRotate,tomakeourpositionsadvance*/DBUG_PRINT(“info”,(“seeinganignoredendsegment”));ev=newRotate_log_event(rli->ign_master_log_name_end,0,rli->ign_master_log_pos_end,exec_relay_log_eventRotate_log_event::DUP_NAME);//构建一个RotateEvent，位置为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=”SlaveSQLthreadfailedtocreateaRotateevent””(outofmemory),SHOWSLAVESTATUSmaybeinaccurate”;gotoerr;}ev->server_id=0;//don’tbeignoredbyslaveSQLthreadDBUG_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五、其他问题额外的问题：
如果双主双写
S1S2T1T2T3如果按照上面的理论那么T3的更新的位置可能会被T2事务的位点重置。因为主库的SQL线程通过构建的Rotate_log_event可能会出现Exec_Master_Log_Pos倒退的可能性，这显然是不行的。但是代码中构建Rotate_log_event的逻辑包裹在如下逻辑下面。
if(!cur_log->error)/*EOF*///当前relaylog已经读取完了{/*Onahotlog,EOFmeansthattherearenomoreupdatestoprocessandwemustblockuntilI/Othreadaddssomeandsignalsustocontinue*/if(hot_log)//如果是当前relaylog我们可以看到只有在当前 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;//lasteventisnotignored
Enjoy MySQL 🙂
全文完。
由叶老师主讲的知数堂「MySQL优化课」课程早已升级到MySQL 8.0版本了，现在上车刚刚好，扫码开启MySQL 8.0的修行之旅吧。
另外，叶老师在腾讯课堂《MySQL性能优化》精编版第一期已完结，本课程讲解读几个MySQL性能优化的核心要素：合理利用索引，降低锁影响，提高事务并发度。
下面是自动拼团的二维码直接享受组团价