MySQL复制问题的分析

最近有个业务的MySQL复制问题还是比较多，做了事务降维之后，把一些敏感操作和线上环境隔离起来，整体的效果好了许多，不过今天在外面的时候，又收到一条报警短信，让我心里咯噔一下。

这个环境是一个中间件的分布式环境，有8个物理节点（主库），即有6个主库+8个从库，我查看了下邮件，发现报错的这个环境是昨天同事帮忙新建的从库，到今天才这么短的时间，而且是基于GTID复制的模式，又出现了这类问题，我的心里还是比较忐忑的，因为如果我再收到几条其他环境类似的复制错误，那么毫无疑问就属于一起计划外的故障了。

故障离我们很近，但是在不同的时间有不同的理解。因为这段时间的做了数据迁移的一些高可用测试，压力测试，数据重构，整体该做的工作都做差不多了，到了临门一脚的时候，出现一些频繁的问题，我让我有所措手不及，而问题能够定位可控，很容易理解，可以查漏补缺，而如果问题是集中出现，那就说明之前的工作没有做到位，一旦发现严重的bug导致服务不可用，如果反复出现，不管过程如何，结果就是不合格的。这种感觉就好比是高速公路给汽车换轮胎，时间紧，任务重。

所幸的是，我等了一会没有再收到其他环境的问题，所以一个基本的定位：不是很严重。

等我回到酒店之后，开始处理的时候，脑海里一直在琢磨，到底是一条什么样的SQL语句会导致这样奇怪的问题。

很快就查到了相关的描述信息：

LAST_ERROR_MESSAGE: Worker 0 failed executing transaction 'db8f9860-8202-11e9-991e-005056b7f69e:854286845' at master log mysqlbin.000601, end_log_pos 936077509; Could not execute Update_rows event on table dbo_testdb.dbo_testdata; Can't find record in 'dbo_testdata', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysqlbin.000601, end_log_pos 936077509

看起来问题是在binlog日志000601的偏移量936077509附近，看到这个偏移量心里一纠，可以看到文件已经超过900M了，解析起来已经有一些性能问题了。

查看show slave status的结果：

Slave_IO_Running: Yes

Slave_SQL_Running: No

可以看到IO_thread依然可用，说明复制的过程中整体的数据传输是OK的，是在应用的时候出现了问题 。

我使用如下的语句开始解析这个偏移量附近的一些错误。

/usr/local/mysql/bin/mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS mysqlbin.000601 | grep -A '10' 936077509

得到了如下的结果：

#190705 19:27:15 server id 211 end_log_pos 936077509 CRC32 0x590574c3 Update_rows: table id 599753 flags: STMT_END_F

### UPDATE `dbo_testdb`.`dbo_testdata`

### WHERE

### @1=748890203 /* LONGINT meta=0 nullable=0 is_null=0 */

### @2=60 /* INT meta=0 nullable=0 is_null=0 */

### @3=13 /* INT meta=0 nullable=0 is_null=0 */

### @4='2019-07-05 19:27:15' /* DATETIME(0) meta=0 nullable=0 is_null=0 */

### @5='2019-07-05 19:27:15' /* DATETIME(0) meta=0 nullable=0 is_null=0 */

### @6=0 /* LONGINT meta=0 nullable=0 is_null=0 */

### SET

### @1=748890203 /* LONGINT meta=0 nullable=0 is_null=0 */

--

# at 936077509

#190705 19:27:15 server id 211 end_log_pos 936077540 CRC32 0x78404313 Xid = 221915192

COMMIT/*!*/;

# at 936077540

#190705 19:27:15 server id 211 end_log_pos 936077605 CRC32 0x6e307159 GTID last_committed=1762227 sequence_number=1762248

SET @@SESSION.GTID_NEXT= 'db8f9860-8202-11e9-991e-005056b7f69e:854286846'/*!*/;

# at 936077605

#190705 19:27:15 server id 211 end_log_pos 936077696 CRC32 0x00c8479d Query thread_id=854 exec_time=0 error_code=0

SET TIMESTAMP=1562326035/*!*/;

BEGIN

可以看到这是一条update语句，它的格式比较奇怪，如下：

update xxx

where userid=xxxx,value=xxxx

set userid=xxxx

从语句来看明显是不符合业务场景的，自己变更自己，明显不合理的。

我们来进一步验证。

主库端查看数据，把上面的update转义成select语句：

select * from `dbo_testdb`.`dbo_testdata`

WHERE

userid=748890203 and

xxx=60 and

value=13 and

moddate='2019-07-05 19:27:15' and

crtdate='2019-07-05 19:27:15' and

modver=0

发现主库端和从库端都不存在这条语句。

所以这就牵扯出来两个问题：

1）如果MySQL在主库端的SQL语句没有发生数据变更，是否会依然产生binlog

2)一条update语句，在MySQL里的解析应该是类似如下的形式：

update xxxx set xxxxx where 的形式，在这里明显没有走这种解析的方式。

3）这条语句如何修复，因为后面的数据都等着这个断点。

4）如果后续还有这种问题，该如何预防。

我们为了快速修复，经过评估，主从库端都没有相应的数据，说明这条语句是没有产生影响的，我们可以跳过这个事务。

stop slave;

SET @@SESSION.GTID_NEXT= 'db8f9860-8202-11e9-991e-005056b7f69e:854286846';

begin;commit;

SET SESSION GTID_NEXT = AUTOMATIC;

start slave;

再次尝试这个问题暂时正常了，在反复验证中暂时没有发现问题。

而后续的进一步验证得找下环境，会后续继续说明。

对于问题本身，也需要和研发团队做一下确认，这种操作的需求需要引导，后续不要再出现。