为什么还原innobackupex备份后查看到的Executed_Gtid_Set与xtrabackup_binlog_info不一致

基本环境：官方社区版MySQL 5.7.19，innobackupex version 2.4.8

一、什么不一致

1.1、不一致

首先使用下面脚本来构建Executed_Gtid_Set与xtrabackup_binlog_info不一致，到底指的是什么不一致

1、准备测试数据
# 切换日志
mydba@192.168.85.132,3306 [replcrash]> flush binary logs;
Query OK, 0 rows affected (0.07 sec)
# 查看当前位置
mydba@192.168.85.132,3306 [replcrash]> show master status;
+------------------+----------+--------------+------------------+-----------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                             |
+------------------+----------+--------------+------------------+-----------------------------------------------+
| mysql-bin.000191 |      194 |              |                  | 8ab82362-9c37-11e7-a858-000c29c1025c:1-507450 |
+------------------+----------+--------------+------------------+-----------------------------------------------+
1 row in set (0.00 sec)
# 清空数据
mydba@192.168.85.132,3306 [replcrash]> truncate table py_user;
Query OK, 0 rows affected (0.01 sec)
mydba@192.168.85.132,3306 [replcrash]> show create table py_user;
+---------+---------------------------------------------------------+
| Table   | Create Table                                            |
+---------+---------------------------------------------------------+
| py_user | CREATE TABLE `py_user` (
  `uid` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(32) DEFAULT NULL,
  `add_time` datetime DEFAULT CURRENT_TIMESTAMP,
  `server_id` varchar(10) DEFAULT NULL,
  PRIMARY KEY (`uid`),
  KEY `name` (`name`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
+---------+---------------------------------------------------------+
1 row in set (0.04 sec)
# 写入数据
mydba@192.168.85.132,3306 [replcrash]> insert into py_user(name,server_id) select left(uuid(),30),@@server_id;
Query OK, 1 row affected (0.02 sec)
Records: 1  Duplicates: 0  Warnings: 0
# 写入数据
mydba@192.168.85.132,3306 [replcrash]> insert into py_user(name,server_id) select left(uuid(),30),@@server_id;
Query OK, 1 row affected (0.00 sec)
Records: 1  Duplicates: 0  Warnings: 0
# 删除数据
mydba@192.168.85.132,3306 [replcrash]> delete from py_user where uid=2;
Query OK, 1 row affected (0.04 sec)
# 查看数据
mydba@192.168.85.132,3306 [replcrash]> select * from py_user;
+-----+--------------------------------+---------------------+-----------+
| uid | name                           | add_time            | server_id |
+-----+--------------------------------+---------------------+-----------+
|   1 | 64410b10-f504-11e7-a71e-000c29 | 2018-01-09 14:14:46 | 1323306   |
+-----+--------------------------------+---------------------+-----------+
1 row in set (0.00 sec)
# 查看当前位置
mydba@192.168.85.132,3306 [replcrash]> show master status;
+------------------+----------+--------------+------------------+-----------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                             |
+------------------+----------+--------------+------------------+-----------------------------------------------+
| mysql-bin.000191 |     1329 |              |                  | 8ab82362-9c37-11e7-a858-000c29c1025c:1-507454 |
+------------------+----------+--------------+------------------+-----------------------------------------------+
1 row in set (0.00 sec)
# 查看mysql.gtid_executed
mydba@192.168.85.132,3306 [replcrash]> select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 8ab82362-9c37-11e7-a858-000c29c1025c |              1 |       507450 |
+--------------------------------------+----------------+--------------+
1 row in set (0.00 sec)


2、备份并还原到新实例
# backup
[root@ZST1 ~]# innobackupex --defaults-file=/data/mysql/mysql3306/my.cnf -S /tmp/mysql3306.sock -uroot -pmysql5719 --no-timestamp /data/backup/full/20180109
# 查看备份位置
[root@ZST1 ~]# cat /data/backup/full/20180109/xtrabackup_binlog_info
mysql-bin.000191        1329    8ab82362-9c37-11e7-a858-000c29c1025c:1-507454
[root@ZST1 ~]# 

# apply-log
[root@ZST1 ~]# innobackupex --apply-log /data/backup/full/20180109
# 查看innodb位置(apply-log后生成)
[root@ZST1 ~]# cat /data/backup/full/20180109/xtrabackup_binlog_pos_innodb
mysql-bin.000191        1329
[root@ZST1 ~]# 

# copy-back
• 需要恢复的MySQL实例需要关闭(关闭前reset master方便后续对比)
• 目标datadir为空
• 手工把apply后的文件copy过去，或者
[root@ZST1 ~]# innobackupex --defaults-file=/data/mysql/mysql3308/my.cnf --copy-back /data/backup/full/20180109
• 更改copy过去的权限
[root@ZST1 ~]# chown -R mysql:mysql /data/mysql/mysql3308/data
• 启动MySQL
[root@ZST1 ~]# /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql/mysql3308/my.cnf &

# 登录查询
mydba@192.168.85.132,3308 [replcrash]> show master status;
+------------------+----------+--------------+------------------+-----------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                             |
+------------------+----------+--------------+------------------+-----------------------------------------------+
| mysql-bin.000002 |      154 |              |                  | 8ab82362-9c37-11e7-a858-000c29c1025c:1-507450 |
+------------------+----------+--------------+------------------+-----------------------------------------------+
1 row in set (0.00 sec)

mydba@192.168.85.132,3308 [replcrash]> select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 8ab82362-9c37-11e7-a858-000c29c1025c |              1 |       507450 |
+--------------------------------------+----------------+--------------+
1 row in set (0.00 sec)

还原后通过show master status得到的Executed_Gtid_Set为8ab82362-9c37-11e7-a858-000c29c1025c:1-507450；实际备份的位置是8ab82362-9c37-11e7-a858-000c29c1025c:1-507454(xtrabackup_binlog_info)
上面就是Executed_Gtid_Set与xtrabackup_binlog_info不一致的例子，应该说大部分情况这两个值是不一致的。只是大部分的操作中，我们对Executed_Gtid_Set值基本无感，因此很少会注意到它们不一致

1.2、一致

下面我们执行flush binary logs，然后备份并进行后续操作

3、flush binary logs
# 续上，3306执行flush logs操作
mydba@192.168.85.132,3306 [replcrash]> flush binary logs;
Query OK, 0 rows affected (0.13 sec)
# 查看mysql.gtid_executed
mydba@192.168.85.132,3306 [replcrash]> select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 8ab82362-9c37-11e7-a858-000c29c1025c |              1 |       507454 |
+--------------------------------------+----------------+--------------+
1 row in set (0.00 sec)
mysql.gtid_executed表中的信息已经更新


4、再一次备份并还原到新实例
# backup
[root@ZST1 ~]# innobackupex --defaults-file=/data/mysql/mysql3306/my.cnf -S /tmp/mysql3306.sock -uroot -pmysql5719 --no-timestamp /data/backup/full/20180109new
# 查看备份位置
[root@ZST1 ~]# cat /data/backup/full/20180109new/xtrabackup_binlog_info
mysql-bin.000192        194     8ab82362-9c37-11e7-a858-000c29c1025c:1-507454
[root@ZST1 ~]# 

# apply-log
[root@ZST1 ~]# innobackupex --apply-log /data/backup/full/20180109new
# 查看innodb位置(apply-log后生成)
[root@ZST1 ~]# cat /data/backup/full/20180109new/xtrabackup_binlog_pos_innodb 
mysql-bin.000191        1329
[root@ZST1 ~]# 
注意此时xtrabackup_binlog_info与xtrabackup_binlog_pos_innodb也不一致。一般执行flush logs，或者ddl语句(<=5.7不记录redo)会导致两者不一致

# copy-back
• 需要恢复的MySQL实例需要关闭(关闭前reset master方便后续对比)
• 目标datadir为空
• 手工把apply后的文件copy过去，或者
[root@ZST1 ~]# innobackupex --defaults-file=/data/mysql/mysql3308/my.cnf --copy-back /data/backup/full/20180109new
• 更改copy过去的权限
[root@ZST1 ~]# chown -R mysql:mysql /data/mysql/mysql3308/data
• 启动MySQL
[root@ZST1 ~]# /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql/mysql3308/my.cnf &

# 登录查询
mydba@192.168.85.132,3308 [replcrash]> show master status;
+------------------+----------+--------------+------------------+-----------------------------------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                             |
+------------------+----------+--------------+------------------+-----------------------------------------------+
| mysql-bin.000002 |      154 |              |                  | 8ab82362-9c37-11e7-a858-000c29c1025c:1-507454 |
+------------------+----------+--------------+------------------+-----------------------------------------------+
1 row in set (0.00 sec)

mydba@192.168.85.132,3308 [replcrash]> select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 8ab82362-9c37-11e7-a858-000c29c1025c |              1 |       507454 |
+--------------------------------------+----------------+--------------+
1 row in set (0.00 sec)

还原后通过show master status得到的Executed_Gtid_Set为8ab82362-9c37-11e7-a858-000c29c1025c:1-507454；实际备份的位置是8ab82362-9c37-11e7-a858-000c29c1025c:1-507454(xtrabackup_binlog_info)
发现没有，flush binary logs后得到的备份，在还原后Executed_Gtid_Set与xtrabackup_binlog_info保持一致

二、为什么不一致

2.1、show master status

数据库实例刚启动时，MySQL 5.7从mysql.gtid_executed表获取执行过的事务的GTID->Executed_Gtid_Set
数据库实例运行过程中，show master status返回实时信息。开启binlog，mysql.gtid_executed需发生切换才写入新数据，那么show master status的数据是从哪获取的？

2.2、mysql.gtid_executed

还原后，我们看到的Executed_Gtid_Set信息应该来自mysql.gtid_executed(这里指的是还原后，还没有ddl、dml等操作)
mysql.gtid_executed表按照下面的方式写入
• 如果没有开启log_bin或者没有开启log_slave_updates，从库在应用relay-log中的每个事务会执行一个insert mysql.gtid_executed操作。这只针对从库而言~
• 如果开启log_bin，在binlog发生rotate(flush binary logs/达到max_binlog_size)或者关闭服务时，会把所有写入到binlog中的Gtid信息写入到mysql.gtid_executed表。这适用于主库和从库~
原实例本身开启了binlog，当我们执行flush binary logs时就将当前的GTID信息写入到mysql.gtid_executed表。。。
第一次的测试，虽然有很多insert、delete，但是由于没有发生binlog切换，相应的GTID信息没有写入到mysql.gtid_executed表(innodb)，此时innobackupex备份，将对应的.ibd备份起来，还原后还是原来的数据
最开始并没注意到mysql.gtid_executed，总以为innobackupex会自己执行某个set gtid_purged语句。在配置文件开启general_log，并且starce 启动服务，结果毛线都没看到~~~

# general_log
[mysqld]
general_log=1
general_log_file=/data/mysql/mysql3308/data/mysql-general.log
# strace
shell> strace /usr/local/mysql/bin/mysqld --defaults-file=/data/mysql/mysql3308/my.cnf >/tmp/3308.log 2>&1

23:09 2018/1/26 补充，上面的解释不太准确，参考新随笔：gtid_executed和gtid_purged变量是如何初始化的以及文末总结

2.3、不一致会有什么影响

使用innobackupex的备份搭建从库，在还原后都需要通过xtrabackup_binlog_info或者xtrabackup_binlog_pos_innodb中的信息，SET @@GLOBAL.GTID_PURGED='uuid:seq';然后再做change master to操作
其他几个备份工具得到的GTID信息

# mysqldump
[root@ZST1 ~]# mysqldump -h127.0.0.1 -P3306 -uroot -p --single-transaction --master-data=2 replcrash >/data/backup/replcrash_dump_1323306_`date +%Y%m%d`.sql
[root@ZST1 ~]# more /data/backup/replcrash_dump_1323306_`date +%Y%m%d`.sql
SET @@GLOBAL.GTID_PURGED='8ab82362-9c37-11e7-a858-000c29c1025c:1-507455';
# mysqlpump
[root@ZST1 ~]# mysqlpump -h127.0.0.1 -P3306 -uroot -p --single-transaction --add-drop-table --exclude-databases=mysql,sakila,backupdb -A >/data/backup/replcrash_pump_1323306_`date +%Y%m%d`.sql
[root@ZST1 ~]# more /data/backup/replcrash_pump_1323306_`date +%Y%m%d`.sql
SET @@GLOBAL.GTID_PURGED=/*!80000 '+'*/ '8ab82362-9c37-11e7-a858-000c29c1025c:1-507455';
# mydumper
[root@ZST1 ~]# mydumper -h 127.0.0.1 -P 3306 -u root -p mysql5719 -v 3 -B replcrash -o /data/backup/mydumper
[root@ZST1 ~]# more /data/backup/mydumper/metadata 
Started dump at: 2018-01-09 16:59:37
SHOW MASTER STATUS:
        Log: mysql-bin.000192
        Pos: 353
        GTID:8ab82362-9c37-11e7-a858-000c29c1025c:1-507455

Finished dump at: 2018-01-09 16:59:38
# innobackupex
[root@ZST1 ~]# innobackupex --defaults-file=/data/mysql/mysql3306/my.cnf -S /tmp/mysql3306.sock -uroot -pmysql5719 --no-timestamp /data/backup/full/20180109
[root@ZST1 ~]# more /data/backup/full/20180109/xtrabackup_binlog_info 
mysql-bin.000191        1329    8ab82362-9c37-11e7-a858-000c29c1025c:1-507454
[root@ZST1 ~]# 
innobackupex之后，在原实例执行过truncate table py_user，因此上面的gtid不一样

使用mydumper(myloader不会产生binlog，也不会应用metadata中的GTID)和innobackupex的备份文件搭建从库，需要手动SET @@GLOBAL.GTID_PURGED
我们创建了不少的数据库备份，但却很少去检验备份是否有效。即使偶尔使用备份搭建测试环境、搭建从库、恢复数据
• 搭建测试环境，还原~game over
• 恢复数据，全备+binlog完美~game over
• 搭建从库，还原+reset master+change master to~game over
我们脑子里都有相应的套路，只需按步骤PaPaPa，就能完成大部分工作。经验之谈让我们规避了不少坑，同时也"错过"深挖坑的机会~

---

16:01 2018/3/13 总结补充
1、show master status中的Executed_Gtid_Set信息来自哪里
@@global.gtid_executed：MySQL数据库已经执行过的Gtid事务，处于内存中。show master status/show slave status中的Executed_Gtid_Set取自这里
@@global.gtid_executed是由gtids_in_binlog和mysql.gtid_executed表的并集初始化的
2、gtids_in_binlog是如何计算的
依据mysql-bin.index，迭代对应binary log files中的Previous_gtids_log_event/Gtid_log_event计算，需迭代的文件受binlog_gtid_simple_recovery参数影响
3、mysql.gtid_executed表如何写入
3.1、mysql.gtid_executed表的写入由内部机制控制，不会记录到binlog(解析binlog看不到任何与mysql.gtid_executed相关的信息)
3.2、mysql.gtid_executed表写入时机
• 如果没有开启log_bin或者没有开启log_slave_updates，从库在应用relay-log中的每个事务会执行一个insert mysql.gtid_executed操作。这只针对从库而言~
• 如果开启log_bin，在binlog发生rotate(flush binary logs/达到max_binlog_size)或者关闭服务时，会把所有写入到binlog中的Gtid信息写入到mysql.gtid_executed表。这适用于主库和从库~
4、xtrabackup备份流程
start xtrabackup_log拷贝redo log->copy .ibd;ibdata1备份InnoDB表->FTWRL->备份non-InnoDB表等->show master status获取当前位置->unlock tables->stop and copy xtrabackup_log
mysql.gtid_executed表使用innodb存储引擎，mysql.gtid_executed表中的数据并不是实时更新的，并且对其所有的写入不会记录binlog，也就是不会存在于redo log中
因此xtrabackup备份所得到的mysql.gtid_executed，就是copy gtid_executed.ibd时刻mysql.gtid_executed表中已有的数据。此数据与当时show master status的返回值极可能不一致(没满足写入时机)，并且后续拷贝到xtrabackup_logfile文件也不会包含mysql.gtid_executed相关信息，因此apply-log不会影响mysql.gtid_executed表中的数据
5、还原xtrabackup备份
根据前面的分析还原后mysql.gtid_executed表中的数据是copy gtid_executed.ibd时刻的数据
xtrabackup_binlog_info是备份non-InnoDB表后通过show master status得到
在有写操作的环境中，只要没触发mysql.gtid_executed表的写入，mysql.gtid_executed表与show master status中的Executed_Gtid_Set不可能一致
注意：如果还原实例的../logs/目录下存在binlog，在启动数据库服务时，它们会被计算到gtids_in_binlog，然后结合mysql.gtid_executed表初始化@@global.gtid_executed
因此使用xtrabackup备份做从库的情况下，一定记得要根据xtrabackup_binlog_info去SET @@GLOBAL.GTID_PURGED