MySQL复制错误1837的相关缺陷一例

故障现象

主从gtid报错，复制错误1837,这个复制故障可以说是第一次遇到。

Last_Errno: 1837  
Last_Error: Error 'When @@SESSION.GTID_NEXT is set to a GTID, you must explicitly set it to a different value after a COMMIT or ROLLBACK. Please check GTID_NEXT variable manual page for detailed explanation. Current @@SESSION.GTID_NEXT is '2a46b388-5469-11e6-b949-845b123e2eff:64734471'.' on query. Default database: 'fander'. Query: 'delete from t_fander'

故障可能原因

从故障的报错，网上搜到的答案引导了我去看官方文档的“gtid的限制”的这一章节。
参考:https://dev.mysql.com/doc/refman/5.6/en/replication-gtids-restrictions.html

  1. 涉及非事务性存储引擎的更新。例如，myisam引擎表，主库执行insert delayed into xx values...
  2. enforce_gtid_consistency为OFF，CREATE TABLE ... SELECT语句。
  3. 主从引擎不一致，主库innodb引擎一个事务中写入两条数据，传到从库的myisam引擎执行这个事务
  4. 临时表
  5. 较早之前的一些bug

故障可能原因的分析

1.检查过所有表都是innodb表，没有myisam表，故排除。

mysql> select table_schema,table_name,engine from information_schema.tables where engine !='innodb' and table_schema not in ('mysql','information_schema','performance_schema');
Empty set (0.00 sec)

2.事实上检查过enforce_gtid_consistency主从库都为on，CREATE TABLE ... SELECT语句不能执行成功，并且这次故障并不涉及CREATE TABLE ... SELECT语句，故排除。

mysql> create table t7 select * from t6;
ERROR 1786 (HY000): CREATE TABLE ... SELECT is forbidden when @@GLOBAL.ENFORCE_GTID_CONSISTENCY = 1.

3.由于这个case是第一次发生了，上周才重做过从库，所以不存在主从不一致引擎的可能，并且第1步分析也知道库里并没有myisam表，故排除。

4.没有涉及临时表
5.查阅了这些bug在5.6.9和5.6.7上分别修复了。我们目前MySQL版本为5.6.23

然而并没有找到合适的答案，接着申请权限，来解析一下binlog探个究竟吧。

故障定位

从1837报错的英文信息描述上，我们得出以下信息:

  1. 发生故障的gtid号是2a46b388-5469-11e6-b949-845b123e2eff:64734471
  2. 发生故障的sql为delete from t_fander，或前后。
  3. 提示信息:设置为GTID时，您必须在提交或回滚之后显式地将其设置为不同的值

出于隐私考虑，我没有办法展示原始的binlog。
在解析了主从两个数据库的binlog后，发现从库大概是在执行以下sql时出了问题:
主库:

begin;
use fander;update t1,t2,t3,(select * from (select * from t4)d)d set t1.a='123';
use fander;delete from t5;
use fander;delete from t6;
commit;

#原update的sql比这个复杂得多，有where条件的，请不要纠结我这个sql为什么没事关联那么多张表。。。

主库上着3条DML操作是同一个事务，但在从库回放时，发生了事务的拆分。变成如下的样子。
从库:

begin;
use fander;update t1,t2,t3,(select * from (select * from t4)d)d set t1.a='123';
commit; #从库解析时，无端端给加了一个commit。
use fander;delete from t5; #这条在从库binlog里并没有。也就是上面commit后，正常需要设置不同的@@SESSION.GTID_NEXT，但他没有设置，所以报复制错误了。事务发生了异常拆分了！！

故障重现

主库上操作:

vi /tmp/c.sql
begin;
#经过多次测试，update语句可以修改为这个更简单的语句
use fander;update t1,t2,t3,t4 set t1.a='123';
use fander;delete from t5;
use fander;delete from t6;
commit;

mysql> create database fander;
mysql> set global  tx_isolation='Repeatable-Read';
mysql> set global  binlog_format='Mixed';
mysql> create table t1(a int);
mysql> create table t2(a int);
mysql> create table t3(a int);
mysql> create table t4(a int);
mysql> create table t5(a int);
mysql> create table t6(a int);
mysql> flush logs;
mysql> exit

mysql> source /tmp/c.sql

binlog 如下:

SET @@SESSION.GTID_NEXT= '316d072f-9633-11e8-b0f3-000c294a5f55:16719'/*!*/;
# at 1588
#180815 21:51:29 server id 897905305  end_log_pos 1672 CRC32 0xbf36600e         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
BEGIN
/*!*/;
# at 1672
#180815 21:51:29 server id 897905305  end_log_pos 1784 CRC32 0xdc2d6070         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
update t1,t2,t3,t4 set t1.a='123'
/*!*/;
# at 1784
#180815 21:51:29 server id 897905305  end_log_pos 1869 CRC32 0x931ab661         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
COMMIT   <<<-----被额外添加的commit----------
/*!*/;
# at 1869
#180815 21:51:29 server id 897905305  end_log_pos 1917 CRC32 0x116a4cfb         GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '316d072f-9633-11e8-b0f3-000c294a5f55:16720'/*!*/;
# at 1917
#180815 21:51:29 server id 897905305  end_log_pos 1992 CRC32 0x6fe6ccaa         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
BEGIN
/*!*/;
# at 1992
#180815 21:51:29 server id 897905305  end_log_pos 2076 CRC32 0x0695b437         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
delete from t5
/*!*/;
# at 2076
#180815 21:51:29 server id 897905305  end_log_pos 2160 CRC32 0x56083744         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
delete from t6
/*!*/;
# at 2160
#180815 21:51:29 server id 897905305  end_log_pos 2191 CRC32 0xfe7fe294         Xid = 31066
COMMIT/*!*/;

测试结果:

数据库版本: MySQL5.6.23
参数:
tx_isolation='Repeatable-Read';
binlog_format='Mixed';
autocommit=1；
结果:
多表关联update操作后，事务就被拆分了。

事务被拆分，这现象不正常啊？下面测试是否BUG。在参数配置不变的情况下，升级实例为mysql5.7.21,我们再来一次测试。

测试步骤一样。binlog如下：

BEGIN
/*!*/;
# at 303
#180816 15:01:12 server id 352148329  end_log_pos 415 CRC32 0xe61e4415  Query thread_id=1477446 exec_time=0 e
rror_code=0
use `fander`/*!*/;
SET TIMESTAMP=1534402872/*!*/;
update t1,t2,t3,t4 set t1.a='123'
/*!*/;
# at 415
#180816 15:01:12 server id 352148329  end_log_pos 499 CRC32 0xd51c509c  Query thread_id=1477446 exec_time=0 e
rror_code=0
SET TIMESTAMP=1534402872/*!*/;
delete from t5
/*!*/;
# at 499
#180816 15:01:12 server id 352148329  end_log_pos 583 CRC32 0x17e3871d  Query thread_id=1477446 exec_time=0 e
rror_code=0
SET TIMESTAMP=1534402872/*!*/;
delete from t6
/*!*/;
# at 583
#180816 15:01:12 server id 352148329  end_log_pos 614 CRC32 0x59f429aa  Xid = 44831936
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

测试结果:

数据库版本: MySQL5.7.21
参数:
tx_isolation='Repeatable-Read';
binlog_format='Mixed';
autocommit=1；
结果:
可以看出update和delete之间并没有自动添加commit，没有自动拆分事务。

BUG确认

在查阅mysql bug库后，发现这个是一个已知bug，并已经在5.6.27上修复了。

Replication: If statement based logging was in use, when updating multiple tables in a single statement, a single transaction could be logged as two different transactions. This was due to the binary logging process not properly identifying statements which were operating over transactional tables. The fix ensures that they are correctly identified, even if such statements do not change the contents of the tables. (Bug #16621582, Bug #21349028)

复制：如果使用基于语句的日志记录，当在单个语句中更新多个表时，会将单个事务记录为两个不同的事务。这是由于二进制日志记录过程无法正确识别在事务表上操作的语句。现在修复了，现在确保它们会被正确识别，即使语句不会修改表的内容。（bug 16621582，bug 21349028）

解决方法

解决方法就是避免不正确的拆事务的发生。

方案一:

开发修改sql。这个方案可以说是第一个排除的。因为只能解决这次问题，并不能根治。

方案二：

升级MySQL5.6.23到MySQL5.6.X(最新版本)或MySQL5.7.21。升级5.7.21是可行的，目前我们有提供MySQL5.7.21的安装服务，但这需要测试sql兼容问题。

方案三:

修改binlog格式。从bug的描述可知，此问题只出现在基于语句的日志记录，所以binlog_format修改为row格式可以解决这个问题。

方案四:

修改事务隔离级别。因为RC事务隔离级别下是不支持statement格式的。所以
修改tx_isolation='Read-committed',在binlog_format='Mixed'格式下,所有DML操作都会转为row格式。这个方案解决的原理只是把binlog转化为row格式，而改事务隔离级别是有风险的，尤其是涉及金钱交易，这个需要先与开发一同测试后方能修改。

经过选择和测试，方案三解决了这次的问题。

posted on 2018-08-16 18:07  fanderchan  阅读(2376)  评论(0)  编辑  收藏  举报

导航