如果將relay_log_recovery設定為0會發生什麼？
| 背景
在MySQL5.7版本中，開啟並行複製後，設定relay-log-recovery=1，從庫啟動後偶爾會報錯，類似於。所以嘗試將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 /*!*/; # 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 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 ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
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體系架構、主從複製，熟悉問題定位與解決。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/28218939/viewspace-2564367/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 【科普】如果程式設計師穿越到古代當皇帝，會發生什麼？程式設計師
- 為什麼索引的PCTUSED被設定為0索引
- 如果往錯誤的NEO地址轉賬會發生什麼
- 支付寶面試太太太刁鑽了！！如果把執行緒池 corePoolSize 設定為 0，會出現什麼情況？面試執行緒
- 3 * 0.1 == 0.3將會返回什麼？為什麼?
- 為什麼float:right的元素會發生換行
- 為什麼設定反省錄
- [ASP.NET] 如果將快取“滑動過期時間”設定為1秒會怎樣？ASP.NET快取
- 如果問你 WSGI 是什麼？0歲Web後端開發必看Web後端
- 為什麼Web 設計會“死”？Web
- mysql什麼時候會發生file sortMySql
- 我的組播程式如果設定了setLoopbackMode(true)為什麼就收不到訊息了？OOP
- 為什麼新人不會程式設計程式設計
- 為什麼很多大學生都會覺得程式設計很難？程式設計
- ThreadPoolTaskExecutor 如果執行緒池預設的queue滿了，會觸發什麼異常thread執行緒
- 為什麼前端開發這麼不穩定？前端
- 記憶體耗盡後Redis會發生什麼記憶體Redis
- 私家車開車回家過節會發生什麼事情
- 做APP究竟有什麼好處，為什麼想要發展好的公司一定會做APP
- 為什麼女程式設計師會這麼少？程式設計師
- 2019 年，容器技術生態會發生些什麼？
- 使用SAP CRM text api將空的文字寫入到後臺，會發生什麼事API
- electron-store會將資料儲存為什麼格式
- Java 當一個int和double相加 會發生什麼？Java
- php8引入jit後會發生什麼?PHP
- 在Linux上啟動程式時會發生什麼？Linux
- 當大資料邂逅六西格瑪，會發生什麼？大資料
- 瀏覽器輸入一個URL會發生什麼？瀏覽器
- 如果沒有 Android 世界會是什麼樣子？Android
- 為什麼為什麼為什麼為什麼為什麼你要做一名程式設計師？程式設計師
- 專案研發為什麼會失敗？（轉）
- 為什麼有的程式設計師不會程式設計？程式設計師
- Python 網路程式設計：當核心讀緩衝區為空，呼叫 socket 的 recv 的會發生什麼？Python程式設計
- win10怎麼將potplayer設定為預設播放器_win10如何將potplayer設定為預設播放器Win10播放器
- 系統呼叫時為什麼發生任務切換？
- Linux中什麼情況下會發生程式排程?Linux
- Qualtrics XM Institute：糟糕的體驗後會發生什麼
- 騰訊一面：記憶體滿了，會發生什麼？記憶體