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