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中,但是缺点很明显,例如insertinto 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 SETTIMESTAMP=1632290496/*!*/; insertinto 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 setname= 'xxx'whereid=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增加个主键,altertable 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=minimal
- binlog日志内容
-- 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 SETTIMESTAMP=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/*!*/; CREATEDATABASE/*!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`/*!*/; SETTIMESTAMP=1632293697/*!*/; createtable tb_test (idint,stu_id varchar(64),namevarchar(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 SETTIMESTAMP=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 SETTIMESTAMP=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 SETTIMESTAMP=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 SETTIMESTAMP=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,对应的 showbinlogeventsin'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位置,看下到底是什么问题导致异常,然后执行 stopslave; setglobal sql_slave_skip_counter=1; startslave; 跳过此异常
(3)I/O异常情况
这类异常比较麻烦,也是本文讲解的重点,分为两种:一种是master的binlog日志异常,二种是slave的relaylog异常。
我们要做的首先确定Relay_Master_Log_File,这是slave已经同步到的master的binlog日志,通过mysqlbinlog获取该文件的内容,找到最后的eng_log_pos,利用
第一个参数是同步的binlog文件,第二个是pos,第三个是等待时间(单位秒) selectmaster_pos_wait('mysql-bin.000017',25138958,5); 如果指定的pos值已经同步,改select将返回0,如果没有同步,将阻塞直到指定的时间,根据Exec_Master_Log_Pos的值可以判定同步的具体pos在哪,这样便能找到下一次同步的pos,通过slave上执行 stopslave; changemasterto master_log_pos=xxx; startslave; 便能恢复数据同步。
接下来以经典的1236异常来说明怎么解决I/O的问题,1236问题并不是一个异常,而是一类异常,这类异常又有区分,不同的问题不同对待。
1. Got fatal error 1236 from master when reading data from binary log: 'Client requested master to startreplicationfromposition > filesize' 这类异常最常见,触发的时机是主库在不断的数据入库,突然断电或强制重启,或强删(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; 修复完把本次异常跳过即可。
声明:本文为 脚本之家专栏作者 投稿,未经允许请勿转载。