最近在生产上的MySQL集群出现了所有从节点异常退出的奇怪现象,可给孩子吓得不轻,立马开始排查问题

java中唯一索引冲突异常导致程序中断如何解决 mysql唯一索引冲突错误码_数据


和当时正在做操作的老师沟通后定位到他们当时正在使用mysqlsh的import工具进行数据导入。

具体的执行命令如下

mysqlsh --uri dcsp@$ip $port -pd$pwd -e "util.importTable('data.txt',
{schema:'mydb',table: 'mytable', fieldsTerminatedBy:'|',characterSet:'gbk', 
bytesPerChunk:'50M',threads: 8})

首先查看MySQL从节点的error日志发现从节点上出现了重复唯一键报错

[ERROR][MY-010584][Repl] Slave SQL for channel group_replication_appier Worker 2 failed executing transaction '$gtid';Could not execute Write_rows event on table mydb.mytable, Duplicate entry 'abcd1234-0000' for key 'uk_1', Error_code 1062, handler error HA_ERR_FOUND_DUPP_KEY.Error code:MY-001062

mytable的唯一键索引为为uk_1(b,a)

从节点上出现了重复唯一键的数据,是由什么问题引起的呢?这个让我大大的不解

java中唯一索引冲突异常导致程序中断如何解决 mysql唯一索引冲突错误码_数据_02

死锁?

通过查看他们的脚本日志发现很多的deadlock死锁问题,这个死锁问题其实也比较正常,因为他们导入的数据中本身包含了重复的数据,相当于他们通过MySQL的校验来筛除重复。

但是死锁问题会导致从节点上出现不一致吗?感觉这两个问题没有必然联系。

于是我们将import导入的线程数改为1,然后重新导入,如果没有出现问题,说明跟死锁有关联。

使用命令如下

mysqlsh --uri dcsp@$ip $port -pd$pwd -e "util.importTable('data.txt',
{schema:'mydb',table: 'mytable', fieldsTerminatedBy:'|',characterSet:'gbk', 
bytesPerChunk:'50M',threads: 1})

结果是令人意外的,线程数为1导入数据的时候同样出现了集群从节点全部退出的情况。MySQL从节点的error日志和之前的报错一模一样,没有改变。脚本日志中也没有再出现死锁问题

此时,可以确定集群问题和死锁没有关系。那么,集群异常的真实原因到底是什么呢?

java中唯一索引冲突异常导致程序中断如何解决 mysql唯一索引冲突错误码_数据库_03

唯一索引失效!

这个时候的思路不是很清晰了。于是我们继续观察了MySQL从节点的error日志,不如看一下报错的事务,解析一下当时的binlog看看是否有异常

发现并没有什么奇怪的地方(其实有,但是我们没有注意到)

#211221 21:39:29 server id 330215112 end_log_pos 670570655 GTID last_committed=570 tansaction_length=29832407
/*:50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
#original commit timestamp=1640094019096110(2021-12-2121:40:19.096110 csT)
#immediate comm1 t timestamp=1640094019840325(2021-12-2121:40:19.840325CsT)
/*!80001 SET 0@session.original commit timestamp=1640094019096110*//*!*/;
/*!80014 SET 00session.original server version=80021*//*!*/;
/*!80014 SET 00session.immediate server version=80021*//*!*/;
SET @@SESSION.GTID NEXT='$gtid'/*!*/
#at 670570655
#211221 21:39:29 server id 330215112 end_1og_pos 670570727
SET TIMESTAMP=1640093969/*!*/;
SET @@session.foreign_key_checks=0,@@session.unique_checks=0/*!*/;
SET @@session.sq1_mode='1168637984'/*!*/;
/*!\C utf8mb4*//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=46/*!*/;
BEGIN
/*!*/;
# at 670570727
#211221 21:39:29 server id 330215112 end_log_pos 670570977 Rows_query
# LOAD DATA LOCAL INFILE 'data.txt' into table 'mydb'.'mytable' field terminated by '|' characterset 'gbk';

然后,我们说要不在主库查一下那条报错的数据,这不查不知道,一查吓一跳。

mysql> select a,b from mytable where b ='abcd1234' and a = '0000';

java中唯一索引冲突异常导致程序中断如何解决 mysql唯一索引冲突错误码_dba_04

主节点上居然有两条唯一键相同的数据,这个时候细想一下大致能找到原因了。主节点上有两条唯一键相同的数据,那么从节点回放的时候必然也会有这两条唯一键相同的数据,疑惑的点在于主节点的唯一索引校验失效但是从节点的唯一索引校验没有失效(否则不会报错了)。

于是我们搜索唯一索引失效的场景

  1. 当有一列为null时
  2. 当unique_checks设置为0,并且此时使用批量导入数据(load data)时

我们明显不属于第一种情况,这下需要关注的点来到了unique_checks上面,我们回过头去查看我们解析出来的binlog日志,豁然开朗。

这里发现在load之前session的unique_checks被修改为0

SET @@session.foreign_key_checks=0,@@session.unique_checks=0/*!*/;

复现

我们在测试环境同样使用mysqlsh的import导数,解析binlog同样会看到unique_checks被修改,但是发现很难复现跟生产类似的情况,于是我们参考了这篇文章

把buffer pool的大小调低,只要将事先插入的数据挤出了buffer pool,那么就会出现从节点唯一键冲突的报错,然后主动退出集群。尝试之后成功复现了当时的情景,具体如何操作后面单独出一篇博客吧

java中唯一索引冲突异常导致程序中断如何解决 mysql唯一索引冲突错误码_dba_05

真相

mysqlsh.import工具每次导入时会将session的unique_checks设置为0,此时我们导入的目标表数据如果不在buffer pool里面,那么唯一索引的校验将会失效(主从节点都是这样的,可以通过select * from把buffer pool撑满),主节点上的目标表数据不在buffer pool,而从节点上的目标表数据在buffer pool中,那么就会出现从节点报错然后主动退出的异常。

解决方案:将文件拆小,使用load data的方式。(因为我们限制了单个事务的大小)

之前有看过大佬对mysqlsh和load做过比较,但是没有提到unique_checks这一点,想必mysqlsh的速度提升很大程度上和unique_checks、foreign_key_checks以及多线程有关吧。

目前将这个问题提交给了官方,是否可以将这两个checks参数做可配置化。