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 using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave 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 */;
   230  INSERT 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 Query     FLUSH /*!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: 13001  Unix socket: /root/mysql5.7.14/percona-server-5.7.14-7/mysql-test/var/tmp/mysqld.1.sock
Time                 Id Command    Argument
2017-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.net/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.01 sec)

mysql> purge binary logs to 'binlog.000003';
Query OK, 0 rows affected (0.04 sec)

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.gtid_executed表的作用和其更改时机，如果我们对其有深刻的了解这个案例也是很容易分析的，当然解决办法在第八节主从搭建的步骤中我已经给出了，也就是在搭建完成后进行reset master和set global gtid_pruged两步重新初始化一下mysql.gtid_executed表。

作者微信：

微信.jpg

时间： 2024-10-25 15:15:17

Mysql 5.7 Gtid内部学习(十) 实际案例(二)的相关文章

Mysql 5.7 Gtid内部学习(九) 实际案例(一)

本案例是一个朋友的案例他也写了出来如下:https://mp.weixin.qq.com/s/XSnFkuYzIlGWMaXIl-oPeQ 但是和他交流后他也准备改因为分析有一些小问题. 一.触发条件 binlog_gtid_simple_recovery=false. 5.7.6以上版本. Gtid 关闭或者Gtid中途开启有大量的未开启Gtid的binlog. 二.本案例回顾 版本:MySQL版本 5.7.19. 故障为:大概每半小时发生一次故障,整个Mysql压力巨大,很多简单的操作都相应

Mysql 5.7 Gtid内部学习(一) 导读

Mysql Gtid特性是5.6加入的一个强大的特性,它的目的在于使用Gtid的Mysql能够在整个复制环境中能够自动的切换,而不像以前需要指定文件和位置,这也一定是未来发展的方向,我们熟知的MGR也是基于Gtid的,所以了解Gtid的原理也是必要的. Gtid的维护是完全自动的,但是实际使用上确实有较多的坑,也导致很多朋友对Gtid还是觉得畏惧,本系列文章将从Gtid模块的源码出发分析,并且给出总结,然后结合运维和案例进行综合的解析,我希望抛砖引玉让希望了解源码的朋友也有所收获,但是能力有限特

Mysql 5.7 Gtid内部学习(二) Gtid相关内部数据结构

1. Gtid基本格式 单个Gtid: e859a28b-b66d-11e7-8371-000c291f347d:1 前一部分是server_uuid,后面一部分是执行事务的唯一标志,通常是自增的.内部使用Gtid这种数据结构表示,后面会描述. 区间Gtid: e859a28b-b66d-11e7-8371-000c291f347d:1-5 前一部分是server_uuid,后面一部分是执行事务的唯一标志集合,在内部使用Gtid_set中某个Sidno对应的Interval节点表示,后面会描述.

Mysql 5.7 Gtid内部学习(五) mysql.gtid_executed表/gtid_executed变量/gtid_purged变量的更改时机

本节将集中讨论下面三种Gtid更新的时机,这部分相当重要,后面的故障案列会和这节有关.下面先来看一下他们的定义 mysql.gtid_executed表:Gtid持久化的介质,Mysql启动阶段会读取这个表来获取gtid_executed变量的值. gtid_executed变量(show global variables):Mysql数据库已经执行了哪些Gtid事务,处于内存中.show slave status中的Executed_Gtid_Set也取自这里. gtid_purged变量(s

Mysql 5.7 Gtid内部学习(八) Gtid带来的运维改变

依托前文的解析来讲5.7中 Gtid带来的运维改变,我想理解应该是更加深刻,这节主要讨论以下几个部分: 如何跳过一个事务 mysqldump导出行为的改变 5.7中搭建基于Gtid的主从 5.7中Gtid的主从的切换 5.7中在线改变Gtid模式 一.如何跳过一个事务 和传统基于位置的主从不同,如果从库报错我们需要获得从库执行的最后一个事务,方法有如下: show slave status \G 中的 Executed_Gtid_Set. show global variables like '

Mysql 5.7 Gtid内部学习(四) mysql.gtid_executed表Previous gtid Event的改变

之所以把mysql.gtid_executed表的作用和Previous gtid Event的改变放到一起进行描述是因为它们后面文章探讨的基础.这部分使用到了我自己使用C语言写的原生binlog解析工具infobin. 百度云盘下载如下:http://pan.baidu.com/s/1jHIWUN0 一.Gtid event 为什么要先描述什么是Gtid event呢?因为后面会用到,实际上在中其核心元素就是一个形如: 31704d8a-da74-11e7-b6bf-52540a7d243:1

Mysql 5.7 Gtid内部学习(三) Gtid和Last_commt/sequnce_number的生成时机

一.Gtid生成类型 这里首先使用源码的解释给出三种类型: AUTOMATIC_GROUP GTID_GROUP ANONYMOUS_GROUP 其中AUTOMATIC_GROUP通常用于主库开启Gtid的情况,GTID_GROUP通常用于备库和使用了GTID_NEXT的情况下. 源码中有详细解释如下: /** Specifies that the GTID has not been generated yet; it will be generated on commit. It will d

[MySQL 5.6] GTID内部实现、运维变化及存在的bug

由于之前没太多深入关注gtid,这里给自己补补课,本文是我看文档和代码的整理记录. 本文的主要目的是记下跟gtid相关的backtrace,用于以后的问题排查.另外也会讨论目前在MySQL5.6.11版本中存在的bug. 本文讨论的内容包括 一.主库上的gtid产生及记录 二.备库如何使用GTID复制 三.主备运维的变化 四.MySQL5.6.11存在的bug 前言:什么是GTID 什么是GTID呢, 简而言之,就是全局事务ID(global transaction identifier ),最

MySQL EXPLAIN命令详解学习（执行计划）

MySQL EXPLAIN命令详解学习(执行计划) MySQL EXPLAIN 命令详解 MySQL的EXPLAIN命令用于SQL语句的查询执行计划(QEP).这条命令的输出结果能够让我们了解MySQL 优化器是如何执行 SQL 语句的.这条命令并没有提供任何调整建议,但它能够提供重要的信息帮助你做出调优决策. 1 语法 MySQL 的EXPLAIN 语法可以运行在SELECT 语句或者特定表上.如果作用在表上,那么此命令等同于DESC 表命令.UPDATE 和DELETE 命令也需要进行性能改