1.binlog的日志内容
IO线程把binlog日志从master抽取到slave,转存到relaylog,但pos保持一致。
可用途mysqlbinlog工具查看
查看master指定pos的日志
[root@localhost testRepl]# mysqlbinlog -v --base64-output=DECODE-ROWS /usr/local/mysql/data/mysql-bin.000002 | grep -A '10' 106881433
#200518 20:14:42 server id 1 end_log_pos 106881433 CRC32 0xdf0e4b13 Write_rows: table id 112 flags: STMT_END_F
### INSERT INTO `test`.`repl_status_chk`
### SET
### @1='2020-05-18 20:14:42'
### @2='repl_insert_cnt'
### @3=168474
# at 106881433
#200518 20:14:42 server id 1 end_log_pos 106881464 CRC32 0x8bbda1d3 Xid = 503095
COMMIT/*!*/;
# at 106881464
#200518 20:14:47 server id 1 end_log_pos 106881529 CRC32 0x8cac766f Anonymous_GTID last_committed=209446 sequence_number=209447 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 106881529
#200518 20:14:47 server id 1 end_log_pos 106881609 CRC32 0x63682308 Query thread_id=40976 exec_time=0 error_code=0
SET TIMESTAMP=1589847287/*!*/;
BEGIN
可以看到是在执行sql:
insert into `test`.`repl_status_chk` values ('2020-05-18 20:14:42','repl_insert_cnt',168474);
查看slave的relay日志
[root@localhost data]# mysqlbinlog -v --base64-output=DECODE-ROWS /usr/local/mysql/data/localhost-relay-bin.000018 | grep -A '10' 106881433
#200518 20:14:42 server id 1 end_log_pos 106881433 CRC32 0xdf0e4b13 Write_rows: table id 112 flags: STMT_END_F
### INSERT INTO `test`.`repl_status_chk`
### SET
### @1='2020-05-18 20:14:42'
### @2='repl_insert_cnt'
### @3=168474
# at 164334
#200518 20:14:42 server id 1 end_log_pos 106881464 CRC32 0x8bbda1d3 Xid = 503095
COMMIT/*!*/;
# at 164365
#200518 20:14:47 server id 1 end_log_pos 106881529 CRC32 0x8cac766f Anonymous_GTID last_committed=209446 sequence_number=209447 rbr_only=yes
与master的内容一样。
注意:主从log的pos是一样的,slave status的relay-log-pos,原来以为是log文件映射了,pos也映射,但没有。
2.binlog抽取时间戳
master当前事务时间戳pos
mysql> show master status;
+------------------+-----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+-----------+--------------+------------------+-------------------+
| mysql-bin.000002 | 114928598 | | | |
+------------------+-----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)
slave的抽取时间戳
mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 10.91.57.187
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000002
Read_Master_Log_Pos: 114928598
Relay_Log_File: localhost-relay-bin.000018
Relay_Log_Pos: 8211499
Relay_Master_Log_File: mysql-bin.000002
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Exec_Master_Log_Pos: 114928598
Relay_Log_Space: 8211710
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
这里:Read_Master_Log_Pos: 114928598
也可以查看master.info文件信息。
slave的SQL执行时间戳
这里: Exec_Master_Log_Pos: 114928598
也可以查看relay-log.info文件信息。
3.应用举例
slave的SQL线程退出,报错HA_ERR_FOUND_DUPP_KEY
2020-05-18T23:57:06.860896Z 11 [ERROR] Slave SQL for channel ‘’: Could not execute Write_rows event on table test.repl1; Duplicate entry ‘4’ for key ‘PRIMARY’, Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event’s master log mysql-bin.000002, end_log_pos 106173773, Error_code: 1062
根据binlog和pos查看导致错误的内容
[root@localhost testRepl]# mysqlbinlog -v --base64-output=DECODE-ROWS /usr/local/mysql/data/mysql-bin.000002 | grep -A '10' 106173773
#200518 13:00:53 server id 1 end_log_pos 106173773 CRC32 0xe59e49be Write_rows: table id 108 flags: STMT_END_F
### INSERT INTO `test`.`repl1`
### SET
### @1=4
### @2='first_record444'
# at 106173773
#200518 13:00:53 server id 1 end_log_pos 106173804 CRC32 0xc3d0467e Xid = 493439
COMMIT/*!*/;
# at 106173804
#200518 13:00:53 server id 1 end_log_pos 106173869 CRC32 0x367d06ac Anonymous_GTID last_committed=207095 sequence_number=207096 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 106173869
#200518 13:00:53 server id 1 end_log_pos 106173941 CRC32 0xe9c22a0f Query thread_id=6 exec_time=0 error_code=0
SET TIMESTAMP=1589821253/*!*/;
BEGIN
可以看出,是在执行insert into test
.repl1
values (4,‘first_record444’)。
当时实验时,在slave手工插入了id=4的记录,故报主键冲突。与日志报错是一致。 Duplicate entry ‘4’ for key ‘PRIMARY’, Error_code: 1062;
手工删除slave节点id=4的记录。
总结
- binlog同步的设计很清晰,容易理解。
- 同步出错时,可通过查看导致报错的日志,得到完成的sql内容,比较透明。