一、背景
MySQL 8.0已经成为最受瞩目的版本，增加了许多新特性，如Clone Plugin、Hash Join等等。由于新的MySQL重做日志和数据字典格式，所以推出新的XtraBackup 8.0版本，本文基于MySQL产品在自动搭建备库时遇到问题做出解析。
1.1 测试环境
- MySQL 8.0.18
- xtrabackup 8.0.8
- binlog_format=raw,gtid_mode=on,log-bin=1
- sysbench 1.0.17
1.2 问题来源
某天，QFusion测试人员遇到了MySQL 8.0在备库搭建时报错，需要DBA同学跟进问题。首先通过show slave status查看报错信息，发现从库的sql thread出现异常。
root@localhost : (none) 08:56:40> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: test-58-aa-f8aa500-headless
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000085
Read_Master_Log_Pos: 1751589
Relay_Log_File: mysql-relay-bin.000002
Relay_Log_Pos: 416
Relay_Master_Log_File: mysql-bin.000050
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: 1062
Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758' at master log , end_log_pos 16052967. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
Skip_Counter: 0
Exec_Master_Log_Pos: 15520378
Relay_Log_Space: 19285319437
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: 1062
Last_SQL_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758' at master log , end_log_pos 16052967. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
Replicate_Ignore_Server_Ids:
Master_Server_Id: 41796
Master_UUID: 4a8f2de4-1fe1-11ea-a7d3-42549a90e353
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: 191216 18:56:49
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: 4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758-48217
Executed_Gtid_Set: 4a8f2de4-1fe1-11ea-a7d3-42549a90e353:1-25757
Auto_Position: 1
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
Master_public_key_path:
Get_master_public_key: 0
Network_Namespace:
1 row in set (0.00 sec)通过报错信息中的提示，发现是出现了主键冲突。
root@localhost : (none) 08:57:05> select * from performance_schema.replication_applier_status_by_worker limit 1\G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 1
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_ERROR_NUMBER: 1062
LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758' at master log , end_log_pos 16052967; Could not execute Write_rows event on table test.sbtest24; Duplicate entry '1529529' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 16052967
LAST_ERROR_TIMESTAMP: 2019-12-16 18:56:49.326384
LAST_APPLIED_TRANSACTION:
LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
LAST_APPLIED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 0000-00-00 00:00:00.000000
LAST_APPLIED_TRANSACTION_START_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP: 0000-00-00 00:00:00.000000
APPLYING_TRANSACTION: 4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758
APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2019-12-16 17:31:13.653629
APPLYING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2019-12-16 17:31:13.653629
APPLYING_TRANSACTION_START_APPLY_TIMESTAMP: 2019-12-16 18:56:49.325745
LAST_APPLIED_TRANSACTION_RETRIES_COUNT: 0
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE:
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
APPLYING_TRANSACTION_RETRIES_COUNT: 0
APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE:
APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
1 row in set (0.00 sec)查看当前slave最新的gtid信息
root@localhost : (none) 12:05:14> show master status\G
*************************** 1. row ***************************
File: mysql-bin.000008
Position: 155
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set: 4a8f2de4-1fe1-11ea-a7d3-42549a90e353:1-25757
1 row in set (0.00 sec)查看xtrabackup备份时的binlog的pos和gtid信息
[root@test-58-aa-f8aa501-0 mydata]# cat xtrabackup_info
...
binlog_pos = filename 'mysql-bin.000050', position '33110447', GTID of the last change '4a8f2de4-1fe1-11ea-a7d3-42549a90e353:1-25757'
...此时对比发现，slave的gtid信息和备份完成时的gtid是一致的，那为什么还是出现了主键冲突的情况呢？
此时我们根据pos位点解析master的binlog信息
[root@test-58-aa-f8aa500-0 archive]# mysqlbinlog -vv mysql-bin.000050 --start-position=33110447 | head -20
mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8mb4'.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 195
#191216 17:31:12 server id 41796 end_log_pos 124 CRC32 0xc9ad2c11 Start: binlog v 4, server v 8.0.18 created 191216 17:31:12
BINLOG '
4E73XQ9EowAAeAAAAHwAAAAAAAQAOC4wLjE4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgERLK3J
'/*!*/;
# at 33110447
#191216 17:31:13 server id 41796 end_log_pos 33110527 CRC32 0x27442dd4 GTID last_committed=15 sequence_number=34 rbr_only=yes original_committed_timestamp=1576488674113763 immediate_commit_timestamp=1576488674113763 transaction_length=1034680
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1576488674113763 (2019-12-16 17:31:14.113763 CST)
# immediate_commit_timestamp=1576488674113763 (2019-12-16 17:31:14.113763 CST)
/*!80001 SET @@session.original_commit_timestamp=1576488674113763*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= '4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25776'/*!*/;
# at 33110527根据binlog的pos位点，发现下一个事务GTID为4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25776；而备份结束的GTID为4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25757。
此时我们根据pos位点解析master的binlog信息
### 主库查看4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758的执行语句
[root@test-58-aa-f8aa500-0 archive]# mysqlbinlog -vv mysql-bin.000050 | grep -B 50 4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25759
...
### INSERT INTO `test`.`sbtest24`
### SET
### @1=1532200 /* INT meta=0 nullable=0 is_null=0 */
### @2=2512693 /* INT meta=0 nullable=0 is_null=0 */
### @3='89203990588-69103074818-52114821100-93439894362-23847143576-07484173808-05428369926-02975913993-41574550041-26938280355' /* STRING(360) meta=61032 nullable=0 is_null=0 */
### @4='45342050513-61911498937-97819152099-08587625932-60582159210' /* STRING(180) meta=65204 nullable=0 is_null=0 */
### INSERT INTO `test`.`sbtest24`
### SET
### @1=1532201 /* INT meta=0 nullable=0 is_null=0 */
### @2=2516379 /* INT meta=0 nullable=0 is_null=0 */
### @3='16016112465-66688149957-19003543589-12752783330-10140834595-17946818527-54058037200-83940103252-07788820899-59081899782' /* STRING(360) meta=61032 nullable=0 is_null=0 */
### @4='02966014962-81012143426-29059376957-22789496327-25833494842' /* STRING(180) meta=65204 nullable=0 is_null=0 */
### INSERT INTO `test`.`sbtest24`
### SET
### @1=1532202 /* INT meta=0 nullable=0 is_null=0 */
### @2=2707896 /* INT meta=0 nullable=0 is_null=0 */
### @3='16925828637-58090054889-95780407302-10293804842-12632614860-03811213734-46471823942-17333962963-31790381481-07019946586' /* STRING(360) meta=61032 nullable=0 is_null=0 */
### @4='77178758790-70128854370-00264407205-64007208401-22279618099' /* STRING(180) meta=65204 nullable=0 is_null=0 */
# at 16555027
#191216 17:31:11 server id 41796 end_log_pos 16555058 CRC32 0x6f8135d4 Xid = 36324
COMMIT/*!*/;
# at 16555058
#191216 17:31:11 server id 41796 end_log_pos 16555138 CRC32 0x7fcb97ac GTID last_committed=0 sequence_number=17 rbr_only=yes original_committed_timestamp=1576488673657448 immediate_commit_timestamp=1576488673657448 transaction_length=1034680
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1576488673657448 (2019-12-16 17:31:13.657448 CST)
# immediate_commit_timestamp=1576488673657448 (2019-12-16 17:31:13.657448 CST)
/*!80001 SET @@session.original_commit_timestamp=1576488673657448*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= '4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25759'/*!*/;
### 从库查看事务4a8f2de4-1fe1-11ea-a7d3-42549a90e353:25758的数据是否存在
root@localhost : (none) 09:23:04> select * from test.sbtest24 order by id desc limit 10;
+---------+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| id | k | c | pad |
+---------+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
| 1532202 | 2707896 | 16925828637-58090054889-95780407302-10293804842-12632614860-03811213734-46471823942-17333962963-31790381481-07019946586 | 77178758790-70128854370-00264407205-64007208401-22279618099 |
| 1532201 | 2516379 | 16016112465-66688149957-19003543589-12752783330-10140834595-17946818527-54058037200-83940103252-07788820899-59081899782 | 02966014962-81012143426-29059376957-22789496327-25833494842 |
| 1532200 | 2512693 | 89203990588-69103074818-52114821100-93439894362-23847143576-07484173808-05428369926-02975913993-41574550041-26938280355 | 45342050513-61911498937-97819152099-08587625932-60582159210 |
| 1532199 | 2502576 | 09802368960-91917733453-96239669598-54904648916-77296852719-98016730243-90741158106-18793912721-49864482275-01438682979 | 97383280864-09719424624-52657831677-16997497487-42888128592 |
| 1532198 | 2492769 | 50767886676-93929990978-69338677932-87282029008-76889813973-90185628217-96733941319-68335970853-94711333694-25795217601 | 19336837263-95804875039-06595487043-70523328561-09413324879 |
| 1532197 | 1955396 | 00397406795-74747838176-71394165168-41273836833-69479591787-42154528121-51771653744-67255388362-49886388719-58697178839 | 02673409369-19296574832-28003465943-79301421425-80480578998 |
| 1532196 | 2493231 | 86498404871-42108054116-40071340969-11350042446-06300939909-05201025379-06411857335-03954766664-39537185462-91490507327 | 84818317688-20764928816-31090759998-91731449425-90118225230 |
| 1532195 | 2499593 | 77660688834-45252238334-24137839414-65367466774-19337774130-53076983367-01390519320-71314042514-11226819773-51096244448 | 21997720631-75948312175-91821894792-80556960963-06584097138 |
| 1532194 | 2515138 | 66646860538-72521674543-39777861094-01574256160-18755135370-00487912454-64289722053-52102961561-41410923742-00667455284 | 84070066757-97543385536-80074118200-18008298945-61299807560 |
| 1532193 | 2517655 | 50560105798-09418525134-35753621841-55990140866-27080595470-36899245149-55668180470-33559752487-83646593848-17843254144 | 79647081405-62007589765-85313418965-19437322653-89655822041 |
+---------+---------+-------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------+
10 rows in set (0.00 sec)此时我们根据pos位点解析master的binlog信息确认下一个事务已经执行。
二、问题排查
2.1 前期准备
MySQL 8.0的备份取消了FLUSH TABLES WITH READ LOCK的全局加锁限制，具体备份流程后续会写文章对比；使用performance_schema.log_status表来获取binlog的pos和GTID信息。
首先我们介绍下8.0新增的performance_schema.log_status表的具体内容。
root@localhost : (none):47: > select * from performance_schema.log_status\G
*************************** 1. row ***************************
SERVER_UUID: 9eed5dd0-213c-11ea-a06f-fa9c144d7000
LOCAL: {"gtid_executed": "d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2344524", "binary_log_file": "mysql-bin.000036", "binary_log_position": 8237993}
REPLICATION: {"channels": [{"channel_name": "", "relay_log_file": "mysql-relay-bin.000002", "relay_log_position": 130357303}]}
STORAGE_ENGINES: {"InnoDB": {"LSN": 13536450538, "LSN_checkpoint": 13522598241}}
1 row in set (0.00 sec)- SERVER_UUID：此服务器实例的服务器UUID。这是只读系统变量server_uuid的唯一值。
-
LOCAL：来自主服务器的日志位置状态信息，以单个JSON对象的形式提供，并具有以下信息：
- binary_log_file：当前二进制日志文件的名称。
- binary_log_position：访问log_status表时的当前二进制日志位置。
- gtid_executed：在访问log_status表时，全局变量gtid_execute的当前值。此信息与binary_log_file和binary_log_position键一致。
-
REPLICATION：一个通道的JSON数组，每个通道具有以下信息：
- channel_name：复制通道的名称。
- relay_log_file：复制通道的当前中继日志文件的名称。
- relay_log_pos：访问log_status表时的当前中继日志位置。
- STORAGE_ENGINES：来自各个存储引擎的相关信息，以JSON对象的形式提供，每个适用的存储引擎都有一个密钥。
2.2 验证show master status的输出信息
evernotecid://232882CB-0E86-4D89-B07A-EA1AE2F94E20/appyinxiangcom/15365034/ENResource/p17613
这里可以看到，在并发场景下，show master status输出的GTID和binlog的pos位点不是对应的。查看代码后发现：binlog的file和pos位点的更新在group commit的flush阶段后，即可对其他会话可见。而GTID是在group commit的commit阶段后可对其他会话可见，所以也就造成了show master status输出的binlog信息和GTID信息非原子性。
三、复现问题
3.1 开始备份
[root@qfusion1 ~]# xtrabackup --defaults-file=/etc/mysql/my.cnf --user=root --host=127.0.0.1 --password=xxx --port=3306 --extra-lsndir=/opt/full_lsn --stream=xbstream --backup --target-dir=./ | sshpass -p'letsg0' ssh root@qfusion2 'cat -> /data/backup/full_`date +%F_%H-%M-%S`.tar'
...
191217 19:02:45 [01] ...done
191217 19:02:45 Finished backing up non-InnoDB tables and files
191217 19:02:45 Executing FLUSH NO_WRITE_TO_BINLOG BINARY LOGS
191217 19:02:46 Selecting LSN and binary log position from p_s.log_status
191217 19:02:46 [00] Streaming /var/lib/mysql/archive/mysql-bin.000035 to <STDOUT> up to position 290601
191217 19:02:46 [00] ...done
191217 19:02:46 [00] Streaming <STDOUT>
191217 19:02:46 [00] ...done
191217 19:02:46 [00] Streaming <STDOUT>
191217 19:02:46 [00] ...done
191217 19:02:46 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '13470381978'
xtrabackup: Stopping log copying thread at LSN 13522426897.
191217 19:02:46 >> log scanned up to (13522598105)
191217 19:02:48 All tables unlocked
191217 19:02:48 [00] Streaming ib_buffer_pool to <STDOUT>
191217 19:02:48 [00] ...done
191217 19:02:48 Backup created in directory '/root/'
MySQL binlog position: filename 'mysql-bin.000035', position '290601', GTID of the last change 'd3eff916-0e03-11ea-a98d-fa84dc05a100:1-2340959'
191217 19:02:48 [00] Streaming <STDOUT>
191217 19:02:48 [00] ...done
191217 19:02:48 [00] Streaming <STDOUT>
191217 19:02:48 [00] ...done
xtrabackup: Transaction log of lsn (12972859512) to (13526909324) was copied.
191217 19:02:50 completed OK!3.2 查看xtrabackup的信息
[root@qfusion2 full]# ls
backup-my.cnf ibdata1 mysql-bin.000035 mysql.ibd sbtest test undo_002 xtrabackup_checkpoints xtrabackup_logfile
ib_buffer_pool mysql mysql-bin.index performance_schema sys undo_001 xtrabackup_binlog_info xtrabackup_info xtrabackup_tablespaces
[root@qfusion2 full]# cat xtrabackup_binlog_info
mysql-bin.000035 290601 d3eff916-0e03-11ea-a98d-fa84dc05a100:1-23409593.3 查看对应的binlog信息
[root@qfusion2 full]# mysqlbinlog -vv mysql-bin.000035 | grep d3eff916-0e03-11ea-a98d-fa84dc05a100 | tail -10
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340970'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340971'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340972'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340973'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340974'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340975'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340976'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340977'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340978'/*!*/;
SET @@SESSION.GTID_NEXT= 'd3eff916-0e03-11ea-a98d-fa84dc05a100:2340979'/*!*/;
[root@qfusion2 full]# mysqlbinlog -vv mysql-bin.000035 --start-position=290601
mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 195
#191217 19:02:45 server id 2433306 end_log_pos 124 CRC32 0x6d85a9e8 Start: binlog v 4, server v 8.0.18 created 191217 19:02:45
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
1bX4XQ8aISUAeAAAAHwAAAABAAQAOC4wLjE4AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgHoqYVt
'/*!*/;
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*/;3.4 开始恢复
[root@qfusion2 full]# xtrabackup --defaults-file=/etc/mysql/my.cnf --prepare --use-memory=5G --target-dir=/data/backup/full/
[root@qfusion2 full]# xtrabackup --defaults-file=/etc/mysql/my.cnf --move-back --target-dir=/data/backup/full/
[root@qfusion2 full]# chown -R mysql:mysql /var/lib/mysql/
[root@qfusion2 full]# mysqld_safe --defaults-file=/etc/mysql/my.cnf &
[root@qfusion2 full]# mysql -uroot -pxxx
root@localhost : (none):19: > show master status\G
*************************** 1. row ***************************
File: mysql-bin.000036
Position: 195
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set: d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2340979
1 row in set (0.00 sec)
[root@qfusion2 full]# cat xtrabackup_binlog_info
mysql-bin.000035 290601 d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2340959备份恢复完成后，我们可以看到，show master status输出的GTID信息与xtrabackup_binlog_info文件的GTID是不一致的，对比产品中遇到主键冲突的问题中的show master status的GTID和与xtrabackup_binlog_info文件的GTID是一致的；可以确认的事情是恢复之后是有过对数据库的操作了。此时应该找下原型预研文档和产品开发人员确认下是否在MySQL恢复之后有其他额外的操作，得到反馈是执行了如下的语句操作：
reset master;
...
set global gtid_purged='xxx'这些步骤是MySQL 5.7下的搭建备库必要的操作（下面内容有验证），因为在5.7备份是没有binlog的备份，且GTID的持久化是在mysql.gtid_executed表，但是该表不是实时更新的，在主库的更新策略如下：
- 主库开启binlog时，mysql.gtid_executed表会记录GTID信息，且在binlog rotation或者server重启时进行更新。
- 主库未开启binlog时，mysql.gtid_executed表不会记录任何信息。
那么MySQL 8.0下的mysql.gtid_executed表的更新策略是什么样的呢？此时我们可以查询官方文档寻找答案：
简单翻译下：如果启用了二进制日志（log_bin为ON），则从MySQL 8.0.17起对InnoDB存储引擎，mysqld以禁用binlog记录或slave更新日志记录的相同方式更新mysql.gtid_executed表，并存储GTID用于事务提交时的每个事务。但是，在MySQL 8.0.17之前的版本以及其他存储引擎中，仅在切换binlog或重启mysqld时，mysqld将所有写入上一个binlog的事务的GTID写入mysql.gtid_executed表。
我们也可以测试验证下：
root@localhost : test:12: > select * from mysql.gtid_executed;show master status;
+--------------------------------------+----------------+--------------+
| source_uuid | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 1 | 2764676 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2764677 | 2764783 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2764784 | 2764893 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2764894 | 2765008 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765009 | 2765074 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765075 | 2765143 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765144 | 2765185 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765186 | 2765283 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765284 | 2765384 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765385 | 2765485 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765486 | 2765571 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765572 | 2765652 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765653 | 2765746 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765747 | 2765865 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765866 | 2765948 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765949 | 2766028 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2766029 | 2766052 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2766053 | 2766053 |
+--------------------------------------+----------------+--------------+
18 rows in set (0.00 sec)
+------------------+-----------+--------------+------------------+------------------------------------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+-----------+--------------+------------------+------------------------------------------------+
| mysql-bin.000036 | 450959566 | | | d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2766053 |
+------------------+-----------+--------------+------------------+------------------------------------------------+
1 row in set (0.01 sec)
root@localhost : test:12: > insert into test values(1,1,'1');
Query OK, 1 row affected (0.00 sec)
root@localhost : test:12: > insert into test values(2,2,'2');
Query OK, 1 row affected (0.01 sec)
root@localhost : test:12: > select * from mysql.gtid_executed;show master status;
+--------------------------------------+----------------+--------------+
| source_uuid | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 1 | 2764676 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2764677 | 2764783 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2764784 | 2764893 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2764894 | 2765008 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765009 | 2765074 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765075 | 2765143 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765144 | 2765185 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765186 | 2765283 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765284 | 2765384 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765385 | 2765485 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765486 | 2765571 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765572 | 2765652 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765653 | 2765746 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765747 | 2765865 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765866 | 2765948 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2765949 | 2766028 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2766029 | 2766052 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2766053 | 2766053 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2766054 | 2766054 |
| d3eff916-0e03-11ea-a98d-fa84dc05a100 | 2766055 | 2766055 |
+--------------------------------------+----------------+--------------+
20 rows in set (0.01 sec)
+------------------+-----------+--------------+------------------+------------------------------------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+-----------+--------------+------------------+------------------------------------------------+
| mysql-bin.000036 | 450960258 | | | d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2766055 |
+------------------+-----------+--------------+------------------+------------------------------------------------+
1 row in set (0.00 sec)3.5 手动删除备份的binlog文件
[root@qfusion2 full]# ls
backup-my.cnf mysql-bin.000035 sbtest undo_002 xtrabackup_logfile
ib_buffer_pool mysql-bin.index sys xtrabackup_binlog_info xtrabackup_tablespaces
ibdata1 mysql.ibd test xtrabackup_checkpoints
mysql performance_schema undo_001 xtrabackup_info
[root@qfusion2 full]# mv mysql-bin.* ../
[root@qfusion2 full]# ls
backup-my.cnf mysql.ibd test xtrabackup_checkpoints
ib_buffer_pool performance_schema undo_001 xtrabackup_info
ibdata1 sbtest undo_002 xtrabackup_logfile
mysql sys xtrabackup_binlog_info xtrabackup_tablespaces
[root@qfusion2 full]# xtrabackup --defaults-file=/etc/mysql/my.cnf --prepare --use-memory=5G --target-dir=/data/backup/full/
[root@qfusion2 full]# xtrabackup --defaults-file=/etc/mysql/my.cnf --move-back --target-dir=/data/backup/full/
[root@qfusion2 full]# chown -R mysql:mysql /var/lib/mysql/
[root@qfusion2 full]# mysqld_safe --defaults-file=/etc/mysql/my.cnf &
[root@qfusion2 full]# mysql -uroot -pxxx
root@localhost : (none):46: > show master status\G
*************************** 1. row ***************************
File: mysql-bin.000003
Position: 155
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set: d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2340959
1 row in set (0.00 sec)
[root@qfusion2 full]# cat xtrabackup_binlog_info
mysql-bin.000035 290601 d3eff916-0e03-11ea-a98d-fa84dc05a100:1-2340959在手动移除备份生成的相关binlog文件后，发现事务是回滚到xtrabackup_binlog_info记录的GTID的位置。与MySQL 5.7下的备份恢复的情况一致；具体可以查看下面的验证。
四、MySQL 5.7下的物理备份
4.1 测试环境
- MySQL 5.7.28
- xtrabackup 2.4.17
- binlog_format=raw,gtid_mode=on,log-bin=1
- sysbench 1.0.17
4.2 开始备份
[root@qfusion3 archive]# xtrabackup --defaults-file=/etc/mysql/my.cnf --user=root --host=127.0.0.1 --password=abc123 --port=3306 --extra-lsndir=/opt/full_lsn --stream=xbstream --backup --target-dir=./ | sshpass -p'letsg0' ssh root@qfusion4 'cat -> /data/backup/full_`date +%F_%H-%M-%S`.tar'4.3 开始恢复
[root@qfusion4 full]# cd /data/backup
[root@qfusion4 full]# xbstream -x < full_2019-12-18_14-06-10.tar -C full
[root@qfusion4 full]# cd full
[root@qfusion4 full]# ls
backup-my.cnf ibdata1 performance_schema sys undo002 undo004 undo006 undo008 undo010 undo012 undo014 undo016 xtrabackup_checkpoints xtrabackup_logfile
ib_buffer_pool mysql sbtest undo001 undo003 undo005 undo007 undo009 undo011 undo013 undo015 xtrabackup_binlog_info xtrabackup_info
[root@qfusion4 full]# xtrabackup --defaults-file=/etc/mysql/my.cnf --prepare --use-memory=5G --target-dir=/data/backup/full/
[root@qfusion4 full]# xtrabackup --defaults-file=/etc/mysql/my.cnf --move-back --target-dir=/data/backup/full/
[root@qfusion4 full]# chown -R mysql:mysql /var/lib/mysql/
[root@qfusion4 full]# mysqld_safe --defaults-file=/etc/mysql/my.cnf &
[root@qfusion4 full]# mysql -uroot -pxxx
root@localhost : (none):13: > select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 189fb8ac-1fe8-11ea-9b92-faf16b07cf00 | 1 | 535 |
+--------------------------------------+----------------+--------------+
1 row in set (0.01 sec)
root@localhost : (none):13: > show master status\G
*************************** 1. row ***************************
File: mysql-bin.000001
Position: 154
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set: 189fb8ac-1fe8-11ea-9b92-faf16b07cf00:1-535
1 row in set (0.00 sec)
[root@qfusion4 full]# cat xtrabackup_binlog_info
mysql-bin.000003 175325364 189fb8ac-1fe8-11ea-9b92-faf16b07cf00:1-736可以看到MySQL 5.7版本的备份恢复后的GTID是依赖于mysql.gtid_executed表，但是该表不是实时更新，此时的GTID其实是滞后的，所以也需要额外执行set global gtid_purged=‘xxx’。
五、总结
- MySQL 8.0下的物理备份生成的GTID值是不可靠，因为备份了最后一个binlog文件，恢复时会recovery到最新的事务。
- MySQL 8.0下的物理备份会执行FLUSH NO_WRITE_TO_BINLOG BINARY LOGS操作，在有大事务对数据进行修改时，一不小心可能就会出现数据库hang死，所以建议使用小事务。
