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;

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

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

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

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2019-07-06

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

扫码关注云+社区

领取腾讯云代金券