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中有些不正常，截图如下:
master日志
继续查看slave的日志，似乎有些问题:
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先发送心跳，从而保证心跳为长连接。心跳没有重连，也就不会开始的问题。
网友评论