MySQL复制问题的分析
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;
再次尝试这个问题暂时正常了，在反复验证中暂时没有发现问题。
而后续的进一步验证得找下环境，会后续继续说明。
对于问题本身，也需要和研发团队做一下确认，这种操作的需求需要引导，后续不要再出现。
