MySQL XA 事务并发执行问题（slave lock time out）

一、问题现象

近期在客户的实例上出现如下错误：

2021-04-22T19:00:43.161326+08:00 691 [Warning] Slave SQL for channel '': Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'lapiswars07'. Query: 'INSERT INTO `party_slots` (`id`,`created_at`,`updated_at`,`time_deleted`,`uid`,`type`,`type_slot`,`slot`) VALUES (NULL,'2021-04-22 18:50:46','2021-04-22 18:50:46',0,'18080566',7,1,0),(NULL,'2021-04-22 18:50:46','2021-04-22 18:50:46',0,'18080566',7,1,1),(NULL,'2021-04-22 18:50:46','2021-04-22 18:50:46',0,'18080566',7,1,2),(NULL,'2021-04-22 18:50:46','2021-04-22 18:50:46',0,'18080566',7,1,3),(NULL,'2021-04-22 18:50:46','2021-04-22 18:50:46',0,'18080566',7,1,4)', Error_code: 1205
2021-04-22T19:00:43.161374+08:00 691 [ERROR] Slave SQL for channel '': Slave SQL thread retried transaction 10 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable. Error_code: 1205
2021-04-22T19:00:43.161379+08:00 691 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205
2021-04-22T19:00:43.161382+08:00 691 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'binlog.000001' position 3970105

上述报错的意思是从库sql线程锁等待超时了，然后重试10次就是失败了，最后报上述错误。线上的从库并没有开启多线程复制，为什么会锁超时呢？于是分析了binlog，binlog中有两个交叉的XA事务，执行顺序如下：

xa start '111'
sql 1
sql 2
sql 3
sql n
......
Xa end '111'
Xa prepare '111'


xa start '222'
sql 1
sql 2
sql 3
sql n
......
xa end '222'
xa prepare '222'


xa commit '111'
xa commit '222'

这里猜想是不是两个xa事务冲突了，第一个xa事务拿了锁，执行到了prepare阶段还没有提交所以锁没有释放，然后马上执行了第二个xa事务，这个时候第二个事务就会一直等待这个锁，这就造成了一个“死锁”，这里的死锁跟我们平常说的死锁还不太一样。

那这里还有一个问题就是为什么主库执行了没有问题，从库sql线程应用的时候就有问题了？因为XA事务交叉在一起了，有可能在主库的执行顺序和在从库的执行顺序不一样。

为什么XA事务为什么在主库上和从库上执行顺序不一样，我们可以简单的模拟出来，如下所示：

transaction 1:
xa start '111'
sql 1
xa end '111'

transaction 2:
xa start '222'
sql 2
xa end '222'
xa prepare '222'

transaction 1:
xa prepare '111'
xa commit '111'

transaction 2:
xa commit '222'

通过上述执行流程，我们可以看到在主库上sql1是执行在sql2前面的，但是sql2优先prepare，那么它就优先写入到binlog中，然后sql1再prepare写入到binlog中，所以在从库上回放的时候sql2是执行在sql1之前的。

结合上述这里有个简单的猜想，有没有一种加锁情况如下所示：

先执行A事务再执行B事务，没有锁互斥情况。
反过来先执行B事务再执行A事务，有锁互斥的情况。

那这里也是测试了很久，发现间隙锁可能会出现这种情况，详细见下一节复现步骤。

二、复现步骤

上一节我们猜测间隙锁可能会产生两个事务顺序和倒序执行的时候加锁情况可能不太一样，下面我们来复现下。

先准备数据：

创建表：

CREATE TABLE `test1` (
  `id` int(11) DEFAULT NULL,
  `name` varchar(36) DEFAULT NULL,
  KEY `idx_id` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

准备数据：

mysql> insert into test1() values(1, "zbdba"),(3, "zbdba"),(5, "zbdba"),(6, "zbdba"),(10, "zbdba"),(10, "zbdba"),(15, "zbdba"),(18, "zbdba");
Query OK, 8 rows affected (0.03 sec)
Records: 8  Duplicates: 0  Warnings: 0

我们可以看到表结构没有主键，只是在id上创建了一个非唯一索引，这是为了更好的制造出间隙锁的场景。

下面我们来做一个测试：

transaction 1:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test1() values(8, "zbdba");
Query OK, 1 row affected (0.00 sec)

transaction 2:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> delete from test1 where id = 10;
Query OK, 2 rows affected (0.30 sec)

transaction 1:
mysql> commit;
Query OK, 0 rows affected (0.00 sec)

transaction 2:
mysql> commit;
Query OK, 0 rows affected (0.00 sec)

我们可以看到上述没有锁互斥的情况造成锁等待，下面我们把两个事务执行顺序交换下：

执行前先把数据还原：

mysql> delete from test1;                                                                                                                                                                                                                   Query OK, 7 rows affected (0.01 sec)


mysql> insert into test1() values(1, "zbdba"),(3, "zbdba"),(5, "zbdba"),(6, "zbdba"),(10, "zbdba"),(10, "zbdba"),(15, "zbdba"),(18, "zbdba");
Query OK, 8 rows affected (0.01 sec)
Records: 8  Duplicates: 0  Warnings: 0

然后开始交换顺序执行：

transaction 1:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> delete from test1 where id = 10;
Query OK, 2 rows affected (0.00 sec)

transaction 2:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test1() values(8, "zbdba");
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

我们可以看到上述事务2等待锁超时退出了。

为什么间隙锁会产生上述的情况呢，我们先简单看看加锁的情况：

insert into test1() values(8, "zbdba”); 会加什么锁？

主要分为两个阶段，第一个阶段是插入意向锁这里没有冲突可以忽略，第二个阶段是加隐式的记录锁，隐式的锁其实就是判断当前没有锁冲突的情况下就不加锁，如果其他会话发现跟当前会话的数据冲突了，由其他会话为当前会话加锁。

delete from test1 where id = 10; 会加什么锁？

我们先看数据分布情况：

1 3 5 6 10 10 15 18

上述语句会在[6,10],[10,10],[10,15] 加上间隙锁

所以如果我们先执行插入语句，再执行delete语句，是没有锁冲突的。如果先执行delete语句[6,10]这个范围会被锁定，在执行insert语句的时候就发现有锁冲突就会会进行锁等待。

上述我们已经能复现出普通事务按照顺序和倒序会产生不同的加锁情况，那么我们结合XA事务执行顺序如下：

transaction 1:
mysql> xa start '111';
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test1() values(8, "zbdba");
Query OK, 1 row affected (0.01 sec)
mysql> xa end '111';
Query OK, 0 rows affected (0.01 sec)

transaction 2:
mysql> xa start '222';
Query OK, 0 rows affected (0.00 sec)
mysql> delete from test1 where id = 10;
Query OK, 2 rows affected (0.00 sec)
mysql> xa end '222';
Query OK, 0 rows affected (0.00 sec)
mysql> xa prepare '222';
Query OK, 0 rows affected (0.00 sec)

transaction 1:
mysql> xa prepare '111';
Query OK, 0 rows affected (0.00 sec)
mysql> xa commit '111';
Query OK, 0 rows affected (0.00 sec)

transaction 2:
mysql> xa commit '222';
Query OK, 0 rows affected (0.00 sec)

然后去从库上观察就会发现如下错误：

2021-04-25T13:22:49.565605Z 5 [Warning] Slave SQL for channel '': Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'zbdba15'. Query: 'insert into test1() values(8, "zbdba")', Error_code: 1205
2021-04-25T13:23:45.614629Z 5 [Warning] Slave SQL for channel '': Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'zbdba15'. Query: 'insert into test1() values(8, "zbdba")', Error_code: 1205
2021-04-25T13:24:41.671610Z 5 [Warning] Slave SQL for channel '': Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'zbdba15'. Query: 'insert into test1() values(8, "zbdba")', Error_code: 1205
2021-04-25T13:24:41.671661Z 5 [ERROR] Slave SQL for channel '': Slave SQL thread retried transaction 10 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable. Error_code: 1205
2021-04-25T13:24:41.671667Z 5 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205

到此问题已经复现，那么客户是否就是这个问题呢，目前客户这两个XA事务包含了几十条SQL语句，比较难分析到底是哪个sql产生的锁互斥等待情况。不过按照目前的现象来看确定是这个问题。

三、问题原因

上述我们其实已经大概知道此次问题造成的主要原因，是因为两个XA事务并行执行会导致在主库上和从库上回放顺序一致，如果再恰好遇见上述举例的间隙锁的情况，那么就会触发这个bug。那其根本原因还是因为在MySQL 5.7的时候为了解决XA prepare的问题，在XA事务第一阶段xa prepare 执行完成后就将xa prepare持久化到binlog中，导致xa 事务两个阶段在binlog中进行分离，在这个空隙中其他事务可以插入进来。

当然我们不能排除有其他情况的可能，可能不只是间隙锁这种情况，只要是两个事务顺序和倒序执行会产生不通的加锁情况都有可能触发此问题，后续如果有其他场景触发再做分析。

四、解决方案

目前解决这个问题有两个思路：
第一个是修改xa prepare持久化的逻辑，xa prepare持久化引入了很多bug我之前也提到过。但是这个改动会比较大，然后官方最新的版本也没有改动。
第二个问题是规避这种情况的发生，我们总结下这种情况发生的条件需要满足如下情况：

1、并行执行XA事务
2、XA事务中操作的数据可能造成间隙锁

那我们要规避其实就很简单，干掉间隙锁就OK了，将事务级别修改为RC隔离级别即可。

那其实还有一种稍微优雅一点的方法，就是将binlog格式修改为row格式，这个也是MySQL建议的。为什么修改为row格式就可以了，其实在从库sql线程应用的时候会判断binlog的格式，如果是row格式的数据，会讲事务隔离级别设置为RC，相关逻辑如下：

  if (DBUG_EVALUATE("force_trx_as_rbr_only", true,
                    !may_have_sbr_stmts &&
                    thd->tx_isolation > ISO_READ_COMMITTED &&
                    gtid_pre_statement_checks(thd) != GTID_STATEMENT_SKIP))
  {
    DBUG_ASSERT(thd->get_transaction()->is_empty(Transaction_ctx::STMT));
    DBUG_ASSERT(thd->get_transaction()->is_empty(Transaction_ctx::SESSION));
    DBUG_ASSERT(!thd->lock);
    DBUG_PRINT("info", ("setting tx_isolation to READ COMMITTED"));
    set_tx_isolation(thd, ISO_READ_COMMITTED, true/*one_shot*/);
  }

五、相关链接

https://bugs.mysql.com/bug.php?id=85639 （他这里面举的例子有点绕，是用外键约束来制造这个场景的，不过归根结底还是间隙锁，不清楚的可以找我私聊）

六、相关问题

1、普通事务会不会在binlog中出现交叉的情况
普通事务不会交叉，因为组提交的时候由一个leader顺序的将其他follower的binlog cache写入到binlog文件中并且刷盘。

2、RC隔离级别下，为什么就没有间隙锁了
间隙锁是RR隔离级别为了解决幻读问题引入的，在加记录锁的时候，会每次都会判断隔离级别，如果不是RR级别就不会加间隙锁，如下代码所示：
if (!set_also_gap_locks

|| srv_locks_unsafe_for_binlog
|| trx->isolation_level <= TRX_ISO_READ_COMMITTED
|| (unique_search && !rec_get_deleted_flag(rec, comp))
|| dict_index_is_spatial(index)) {


goto no_gap_lock;

} else {

lock_type = LOCK_ORDINARY;

}

3、row格式的binlog，为什么可以设置RC

这个问题需要从如下两个方面解答：

a.为什么从库sql线程可以设置成RC隔离级别？
隔离级别主要是解决多个会话中事务并发读写数据的问题，不管是RC或者RR其实主要是影响快照读，因为RC和RR它们创建read view的时机不太一样导致能看到的数据也不一样。但是如果是变更数据，那么就是当前读，当前读不会构造快照数据，会获取当前已提交的数据进行变更。另外一个区别就是RR级别和RC加锁情况不同，RR级别会加间隙锁，这个其实也是防止幻读问题。由于从库线程只是变更数据，不涉及到快照读，没有间隙锁也没有什么影响，所以这里把隔离级别从RR设置从RC并没有什么影响。这里这样设置的主要原因也是为了避免RR级别的间隙锁。

b.为什么row格式下可以设置RC隔离级别，而statement格式下不能设置

其实在RC级别下设置binlog格式为statement模式是不安全，这个之前很早就有人报了bug，目前如果这样设置，会直接报如下错误：

ERROR 1665 (HY000): Cannot execute statement: impossible to write to binary log since BINLOG_FORMAT = STATEMENT and at least one table uses a storage engine limited to row-based logging. InnoDB is limited to row-logging when transaction isolation level is READ COMMITTED or READ UNCOMMITTED.

为什么会有问题呢？下面看一个case：

创建表：

CREATE TABLE `t1` (
  `a` int(11) DEFAULT NULL,
  `b` int(11) DEFAULT NULL,
  KEY `a` (`a`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

插入数据：

insert into t1 values(10,2),(20,1);

分别在binlog格式为row和statement格式执行如下SQL：

transaction 1:
set session transaction isolation level read committed;
begin;
UPDATE t1 SET a=11 where b=2;

transaction 2:
set session transaction isolation level read committed;
UPDATE t1 SET b=2 where b=1;
commit;

transaction 1:
commit;

在row格式下，binlog内容如下：

### UPDATE `zbdba15`.`t1`
### WHERE
###   @1=20 /* INT meta=0 nullable=1 is_null=0 */
###   @2=1 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=20 /* INT meta=0 nullable=1 is_null=0 */
###   @2=2 /* INT meta=0 nullable=1 is_null=0 */




### UPDATE `zbdba15`.`t1`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
###   @2=2 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=11 /* INT meta=0 nullable=1 is_null=0 */
###   @2=2 /* INT meta=0 nullable=1 is_null=0 */

在statement格式下，binlog内容如下：

UPDATE t1 SET b=2 where b=1;


UPDATE t1 SET a=11 where b=2;

那在主库上最后的结果是：

(11,2),(20,2)

binlog为row的时候，从库上结果也是(11,2),(20,2)，binlog为statement的时候，从库上的结果是(11,2),(11,2)

这就造成主从不一致了，这也就是为什么RC隔离级别下为什么不能设置binlog为statement格式，那为什么RR级别可以呢，因为RR级别有间隙锁控制，上述事务2语句在执行的时候直接会夯住。即使是statement格式，RR级别是能保证执行顺序的。