前段时间发现,在使用RockerMQ console时,查询消息的时候出现很慢,查询耗时大于10秒,少则5、6秒,多则14+秒。
如下图:
这到底是为什么?查询消息为啥会出现这么大的耗时?
当前使用的开发环境:操作系统是Windows10,JDK8,RocketMQ为4.5.2。
在其它机器上则没有此问题,也在本机器上的虚拟机VMware上安装的Linux部署了RocketMQ 和 console,并且验证是没问题的。
那么到底我的机器是怎么了???
由于当前是接口的耗时问题,我们并不知道耗时主要在哪个地方,所以使用Arthas来跟踪下调用链的耗时。
使用trace命令:
trace命令
方法内部调用路径,并输出方法路径上的每个节点上耗时。
trace 命令能主动搜索 class-pattern/method-pattern 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
trace org.apache.rocketmq.console.service.impl.MessageServiceImpl queryMessageByTopic
trace org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>
从构造器初始化入口看,耗时并不大。
那么接下来再看下DefaultMQPullConsumer的启动方法:
[E] 开启正则表达式匹配,默认为通配符匹配
trace -E org.apache.rocketmq.client.consumer.DefaultMQPullConsumer start
trace -E org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>|start
trace org.apache.rocketmq.client.impl.MQClientManager getAndCreateMQClientInstance
trace org.apache.rocketmq.client.ClientConfig cloneClientConfig
接着看ClientConfig#cloneClientConfig方法:
public ClientConfig cloneClientConfig() {
ClientConfig cc = new ClientConfig();
cc.namesrvAddr = namesrvAddr;
cc.clientIP = clientIP;
cc.instanceName = instanceName;
cc.clientCallbackExecutorThreads = clientCallbackExecutorThreads;
cc.pollNameServerInterval = pollNameServerInterval;
cc.heartbeatBrokerInterval = heartbeatBrokerInterval;
cc.persistConsumerOffsetInterval = persistConsumerOffsetInterval;
cc.unitMode = unitMode;
cc.unitName = unitName;
cc.vipChannelEnabled = vipChannelEnabled;
cc.useTLS = useTLS;
cc.namespace = namespace;
cc.language = language;
return cc;
}
可以看到很多赋值操作,这些可以不关注,只要关注new ClientConfig():
trace org.apache.rocketmq.client.ClientConfig <init>
可以看到主要耗时在3~4秒,并且耗时主要是这个工具类方法:RemotingUtil#getLocalAddress
trace org.apache.rocketmq.remoting.common.RemotingUtil getLocalAddress
到现在,已经跟踪到JDK方法调用了:NetworkInterface#getNetworkInterfaces。
接着想查看JDK函数调用:
trace --skipJDKMethod false java.net.NetworkInterface getNetworkInterfaces
--skipJDKMethod <value> skip jdk method trace, default value true.
默认情况下,trace不会包含jdk里的函数调用,如果希望trace jdk里的函数,需要显式设置--skipJDKMethod false。
此时不能跟踪,那么根据4点提示排查和issue:https://github.com/alibaba/arthas/issues/47
https://github.com/alibaba/arthas/issues/807
最后确定需要开启unsafe。
options unsafe true
开启完成。
再次执行,即可看到jdk的调用链了。
到这里,算是把RocketMQ console查询慢的罪魁祸首找到了:在获取本机网卡接口时,出现耗时时间长。这其实也算是jdk跟操作系统层面的意思了,与中间件RocketMQ无关,一开始我是怀疑是不是持久化存储在加载时慢的可能(基本排除)。
那么为什么会调用当前操作系统的网卡接口时会出现耗时严重呢?
此时关注到了java.net.NetworkInterface#getNetworkInterfaces
public static Enumeration<NetworkInterface> getNetworkInterfaces()
throws SocketException {
final NetworkInterface[] netifs = getAll();
// specified to return null if no network interfaces
if (netifs == null)
return null;
return new Enumeration<NetworkInterface>() {
private int i = 0;
public NetworkInterface nextElement() {
if (netifs != null && i < netifs.length) {
NetworkInterface netif = netifs[i++];
return netif;
} else {
throw new NoSuchElementException();
}
}
public boolean hasMoreElements() {
return (netifs != null && i < netifs.length);
}
};
}
private native static NetworkInterface[] getAll() throws SocketException;
可以看到jdk函数已经调用到了native方法,也就是jdk底层的实现(c/c++)了,跟操作系统非常紧密。
接着debug进getNetworkInterfaces方法查看到底有哪些网卡接口:
一查发现竟然有81个!接着查看本机的网络适配器:
本机Windows上有Wlan、VPN、VMware等网络适配器。
最后事实就是跟他们有关,我把相应的适配器禁用之后,重新调用NetworkInterface#getNetworkInterfaces,此时耗时从3+秒降到几百毫秒。
最后,很遗憾还是没能剖析出为什么Windows下调用网卡接口native方法会出现那么大耗时。并且肯定跟我的机器有关,因为其他机器验证没有问题。
如果要剖析原因,就得需要有c/c++更加底层的功底才能搞定吧?
如果你有遇过知道怎么解决、或熟悉底层实现或者有更好的思路麻烦留言指导下。(抱拳)
总结
-
Windows下可能容易出现一些非正常问题,竟然也能给我遇到这个^@^。幸好一般使用Windows还是比较少,除非是开发机器较多,Linux(unix)部署RocketMQ等中间件还是很稳的。 -
使用Arthas trace可以跟踪方法的调用路径,并且追踪每一步的耗时,可以方便的排查瓶颈问题。 -
-E参数支持正则表达式匹配;--skipJDKMethod false支持包含JDK的函数调用;跟踪jdk函数等,如果找不到对应类或者方法,可能需要开启unsafe。
回复公众号【资料】获得干货资料集锦:技术ppt、IT大会资料、架构、分布式资料等。
3、Kafka面试题!掌握它才说明你真正懂Kafka
4、Netty 5.0为啥被舍弃?原因竟然是...
5、中台之上——业务架构系列【汇总】
-关注搬运工来架构,与优秀的你一同进步-
如果喜欢这篇文章可以点在看哦↘
本文仅供学习!所有权归属原作者。侵删!文章来源: 搬运工来架构
文章评论