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;
修复完把本次异常跳过即可。
声明:本文为 脚本之家专栏作者 投稿,未经允许请勿转载。
推荐阅读: