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

前言

本文创作于 2018 年，并首次发布于博客园。之所以迁移到公众号，主要是出于对博客园可能关闭导致文章丢失的担忧。未来几周可能会有许多类似的低质量文章出现，它们的知识含量不高或者知识太陈旧，请大家注意甄别，有一些是不推荐阅读的。

好消息是，有些文章，我会对文章有小修改，并且备注现在的一些新想法。

故障现象

主从 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]

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)

1. 事实上检查过 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.

1. 由于这个 case 不是第一次发生了，上周才重做过从库，所以不存在主从不一致引擎的可能，并且第 1 步分析也知道库里并没有 myisam 表，故排除。
2. 没有涉及临时表
3. 查阅了这些 bug 在 5.6.9 和 5.6.7 上分别修复了。我们目前 MySQL 版本为 5.6.23

所以，我并没有找到合适的答案，接着向上一级申请 binlog 的解析权限吧，我来解析一下 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，但他没有设置，所以报复制错误了。事务发生了异常拆分了！！

故障重现

主库上操作:

编辑 sql 文件

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

载入 sql 文件

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(编者按：当时最新 5.7 小版本)，我们再来一次测试。

测试步骤一样。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 兼容问题，可行性不大。

编者按: 方案二中的升级 MySQL5.6.X(最新版本) 实际上才是最佳方法，这个和公司规定有关，有些公司喜欢统一小版本。

方案三:

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

方案四:

修改事务隔离级别。因为 RC 事务隔离级别下是不支持 statement 格式的。所以

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

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

参考资料