现象
前天11点左右有几个业务方找过来说生产环境RocketMQ一直报FLUSH_SLAVE_TIMEOUT异常，查看源码只知道是主从同步超时，但未找到逻辑上导致这个异常的原因
定位问题
跟运维沟通，了解到在这个时间点开启了一个topic的一个group的消费，经比对跟出现异常的时间匹配上，找对应的业务方，业务方认为这个topic还有其余group在消费，别的group消费没问题，那这个应该也没啥问题，这听起来确实也没法反驳，后面观察该group单台消费能力在5000tps的样子，线上一共有4台机器，也就是会有20000的tps（刚开启时有一百多万的数据堆积）
由于这个业务恰好那次上线半个小时出了点问题，后面下线了，而这个业务业务下次上线时间定在3天后，因此准备在压测环境测试看能否复现这个问题，在压测环境堆积了200w数据后，生产者一直造数据，查看broker日志没有出现FLUSH_SLAVE_TIMEOUT的异常，开启该业务group的消费之后，store.log中一直报FLUSH_SLAVE_TIMEOUT，因此基本可以断定为是该消费者导致
后面在mq store模块中加了一些日志，打包到压测环境环境，发现有大量的延迟消息保存到commitLog，每次压测之前都是清空了存储目录了的，正常来说是不会有延迟消息的，后发现延迟消息都是该业务消费者的延迟消息，也就是说这个业务消费消息一直失败，然后一直sendback到broker，也就是以20000tps的速率发送消息到broker，但就算producer端发送压力大，据以前的经验，也应该是BROKER_BUSY，没办法，只能去看主从同步的源码
主从同步流程如下：
主从同步
正常来说groupTransferService唤醒都是代表当前请求已经同步到slave了，失败也应该是超时（超过5s），但日志显示是没超过5s直接返回的失败，也就是图中的步骤4进行了5次无效唤醒
handleHA方法中封装GroupCommitRequest到groupTransferService，后面发现连着的两个request的写入位置差别很大，大于实际消息体的长度，再次加上一些log打包之后发现，这两个消息中间有很多的延迟消息被put到了commitLog，延迟消息在put之前调用的msgInner.setWaitStoreMsgOK(false)，而handleHA中判断该值为true才会封装GroupCommitRequest到groupTransferService,也就是说第一条正常同步的消息跟第二条同步异常的消息中间由于插入了大量的延迟消息，而每次主从同步默认最大只同步32k数据，每同步一次数据slave上报一次offset，只要这中间延迟的消息多就一定会导致slave上报超过5次导致的无效唤醒
备注：mq主从配置为SYNC_MASTER,ASYNC_FLUSH
网友评论