RocketMQ 很慢？引出了一个未解之谜

作者 | 秋天

【Arthas 官方社区正在举行征文活动，参加即有奖品拿~点击投稿】

前段时间发现，在使用 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

从当前调用路径得到主要耗时在于：DefaultMQPullConsumer 构造器初始化 + DefaultMQPullConsumer 启动耗时。那么接下来我们继续往内部跟进。

此时我们关注下 DefaultMQPullConsumer 构造器初始化：

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

接着发现耗时主要是在获取 MQClientInstance 实例。

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 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 interfacesif (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。

作者 | 秋天，关注 Java 后端，分布式，微服务，系统架构等。个人公众号《搬运工来架构》。

RocketMQ 很慢？引出了一个未解之谜相关推荐

一个常见的物理现象，直今还是未解之谜！
全世界只有3.14 % 的人关注了爆炸吧知识在我们的日常生活中存在着很多有趣的物理现象, 科学家对这些现象进行深入研究后,可以通过这些现象延伸,从而在前沿科技发展上得到很大的帮助,甚至去解决宇宙中 ...
很多未解之谜终于有答案了——2018年JVM生态系统报告出炉
在Java开发者中,一直存在着很多鄙视链.如: IntelliJ → Eclipse → NetBeans Unix → Linux → Mac OS→ Windows → DOS Emacs → V ...
微信拉黑和删除有啥区别？这是一个困扰良久的未解之谜，微信团队官微在微博科普了拉黑与删除的区别
这是一个困扰良久的未解之谜.拉黑和删除之后,还可以收发消息吗?聊天记录还在吗?还可以重新添加吗?对方知道自己被我拉黑/删除吗?来,你要的答案都在这.以后,拉黑还是删除,你不会再搞错了吧. 问:还可以收 ...
深度丨AI界的七大未解之谜：OpenAI丢出一组AI研究课题
今天,OpenAI在官方博客上丢出了7个研究过程中发现的未解决问题. OpenAI希望这些问题能够成为新手入坑AI的一种有趣而有意义的方式,也帮助从业者提升技能. OpenAI版AI界七大未解之谜,现 ...
AI界的七大未解之谜：OpenAI丢出一组AI研究课题
来源:三体智讯今天,OpenAI在官方博客上丢出了7个研究过程中发现的未解决问题. OpenAI希望这些问题能够成为新手入坑AI的一种有趣而有意义的方式,也帮助从业者提升技能. OpenAI版AI界 ...
难道这又是个未解之谜?--- 关于DLL中使用ADODATASET出错的问题
难道这又是个未解之谜?--- 关于DLL中使用ADODATASET出错的问题 Delphi / Windows SDK/API http://www.delphi2007.net/DelphiAPI/ ...
hibernate 复合主键根据主键删除_Python 之 MySql“未解之谜”11--主键 id 那些事
主键 id 用自增和 uuid 有什么区别? ● uuid 有 16 个字节,比 int(4 byte)和 bigint(8 byte)占用更多存储空间有大量数据的时候 uuid 主键不会像自增主键 ...
山东科技大学c语言完全题库,“山东科技大学十大未解之谜”之完全解答
"山东科技大学十大未解之谜"之完全解答 (2012-04-24 13:53:36) 标签: 娱乐当我还是一枚小正太刚刚进入山科大的时候,我就看到过这些未解之谜,现在每每看到童鞋们 ...
★大脑的9大未解之谜
大脑的9大未解之谜 1.大脑为什么有时间的意识为什么人人都自带"生物闹钟",比如想要第二天早晨办的很紧急的事,清晨一起床就想起来了(当然,健忘者另当别论):等待的时间越长,你会感 ...

RocketMQ 很慢？引出了一个未解之谜

[E] 开启正则表达式匹配，默认为通配符匹配

总结：

RocketMQ 很慢？引出了一个未解之谜相关推荐

最新文章

热门文章