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

野性酷女 2022-12-25 04:59 443阅读 0赞

作者 | 秋天

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

前段时间发现，在使用 RockerMQ console 时，查询消息的时候出现很慢，查询耗时大于 10 秒，少则 5、6 秒，多则 14+ 秒。

如下图：

![1.png][]

这到底是为什么？查询消息为啥会出现这么大的耗时？

当前使用的开发环境：操作系统是 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

![2.png][]

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

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

trace org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>

![3.png][]

从构造器初始化入口看，耗时并不大。

那么接下来再看下 DefaultMQPullConsumer 的启动方法：

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

trace -E  org.apache.rocketmq.client.consumer.DefaultMQPullConsumer start

![4.png][]

trace -E  org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>|start

![5.png][]

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

trace org.apache.rocketmq.client.impl.MQClientManager getAndCreateMQClientInstance

![6.png][]

trace org.apache.rocketmq.client.ClientConfig cloneClientConfig

![7.png][]

接着看 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>

![8.png][]

可以看到主要耗时在 3~4 秒，并且耗时主要是这个工具类方法：

\`RemotingUtil\#getLocalAddress\`\`\`

trace org.apache.rocketmq.remoting.common.RemotingUtil getLocalAddress

![9.png][]

到现在，已经跟踪到 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。

![10.png][]

此时不能跟踪，那么根据 4 点提示排查和 issue：

*[https://github.com/alibaba/arthas/issues/47][https_github.com_alibaba_arthas_issues_47]*

*[https://github.com/alibaba/arthas/issues/807][https_github.com_alibaba_arthas_issues_807]*

最后确定需要开启 unsafe。

options unsafe true

![11.png][]

开启完成。

再次执行，即可看到 jdk 的调用链了。

![12.png][]

到这里，算是把 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 方法查看到底有哪些网卡接口：

![13.png][]

一查发现竟然有 81个！接着查看本机的网络适配器：

![14.png][]

本机 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 后端，分布式，微服务，系统架构等。个人公众号《搬运工来架构》 。

[Link 1]: http://alibabacloud.mikecrm.com/9khcRrs
[1.png]: /images/20221120/61a834908ae946afbf07fd09b3cbc4fb.png
[2.png]: /images/20221120/3fb31e7b3f5147d187d6cba76d27b2b2.png
[3.png]: /images/20221120/9373eaeda78a427a8f0ae8f323a9c1cc.png
[4.png]: /images/20221120/4fbc49c9472249af92b38b1f1203eb89.png
[5.png]: /images/20221120/48754c9e776f4d7c9d1b939abd25189d.png
[6.png]: /images/20221120/0586d10a93cb453f8498762b0e9e914d.png
[7.png]: /images/20221120/1b2d79d60e64490caf777116c06cbd71.png
[8.png]: /images/20221120/b0452a42d985424788b3cf1cb0574558.png
[9.png]: /images/20221120/320470d77dbb4e2691318656bfc54a85.png
[10.png]: /images/20221120/e9d4d203743e42a49e31956e8771d310.png
[https_github.com_alibaba_arthas_issues_47]: https://github.com/alibaba/arthas/issues/47
[https_github.com_alibaba_arthas_issues_807]: https://github.com/alibaba/arthas/issues/807
[11.png]: /images/20221120/10005f18dfc443aaac54f7b40e1c5571.png
[12.png]: /images/20221120/a0a0c898ca414935890e82d7fd14aa86.png
[13.png]: /images/20221120/6bd9eb5fe4e74681b4c1edcb81bd41fe.png
[14.png]: https://img-blog.csdnimg.cn/img_convert/d99ca6afe8288b977f3fbaf626cbdb79.png