故障分析 | 使用 mysqldump 备份导致数据丢失

爱可生开源社区 2021-12-08

1484

作者：林靖华

爱可生服务团队成员，负责处理客户在 MySQL 日常运维中遇到的问题；对数据库相关技术有浓厚的兴趣，喜欢钻研各种问题。

本文来源：原创投稿

* 爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

背景

最近在进行一套 MySQL 数据库的数据迁移工作，由于数据量不大，于是使用 mysqldump 把现有集群的数据导到新实例中，建立复制关系先同步一段时间，后面再把应用切过来。

但是在导完数据，建立复制关系之后过一会，SQL 线程居然报错了，update 语句找不到对应的行。这就奇怪了，导出的表都是 InnoDB 引擎，--single-transaction
和 --master-data
也都加上了，为什么还会出现问题？

尝试重新导一份数据建立复制关系，还是出现同样的问题，不过报错的行变了。查了一下这一行数据在主库上有，新库上没有。数据里有一列字段是创建时间，发现报错的行的创建时间正好是在备份过程中，说明有可能备份过程中操作的数据没有备份到文件里。

猜想

先看下备份出来的 sql 文件，发现了一个与平常不一样的地方，在文件的开头没有看到 SET @@GLOBAL.GTID_PURGED
的语句，排查后发现这个语句写到了文件的结尾。

--
-- GTID state at the end of the backup 
--

SET @@GLOBAL.GTID_PURGED='cb75d9d8-5328-11ec-87b4-02000aba3c08:1-13637422';
/*!40103 SET TIME_ZONE=@OLD_TIME_ZONE */;

/*!40101 SET SQL_MODE=@OLD_SQL_MODE */;
/*!40014 SET FOREIGN_KEY_CHECKS=@OLD_FOREIGN_KEY_CHECKS */;
/*!40014 SET UNIQUE_CHECKS=@OLD_UNIQUE_CHECKS */;
/*!40101 SET CHARACTER_SET_CLIENT=@OLD_CHARACTER_SET_CLIENT */;
/*!40101 SET CHARACTER_SET_RESULTS=@OLD_CHARACTER_SET_RESULTS */;
/*!40101 SET COLLATION_CONNECTION=@OLD_COLLATION_CONNECTION */;
/*!40111 SET SQL_NOTES=@OLD_SQL_NOTES */;

-- Dump completed on 2021-11-30 20:24:21

复制

线上的 MySQL 版本是 5.7.36，本地测试环境 5.7.33 没有这个现象，说明 mysqldump 在 5.7.33 后面的版本有过改动。

查找了 Release Notes 后在 5.7.36 的 Bugs Fixed 里面找到了对应的改动：

Replication: The contents of the gtid_executed and gtid_purged GTID sets were not persisted after restoring a dump taken using mysqldump. The dump file sequence has now been changed so that the mysql schema (which contains the mysql.gtid_executed table) is not dropped after the gtid_purged GTID set is written. A new option --skip-mysql-schema is added for mysqldump which lets you choose not to drop the mysql schema at all. (Bug #32843447)

上面有提到导出来的数据文件里面内容的顺序有改变，或许就是这个改动导致了问题的出现。

实验

在本地尝试复现一下现象，分别使用 5.7.33 和 5.7.36 的 mysqldump 来备份数据。

先创建一张表，往里面造多一点数据，保证有足够的备份时间可以操作：

mysql> create database test;
Query OK, 1 row affected (0.00 sec)

mysql> use test
Database changed

mysql> create table test(id int,name varchar(10),msg varchar(100))engine=innodb;
Query OK, 0 rows affected (0.09 sec)

mysql> insert into test values(1,'aaa','fasgsagaehgag'),(2,'bbb','fasgahfjfjfjfjfjfj'),(3,'ccc','fasg4hegegeege');
Query OK, 3 rows affected (0.03 sec)
Records: 3  Duplicates: 0  Warnings: 0

...

mysql> insert into test select * from test;
Query OK, 3145728 rows affected (17.38 sec)

复制

使用 5.7.33 版本的 mysqldump 进行备份：

当前的 gtid 值：

mysql> show master status;
+------------------+-----------+--------------+------------------+-----------------------------------------------+
| File             | Position  | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                             |
+------------------+-----------+--------------+------------------+-----------------------------------------------+
| mysql-bin.000002 | 123212851 |              |                  | d04c5260-48e3-11ec-865e-02000aba3c05:1-145899 |
+------------------+-----------+--------------+------------------+-----------------------------------------------+
1 row in set (0.00 sec)

然后执行备份：

mysqldump -u -p -h -P --single-transaction --master-data=2 --set-gtid-purged=on -ER --databases test > 1.sql

备份过程中用另外一个线程插入数据：

mysql> insert into test values(5,'qqq','gdhdhdjhdjdjdjdjd');
Query OK, 1 row affected (0.02 sec)

复制

最终结果为：

SET @@GLOBAL.GTID_PURGED
语句在文件的开头，值为 d04c5260-48e3-11ec-865e-02000aba3c05:1-145899
，数据里不包含备份过程中插入的行。

从结果来看，5.7.33 的数据和 GTID 都是正确的，没有问题。

把新插入的数据清理掉，然后还原 gtid，使用同样的方法用 5.7.36 版本的 mysqldump 进行备份，最终结果为：

SET @@GLOBAL.GTID_PURGED
语句在文件的结尾，值为 d04c5260-48e3-11ec-865e-02000aba3c05:1-145900
，数据里不包含备份过程中插入的行。

很明显，5.7.36 的数据与 GTID 不一致，可以认为数据丢失了。

排查

我们再从 general log 去寻找问题的根本原因，下面来看下两次备份时 general log 里的内容：

5.7.33:
2021-12-02T15:57:49.407761+08:00        91450 Query     /*!40100 SET @@SQL_MODE='' */
2021-12-02T15:57:49.408036+08:00        91450 Query     /*!40103 SET TIME_ZONE='+00:00' */
2021-12-02T15:57:49.408243+08:00        91450 Query     FLUSH /*!40101 LOCAL */ TABLES
2021-12-02T15:57:49.408874+08:00        91450 Query     FLUSH TABLES WITH READ LOCK
2021-12-02T15:57:49.409007+08:00        91450 Query     SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
2021-12-02T15:57:49.409112+08:00        91450 Query     START TRANSACTION /*!40100 WITH CONSISTENT SNAPSHOT */
2021-12-02T15:57:49.409433+08:00        91450 Query     SHOW VARIABLES LIKE 'gtid\_mode'
2021-12-02T15:57:49.413486+08:00        91450 Query     SELECT @@GLOBAL.GTID_EXECUTED
2021-12-02T15:57:49.413648+08:00        91450 Query     SHOW MASTER STATUS
2021-12-02T15:57:49.413758+08:00        91450 Query     UNLOCK TABLES
...
2021-12-02T15:58:06.659969+08:00        91450 Quit

5.7.36:
2021-12-02T16:24:08.865982+08:00        93058 Query     /*!40100 SET @@SQL_MODE='' */
2021-12-02T16:24:08.866188+08:00        93058 Query     /*!40103 SET TIME_ZONE='+00:00' */
2021-12-02T16:24:08.866355+08:00        93058 Query     FLUSH /*!40101 LOCAL */ TABLES
2021-12-02T16:24:08.867006+08:00        93058 Query     FLUSH TABLES WITH READ LOCK
2021-12-02T16:24:08.867110+08:00        93058 Query     SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
2021-12-02T16:24:08.867214+08:00        93058 Query     START TRANSACTION /*!40100 WITH CONSISTENT SNAPSHOT */
2021-12-02T16:24:08.867379+08:00        93058 Query     SHOW VARIABLES LIKE 'gtid\_mode'
2021-12-02T16:24:08.869615+08:00        93058 Query     SHOW MASTER STATUS
2021-12-02T16:24:08.869788+08:00        93058 Query     UNLOCK TABLES
...
2021-12-02T16:24:21.685552+08:00        93058 Query     SELECT @@GLOBAL.GTID_EXECUTED
2021-12-02T16:24:21.754689+08:00        93058 Quit

复制

可以看到，5.7.33 的 mysqldump 在加上全局锁后获取一致性快照和 @@GLOBAL.GTID_EXECUTED
后才释放锁，这样可以保证数据和 GTID 能保持一致。

但 5.7.36 是在备份完所有数据之后才去获取 @@GLOBAL.GTID_EXECUTED
，这样意味着备份期间新增的 GTID 也写到了备份文件里，但没有备份相关的数据，导致数据和 GTID 不一致。

总结

由于 5.7.36 版本的 mysqldump 备份时获取 GTID 的时机发生了变化，导致备份出来的数据和记录的 GTID 不一致，所以恢复出来的实例和主库建立复制关系后会发生找不到对应行的问题。在问题修复前建议使用低版本的 mysqldump 进行备份。

虽然 8.0.27 的 Release Notes 里也写到了 mysqldump 这个改动，但本地测试下来发现无论是获取 GTID 的时机还是在备份文件里的 SET @@GLOBAL.GTID_PURGED
顺序都与旧版本一样。通过对比源码，发现这个改动没有出现在 8.0.27 的 mysqldump 代码中，不知道为什么会有这样的情况。

已将此问题提交给官方：https://bugs.mysql.com/bug.php?id=105761

文章推荐：

故障分析 | 从库并行回放死锁问题分析

故障分析 | 正确使用 auth_socket 验证插件

故障分析 | 崩溃恢复巨慢原因分析