其他
如果将relay_log_recovery设置为0会发生什么？（下）
作者 韩杰·沃趣科技MySQL数据库工程师
出品 沃趣科技
上期《如果将relay_log_recovery设置为0会发生什么？（上）》，由于篇幅限制，只为大家介绍了模拟Retrieved_Gtid_Set < Executed_Gtid_Set的情况，本期将继续为大家介绍模拟Retrieved_Gtid_Set > Executed_Gtid_Set 。
Retrieved_Gtid_Set > Executed_Gtid_Set
停掉slave的sql线程，模拟Retrieved_Gtid_Set > Executed_Gtid_Set，如下：
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 16:08:48]>stop slave sql_thread;
Query OK, 0 rows affected (0.00 sec)
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 16:08:57]>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.000011 | 1787845 | mysql-bin.000001 | 3158537 | 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: 3171077
Relay_Log_File: mysql-relay-bin.000011
Relay_Log_Pos: 1787845
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: Yes
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: 3158537
Relay_Log_Space: 2542538
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-7587
Executed_Gtid_Set: 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-7557
Auto_Position: 1
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
关闭数据库stopmysql
$stopmysql
查看mysql-relay-bin.000011最后一个事务GTID为2662c965-fdb2-11e8-8157-0cc47a3aae0d:7604
$mysqlbinlog -vvv mysql-relay-bin.000011
COMMIT/*!*/;
# at 1807073
#181214 16:09:40 server id 330618 end_log_pos 3177830 CRC32 0xe6febde8 GTID last_committed=7603 sequence_number=7604 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '2662c965-fdb2-11e8-8157-0cc47a3aae0d:7604'/*!*/;
# at 1807138
#181214 16:09:40 server id 330618 end_log_pos 3177922 CRC32 0x83a67d51 Query thread_id=56362 exec_time=0 error_code=0
SET TIMESTAMP=1544774980/*!*/;
BEGIN
/*!*/;
# at 1807230
#181214 16:09:40 server id 330618 end_log_pos 3178015 CRC32 0x904b0728 Rows_query
# update qdata_mysql_heartbeat set ts=now() where server_id=@@server_id
# at 1807323
#181214 16:09:40 server id 330618 end_log_pos 3178088 CRC32 0xd4354200 Table_map: `qdata_mysql`.`qdata_mysql_heartbeat` mapped to number 108
# at 1807396
#181214 16:09:40 server id 330618 end_log_pos 3178152 CRC32 0xc545f0a4 Update_rows: table id 108 flags: STMT_END_F
BINLOG '
RGUTXB16CwUAXQAAAB9+MACAAEV1cGRhdGUgcWRhdGFfbXlzcWxfaGVhcnRiZWF0IHNldCB0cz1u
b3coKSB3aGVyZSBzZXJ2ZXJfaWQ9QEBzZXJ2ZXJfaWQoB0uQ
RGUTXBN6CwUASQAAAGh+MAAAAGwAAAAAAAEAC3FkYXRhX215c3FsABVxZGF0YV9teXNxbF9oZWFy
dGJlYXQAAggSAQAAAEI11A==
RGUTXB96CwUAQAAAAKh+MAAAAGwAAAAAAAEAAgAC///8egsFAAAAAACZoZ0CZ/x6CwUAAAAAAJmh
nQJopPBFxQ==
'/*!*/;
### UPDATE `qdata_mysql`.`qdata_mysql_heartbeat`
### WHERE
### @1=330618 /* LONGINT meta=0 nullable=0 is_null=0 */
### @2='2018-12-14 16:09:39' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
### @1=330618 /* LONGINT meta=0 nullable=0 is_null=0 */
### @2='2018-12-14 16:09:40' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
# at 1807460
#181214 16:09:40 server id 330618 end_log_pos 3178183 CRC32 0x6a5edec2 Xid = 764012
COMMIT/*!*/;
# at 1807491
#181214 16:09:51 server id 330619 end_log_pos 1807514 CRC32 0xed4f17f3 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*/;
执行以下命令将GTID为2662c965-fdb2-11e8-8157-0cc47a3aae0d:7600的事务截掉一半，2662c965-fdb2-11e8-8157-0cc47a3aae0d:7601、2662c965-fdb2-11e8-8157-0cc47a3aae0d:7602、2662c965-fdb2-11e8-8157-0cc47a3aae0d:7603、2662c965-fdb2-11e8-8157-0cc47a3aae0d:7604全部抹掉
dd if=mysql-relay-bin.000011 of=/tmp/mysql-relay-bin.000011 bs=1 count=1805788
mv /tmp/mysql-relay-bin.000011 ./
chown -R mysql:mysql *
#1805788这个位点对应事务的GTID为7600
at 1805401
181214 16:09:36 server id 330618 end_log_pos 3176158 CRC32 0xeb1649f2 GTID last_committed=7599 sequence_number=7600 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '2662c965-fdb2-11e8-8157-0cc47a3aae0d:7600'/*!*/;
at 1805466
181214 16:09:36 server id 330618 end_log_pos 3176250 CRC32 0x9e2a31e5 Query thread_id=56358 exec_time=0 error_code=0
SET TIMESTAMP=1544774976/*!*/;
BEGIN
/*!*/;
at 1805558
181214 16:09:36 server id 330618 end_log_pos 3176343 CRC32 0x920329a0 Rows_query
update qdata_mysql_heartbeat set ts=now() where server_id=@@server_id
at 1805651
181214 16:09:36 server id 330618 end_log_pos 3176416 CRC32 0x2204d593 Table_map: `qdata_mysql`.`qdata_mysql_heartbeat` mapped to number 108
at 1805724
181214 16:09:36 server id 330618 end_log_pos 3176480 CRC32 0x2f91a93a Update_rows: table id 108 flags: STMT_END_F
BINLOG '
QGUTXB16CwUAXQAAAJd3MACAAEV1cGRhdGUgcWRhdGFfbXlzcWxfaGVhcnRiZWF0IHNldCB0cz1u
b3coKSB3aGVyZSBzZXJ2ZXJfaWQ9QEBzZXJ2ZXJfaWSgKQOS
QGUTXBN6CwUASQAAAOB3MAAAAGwAAAAAAAEAC3FkYXRhX215c3FsABVxZGF0YV9teXNxbF9oZWFy
dGJlYXQAAggSAQAAk9UEIg==
QGUTXB96CwUAQAAAACB4MAAAAGwAAAAAAAEAAgAC///8egsFAAAAAACZoZ0CY/x6CwUAAAAAAJmh
nQJkOqmRLw==
'/*!*/;
## UPDATE `qdata_mysql`.`qdata_mysql_heartbeat`
## WHERE
## @1=330618 /* LONGINT meta=0 nullable=0 is_null=0 */
## @2='2018-12-14 16:09: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 16:09:36' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
at 1805788
181214 16:09:36 server id 330618 end_log_pos 3176511 CRC32 0xa6103d84 Xid = 764000
COMMIT/*!*/;
启动数据库startmysql
$startmysql
查看复制状态是否正常，显示正常。
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 16:19:05]>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.000013 | 236672 | mysql-bin.000001 | 3412263 | 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: 3412263
Relay_Log_File: mysql-relay-bin.000013
Relay_Log_Pos: 236672
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: 3412263
Relay_Log_Space: 2784908
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-8164
Executed_Gtid_Set: 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-8164
Auto_Position: 1
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
查看error.log
2018-12-14T16:17:37.822661+08:00 1 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'mysql-bin.000001' at position 3158537, relay log '/home/mysql/data/mysqldata1/relaylog/mysql-relay-bin.000011' position: 1787845
2018-12-14T16:17:37.822915+08:00 2 [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 2764613
2018-12-14T16:17:37.826982+08:00 0 [Note] Event Scheduler: Loaded 0 events
2018-12-14T16:17:37.827132+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-14T16:17:38.020740+08:00 1 [Note] Slave SQL for channel '': Rolling back unfinished transaction (no COMMIT or ROLLBACK in relay log). A probable cause is partial transaction left on relay log because of restarting IO thread with auto-positioning protocol. Error_code: 0
2018-12-14T16:17:39.639144+08:00 4 [Note] Start binlog_dump to master_thread_id(4) slave_server(330618), pos(, 4)
查看下一个relaylog的信息
$mysqlbinlog -vvv mysql-relay-bin.000012
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181214 16:17:37 server id 330619 end_log_pos 123 CRC32 0x32f87201 Start: binlog v 4, server v 5.7.22-log created 181214 16:17:37
# This Format_description_event appears in a relay log and was generated by the slave thread.
# at 123
#181214 16:17:37 server id 330619 end_log_pos 242 CRC32 0x524f2179 Previous-GTIDs
# 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-101:104-1504:1509-2079:2082-7599
# at 242
#181214 16:17:37 server id 330619 end_log_pos 295 CRC32 0xfe1b4a1f Rotate to mysql-relay-bin.000013 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:7600这个GTID对应的日志
$mysqlbinlog -vvv mysql-relay-bin.000013
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181214 16:17:37 server id 330619 end_log_pos 123 CRC32 0x32f87201 Start: binlog v 4, server v 5.7.22-log created 181214 16:17:37
# This Format_description_event appears in a relay log and was generated by the slave thread.
# at 123
#181214 16:17:37 server id 330619 end_log_pos 242 CRC32 0x524f2179 Previous-GTIDs
# 2662c965-fdb2-11e8-8157-0cc47a3aae0d:1-101:104-1504:1509-2079:2082-7599
# 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 16:17:37 server id 0 end_log_pos 455 CRC32 0x340c6196 Rotate to mysql-bin.000001 pos: 154
# at 455
#181214 16:17:37 server id 0 end_log_pos 502 CRC32 0x62bfc8f3 Rotate to mysql-bin.000001 pos: 3176093
# at 502
#181214 16:09:36 server id 330618 end_log_pos 3176158 CRC32 0xeb1649f2 GTID last_committed=7599 sequence_number=7600 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '2662c965-fdb2-11e8-8157-0cc47a3aae0d:7600'/*!*/;
# at 567
#181214 16:09:36 server id 330618 end_log_pos 3176250 CRC32 0x9e2a31e5 Query thread_id=56358 exec_time=0 error_code=0
SET TIMESTAMP=1544774976/*!*/;
SET @@session.pseudo_thread_id=56358/*!*/;
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 16:09:36 server id 330618 end_log_pos 3176343 CRC32 0x920329a0 Rows_query
# update qdata_mysql_heartbeat set ts=now() where server_id=@@server_id
# at 752
| 总结
从error.log中能看到，MySQL重启后，Slave SQL thread会根据mysql.slave_relay_log_info表中记录的位置点信息去starting replication
[root@shadow:/root 5.7.22-log_Instance1 root@localhost:(none) 16:08:57]>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.000011 | 1787845 | mysql-bin.000001 | 3158537 | 0 | 0 | 1 | |
+-----------------+-------------------------------------------------------------+---------------+------------------+----------------+-----------+-------------------+----+--------------+
1 row in set (0.00 sec)
2018-12-14T16:17:37.822661+08:00 1 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'mysql-bin.000001' at position 3158537, relay log '/home/mysql/data/mysqldata1/relaylog/mysql-relay-bin.000011' position: 1787845
观察两种情况下error.log日志中内容，发现：
Retrieved_Gtid_Set < Executed_Gtid_Set下，SQL线程按mysql.slave_relay_log_info表中记录的位置点信息（mysql-relay-bin.000017，186094）去starting replication时，发现对应的日志信息不存在（mysql-relay-bin.000017日志被我截断到185090），就继续执行下一个relaylog。因为Executed_Gtid_Set > Retrieved_Gtid_Set，UNION集合就是Executed_Gtid_Set，所以新生成的relaylog里拉取的第一个GTID是Executed_Gtid_Set的下一个GTID，SQL线程正常回放。
Retrieved_Gtid_Set > Executed_Gtid_Set下，error.log中有如下信息。因为在Executed_Gtid_Set小于Retrieved_Gtid_Set情况下，被截断的GTID还未被执行，所以SQL线程会尝试去执行，执行了发现事务不完整，会进行rollback；且MySQL启动后，这个不完整的事务会被放到last_received_GTID中，这样MySQL会根据UNION(@@global.gtid_executed, Retrieved_gtid_set - last_received_GTID)集合，IO线程会重新拉取这个不完整的事务，此时拉取后事务完整，SQL线程正常回放。
2018-12-14T16:17:38.020740+08:00 1 [Note] Slave SQL for channel '': Rolling back unfinished transaction (no COMMIT or ROLLBACK in relay log). A probable cause is partial transaction left on relay log because of restarting IO thread with auto-positioning protocol. Error_code: 0
| 问题
在GTID模式下，设置relay-log-recovery=0会不会影响从库的数据一致性？
并行复制下呢？
| 作者简介
韩杰 沃趣科技MySQL数据库工程师
熟悉mysql体系架构、主从复制，熟悉问题定位与解决。
点击查看招聘信息
相关链接
更多干货，欢迎来撩~