Hi，
感谢卢松的两篇文章，非常欢迎大家投稿 ~ 鉴于RocketMQ的官方投稿流程刚刚启动，能否麻烦把文章在Google Doc上贴出来，然后user列表和我们讲下地址，我们一起看看先。对啦，麻烦授权以下账号修改权限: lizhan...@gmail.com z...@xinyu.im fengji...@gmail.com Best Regards, Von Gosling > 在 2018年4月2日，12:27，yukon <yu...@apache.org> 写道： > > Hi, > > 非常欢迎撰写RocketMQ相关的技术文章，建议放到Google DOC上并共享出来方便大家进行Comment。 > > Regards, > yukon > > 2018-04-02 12:06 GMT+08:00 404828407 <404828...@qq.com > <mailto:404828...@qq.com>>: > > > RocketMQ Master宕机后重启出现的严重问题分析 > > > 作者：卢松 > > 以前发现RocketMQ的master机器宕机时会出现很多诡异的问题，所以最近做了一系列实验来试图找到问题的原因，也是想发现风险点。没想到发现了一个更严重的问题，下面会详细的说明下，另外出现问题的原因属于猜测，望高人看到后能指点下。 > > 试验环境准备： > 1.RocketMQ版本：阿里的3.2.6版本 > 2.集群包含2组broker，每组broker都是1master + 1slave，都设置成SYNC_MASTER、ASYNC_FLUSH模式。 > 3.每个broker上已经存储过好几个commitlog文件，并且已经有commitlog文件删除过（数据过期了）。 > > 测试步骤： > 1.尽量多的消费组、尽量多的消费者（10个以上）开始消费多个topic，消费者自始至终不停机。 > 2.在消费者消费时，突然把其中一组broker（姑且命名为BrokerA吧）的master断电（注意是断电或者硬盘损坏、不是kill -9）。 > 3.过一段时间（半小时左右），重启宕机的这个master。 > > 观察现象，记录事后的现象及疑问： > 1.BrokerA的slave机器一直存活着，master宕机后，消费者新的消费进度会存在slave上面。 > 2.宕机后，拉取BrokerA的master中的数据文件，文件没有损坏。 > 3.重启master后，消费客户端会从很久以前的queue offset开始拉取消息，为啥会去取到很久以前的queueOffset？ > 4.重启master后，这个master出现大量如下异常，异常日志达到10分钟每G的量： > { > "timestamp": "2017-12-28T00:18:48.620+0800", > "level": "WARN", > "thread": "FlushConsumeQueueService", > "logger": "RocketmqStoreError", > "message": "findMapedFileByOffset offset not matched, request Offset: 0, > index: -6, mapedFileSize: 6000000, mapedFiles count: 2, StackTrace: > \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.commit(MapedFileQueue.java:442)\n\tcom.alibaba.rocketmq.store.ConsumeQueue.commit(ConsumeQueue.java:345)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.doFlush(DefaultMessageStore.java:1459)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.run(DefaultMessageStore.java:1479)\n\tjava.lang.Thread.run(Thread.java:722)" > } > > 5.另外还有大量的这种异常，这类异常显示大量消费客户端去拉取很久以前的消息。 > { > "timestamp": "2017-12-28T00:39:01.748+0800", > "level": "WARN", > "thread": "PullMessageThread_15", > "logger": "RocketmqStoreError", > "message": "findMapedFileByOffset offset not matched, request Offset: > 19382879484, index: -7, mapedFileSize: 1073741824 <tel:010%207374%201824>, > mapedFiles count: 2, StackTrace: > \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.CommitLog.getMessage(CommitLog.java:664)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore.getMessage(DefaultMessageStore.java:546)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:283)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:84)\n\tcom.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:172)\n\tjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)\n\tjava.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)\n\tjava.util.concurrent.FutureTask.run(FutureTask.java:166)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tjava.lang.Thread.run(Thread.java:722)" > } > > > 这种现象的原因分析过程： > 首先第二类异常出在PullMessageProcessor的拉取消息过程中，消费客户端不停拉取消息时，PullMessageProcessor会调用DefaultMessageStore.getMessage()，而在getMessage()中，更具体的是在CommitLog的public > SelectMapedBufferResult getMessage(final long offset, final int size) > 方法中，这个方法会调用MapedFileQueue的方法findMapedFileByOffset(final long offset, final > boolean returnFirstOnNotFound)，具体看下图： > > > > > > > > 从代码上看，出现这个异常原因就是DefaultMessageStore.getMessage()中offsetPy拿到的值过小，这个值实际上是从ConsumeQueue的文件中读到的单条消息的CommitlogOffset，说明bufferConsumeQueue这个对象拿到的是老的数据。如下图： > > > > bufferConsumeQueue对象又是根据offset定位的，offset是每一个queue的queueOffset，这个offset实际上是消费端拉取消息时传递过来的，它来自于两种地方，一是消费端自己拉取的消费进度，另外一种是消费端每次拉取消息，拉取不到后拿到的nextBeginOffset参数。如下图： > > > > 所以根源就出在这个nextBeginOffset的计算逻辑上，为什么nextBeginOffset会计算出过小的值，导致消费端一直在消费过小的queueOffset对应的消息？ > > 我们先不去查这个问题的原因，就按照这个逻辑走下去，看看会发生什么情况。还是回到DefaultMessageStore.getMessage()中，当SelectMapedBufferResult > selectResult = this.commitLog.getMessage(offsetPy, > sizePy);拿不到数据后，selectResult返回的是null，这个方法最终返回的状态是GetMessageStatus.MESSAGE_WAS_REMOVING，表示消息的数据文件正在被删除。 > > > > 而调用这个方法的PullMessageProcessor返回给消费客户端的是这个状态，请消费端立即尝试重新拉取消息： > > > > 消费客户端MQClientAPIImpl在方法PullResult processPullResponse(final RemotingCommand > response) 处理这个返回状态，转换成NO_MATCHED_MSG的结果。 > > > > 同样是消费客户端，在DefaultMQPushConsumerImpl的pullMessage(final PullRequest > pullRequest)方法中，PullCallback是这么处理这种NO_MATCHED_MSG结果的： > 从收到的nextBeginOffset开始，立即去重新拉取后面的消息。 > > > > > 而每次依然是去拉取很久前的消息，这样就形成了消费端不停拉取消息的日志，broker出现大量找不到消息的日志，并且broker负载很高。问题的关键是DefaultMessageStore.getMessage()中，为啥拿到的offsetPy是已经删除的commitlog > > offset，难道是/home/logs/rocketmq/store/consumequeue中文件损坏（这种可能性极低，目前还没有发现断电导致文件损坏的情况）？ > > 那就有另一种可能： > master突然断电，master上数据就有可能丢失（没有来得及刷盘），consumequeue数据在master、slave的不一致。而消费端在master宕机后切换到slave上消费，消费进度也会提交到slave上，导致消费进度queue > > offset在master、slave上不一样。然后master重启后，消费端重新回到master拉取消息，master上的数据丢失了，master识别不出消费端提交的queue > offset。 > > 总结下，slave上存储的/home/logs/rocketmq/store/consumequeue比master新，假如slave上最小、最大offset是1000，15000，而这时候master的consumequeue最小、最大数据是1000，10000。当master重启后，消费客户端在slave上已经消费到15000，在master上会从15000开始去master上拉取消息进行消费，在DefaultMessageStore.getMessage()中，当发现offset > > overflow严重溢出（大于maxOffset）时，就可能会把nextBeginOffset设置为0（恰好此consumequeue的minoffset为0），下次就从offset=0开始拉取消息。 > > 开始从0消费就会拉取很久前的消息数据了。 > > > > > 我猜测这不是rocketmq的bug，应该是RocketMQ审慎的选择，它的原则是：宁愿多消费，重复消费也不要漏消费。 > > 之所以这么设计，我的猜测或者解释如下： > 当consumeQueue的minOffset=0时，说明这个consumeQueue可能是新的queue，也可能是新扩容的queue，这时候为了避免有消息漏掉，在超过maxOffset这种奇怪的情况下，消费端下次消费就从0开始消费，宁愿重复消费也不要漏掉消费。 > > 当minOffset大于0时，说明这个queue已经长时间存在过了，不会是新queue，也不会是新扩容的，只需从maxOffset继续消费就行了。 > > 这么设计正常情况下没有问题，但是当一个topic下面的某个queue上积压了很多消息，并且minOffset=0时(表示没有删除过)。这时候master突然宕机了，slave上的数据比master新，并且消费客户端从slave上消费了这个queue上的消息。master重启后，消费客户端切换到master上消费，发现自己消费的消息对于master已经溢出了，根据上面的逻辑，就会从0重新消费，大量重复消费，并且会消费那些已经从commitlog中删除的消息，出现大量错误日志。 > > 再看看刚发布不久的Apache RocketMQ 4.2.0版本中DefaultMessageStore.getMessage()这段的实现， > > > > > > 其中this.getMessageStoreConfig().isOffsetCheckInSlave()默认为false，默认不开启在slave上offset的检查。Apache版本的实现更复杂了一点，但是依然解决不了这个问题。 > > Apache版本的逻辑是：当master宕机后，slave数据比master新。消费端先从slave消费，master重启后，消费端再从master消费，当minoffset为0时还会从0开始从新消费。 > 当slave宕机后，master数据比slave的新，消费端从master消费消息。master再宕机，slave重启后，消费端从slave消费，这时候会从master上记录的消费进度开始消费。因为slave的数据总归是来自于master，并且slave已经同步了master的新数据。 > > 好了，问题分析到现在，我大概能说的通这个问题了，虽然事实不一定如此，也少有人碰到这个问题。 > > 如果出现这种情况，也不知道怎么解决的话。我想到方式是：保留现场，堆栈信息，broker端日志，客户端日志，master和slave的所有数据文件。处理好宕机临界点的数据，最终必须要重启master时，要拿备份的slave的数据文件覆盖master的数据文件，这些文件包括commitlog，consumequeue以及config下面的所有文件（消费进度），然后再重启。简单粗暴实用，避免master起来后负载飙升直至不可用的情况。 > > 有什么风险呢？目前还不清楚。 > > 总结：这是目前为止我发现的RocketMQ最严重的一个问题，Apache版本也有此问题。其他问题都是小打小闹，没有太大影响，唯独此问题需要慎重处理。问题根源还是数据不一致，不支持高可用。集群内数据不一致，服务器端又处理不好这种不一致。 > > 不过按照Apache > RocketMQ的规划，要到4.3.0版本才支持高可用，应该不需要等很久。对于这个问题提了个issue：https://issues.apache.org/jira/browse/ROCKETMQ-348 > <https://issues.apache.org/jira/browse/ROCKETMQ-348> > > 最后，以上都属于猜测，大概也许可能是这个问题导致的，还望有高手出来指点迷津，此文算是抛砖引玉了。 > > >
