MySQL主从同步机制和同步延时问题追查

古城微笑少年丶 2022-03-07 13:14 228阅读 0赞

今天遇到一个问题，`Mysql`持续报错，主从同步延时数过大或错误。所以这篇文章给大家分享下主从同步的机制原理以及问题排查思路。

## 故障表现 ##

最直观的表现为：

mysql> show slave status\G;
        // 状态一
        Seconds_Behind_Master: NULL
        // 状态二
        Seconds_Behind_Master: 0
        // 状态三
        Seconds_Behind_Master: 79

连续查询，大部分时间该属性值`=0`，偶发性出现`Null`或者`79`等延时值。导致观察主从同步延时的监控持续报警。

## 故障原因及解决方案 ##

多台备机的`server-id`一致，导致主机无法长时间同某一台备机连接，进而无法正常同步。

修改`server-id`后，重启数据库恢复。

## 主从同步机制 ##

![图片描述][3476590983-5c6515b777260_articlex]

`MySQL`的主从同步，又称为复制（`replication`），是一种内置的高可用高性能集群解决方案，主要功能有：

1.  `数据分布`：同步不需要很大带宽，可以实现多数据中心复制数据。
2.  `读取的负载均衡`：通过服务器集群，可以通过`DNS`轮询、`Linux LVS`等`GSLB`（全局负载均衡）方式，降低主服务器的读压力。
3.  `数据库备份`：复制是备份的一部分，但并不能代替备份。还需要与快照相结合。
4.  `高可用性和故障转移`：从服务器可以快速切换为主服务器，减少故障的停机时间和恢复时间。

主从同步分为3步：

1.  主服务器（`master`）把数据更改记录到二进制日志（`binlog`）中。
2.  从服务器（`slave`）把主服务器的二进制日志复制到自己的中继日志（`relay log`）中。
3.  从服务器重做中继日志中的日志，把更改应用到自己的数据库上，达到数据的一致性。

主从同步是一个异步实时的同步，会实时的传输，但存在执行上的延时，如果主服务器压力很大，延时也会相应扩大。

通过上面的图，可以看到一共需要3个线程：

1.  主服务器的日志传送线程：负责将二进制日志增量传送到备机
2.  从服务器的`I/O`线程：负责读取主服务器的二进制日志，并保存为中继日志
3.  从服务器的`SQL`线程，负责执行中继日志

### 查看`MySQL`线程 ###

我们可以使用`show full processlist;`命令来查看`MySQL`的状态：

主机的状态：  
![图片描述][3144972184-5c651a6d1a2e4_articlex]

备机的状态：  
![图片描述][1800434982-5c651a84048b7_articlex]

可以看到，我的集群架构为1台主机、4台备机，所以在主机中有4个同步线程（已经发送所有的`binlog`数据到备机，等待`binlog`日志更新），1个查看命令线程（`show full processlist`）。在备机中有1个查看命令线程，1个`I/O`线程（等待主机发送同步数据事件），1个`SQL`线程（已经读取了所有中继日志，等待`I/O`线程来更新它）。

### 查看同步状态 ###

因为主从同步是异步实时的，也就是会存在延时的情况，我们可以通过`show slave status;`来查看备机上的同步延时：

![图片描述][4169939472-5c651ce8ed2fd_articlex]

在主从同步中我们需要关注的一些属性，已经给大家标红了：

1.  `Slave_IO_State`: 当前`I/O`线程的状态
2.  `Master_Log_File`: 当前同步的主服务器的二进制文件
3.  `Read_Master_Log_Pos`: 当前同步的主服务器的二进制文件的偏移量，单位为字节，如图中为已经同步了`12.9M(13630580/1024/1024)`的内容
4.  `Relay_Master_Log_File`: 当前中继日志同步的二进制文件
5.  `Slave_IO_Running`: 从服务器中`I/O`线程的运行状态，`YES`为运行正常
6.  `Slave_SQL_Running`: 从服务器中`SQL`线程的运行状态，`YES`为运行正常
7.  `Exec_Master_Log_Pos`: 表示同步完成的主服务器的二进制日志偏移量
8.  `Seconds_Behind_Master`: 表示从服务器数据比主服务器落后的持续时长

同样可以通过`show master status;`命令来查看主服务器的运行状态：  
![图片描述][1941385972-5c65225cd4624_articlex]

正常运行的主从同步状态：

Slave_IO_Running: YES
    Slave_SQL_Running: YES
    Seconds_Behind_Master: 0

## 问题排查 ##

在理解了主从同步的机制后，再来看今天遇到的问题，通过查看备机状态，我们观察在三种状态下的几个关键属性值：

mysql> show slave status\G;
    #状态一：
        Slave_IO_State: Reconnecting after a failed master event read
        Slave_IO_Running: No
        Slave_SQL_Running: Yes
        Seconds_Behind_Master: NULL
    #状态二：
        Slave_IO_State: Waiting for master to send event
        Slave_IO_Running: Yes
        Slave_SQL_Running: Yes
        Seconds_Behind_Master: 0
    #状态三：
        Slave_IO_State: Queueing master event to the relay log
        Slave_IO_Running: Yes
        Slave_SQL_Running: Yes
        Seconds_Behind_Master: 636

通过[MySQL主从复制线程状态转变][MySQL]，我们可以看到三种状态的不同含义：

# 状态一
    # 线程正尝试重新连接主服务器，当连接重新建立后，状态变为Waiting for master to send event。
    Reconnecting after a failed master event read
    # 状态二
    # 线程已经连接上主服务器，正等待二进制日志事件到达。如果主服务器正空闲，会持续较长的时间。如果等待持续slave_read_timeout秒，则发生超时。此时，线程认为连接被中断并企图重新连接。
    Waiting for master to send event
    
    # 状态三
    # 线程已经读取一个事件，正将它复制到中继日志供SQL线程来处理。
    Queueing master event to the relay log

在这里，我们可以猜测，由于某些原因，从服务器不断的和主服务器进行断开并尝试重连，重连成功后又再次断开。

我们再看看主机的运行情况：  
![图片描述][1560107141-5c65298c520e1_articlex]

发现问题出在`10.144.63.*`和`10.144.68.*`两台机器上，我们查看其中一台的错误日志：

190214 11:33:20 [Note] Slave: received end packet from server, apparent master shutdown: 
    190214 11:33:20 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'mysql-bin.005682' at postion 13628070

拿到关键字`Slave: received end packet from server, apparent master shutdown:` `Google`搜索一下，在文章[Confusing MySQL Replication Error Message][]中可以看到原因为两台备机的`server-id`重复。

> One day it happen to me, and took me almost an hour to find that out.  
> Moving foward I always use a base my.cnf to I copy to any other server and the first thing is to increase the server-id.  
> Could MySQL just use the servername intead of a numeric value?

## 问题修复 ##

定位了问题，我们确认下是否重复，发现两台备机的该字段确实相同：

vim my.cnf
    
    #replication
    log-bin=mysql-bin
    # 这个随机数字相同导致的
    server-id=177230069
    sync_binlog=1

更改一个其他不同的数字，保存，重启`MySQL`进程，报警恢复。

## 总结 ##

最终来看，这个问题的解决非常简单，但从刚开始的迷茫到最后的思路清晰，都是我们排查问题所常见的，这篇文章的主要收获是让你明白主从同步的机制和追查问题的思路，希望下次我们都能很快的解决主从同步带给我们的问题。

## 参考资料 ##

1.  《MySQL基础内幕 InnoDB存储引擎 第2版》P8.7 复制
2.  MySQL主从复制线程状态转变: [http://www.ywnds.com/?p=3821][MySQL]
3.  Confusing MySQL Replication Error Message: [https://www.percona.com/blog/...][Confusing MySQL Replication Error Message]

[3476590983-5c6515b777260_articlex]: /images/20220307/7a8a0736e2ef4d97a5099f1d2de0b0e5.png
[3144972184-5c651a6d1a2e4_articlex]: /images/20220307/52816b1b7ad24691b3b6b54402842fda.png
[1800434982-5c651a84048b7_articlex]: /images/20220307/c14b68c8c6cd407dbe7f1020bd03b302.png
[4169939472-5c651ce8ed2fd_articlex]: /images/20220307/d36dd017e4684fe2978a58d987acb9f1.png
[1941385972-5c65225cd4624_articlex]: /images/20220307/6198971c9271423b81d595f01fe72d37.png
[MySQL]: http://www.ywnds.com/?p=3821
[1560107141-5c65298c520e1_articlex]: /images/20220307/6ad80fd319da47228549dbeaeafc7a12.png
[Confusing MySQL Replication Error Message]: https://www.percona.com/blog/2008/06/04/confusing-mysql-replication-error-message/