1.现象
观察接口调用耗时,偶尔会出现一笔调用耗时相对较长:超过2s,且都是发送mq的耗时。或偶尔会出现sendKernelImpl exception的错误日志,但消息可以正常消费。
2.环境说明
rocketmq:4.4.0
java:1.8
rocketmq master主要配置:
brokerRole=SYNC_MASTER
flushDiskType=ASYNC_FLUSH
3.初次问题排查
1)最开始怀疑发送mq代码问题,因为只有一个服务出现报错现象,其他服务只是偶尔超过2s。因为代码很少,配置也都一样,比较后排除此原因。
2)怀疑应用出现full gc。
幸好我们对应用配置了gc日志,查看出问题前后gc日志,确定没有出现full gc或youthgc,此原因也排除。
3)怀疑mq出现full gc
登录服务器,查看master、slave的gc日志,没有问题。此时陷入了迷茫……
4.查阅资料后再次排查问题
在网上搜索异常信息,网上说可能是linux虚拟内存问题,查看/var/log/message日志,发现不符。
继续查看告警时master的日志,发现store.log中有些不正常,截图如下:
继续查看slave的日志,似乎有些问题:
5.研究rocketmq主从同步原理、源码
1)slave心跳(HAClient)
连接master后,会等待5s向master发送心跳(心跳中包含slave的进度),然后每收到master的消息都会更新lasterwritetime。
线程最长1s运行一次,若当前时间-lasterwritetime>5s(haSendHeartbeatInterval默认为5),就会向master发送心跳。
若当前时间-lasterwritetime>20s(haHousekeepingInterval)时关闭连接。
会记录上传mater的进度currentReportedOffset,当存储的数据大于上传进度后会向master发送心跳。
2)master心跳(HAConnection)
等待slave连接,建立连接后创建一个读处理对象ReadSocketService、写处理对象WriteSocketService。
读处理对象,最长每1s运行一次,有slave的数据后更新lastReadTime。当当前时间-lastReadTime>20s(haHousekeepingInterval)时关闭连接。
写处理对象,最长1s运行一次,但是必须等slave上传进度后才会执行后续逻辑(slave建立连接后需要等haSendHeartbeatInterval间隔才会上传心跳)。
根据slave心跳的进度设置回应进度。当master的进度比slave大时,向slave发送心跳。
当前时间-最后写slave的时间>haSendHeartbeatInterval时向slave发送心跳。
3)心跳断开原因
至此,心跳断开的原因已经找到,主从心跳间隔都采用的默认值5s,因为各种原因,当没有新mq消息产生时,主从谁先谁后发心跳是无法保证的。当连续4都是主先发心跳时,slave每次收到心跳后都会更新lasterwritetime,从而无法触发向主发送心跳。而主超过20s都没有收到从的心跳后会认为从已下线,从而关闭从的连接。
4)master接收mq消息处理流程
因当前配置的是SYNC_MASTER模式,master收到客户端发过来的消息后,首先进行持久化。
然后检查必须有一个slave在线,并且等待至少有一个slave的进度与当前master一致。
5)偶尔慢或client报错原因
当slave刚连上master后,此时发送mq消息,master持久化后会等待slave上传心跳并消息进度一致。但slave却需要等5s才第一次向master发送心跳,所以可能会出现发送mq慢或超过3s客户端出现开始时的错误日志。
6.解决方案
方案1:将主从模式修改为ASYNC_MASTER模式
这样master持久化后不用检测或等待slave状态。缺点就是当master突然挂掉后,可能存在少量消息没有同步到slave的情况,从而可能丢消息。
方案2: slave的配置文件中新增haSendHeartbeatInterval=3
这样就不会出现连续4次都是master先发送心跳,从而保证心跳为长连接。心跳没有重连,也就不会开始的问题。