一、背景
公司产品网关是依赖于RocketMQ做为消息通信的中枢,最近开发一个新功能,需要在网关实现类似RPC的功能,将原有的异步流程变成同步调用,但又不想引入新的中间件,主要是不想破坏原有的通信流程和数据模型。
调研后发现RocketMQ的Request/Reply特性,刚好满足产品的需求,采用该模式功能开发和本地调试都正常,但是部署到测试环境出现了请求超时。
一次请求超过10s还没有响应回来,这显然是不正常的,但本地没法复现,这就比较麻烦。 如果对RocketMQ的Request/Reply模式没了解的,可以先看下之前分享的一篇文章:《解读RocketMQ对RPC的设计实现原理》
二、日志查看
出了问题第一反应就是查看模块的请求日志,整个模块的请求日志很正常,但是MQ客户端报了一个异常“unknown err when receiveReplyMsg”。 跟踪源码查找对应异常日志,ClientRemotingProcessor#receiveReplyMessage发现应该是在请求响应回来后出现了异常,同时发现这边还有一个debug日志。 将RocketMQ客户端的日志级别改成debug,重新发了一次请求,发现消费者已经消费并响应回来了,请求超时说明是客户端在某个地方处理卡住了。
三、证实猜测
RocketMQ实现RPC是通过CorrelationId来关联客户端和服务端的请求响应,所以通过它便可跟踪到完整的请求路径,怀疑会不会是网络的问题导致消费者处理响应后的请求一直没有回到客户端,分别在客户端和服务端的机器上抓了个包。
# 在客户端抓取与RocketMQ交互的包
tcpdump port 10911 and host 172.16.1.21 -w /home/hsf/172.16.1.16.cap
# 在服务端抓取与RocketMQ交互的包
tcpdump -i ens160 port 10911 -s 0 -w /home/hsf/10911.cap
使用WireShark分析抓取到的包,可以看到客户端向RocketMQ发送了请求,而RocketMQ确实也响应回来报文了,其中包含我们想要的CorrelationId。 证明确实服务端已经响应回来了,只是客户端在处理的过程中阻塞住了。
四、初露端倪
根据RocketMQ暴露出来的异常日志,已经不足以定位到问题点,只能是给RocketMQ的客户端加多日志,重新打包在同台机器发布一个新的MQ环境。 定位发现是RocketMQ客户端一直阻塞在调用RemotingUtil获取SocketAddress的方法上,两次处理总共耗时了30s+,跟客户端响应延迟时间刚好符合。 继续跟踪发现是阻塞在了创建InetSocketAddress的对象上,InetSocketAddress是Jdk封装的用来获取IP和端口的API,到这一步基本就跟RocketMQ没关系了。 查找了一下关于InetSocketAddress的知识,发现网上也有人遇到过同样的情况,原因是Jdk的一个bug,在某些场景下IPv6获取IP和端口的时候会导致JVM进程出现死锁的情况。部署测试的那两台机器的确开启了IPV6,jstack打出进程的堆栈可以发现存在线程被阻塞。
五、处理方式
目前IPV4对于产品来说还是能满足的,在JVM参数中加上-Djava.net.preferIPv4Stack=true 禁用掉IPV6,只支持IPV4就可以了。
参考文章: 《dns解析超时引发的线程池故障》 《由一次线上故障来理解下 TCP 三握、四挥 & Java 堆栈分析到源码的探秘》
|