其他
如果将relay_log_recovery设置为0会发生什么？（上）
作者 韩杰·沃趣科技MySQL数据库工程师
出品 沃趣科技
| 背景
在MySQL5.7版本中，开启并行复制后，设置relay-log-recovery=1，从库启动后偶尔会报错，类似于https://bugs.mysql.com/bug.php?id=83713。所以尝试将relay-log-recovery设置为0，观察会发生什么。
| 环境
MySQL5.7.22
GTID模式
relay-log-recovery=0
relay_log_purge=off
sync_relay_log = 10000
relay_log_info_repository = TABLE
不开启并行复制
| 模拟relay-log没有sync完全
Retrieved_Gtid_Set < Executed_Gtid_Set
停掉slave，查看相关信息
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 17:20:34]>stop slave;
Query OK, 0 rows affected (0.01 sec)
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 17:20:37]>select * from mysql.slave_relay_log_info;show slave status\G
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
| Number_of_lines | Relay_log_name | Relay_log_pos | Master_log_name | Master_log_pos | Sql_delay | Number_of_workers | Id | Channel_name |
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
| 7 | /home/mysql/data/mysqldata1/relaylog/mysql-relay-bin.000017 | 186094 | mysql-bin.000001 | 4941307 | 0 | 0 | 1 | |
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
1 row in set (0.00 sec)
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: 10.10.30.18
Master_User: repl
Master_Port: 3306
Connect_Retry: 10
Master_Log_File: mysql-bin.000001
Read_Master_Log_Pos: 4941307
Relay_Log_File: mysql-relay-bin.000017
Relay_Log_Pos: 186094
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: No
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
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: 4941307
Relay_Log_Space: 4315819
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: NULL
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: 330618
Master_UUID: 2662c965-fdb2-11e8-8157-0cc47a3aae0d
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State:
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-101:104-1504:1509-2079:2082-11822
Executed_Gtid_Set: 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-11822
Auto_Position: 1
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
关闭数据库stopmysql
$stopmysql
查看最后一个relaylog中的最后一个事务的GTID为2662c965-fdb2-11e8-8157-0cc47a3aae0d:11822
$mysqlbinlog -vvv mysql-relay-bin.000017
# at 185676
#181214 17:20:36 server id 330618 end_log_pos 4940954 CRC32 0xc2acb86d GTID last_committed=11821 sequence_number=11822 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '2662c965-fdb2-11e8-8157-0cc47a3aae0d:11822'/*!*/;
# at 185741
#181214 17:20:36 server id 330618 end_log_pos 4941046 CRC32 0x516997b4 Query thread_id=60654 exec_time=0 error_code=0
SET TIMESTAMP=1544779236/*!*/;
BEGIN
/*!*/;
# at 185833
#181214 17:20:36 server id 330618 end_log_pos 4941139 CRC32 0x65ea73eb Rows_query
# update qdata_mysql_heartbeat set ts=now() where server_id=@@server_id
# at 185926
#181214 17:20:36 server id 330618 end_log_pos 4941212 CRC32 0xb88fd1db Table_map: `qdata_mysql`.`qdata_mysql_heartbeat` mapped to number 108
# at 185999
#181214 17:20:36 server id 330618 end_log_pos 4941276 CRC32 0x67572f7a Update_rows: table id 108 flags: STMT_END_F
BINLOG '
5HUTXB16CwUAXQAAAFNlSwCAAEV1cGRhdGUgcWRhdGFfbXlzcWxfaGVhcnRiZWF0IHNldCB0cz1u
b3coKSB3aGVyZSBzZXJ2ZXJfaWQ9QEBzZXJ2ZXJfaWTrc+pl
5HUTXBN6CwUASQAAAJxlSwAAAGwAAAAAAAEAC3FkYXRhX215c3FsABVxZGF0YV9teXNxbF9oZWFy
dGJlYXQAAggSAQAA29GPuA==
5HUTXB96CwUAQAAAANxlSwAAAGwAAAAAAAEAAgAC///8egsFAAAAAACZoZ0VI/x6CwUAAAAAAJmh
nRUkei9XZw==
'/*!*/;
### UPDATE `qdata_mysql`.`qdata_mysql_heartbeat`
### WHERE
### @1=330618 /* LONGINT meta=0 nullable=0 is_null=0 */
### @2='2018-12-14 17:20:35' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
### @1=330618 /* LONGINT meta=0 nullable=0 is_null=0 */
### @2='2018-12-14 17:20:36' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 186063
#181214 17:20:36 server id 330618 end_log_pos 4941307 CRC32 0x78f64c71 Xid = 776909
COMMIT/*!*/;
# at 186094
#181214 17:21:45 server id 330619 end_log_pos 186117 CRC32 0x014899bc Stop
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*/;
用以下命令模拟relaylog丢失，这样mysql重新启动的时候初始化的Retrieved_Gtid_Set集合会比Executed_Gtid_Set集合小
$dd if=mysql-relay-bin.000017 of=/tmp/mysql-relay-bin.000017 bs=1 count=185090
$mv /tmp/mysql-relay-bin.000017 ./
$chown -R mysql:mysql *
##185090处对应的是2662c965-fdb2-11e8-8157-0cc47a3aae0d:11820这个事务，所以GTID为2662c965-fdb2-11e8-8157-0cc47a3aae0d:11820的事务被截断，2662c965-fdb2-11e8-8157-0cc47a3aae0d:11821、2662c965-fdb2-11e8-8157-0cc47a3aae0d:11822被抹掉
# at 184840
#181214 17:20:34 server id 330618 end_log_pos 4940118 CRC32 0xf6f3aed0 GTID last_committed=11819 sequence_number=11820 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '2662c965-fdb2-11e8-8157-0cc47a3aae0d:11820'/*!*/;
# at 184905
#181214 17:20:34 server id 330618 end_log_pos 4940210 CRC32 0x22409fbf Query thread_id=60652 exec_time=0 error_code=0
SET TIMESTAMP=1544779234/*!*/;
BEGIN
/*!*/;
# at 184997
#181214 17:20:34 server id 330618 end_log_pos 4940303 CRC32 0x436ed81d Rows_query
# update qdata_mysql_heartbeat set ts=now() where server_id=@@server_id
# at 185090
#181214 17:20:34 server id 330618 end_log_pos 4940376 CRC32 0xaadcb170 Table_map: `qdata_mysql`.`qdata_mysql_heartbeat` mapped to number 108
# at 185163
#181214 17:20:34 server id 330618 end_log_pos 4940440 CRC32 0xabc65d06 Update_rows: table id 108 flags: STMT_END_F
启动数据库startmysql
$startmysql
查看复制状态是否正常，复制正常。
且看到是从2662c965-fdb2-11e8-8157-0cc47a3aae0d:11823开始拉取binlog，因为UNION的GTID集合为2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-11822。
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 17:35:33]>select * from mysql.slave_relay_log_info;show slave status\G
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
| Number_of_lines | Relay_log_name | Relay_log_pos | Master_log_name | Master_log_pos | Sql_delay | Number_of_workers | Id | Channel_name |
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
| 7 | /home/mysql/data/mysqldata1/relaylog/mysql-relay-bin.000019 | 371686 | mysql-bin.000001 | 5312491 | 0 | 0 | 1 | |
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
1 row in set (0.00 sec)
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 10.10.30.18
Master_User: repl
Master_Port: 3306
Connect_Retry: 10
Master_Log_File: mysql-bin.000001
Read_Master_Log_Pos: 5312491
Relay_Log_File: mysql-relay-bin.000019
Relay_Log_Pos: 371686
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
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: 5312491
Relay_Log_Space: 4686796
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: 330618
Master_UUID: 2662c965-fdb2-11e8-8157-0cc47a3aae0d
Master_Info_File: mysql.slave_master_info
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: 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-101:104-1504:1509-2079:2082-11819:11823-12710
Executed_Gtid_Set: 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-12710
Auto_Position: 1
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
查看error.log相关信息
2018-12-14T17:34:42.471162+08:00 1 [Note] Slave I/O thread for channel '': connected to master 'repl@10.10.30.18:3306',replication started in log 'mysql-bin.000001' at position 4941307
2018-12-14T17:34:42.474786+08:00 0 [Note] Event Scheduler: Loaded 0 events
2018-12-14T17:34:42.474921+08:00 0 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.7.22-log' socket: '/home/mysql/data/mysqldata1/sock/mysql.sock' port: 3306 MySQL Community Server (GPL)
2018-12-14T17:34:42.476711+08:00 2 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'mysql-bin.000001' at position 4941307, relay log '/home/mysql/data/mysqldata1/relaylog/mysql-relay-bin.000017' position: 186094
2018-12-14T17:34:43.965844+08:00 5 [Note] Start binlog_dump to master_thread_id(5) slave_server(330618), pos(, 4)
查看下个relaylog信息
$mysqlbinlog -vvv mysql-relay-bin.000018
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181214 17:34:42 server id 330619 end_log_pos 123 CRC32 0x0996b423 Start: binlog v 4, server v 5.7.22-log created 181214 17:34:42
# This Format_description_event appears in a relay log and was generated by the slave thread.
# at 123
#181214 17:34:42 server id 330619 end_log_pos 242 CRC32 0x8885f92a Previous-GTIDs
# 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-101:104-1504:1509-2079:2082-11819
# at 242
#181214 17:34:42 server id 330619 end_log_pos 295 CRC32 0x1a4ec323 Rotate to mysql-relay-bin.000019 pos: 4
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*/;
查看再下个relaylog信息，发现是从2662c965-fdb2-11e8-8157-0cc47a3aae0d:11823开始拉取日志
$mysqlbinlog -vvv mysql-relay-bin.000019
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181214 17:34:42 server id 330619 end_log_pos 123 CRC32 0x0996b423 Start: binlog v 4, server v 5.7.22-log created 181214 17:34:42
# This Format_description_event appears in a relay log and was generated by the slave thread.
# at 123
#181214 17:34:42 server id 330619 end_log_pos 242 CRC32 0x8885f92a Previous-GTIDs
# 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-101:104-1504:1509-2079:2082-11819
# at 242
#700101 8:00:00 server id 330618 end_log_pos 0 CRC32 0x073c3e73 Rotate to mysql-bin.000001 pos: 4
# at 289
#181214 13:52:24 server id 330618 end_log_pos 123 CRC32 0x0180f777 Start: binlog v 4, server v 5.7.22-log created 181214 13:52:24
BINLOG '
GEUTXA96CwUAdwAAAHsAAAAAAAQANS43LjIyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AXf3gAE=
'/*!*/;
# at 408
#181214 17:34:42 server id 0 end_log_pos 455 CRC32 0x3dfb4b92 Rotate to mysql-bin.000001 pos: 154
# at 455
#181214 17:34:42 server id 0 end_log_pos 502 CRC32 0x1ff57b1c Rotate to mysql-bin.000001 pos: 4941307
# at 502
#181214 17:20:37 server id 330618 end_log_pos 4941372 CRC32 0xa2232924 GTID last_committed=11822 sequence_number=11823 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '2662c965-fdb2-11e8-8157-0cc47a3aae0d:11823'/*!*/;
# at 567
#181214 17:20:37 server id 330618 end_log_pos 4941464 CRC32 0xdecc7ed2 Query thread_id=60655 exec_time=0 error_code=0
SET TIMESTAMP=1544779237/*!*/;
SET @@session.pseudo_thread_id=60655/*!*/;
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=2, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=83/*!*/;
SET @@session.time_zone='+08:00'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 659
#181214 17:20:37 server id 330618 end_log_pos 4941557 CRC32 0x17e36176 Rows_query
# update qdata_mysql_heartbeat set ts=now() where server_id=@@server_id
# at 752
再次查看mysql-relay-bin.000017中的内容，最后记录如下，多了WARNING的信息
$mysqlbinlog -vvv mysql-relay-bin.000017
BEGIN
/*!*/;
WARNING: The range of printed events ends with a row event or a table map event that does not have the STMT_END_F flag set. This might be because the last statement was not fully written to the log, or because you are using a --stop-position or --stop-datetime that refers to an event in the middle of a statement. The event(s) from the partial statement have not been written to output.
ROLLBACK /* added by mysqlbinlog */ /*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
限于篇幅，本文就先为大家介绍到此，下期将接着为大家介绍“Retrieved_Gtid_Set > Executed_Gtid_Set”，不见不散～
| 作者简介
韩杰 沃趣科技MySQL数据库工程师
熟悉mysql体系架构、主从复制，熟悉问题定位与解决。
点击查看招聘信息
相关链接
更多干货，欢迎来撩~