如果将relay_log_recovery设置为0会发生什么？

水深无声 2022-03-25 12:58 437阅读 0赞

## **| 背景** ##

在MySQL5.7版本中，开启并行复制后，设置relay-log-recovery=1，从库启动后偶尔会报错，类似于[https://bugs.mysql.com/bug.php?id=83713][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
    /*!*/;
    # 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为2662c965-fdb2-11e8-8157-0cc47a3aae0d: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会不会影响从库的数据一致性？   
并行复制下呢？

[https_bugs.mysql.com_bug.php_id_83713]: https://bugs.mysql.com/bug.php?id=83713