Mysql 5.7 Gtid内部实际案例分析

本篇内容介绍了“Mysql 5.7 Gtid内部实际案例分析”的有关知识，在实际案例的操作过程中，不少人都会遇到这样的困境，接下来就让小编带领大家学习一下如何处理这些情况吧！希望大家仔细阅读，能够学有所成！

一、触发条件

本案列我测试过4个版本

percona Mysql 5.7.14

官方社区 Mysql 5.7.17

percona Mysql 5.7.19

percona Mysql 5.7.15

其中percona Mysql 5.7.14和官方社区 Mysql 5.7.17有这个问题。其他版本未知

已知percona Mysql 5.7.14或者官方社区 Mysql 5.7.17。

mysqldump备份没有使用 -F, --flush-logs选项

Gtid打开。

二、故障描述

本故障主要是新搭建的Gtid主从库，运行一段时间后重启主从必然报错如下：

Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: The slave is connecting usingCHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logscontaining GTIDs that theslave requires. 三、故障分析

为什么重启后会报错找到不事物呢，然后发现这个Gtid事物在主库的binlog中已经没有了，应该是很久以前的。其实这个问题我们要回到mysqldump出来的文件如何进行Gtid的初始化以及mysql.gtid_executed表中。

在mysqldump不使用--set-gtid-purged的时候必然会在dump出来的脚本中包含 -- GTID state at the beginning of the backup  SET @@GLOBAL.GTID_PURGED=e859a28b-b66d-11e7-8371-000c291f347d:1-41;

这样一个设置GTID_PURGED的语句，它包含了主库上已经执行的全部Gtid事物。从第五节的源码和总结部分我们知道这个语句至少做了三个更改(DBA可见的只有三个)：

mysql.gtid_executed表的写入

gtid_executed变量的修改

gtid_purged变量的修改

而完成了这一步实际上mysql.gtid_executed表是包含了全部的执行过的Gtid事物的，但是随后我们看到dump脚本包含了如下语句

 210  -- Table structure for table `gtid_executed`    211  --    212    213  DROP TABLE IF EXISTS `gtid_executed`;    214  /*!40101 SET @saved_cs_client     = @@character_set_client */;    215/*!40101 SET character_set_client = utf8 */;    216  CREATE TABLE `gtid_executed` (    217    `source_uuid` char(36) NOT NULL COMMENT uuid of the source where the transaction was originally executed.,    218    `interval_start` bigint(20) NOT NULL COMMENT First number of interval.,    219    `interval_end` bigint(20) NOT NULL COMMENT Last number of interval.,    220    PRIMARY KEY (`source_uuid`,`interval_start`)    221  ) ENGINE=InnoDB DEFAULT CHARSET=utf8;    222  /*!40101 SET character_set_client = @saved_cs_client */;    223    224--    225  -- Dumping data for table `gtid_executed`    226  --    227    228  LOCK TABLES `gtid_executed` WRITE;    229  /*!40000 ALTER TABLE `gtid_executed` DISABLE KEYS */;    230INSERT INTO `gtid_executed` VALUES (e859a28b-b66d-11e7-8371-000c291f347d,1,32);    231  /*!40000 ALTER TABLE `gtid_executed` ENABLE KEYS */;    232  UNLOCK TABLES;

显然这里我们在source的时候从库的mysql.gtid_executed将被重新初始化为：

e859a28b-b66d-11e7-8371-000c291f347d,1,32

而实际的已经执行过的Gtid是：

e859a28b-b66d-11e7-8371-000c291f347d:1-41;

如前文第五节我们通过源码分析后总结如下：

mysql.gtid_executed表修改时机 在binlog发生切换(rotate)的时候保存直到上一个binlog文件执行过的全部Gtid，它不是实时更新的。

因此此时表中并没有完全包含全部执行过的Gtid事物，而在前文第六节的源码分析中我们知道在Gtid模块启动的时候必须要读取两个Gtid持久化的介质：

mysql.gtid_executed

binlog

来判断Gtid的集合，显然从库不可能在binlog包含这个Gtid事物，所以这样的操作步骤就导致了数据库从库后的报错，而这里的正确的步骤是压根不进行mysql.gtid_executed的重建和导入，我发现在percona Mysql 5.7.15和percona Mysql 5.7.19正是这样的。但是为了防范这个问题，我在搭建的Gtid从库导完数据后加入了两个个步骤如下：

reset master； set global gtid_purged=e859a28b-b66d-11e7-8371-000c291f347d:1-41;

这两步也就是为了从新初始化mysql.gtid_executed表，让其正确。

此问题还可以在mysqldump的时候加入-F, --flush-logs选项规避，但是-F会加入如下的MDL LOCK： 2017-12-18T08:16:39.580985Z         6 QueryFLUSH /*!40101 LOCAL */ TABLES 2017-12-18T08:16:39.612598Z         6 Query     FLUSH TABLES WITH READ LOCK 2017-12-18T08:16:39.613406Z         6 Refresh /root/mysql5.7.14/percona-server-5.7.14-7/sql/mysqld,Version: 5.7.14-7-debug-log (Source distribution). started with: Tcp port: 13001Unix socket: /root/mysql5.7.14/percona-server-5.7.14-7/mysql-test/var/tmp/mysqld.1.sock Time                 IdCommand    Argument2017-12-18T08:16:39.965847Z         6 Query     SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ 2017-12-18T08:16:39.966298Z         6 Query     START TRANSACTION /*!40100 WITH CONSISTENT SNAPSHOT */ 2017-12-18T08:16:39.966792Z         6 Query     SHOW VARIABLES LIKE gtid\_mode 2017-12-18T08:16:39.969587Z         6 Query     SELECT @@GLOBAL.GTID_EXECUTED 2017-12-18T08:16:39.970216Z         6 Query     SHOW STATUS LIKE binlog_snapshot_% 2017-12-18T08:16:39.975242Z         6 Query     UNLOCK TABLES

这把锁是GLOBAL级别的MDL_SHARED(S)锁，它会等到你说有的SELECT/DML/DDL语句结束后才能获得，同时会堵塞全部的SELECT/DML/DDL虽然持有时间很短如下：

mysql> flush tables with read lock; Query OK, 0 rows affected (0.01 sec) 2017-08-03T18:19:11.603911Z 3 [Note](acquire_lock)THIS MDL LOCK acquire ok! 2017-08-03T18:19:11.603947Z 3 [Note] (>MDL PRINT) Thread id is 3:  2017-08-03T18:19:11.603971Z 3 [Note] (--->MDL PRINT) Namespace is:GLOBAL  2017-08-03T18:19:11.603994Z 3 [Note] (----->MDL PRINT) Mdl type is:MDL_SHARED(S)  2017-08-03T18:19:11.604045Z 3 [Note] (------>MDL PRINT) Mdl  duration is:MDL_EXPLICIT  2017-08-03T18:19:11.604073Z 3 [Note] (------->MDL PRINT) Mdl  status is:EMPTY  2017-08-03T18:19:11.604133Z 3 [Note] (acquire_lock)THIS MDL LOCK acquire ok!

当然要了解MDL LOCK的朋友可以参考我的文章

http://blog.itpub-/7728585/viewspace-2143093/

MYSQL METADATA LOCK(MDL LOCK)学习(1) 理论知识和加锁类型测试 四、故障模拟

知道了原因后也是很好模拟我使用的版本是社区版5.7.17，搭建过程就是前面说的步骤。只是导完数据后不使用reset master和set gtid_purged表进行重新初始化mysql.gtid_executed表。搭建完成后做几个事物状态正常如下：

mysql> show slave status \G *************************** 1. row ***************************               Master_Log_File: binlog.000002           Read_Master_Log_Pos: 5077                Relay_Log_File: test1-relay-bin.000002                 Relay_Log_Pos: 2498         Relay_Master_Log_File: binlog.000002              Slave_IO_Running: Yes             Slave_SQL_Running: Yes           Exec_Master_Log_Pos: 5077               Relay_Log_Space: 2705                 Last_IO_Errno: 0                 Last_IO_Error:          Seconds_Behind_Master: 0            Retrieved_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:42-49             Executed_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:1-49                 Auto_Position: 1

但是这个时候我们发现mysql.gtid_executed表已经出现了问题如下：

mysql> select * from gtid_executed; +--------------------------------------+----------------+--------------+| source_uuid                          | interval_start | interval_end | +--------------------------------------+----------------+--------------+ | e859a28b-b66d-11e7-8371-000c291f347d |              1 |           32 | | e859a28b-b66d-11e7-8371-000c291f347d |             42 |           42 | | e859a28b-b66d-11e7-8371-000c291f347d |             43 |           43 | | e859a28b-b66d-11e7-8371-000c291f347d |             44 |           44 | | e859a28b-b66d-11e7-8371-000c291f347d |             45 |           45 | | e859a28b-b66d-11e7-8371-000c291f347d |             46 |           46 | | e859a28b-b66d-11e7-8371-000c291f347d |             47 |           47 | | e859a28b-b66d-11e7-8371-000c291f347d |             48 |           48 | | e859a28b-b66d-11e7-8371-000c291f347d |             49 |           49 | +--------------------------------------+----------------+--------------+

很容易发现33-41之间是没有持久化的。如果这个时候如果我们使用purge binary logs to 来清理掉主库的日志那么必将出现问题，如果不清理也会出现Gtid事物重新执行的情况。我们做清理模拟线上错误。主库执行：

mysql> show binary logs; +---------------+-----------+| Log_name      | File_size | +---------------+-----------+ | binlog.000001 |      9974 | | binlog.000002 |      5121 | |binlog.000003 |       194 | +---------------+-----------+ 3 rows in set (0.01sec) mysql> purge binary logs tobinlog.000003; Query OK, 0 rows affected (0.04sec) mysql> show binary logs; +---------------+-----------+| Log_name      | File_size | +---------------+-----------+ | binlog.000003 |       194 | +---------------+-----------+ 1 row in set (0.00 sec)

备库重启后错误重现：

mysql> show slave status \G *************************** 1. row ***************************                Slave_IO_State:                    Master_Host: 192.168.190.62                   Master_User: repl                   Master_Port: 3308                 Connect_Retry: 60               Master_Log_File: binlog.000003           Read_Master_Log_Pos: 194                Relay_Log_File: test1-relay-bin.000005                 Relay_Log_Pos: 4         Relay_Master_Log_File: binlog.000003              Slave_IO_Running: No             Slave_SQL_Running: Yes           Exec_Master_Log_Pos: 194               Relay_Log_Space: 194                 Last_IO_Errno: 1236                 Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.       Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates            Retrieved_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:42-49             Executed_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:1-32:42-49                 Auto_Position: 1

我们发现I/O thread 试图获取主库的33-41的Gtid事物的事物，已经不能获取，实际上即使能获取也会造成事物的重新执行，我们看到Executed_Gtid_Set已经出现了两个连续的区间：

Executed_Gtid_Set: e859a28b-b66d-11e7-8371-000c291f347d:1-32:42-49

“Mysql 5.7 Gtid内部实际案例分析”的内容就介绍到这里了，感谢大家的阅读。如果想了解更多行业相关的知识可以关注网站，小编将为大家输出更多高质量的实用文章！