背景

最近线上发现了一些报警: “send heart beat to broker add: xxx error: request timeout”, 同时伴随着服务重启, 会出现consumer 流量短时间降低, 同时 consumer的连接创建也很缓慢

排查

通过关键字匹配, 发现这个是 rocektmq-golang-sdk 的一处错误打印, 是心跳命令请求broker超时的场景下打印的

rocketmq-sync-timeout

既然是请求rocketmq超时了, 直接登录到线上rocketmq broker查看负载, 但是通过top执行发现cpu和内存占比都比较正常, 同时 netstat -anp | grep pid 扫描的socket的数量也只有几千个,没有异常点.

没有线索的情况下, 我们继续排查日志内容, 通过 tailf broker.log 一段时间后, 发现有一些类似 “event queue size 10000 enough, so drop this event CLOSE” 和 “event queue size 10000 enough, so drop this event CONNECT” 的日志, 同样进行关键字匹配, 发现这段逻辑是 rocketmq 对event的抽象处理, event比如: CONNECT/CLOSE/IDLE/EXCEPTION, 以 CLOSE 为例, 当rocketmq netty server 监听到 主动关闭或者被动关闭 连接的时候, 会实例化一个 CLOSE 类型的 event信息 投递到了 eventQueue, 这个 eventQueue 大小是 1w, 当大小大于 1w 的时候, 就会投递失败 (这里有个坑), eventQueue 投递后的消息是由一个单线程异步处理的, 线程会回调根据注册的listener进行回调, 这一块逻辑参考 NettyRemotingServer#channelInactive、NettyRemotingAbstract#putNettyEvent 和 NettyRemotingAbstract#run, 注册的回调逻辑实现在 ClientHousekeepingService#onChannelClose, 回调都做了什么事情呢?

  1. 从producer注册信息中删除这个地址的channel对象
  2. 从consumer注册信息中删除这个地址的channel对象, 如果consumer group没有连接, 删除这个group, 并回调consumerIdsChangeListener
  3. 从filter注册信息中删除这个地址的注册

如下图 rocketmq-server-channel-close

因此, eventQueue 出现丢弃 event 的情况 是一个问题, 但是和我们的心跳超时并没有太紧密的关联, 并且 event的处理逻辑范围太广, 线索失去了踪迹.

回到rocketmq本身的心跳实现, rocketmq的心跳处理过程也很简单, 就是简单的内存注册, 也没有复杂的实现, 所以心跳处理应该非常快, 不应该存在处理耗时长的情况, 并且, 结合rocketmq processor的实现方式和配置参数, rocektmq heartbeat 的 线程池队列有 5w大小, 难道我们的心跳qps 已经这么高了? 通过内部注入的客户端打点发现, 我们心跳的qps成功 1.8k, 失败 2.8k, 加起来连 5k qps 也不到, 所以 远远低于线程池queue的配置, 那么, 只剩下一个假设了, 心跳处理的很慢, 但是为什么呢?

处理慢的情况, 要么是存在锁竞争, 要么是实现逻辑问题. 因为通过代码查看并没有明显的锁竞争行为, 因此使用火焰图进行了cpu profile: ./profiler.sh -d 60 -f profile.svg pid. 因为是线上场景, 不适合使用 lightweight-java-profiler，这里我们采用了 async-profiler. 注意: 需要打开如下开关

echo 1 > /proc/sys/kernel/perf_event_paranoid
echo 0 > /proc/sys/kernel/kptr_restrict

下载路径: https://github.com/jvm-profiling-tools/async-profiler/blob/master/README.md

火焰图结果如下

rocketmq-timeout-profile

显然, ProducerManager 在 idle 和 closeEvent 分别触发的 doChannelCloseEvent 占用耗时过长，打开存在问题的函数如下

rocketmq-producer-close

根据代码的实现, 我们怀疑 for循环遍历 groupChannelTable 耗时长, 如果是这种场景, 那么, groupChannelTable 应该很大. 为了佐证我们的猜想, 进行了jmap内存分析: jmap -dump:format=b,file=filename.hprof pid, 通过小伙伴 jvisualvm 的分析, 发现 groupChannelTable 的key非常多, 如下图, 将近 140w

rocketmq-timeout-mapkey

根据目前debug的证据: groupChannelTable key太多, for 循环遍历耗时长, 导致处理 doChannelCloseEvent 处理耗时长. 但是这个跟心跳处理又有什么关系呢? 心跳逻辑的实现中, 存在doChannelCloseEvent#add的操作, 根据 ConcurrentHashMap 的内部实现注释, 迭代和add是存在锁竞争操作的, 注释如下:

/**
 * TreeNodes used at the heads of bins. TreeBins do not hold user
 * keys or values, but instead point to list of TreeNodes and
 * their root. They also maintain a parasitic read-write lock
 * forcing writers (who hold bin lock) to wait for readers (who do
 * not) to complete before tree restructuring operations.
 */
static final class TreeBin<K,V> extends Node<K,V> {

那么基本上可以破案了. groupChannelTable key 太多, 迭代时间长, TreeBin 在读写操作上存在锁竞争, 导致心跳超时. 至此, 心跳超时、eventqueue丢弃、cpu profile、heap dump 的内容串联起来了

解决方案

根据分析的内容, 问题出现在了 groupChannelTable 的遍历问题上, 那么, 是否可以 减少 groupChannelTable 的key数量呢? 根据 groupChannelTable的定义, key 是 producer client传递的group, 这个group是 transactional 场景中使用的, 参考: https://rocketmq.apache.org/docs/core-concept/ . 那么, 如果我们让 业务方的客户端 尽量复用 group, 比如说让业务的一个服务中的producer 都是用服务的名字作为group, 那么, 就能大大减少 groupChannelTable 的大小, 并且避免 groupChannelTable 此前的恶性循环 (每次遍历耗时很长, 耗时长又导致关闭缓慢, 进而导致groupChannelTable变大, 因为关闭过程中可能又有新的连接). 确定这个解决方案后, 迅速coding、测试环境部署、上线. 上线后不久 错误日志开始跌0, 同时 超时的qps 也降低到了0, 重新cpu profile得到火焰图也正常了, 如下

rocketmq-timeout-normal

后记

  1. groupChannelTable 的key太多, 还是一个很疑惑的点, 为什么会触发这种问题, 仅仅是因为 我们 producer 很多?

  2. 之前讲到consumer也存在连接耗时长、流量短时间降低的现象

如果队列中有一个心跳请求的处理出现的耗时长的情况，那么后面的请求的耗时也会相应增加, 并且consumer创建的时候, 需要向所有的broker发起一次心跳操作进行订阅信息的注册。在用admin命令获取连接的时候，是根据 retry topic下注册的consumer获取信息，因此，如果订阅信息没有注册上去，admin也就无法获取相关的连接. Producer 的发送行为就不依赖于心跳的成功，因此producer发送没有受到影响.