MYSQL主从同步异常解决方案
MYSQL主从同步异常解决方案
理论上讲，mysql的主从同步无法保证100%不出现异常，mysql本身并不能保证主从的稳定性，当前较流行的MHA等mysql主从同步解决方案也是尽最大努力保证数据的一致性，出现异常还是要进行人工干预。对于MYSQL加快主从同步的方式，经历了库间并发 - 组提交 - WriteSet等一系列减缓复制延迟的问题，但是很遗憾，主从复制做的在快，也解决不了中途出现异常的情况，本文基于MYSQL采用 binlog和利用组提交方式的前提，探讨在主从复制期间产生异常后，应如何解决，达到防止数据丢失，最终恢复主从关系的目的。
前提知识
为了方便阅读，我们定义两台服务器分别是A，B，A作为master，B是slaver。（主主原理一样）。在设置主从时，为了防止因配置导致的主从同步问题，最好将主从的参数设置保持一致。
主从同步流程
B中有两个重要的线程，一个是I/O线程，负责同步A的binlog日志文件，然后将日志文件写到磁盘，写到磁盘的文件起了个名字，叫中继日志，也就是relaylog；另一个是SQL线程，负责读取relaylog中的sql，在从节点重放SQL，以达到主从同步的目的，当然这里面有很多优化细节，例如组提交模式下的线程模型，如何调节relaylog参数，使得中继日志快速落地等，这不属于本文讨论的范围。mysql就是使用此种方式，将AB数据同步。
binlog日志格式
binlog都很熟悉，这是mysql执行命令的底牌，不区分存储引擎，就像流水账一样，将mysql引擎层执行的sql，尽可能详细的记录在案。但是太详细，就会使得binlog日志过大，太少，则无法还原真实面貌。那记录的方式就成了关键，MYSQL为我们提供了三种记录方式，使用binlog_format = row|statement|mixed，特定类型下还有一些细微的调节。
通过以下命令可以明文显示binlog的内容
mysqlbinlog -vv --base64-output=DECODE-ROWS mysql-bin.000001
下面以tb_test(id, stu_id, name)这个表为例子
（1）statement: 这种方式最好理解，直接将sql语句记录在binlog中，但是缺点很明显，例如insert into tb_test values(1, uuid(), 'nnn');这样从在执行时，导致id主从不一致
# at 609
#210922 14:01:36 server id 1 end_log_pos 733 CRC32 0x65647349 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1632290496/*!*/;
insert into tb_test values(1, uuid(), 'nnn')
/*!*/;
# at 733
#210922 14:01:36 server id 1 end_log_pos 764 CRC32 0x0829c9d1 Xid = 21
COMMIT/*!*/;
（2）row：这是mysql默认的方式，不会出现statement的问题，单同样有缺点，在update时，会将所有的列都输出到binlog日志中，导致 binlog的增长量很快，例如现有表 tb_test(id, stu_id, name)，在执行update tb_test set name= 'xxx' where id=1;真正记录binlog的是
# at 294
#210922 14:11:33 server id 1 end_log_pos 353 CRC32 0x52746c43 Table_map: `test_db`.`tb_test` mapped to number 108
# at 353
#210922 14:11:33 server id 1 end_log_pos 481 CRC32 0x4e0adf53 Update_rows: table id 108 flags: STMT_END_F
### UPDATE `test_db`.`tb_test`
### WHERE
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2='28851e78-1b6b-11ec-a9d1-d8c497b8d38b' /* VARSTRING(233) meta=233 nullable=1 is_null=0 */
### @3='xx' /* VARSTRING(22) meta=22 nullable=1 is_null=0 */
### SET
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2='28851e78-1b6b-11ec-a9d1-d8c497b8d38b' /* VARSTRING(233) meta=233 nullable=1 is_null=0 */
### @3='xxdd' /* VARSTRING(22) meta=22 nullable=1 is_null=0 */
# at 481
#210922 14:11:33 server id 1 end_log_pos 512 CRC32 0x59324426 Xid = 6
COMMIT/*!*/;
这样在where和set后将所有字段都列出，当然也能精简binlog的输出，在ROW模式下，使用 binlog_row_image=minimal|full|noblob，其中full是默认的，如上，将镜像前后都设置，所谓镜像就是表在执行update前的数据情况，where记录了镜像前的数据（BI），set记录镜像后的数据（AI），binlog中对于insert只有AI，delete只有BI，而update包含BI和AI，使用minimal后，如下：
# at 294
#210922 14:14:21 server id 1 end_log_pos 353 CRC32 0x029a51df Table_map: `test_db`.`tb_test` mapped to number 108
# at 353
#210922 14:14:21 server id 1 end_log_pos 441 CRC32 0x6cc35569 Update_rows: table id 108 flags: STMT_END_F
### UPDATE `test_db`.`tb_test`
### WHERE
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2='3d3475ee-1b6c-11ec-9c36-d8c497b8d38b' /* VARSTRING(233) meta=233 nullable=1 is_null=0 */
### @3='nnn' /* VARSTRING(22) meta=22 nullable=1 is_null=0 */
### SET
### @3='xxdd' /* VARSTRING(22) meta=22 nullable=1 is_null=0 */
# at 441
#210922 14:14:21 server id 1 end_log_pos 472 CRC32 0x1d0bc509 Xid = 5
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
为什么使用了minimal，镜像前仍然是全量数据，因为mysql规定，如果表没有主键，则镜像前依然和full一样，这里给tb_test增加个主键，alter table tb_test add PRIMARY key(id);在执行update
# at 797
#210922 14:16:03 server id 1 end_log_pos 856 CRC32 0x49bd88c1 Table_map: `test_db`.`tb_test` mapped to number 109
# at 856
#210922 14:16:03 server id 1 end_log_pos 904 CRC32 0xde32ec90 Update_rows: table id 109 flags: STMT_END_F
### UPDATE `test_db`.`tb_test`
### WHERE
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### SET
### @3='xxdds' /* VARSTRING(22) meta=22 nullable=1 is_null=0 */
# at 904
#210922 14:16:03 server id 1 end_log_pos 935 CRC32 0xdacdff35 Xid = 9
COMMIT/*!*/;
（3）mixed：两者的结合，一般的SQL语句以statement形式展示sql语句，当涉及uuid等函数时，使用row的形态；
在使用row和mixed时，可能会问，真正执行的sql语句无法从binlog中展示，很幸运，mysql为我们提供了binlog_rows_query_log_events参数，设置ON|1时，sql语句会以注释的形式写在binlog中
生产建议使用binlog_format=row 配合 binlog_row_image=minimalbinlog日志内容
-- binlog开头用语
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210922 14:46:31 server id 1 end_log_pos 123 CRC32 0x97df49ac Start: binlog v 4, server v 5.7.27-0kord0.16.04.1k2-log created 210922 14:46:31 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 123
#210922 14:46:31 server id 1 end_log_pos 154 CRC32 0x85340b11 Previous-GTIDs
# [empty]
-- 创建数据库
# at 154
#210922 14:48:11 server id 1 end_log_pos 219 CRC32 0x0ccb3436 Anonymous_GTID last_committed=0 sequence_number=1 rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#210922 14:48:11 server id 1 end_log_pos 402 CRC32 0xdfce7c53 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1632293291/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
CREATE DATABASE /*!32312 IF NOT EXISTS*/`my_db` /*!40100 DEFAULT CHARACTER SET utf8 */
/*!*/;
-- 创建表
# at 402
#210922 14:54:57 server id 1 end_log_pos 467 CRC32 0x063edb06 Anonymous_GTID last_committed=1 sequence_number=2 rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 467
#210922 14:54:57 server id 1 end_log_pos 637 CRC32 0xa22dd94a Query thread_id=2 exec_time=0 error_code=0
use `my_db`/*!*/;
SET TIMESTAMP=1632293697/*!*/;
create table tb_test (id int,stu_id varchar(64),name varchar(32)) ENGINE=INNODB
/*!*/;
-- insert表数据
# at 637
#210922 14:56:18 server id 1 end_log_pos 702 CRC32 0xa55b302a Anonymous_GTID last_committed=2 sequence_number=3 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 702
#210922 14:56:18 server id 1 end_log_pos 782 CRC32 0x15ecbfb9 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1632293778/*!*/;
BEGIN
/*!*/;
# at 782
#210922 14:56:18 server id 1 end_log_pos 846 CRC32 0xf0b67ceb Table_map: `my_db`.`tb_test` mapped to number 112
# at 846
#210922 14:56:18 server id 1 end_log_pos 897 CRC32 0xce3a064c Write_rows: table id 112 flags: STMT_END_F
### INSERT INTO `my_db`.`tb_test`
### SET
### @1=1 /* INT meta=0 nullable=1 is_null=0 */
### @2='1111' /* VARSTRING(192) meta=192 nullable=1 is_null=0 */
### @3='nanan' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
# at 897
#210922 14:56:18 server id 1 end_log_pos 928 CRC32 0x1a1f19ed Xid = 17
COMMIT/*!*/;
-- update表
# at 928
#210922 14:57:31 server id 1 end_log_pos 993 CRC32 0x638f8e2f Anonymous_GTID last_committed=3 sequence_number=4 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 993
#210922 14:57:31 server id 1 end_log_pos 1073 CRC32 0x5234432b Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1632293851/*!*/;
BEGIN
/*!*/;
# at 1073
#210922 14:57:31 server id 1 end_log_pos 1137 CRC32 0x499487e2 Table_map: `my_db`.`tb_test` mapped to number 112
# at 1137
#210922 14:57:31 server id 1 end_log_pos 1195 CRC32 0x521abeb5 Update_rows: table id 112 flags: STMT_END_F
### UPDATE `my_db`.`tb_test`
### WHERE
### @1=1 /* INT meta=0 nullable=1 is_null=0 */
### @2='1111' /* VARSTRING(192) meta=192 nullable=1 is_null=0 */
### @3='nanan' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
### SET
### @3='xxxx' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
# at 1195
#210922 14:57:31 server id 1 end_log_pos 1226 CRC32 0xb9a42b3a Xid = 18
COMMIT/*!*/
-- delete
# at 1226
#210922 14:58:31 server id 1 end_log_pos 1291 CRC32 0x913de440 Anonymous_GTID last_committed=4 sequence_number=5 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1291
#210922 14:58:31 server id 1 end_log_pos 1371 CRC32 0x29f9b016 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1632293911/*!*/;
BEGIN
/*!*/;
# at 1371
#210922 14:58:31 server id 1 end_log_pos 1435 CRC32 0x008566a7 Table_map: `my_db`.`tb_test` mapped to number 112
# at 1435
#210922 14:58:31 server id 1 end_log_pos 1485 CRC32 0xb2abadc4 Delete_rows: table id 112 flags: STMT_END_F
### DELETE FROM `my_db`.`tb_test`
### WHERE
### @1=1 /* INT meta=0 nullable=1 is_null=0 */
### @2='1111' /* VARSTRING(192) meta=192 nullable=1 is_null=0 */
### @3='xxxx' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
# at 1485
#210922 14:58:31 server id 1 end_log_pos 1516 CRC32 0xdaabfcd8 Xid = 19
COMMIT/*!*/;
-- binlog文件结尾用语
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
由上面日志可以发现两个问题，
（1）所有的增删改，都有一句/!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED//!/;
这是什么情况，将事物的隔离级别设置成了读已提交，MYSQL默认的不是RR吗？网上找了下，没找到原因，我的理解：mysql本身事务开启是从执行sql开始，而binlog的记录是从commit后记录，
（2）增删改都会产生5个事件，每个事件都以at 事件起点 开头；
这里以update为例子，说明binlog的日志内容
-- 事件起点，以at开头，任何增删改前面都会有两个at，一个标识last_committed，sequence_number信息，一个是thread_id，exec_time信息
# at 928
-- 事件发生的时间 然后标识server id,是从哪台mysql产生的事件，last_committed时提交事务，组提交的方式，两次事务可能一样
#210922 14:57:31 server id 1 end_log_pos 993 CRC32 0x638f8e2f Anonymous_GTID last_committed=3 sequence_number=4 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
-- 第二次at，标识执行线程id，和事务执行时间，错误码，0代表无错误，真正的事务开始时间TIMESTAMP，BEGIN
# at 993
#210922 14:57:31 server id 1 end_log_pos 1073 CRC32 0x5234432b Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1632293851/*!*/;
BEGIN
/*!*/;
-- 表明操作的是tb_test表，此表的ID是112，这值并不是不变的，是表载入内存时临时分配的数值
# at 1073
#210922 14:57:31 server id 1 end_log_pos 1137 CRC32 0x499487e2 Table_map: `my_db`.`tb_test` mapped to number 112
-- 表明事件类型，Update_rows/Delete_rows/Write_rows
# at 1137
#210922 14:57:31 server id 1 end_log_pos 1195 CRC32 0x521abeb5 Update_rows: table id 112 flags: STMT_END_F
### UPDATE `my_db`.`tb_test`
### WHERE
### @1=1 /* INT meta=0 nullable=1 is_null=0 */
### @2='1111' /* VARSTRING(192) meta=192 nullable=1 is_null=0 */
### @3='nanan' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
### SET
### @3='xxxx' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
-- 对应的Xid事务ID
# at 1195
#210922 14:57:31 server id 1 end_log_pos 1226 CRC32 0xb9a42b3a Xid = 18
COMMIT/*!*/
任何一个事务都是以BEGIN，到COMMIT的过程，中间可能会涉及事务执行时间，事件ID，事件类型，表ID等。
增删改的流程可以粗略的记为：last_committed -> thread -> table -> event(含SQL) -> Xid，对应的
show binlog events in 'mysql-bin.000001';中的Event_type列，其他的语句从这五种类型中都能找到答案。
1. Anonymous_Gtid: 包含last_committed，sequence_number，rbr_only设置GTID_NEXT
2. Query：包含thread_id，exec_time，error_code
3. Table_map：表名和ID
4. Update_rows/Delete_rows/Write_rows
5. Xid
同步异常解决方案
由第1条主从同步流程，可以看出重点在于两个线程，所以查看主从是否异常的时候，往往关注 show slave status\G中
如上两个线程的运行状态，如果存在一个No，则说明主从已经停止，异常已经产生。为了方便后续查看同步情况，这里先说明各字段的含义
Slave_IO_State: Waiting for master to send event
Master_Host: 1.1.1.1 -- master服务器IP
Master_User: repl -- 主从同步用户
Master_Port: 3306 -- 主库端口
Connect_Retry: 60 -- 建立连接尝试次数
Master_Log_File: mysql-bin.000014 -- master的binlog日志，在master上执行show master status查看
Read_Master_Log_Pos: 33603949 -- 中继器读到的master binlog的位置
Relay_Log_File: relay-bin.000014 -- 从库中继器的日志文件
Relay_Log_Pos: 367 -- 中继日志读到的位置
Relay_Master_Log_File: mysql-bin.000014 -- 当前中继读到的master的binlog文件
Slave_IO_Running: Yes -- I/O线程状态
Slave_SQL_Running: Yes -- SQL线程状态
Replicate_Do_DB:
Replicate_Ignore_DB: mysql,information_schema,performance_schema,sys -- 主从同步忽略的库
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 33603949 -- SQL线程执行到的Relay_Master_Log_File文件的位置
Relay_Log_Space: 741
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 0 -- 主从数据同步间隔时间
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 2 -- master库的serverId，在my.cnf中配置的，主从不能设置一样
Master_UUID: ccc05185-0bb1-11ec-9019-6c92bf04787e
Master_Info_File: mysql.slave_master_info -- master的信息，这里根据master_info_repository配置决定
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
关于主从同步异常，我们会从一下几个思路去思考
（1）根据业务，将不需要的异常编码排除，例如
1032：记录不存在，当更新或删除一个条不存在的记录时，我们可以忽略此异常
1050：数据表已经存在
还有一些个性化的 1062,等，都可以使用slave-skip-errors=1032，1050跳过这些异常，
注意slave-skip-errors=all千万不要这么设置，研发认为这样设置肯定不会出现主从异常，但是很遗憾，这样设置有多重危害：
1.可能导致主从数据不一致
2.当I/O线程异常时，例如relaylog，binlog等刷盘时异常，高并发下突然断电等情况，使得日志文件损坏，这类异常仅仅通过跳过是不能解决的
（2）纯SQL执行异常
这类异常最好处理，找到执行错误的sql，只需要查看为什么错误，如果对数据一致性不影响，直接在从库执行
为了确保无问题，可以查看Relay_Master_Log_File文件的Exec_Master_Log_Pos位置，看下到底是什么问题导致异常，然后执行
stop slave;
set global sql_slave_skip_counter=1;
start slave;
跳过此异常
（3）I/O异常情况
这类异常比较麻烦，也是本文讲解的重点，分为两种：一种是master的binlog日志异常，二种是slave的relaylog异常。
我们要做的首先确定Relay_Master_Log_File，这是slave已经同步到的master的binlog日志，通过mysqlbinlog获取该文件的内容，找到最后的eng_log_pos，利用
第一个参数是同步的binlog文件，第二个是pos，第三个是等待时间（单位秒）
select master_pos_wait('mysql-bin.000017',25138958,5);
如果指定的pos值已经同步，改select将返回0，如果没有同步，将阻塞直到指定的时间，根据Exec_Master_Log_Pos的值可以判定同步的具体pos在哪，这样便能找到下一次同步的pos，通过slave上执行
stop slave;
change master to master_log_pos=xxx;
start slave;
便能恢复数据同步。
接下来以经典的1236异常来说明怎么解决I/O的问题，1236问题并不是一个异常，而是一类异常，这类异常又有区分，不同的问题不同对待。
1. Got fatal error 1236 from master when reading data from binary log: 'Client requested master to start replication from position > file size'
这类异常最常见，触发的时机是主库在不断的数据入库，突然断电或强制重启，或强删（kill -9）导致主库binlog刷盘异常，从而使从库I/O线程读取到主库不存在的position,导致主从数据不一致。解决办法
从库执行show slave status; 查看Exec_Master_Log_Pos和Read_Master_Log_Pos已经不一致，通过mysqlbinlog查看主库的Relay_Master_Log_File文件，找到对应Exec_Master_Log_Pos相近的pos，这里有两种情况，一种是有相近的pos值，然后从库通过执行select master_pos_wait方式，查看已经同步的pos值，找到未同步的，然后从库执行 change master to master_log_pos=xxx;
另外一种情况就是Relay_Master_Log_File没有相近的pos值，这时候一般是本binlog已经完成同步，将master_log_file指向下一个文件，pos值改成下个文件的最小值即可。所以在配置主从时，为了减少此类事件的发生，设置sync_binlog=1最为靠谱，当然这是以牺牲性能为代价。
2. Got fatal error 1236 from master when reading data from binary log
这个时候需要注意，很有可能是主库的binlog已经被删除，从库无法从主库获取指定文件，这个只能在前期将expire_logs_days设置的较大些，例如180天，即6个月。
3. 从库的异常断电，强制重启，强删导致的relaylog刷盘异常
这类异常和主库binlog异常大同小异，为了防止此类事件的发生，建议设置sync_relay_log=1，这个意思是在从库读到binlog后，relaylog写入磁盘的频率，默认是1000，也就是当出现1000个事物事件后，从库才会执行fdatasync()此系统调用进行刷盘，1000之内的只是将数据写入文件缓存中依赖操作系统刷盘，但是设置的太小又会导致从库的I/O瓶颈，一直在刷盘，降低效率，所有需要综合考虑设置此值。
非主流的异常问题
myisam引擎表损坏导致的同步异常
笔者遇到过因为myisam表索引文件损坏，导致的异常，这类异常排查起来比较麻烦，解决确很容易，通过repair命令或者myisamchk工具将表文件修复，然后执行
stop slave;
set global sql_slave_skip_counter=1;
start slave;
修复完把本次异常跳过即可。声明：本文为 脚本之家专栏作者 投稿，未经允许请勿转载。
推荐阅读：