作者 | 秋天

**【Arthas 官方社群正在舉行徵文活動，參加即有獎品拿~[點選投稿](http://alibabacloud.mikecrm.com/9khcRrs)】**

前段時間發現，在使用 RockerMQ console 時，查詢訊息的時候出現很慢，查詢耗時大於 10 秒，少則 5、6 秒，多則 14+ 秒。

如下圖：

![1.png](https://ucc.alicdn.com/pic/developer-ecology/53d0c024abb34656826c1cda280c9de9.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](https://ucc.alicdn.com/pic/developer-ecology/56497959104749bb9370f0e8817803a8.png)

從當前呼叫路徑得到主要耗時在於：DefaultMQPullConsumer 構造器初始化 + DefaultMQPullConsumer 啟動耗時。那麼接下來我們繼續往內部跟進。

此時我們關注下 DefaultMQPullConsumer 構造器初始化：

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

![3.png](https://ucc.alicdn.com/pic/developer-ecology/affc1575b92c4c43acecce6b97be5aa5.png)

從構造器初始化入口看，耗時並不大。

那麼接下來再看下 DefaultMQPullConsumer 的啟動方法：

### [E] 開啟正規表示式匹配，預設為萬用字元匹配

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

![4.png](https://ucc.alicdn.com/pic/developer-ecology/88a64ec5f38c4120a1319bfb7d48b80b.png)

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

![5.png](https://ucc.alicdn.com/pic/developer-ecology/35c96ed734fc47fc890a10261ab9de97.png)

接著發現耗時主要是在獲取 MQClientInstance 例項。

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

![6.png](https://ucc.alicdn.com/pic/developer-ecology/180f59c27b4d4926bcd7b3fc35c6ece5.png)

```
trace org.apache.rocketmq.client.ClientConfig cloneClientConfig
```

![7.png](https://ucc.alicdn.com/pic/developer-ecology/617f21ba3c7d4c3db8407461d26c1bcf.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](https://ucc.alicdn.com/pic/developer-ecology/d5159e0a33324d589fbee0ad83609176.png)

可以看到主要耗時在 3~4 秒，並且耗時主要是這個工具類方法：

`RemotingUtil#getLocalAddress```

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

![9.png](https://ucc.alicdn.com/pic/developer-ecology/670059d4372e46bfb09df3e563bd9f57.png)

到現在，已經跟蹤到 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。

![10.png](https://ucc.alicdn.com/pic/developer-ecology/98b348673a754d3ca100ca25aacaa618.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](https://ucc.alicdn.com/pic/developer-ecology/a6321c2f69784d0aac5a8395e272d272.png)

開啟完成。

再次執行，即可看到 jdk 的呼叫鏈了。

![12.png](https://ucc.alicdn.com/pic/developer-ecology/98e943cfc84d4288b48f45413b07edcb.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](https://ucc.alicdn.com/pic/developer-ecology/60559467048d46ec83398cd691e8fe73.png)

一查發現竟然有 81個！接著檢視本機的網路介面卡：

![14.png](https://ucc.alicdn.com/pic/developer-ecology/6a18ceff9d1d4abbaae855565c97b1c4.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 後端，分散式，微服務，系統架構等。個人公眾號《搬運工來架構》 。</networkinterface></networkinterface></value></init></init></init>

RocketMQ 很慢？引出了一個未解之謎

相關文章