结合案例说说5.7使用gtid同步后,mysql.gtid_executed引起的从库gtid断层

结合案例说说5.7使用gtid同步后,mysql.gtid_executed引起的从库gtid断层,从库重复拉取主库数据,导致数据在从库被重复执行;

mysql.gtid_executed,5.7.5新增的这张表
在5.7.5之前的版本中,开启gtid模式的同步,slave端必须要开启log_slave_updates,这是因为,当slave重启后无法得知当前slave已经运行到的GTID位置，因为变量gtid_executed是一个内存值.所以.在5.7.5之前的版本中,开启binlog,slave重启,启动时扫描最后一个二进制日志,获取当前执行到的GTID位置信息.
5.7.5之后gtid_executed就固化成表了,存在mysql库里面.这个表存储的是,事物的gtid信息.mysql.gtid_executed表就三个字段,三个子段分别存储的是主库server_id(source_uuid),第一个gtid号(interval_start),最后一个gtid号(interval_end).
mysql.gtid_executed表的初始数据有两种来源:
1.当发生第一个binlog切换(下面详细解释)时,就将第一个binlog中的第一个gtid和最后一个gtid写入mysql.gtid_executed;
2.在set global gtid_perged='xxxxxxxxx:1-xxx'时,会将这个值中的server_uuid和gtid值写入mysql.gtid_executed表;
ps:发出reset master ; 会将mysql.gtid_executed表的数据初始化为空;

mysql.gtid_executed表在主从存储的信息是不一样的.

主库:在开启binlog(一般都开)和gtid时,mysql.gtid_executed表就一行数据(没有切换过主库的情况),server_id和第一个事务gtid基本没什么问题.重点说下第三个字段interval_end.在主库存储的这个值是上一个binlog的最后一个事务的gtid值,每次当binlog刷新切换后,这个值就变为当前binlog的上一个binlog的最后一个值.有点绕..打个比方:比如show master status;看到的binlog为mysql-bin.000028,gtid值为1-20001,mysql.gtid_executed记录的就是从mysql-bin.000001的1到mysql-bin.000027的最后一个gtid值.当我们binlog日志达到定义的大小,或者执行类似flush logs等操作,binlog就切换到下一个,这个例子就是生成一个新的mysql-bin.000029,这个时候mysql.gtid_executed记录的就是mysql-bin.000028的最后一个gtid值.
简而言之就是:mysql.gtid_executed在主库记录的是从第一个事务的gtid到当前binlog的上一个binlog(就是当前binlog的倒数第二个)里面记录的最后一个gtid值.只有当binlog发生切换(重启,flush logs,或者达到定义的大小时等才会发生切换),后,mysql.gtid_executed第三个字段才会变更为上一个binlog最后一个事务的gtid值.
言外之意就是这个值不是实时的,也是不准确的.

从库:从库要分成两种情况
     1.开启log_slave_updates时,mysql_executed表是不会记录数据的,只有当从库自己有执行事务(不是从主库传送过来的)时,才会生成数据,规则跟主库一样.不累述;
  2.未开启log_slave_updates时(默认),是每更新一个事务就记录一条信息到mysql.gtid_executed.当条数累计到gtid_executed_compression_period定义的值后,会进行汇总
  mysql> select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 59194c6e-70db-11e6-b85b-5254002eb131 |              1 |         7013 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7014 |         7014 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7015 |         7015 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7016 |         7016 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7017 |         7017 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7018 |         7018 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7019 |         7019 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7020 |         7020 |
.....
     这里要说明的是,这里的更新事务都是从主库拉取过来的,从库在读到relay-log时,就将这个事务与插入mysql.gtid_executed合并成一个事务,这样就通过事务的一致性来保证mysql.gtid_executed表与事务的一致性.当从库意外宕机或者重启时,只需要读取mysql.gtid_executed表就知道从库同步到哪一个事务,在从主库拉取未同步的事务就行.
  另外,mysql的组提交和并行复制,也在这个mysql.gtid_executed上体现了.众所周知,mysql的组提交和并行复制很可能不是顺序的,也就是说,gtid可能会存在跳跃.比如:一个大事物的gtid为2201,而2203,2204可能是小事务却不是同一个组提交的,所以,从库很可能在存在先写完2203,2204,然后才写完2201.这样一来写入mysql.gtid_executed就可能不连续了,也就是断层,比如:
  mysql> select * from mysql.gtid_executed ;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 59194c6e-70db-11e6-b85b-5254002eb131 |              1 |         3007 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           5009 |         7021 |
   
 为了保证与主库数据的一致性,这种断层mysql是允许的.比如上面的例子,如果在执行完2203,2204,而2201还没有执行完时,从库宕机了.这个时候就存在断层,从库从新启动后,会去重新拉取中间断层部分未执行的事务.所以,mysql的判断:断层就是合理的且必须的.
 
 -----------------------------我是华丽的分割线-------------------------------------------------------------------------------
 前面介绍的全部是背景资料,从这里开始,来分析和解读断层导致的重复拉取数据的问题.
 
案例描述:新建一个从库,主从同步正常,主从数据也一致.后来,因为种种原因,重启了从库mysql服务,然后就发现从库数据不同步了且报错了:
         ...
         Last_SQL_Error: Could not execute Write_rows event on table test.tt1; Duplicate entry '3100' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log testdb3-bin.000003, end_log_pos 483
         .
         .
         .
             Retrieved_Gtid_Set: 59194c6e-70db-11e6-b85b-5254002eb131:3008-5008
             Executed_Gtid_Set: 59194c6e-70db-11e6-b85b-5254002eb131:1-3007:5009-7021
      .
         ..
  
mysql> select * from mysql.gtid_executed ;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 59194c6e-70db-11e6-b85b-5254002eb131 |              1 |         3007 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           5009 |         7013 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7014 |         7014 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7015 |         7015 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7016 |         7016 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7017 |         7017 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7018 |         7018 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7019 |         7019 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7020 |         7020 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7021 |         7021 |

    案例分析:
 1.从slave状态报错看,以为是数据冲突了一小部分.因为当时设置的master_info和relay_log_info都是指定的file,可能是服务在关闭的时候与os文件系统的问题导致的.于是决定一个事务一个事务的连续跳了大概3,4个事务.就还是报错,就发现不对头了.
 2.观察到 Retrieved_Gtid_Set: 59194c6e-70db-11e6-b85b-5254002eb131:3008-5008  发现怎么是从3008开始的?且 Executed_Gtid_Set: 59194c6e-70db-11e6-b85b-5254002eb131:1-3007:5009-7021 中间出现断层.于是发现问题有点严重了.但为了确保问题的准确性,于是去捞binlog来核对
 3. Last_SQL_Error: Could not execute Write_rows event on table test.tt1; Duplicate entry '3100' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log testdb3-bin.000003, end_log_pos 483
 通过这个错误去捞取主库testdb3-bin.000003 的binlog来确认这个事务的gtid和数据.mysqlbinlog --no-defaults --base64-output=decode-rows -v -v --stop-postion
='483'  testdb3-bin.000003 >log001.log
     通过binlog解析出来的结果,确认确实是3008.
 
  由此就确认:从库发生了断层,且这部分断层是已经执行过了的.从库重启后,重新拉取了这部分重复的数据,从而导致从库重复执行事务,而报错.

 
  案例解决方法:
  因为不知道是从哪个点重新拉取的,很有可能数据重复执行是成功的.(比如在断层初始点,是一个update操作,就很可能重复执行),从而导致主从不一致(且不易发现).所以这个时候就只能重做一遍从库(从新导入数据,重新同步).

 问题提炼:
  案例很清楚,是由于断层导致数据重复拉取.在上面的背景介绍里面说过,mysql是允许断层出现的,且是为了保证数据的一致性.那这个断层为什么就会把已经执行的数据融入到断层勒?
  提炼的问题就是:
  1.这个不合理的断层是如何出现的?
  2.如何避免这种不合理的断层出现?
  3.如果已经存在,如何解决这种不合理断层?

    第一个问题:这个不合理的断层是如何出现的
 结合最开始的背景资料,一步一步来细说:
    首先,主库是开启了binlog和gtid的,所以在主库的mysql.gtid_executed表里面只是记录从第一个事务到当前binlog的上一个binlog的最后一个gtid.在备份主库数据(用于从库还原用的)时,会将mysql.gtid_executed表的数据进行备份(备份方式采用mysqldump --single-transtionaction xxxx),一般我们在备份的时候并不会加-F(flush logs),所以这个备份出来的mysql.gtid_executed数据与备份时间点的gtid是有差别的.
    可以打开备份文件查看前几行中有一行
SET @@GLOBAL.GTID_PURGED='59194c6e-70db-11e6-b85b-5254002eb131:1-5008'; 
       在看看mysql.gtid_executed
   
mysql> select * from mysql.gtid_executed;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 59194c6e-70db-11e6-b85b-5254002eb131 |              1 |         3007 |
+--------------------------------------+----------------+--------------+
          可以看到这个set与mysql.gtid_executed表的数据是不一致的.细看一下就会发现.中间的差距就是断层的部分gtid.
    那么,这样就很清晰了:
    当从库在导入数据的时候,按照脚本顺序,先执行SET @@GLOBAL.GTID_PURGED=语句,然后才在导入到mysql库的时候,会将主库的mysql.gtid_executed表的数据导入到从库
    在执行SET @@GLOBAL.GTID_PURGED=时,会初始化mysql.gtid_executed表以及global.gtid_executed内存参数.
    当在导入mysql.gtid_executed表数据时,就会覆盖之前初始化正确的mysql.gtid_executed表数据,导入主库的这个表的数据.
    这样一来,mysql.gtid_executed表和global.gtid_executed内存参数数据不一致了,但在启动slave后,mysql优先读取的是global.gtid_executed内存参数,所以同步启动后,一切都是正常且正确的,所以在show slave status\G看到的信息也是没有问题的.但在mysql.gtid_executed表里就会发现问题,如:
    mysql> select * from mysql.gtid_executed ;
+--------------------------------------+----------------+--------------+
| source_uuid                          | interval_start | interval_end |
+--------------------------------------+----------------+--------------+
| 59194c6e-70db-11e6-b85b-5254002eb131 |              1 |         3007 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           5009 |         7013 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7014 |         7014 |
| 59194c6e-70db-11e6-b85b-5254002eb131 |           7015 |         7015 |
         
    可以看到有两行合并数据,一个是1-3007,另一个是5009-7013.这就是断层现象了.如果重启从库mysql服务,因为global.gtid_executed内存参数重启后就没有了,会重新从mysql.gtid_executed表拉取,因为断层现象是合理的(详细前面背景资料有解释),所以mysql就认为这部分中断的gtid是没有执行的,所以就从新从主库拉取这部分binlog(如果主库还保留有这部分binlog日志).但事实上这部分事务是已经执行过了,所以就出现了重复执行的现象.
     由此可见,出现断层有几个必然的因数:
                         1.主库在备份数据时,mysql.gtid_executed表的gtid不是最新信息(既备份时,实际产生的gtid与mysql.gtid_executed是有一段差距的);
                         2.导入从库时,mysql.gtid_executed与内存参数global.gtid_executed数值是有差距的;
                         3.slave从库重启后才会出现断层,因为一开始内存参数是正确的,只有重启后,重新拉取mysql.gtid_executed才会出现断层;
ps:判断是否有隐在的断层现象,可以直接查看slave从库的mysql.gtid_executed表,看是否有断层现象;

     
     第二个问题:如何避免这种不合理的断层出现?
    1.在导入完成,启动slave之前,重新初始化mysql.gtid_executed表.具体方法:执行reset master; set @@global.gtid_purged='xxx';
          2.在主库使用mysqldump 导出还原数据时加上-F(flush logs),这样就会保证导出时的gtid信息与mysql.gtid_executed表信息一致;
            
       第三个问题:如果已经存在,如何解决这种不合理断层?
    1.最笨的办法重做从库;
    2.停止同步,更改mysql.gtid_executed表的数据,消除断层.
    update mysql.gtid_executed xxxx;
    delete mysql.gtid_executed xxx;
    然后重启,因为这个时候的内存参数已经加载完了,且gtid_excuted和gtid_purged是不能在线更改的(除非为空);

 

可能出现的错误代码:         Error_code: 1062  Error_code: 1396    Error_code:1032  Error: 1050  Error: 1051
先说说这三种错误,
1.  Error_code: 1062
 Error: 1062 SQLSTATE: 23000 (ER_DUP_ENTRY)
Message: Duplicate entry '%s' for key %d
The message returned with this error uses the format string for ER_DUP_ENTRY_WITH_KEY_NAME
这是最常见主键冲突,因为重复拉取了数据,所以就重复执行了insert,导致主键冲突;
2. Error_code:1032
 Error: 1032 SQLSTATE: HY000 (ER_KEY_NOT_FOUND)
Message: Can't find record in '%s'
找到不数据,这是因为重复拉取了delete造成的;

3. Error_code: 1396
 Error: 1396 SQLSTATE: HY000 (ER_CANNOT_USER)
Message: Operation %s failed for %s
这个错误就比较复杂一点,这种错误主要是因为binlog或者某些同步的记录在主库的binlog日志无法找到. 
4. Error: 1050 SQLSTATE: 42S01 (ER_TABLE_EXISTS_ERROR)
Message: Table '%s' already exists
重复拉取创建表(create table)的binlog,创建时如没加if exists就会报此错

5. Error: 1051 SQLSTATE: 42S02 (ER_BAD_TABLE_ERROR)
Message: Unknown table '%s'
重复拉取删除表(drop table)的 binlog.

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/20892230/viewspace-2140409/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/20892230/viewspace-2140409/