作者 | 秋天
【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 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。
作者 | 秋天，關注 Java 后端，分布式，微服務，系統架構等。個人公眾號《搬運工來架構》 。