最新消息:欢迎访问若有所思,如果你也有与我相同的兴趣爱好,请关注我的站点。

metaq异步消息信号量泄漏BUG

问题排查 若远 32409浏览 0评论
||||| 2 |||||

现象概述

近期观察线上系统监控信息时,会偶然性的发现集群中有少量的机器假死不工作(LOAD跌到0,CPU处于空闲状态,SYS占用正常,RT很大)。
metaq异步消息阻塞_3

metaq异步消息阻塞_1

metaq异步消息阻塞_4

从监控数据观察来看发生故障的机器有一定的随机性,而且发生的时间也有一定的偶然性。

问题分析

无法重现问题就很难根据现象来排查问题,所以只有从头查起。首先,翻看了一遍故障机器的日志和系统相关指标监控数据也没有发现什么线索。只好从当前JVM堆栈着手开始分析,使用jstack dump当前的堆栈信息发现有大量的线程阻塞在invokeAsyncImpl的Semaphore上,查看这一部分代码的实现是在METAQ对NETTY消息推送的封装NettyRemotingAbsract类中(这个线上系统会加工数据然后通过METAQ推送给其他系统)。
metaq异步消息阻塞_2

转折点

难道是消息量过大把缓冲池撑满了?但是网络流量的监控数据表明这个推测完全是错误的,而且METAQ发送消息并没有大的开销处理过程。分析到这里现在只有一个线索Metaq的处理逻辑可能存在BUG,只好checkout代码走读源码。

很快就分析完了整个代码流程,处理Metaq发送消息的核心类是com.alibaba.rocketmq.client.impl.MQClientAPIImpl和com.alibaba.rocketmq.remoting.netty.NettyRemotingClient。

metaq异步消息阻塞_6

上图中红色部分为Semaphore的获取、释放处理节点,又仔细的审查了一遍这部分的代码(推测可能是信号量泄漏造成的)。两个操作的入口如下图:
metaq异步消息阻塞_7

metaq异步消息阻塞_8

异步发送消息入口,基本逻辑可以表述为:

  1. 获取信号量锁,如果当前信号量已满那么阻塞等待(最长等待3秒)
  2. 判断当前是否获取到信号量锁,如果是执行3,否则超时放弃发送
  3. 发送消息,等待服务端回应
  4. 释放信号量锁,回调用户自定义回调函数

乍一看并没有什么不妥之处,线索到这里又断了。只要重新再审查一遍日志是否有疏漏(往往所有的证据都隐藏在最原始的日志中),由于日志很大需要通过一些工具来做预处理(METAQ等日志通常在近GB级别)。经过几遍的分析和过滤偶然间发现了一个很有意思的异常,如下图所示:
metaq异步消息阻塞_5

柳暗花明

FastJSON数据越界?暂且不管,往上看异常堆栈,注意到这一行ERROR NettyClientWorkerThread_1 - encode exception。顺藤摸瓜很快定位到源码com.alibaba.rocketmq.remoting.netty.NettyEncoder,当encode异常时会直接关闭连接

难道是连接关闭导致没有正常释放信号量?重新回来分析整个源码,Metaq网络传输基于Netty实现(自定义了一套消息协议),通过processMessageReceived来解析消息做不同的处理,其中processResponseCommand是处理响应的回调函数(刚才说过这个是释放信号量的关键函数)

好,继续往下分析问题。这里简单介绍一下Netty的基本编程框架,Netty在实现上采用了Reactor模型的变种Multiple Reactors,简单的说有两个角色组成:mainReactor和subReactor,mainReactor负责客户端的连接请求,并将请求转交给subReactor,subReactor负责相应通道的IO请求,非IO请求(具体逻辑处理)的任务则会直接写入队列,等待worker threads进行处理,如下图所示:
metaq异步消息阻塞_9

用代码实现较为繁琐,这里简单的使用一些伪代码表示Metaq中Netty组件的初始化过程:

继续分析,从代码中我们可以发现整个NETTY的处理过程和我们目前分析到的链路有关的就只剩下NettyConnectManagerHandler(当encoder失败关闭连接就会触发其中的close回调函数),但是可惜的是整个链路没有一个地方来处理这种异常情况下释放信号量,因此造成了信号量泄漏最终导致系统不可用(即所有触发send操作的RT均被延长到3秒并且肯定失败)。同样,知道了问题所在其实修复问题很简单,注册Netty的Close监听器做响应的处理,不过最终Metaq小组在修正此问题时采用了定时轮询的方式,详见NettyRemotingAbstract.scanResponseTable和两个Patch(见下方)。

至于FastJSON这个有意思的异常分析,有兴趣的朋友请查看本站的另一篇文章:http://i.dotidea.cn/?p=1384

解决方案

受影响范围

METAQ/RocketMQ:客户端3.1.5以下(包括此版本)的版本
FastJSON:1.1.39以下(包括此版本)的版本

可行方案

可升级至最新版本解决问题,仅涉及到METAQ客户端代码和FastJSON二方包

PATCH LINK: https://github.com/alibaba/RocketMQ/commit/5e409c238e20b4eee97ec1197a75884714b70f5b
PATCH LINK: https://github.com/alibaba/RocketMQ/commit/a4d7130f9f2008c7463c13686938dec6036ce715

参考资料

  1. Metaq(RocketMQ) Github:https://github.com/alibaba/rocketmq
  2. FastJSON Github:https://github.com/alibaba/fastjson
  3. Netty Github:https://github.com/netty/netty
  4. 小e的分享:http://hongweiyi.com/2014/01/netty-4-x-thread-model/

转载请注明:若有所思-胡磊 » metaq异步消息信号量泄漏BUG

GuestGuest
发表我的评论
取消评论

表情

Hi,您需要填写昵称和邮箱!

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址