s这是学习笔记的第 2031 篇文章
最近有个业务的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;
再次尝试这个问题暂时正常了,在反复验证中暂时没有发现问题。
而后续的进一步验证得找下环境,会后续继续说明。
对于问题本身,也需要和研发团队做一下确认,这种操作的需求需要引导,后续不要再出现。