本文轉(zhuǎn)載自微信公眾號「 搬運(yùn)工來架構(gòu)」，轉(zhuǎn)載本文請聯(lián)系 搬運(yùn)工來架構(gòu)公眾號。

[[329425]]

前段時間發(fā)現(xiàn)，在使用rockerMQ console時，查詢消息的時候出現(xiàn)很慢，查詢耗時大于10秒，少則5、6秒，多則14+秒。

如下圖：

這到底是為什么?查詢消息為啥會出現(xiàn)這么大的耗時?

當(dāng)前使用的開發(fā)環(huán)境：操作系統(tǒng)是Windows10，JDK8，rocketMQ為4.5.2。

在其它機(jī)器上則沒有此問題，也在本機(jī)器上的虛擬機(jī)VMware上安裝的Linux部署了rocketMQ 和 console，并且驗(yàn)證是沒問題的。

那么到底我的機(jī)器是怎么了???

由于當(dāng)前是接口的耗時問題，我們并不知道耗時主要在哪個地方，所以使用Arthas來跟蹤下調(diào)用鏈的耗時。

使用trace命令：

trace命令

方法內(nèi)部調(diào)用路徑，并輸出方法路徑上的每個節(jié)點(diǎn)上耗時。

trace 命令能主動搜索 class-pattern/method-pattern 對應(yīng)的方法調(diào)用路徑，渲染和統(tǒng)計(jì)整個調(diào)用鏈路上的所有性能開銷和追蹤調(diào)用鏈路。

trace org.apache.rocketmq.console.service.impl.MessageServiceImpl queryMessageByTopic

從當(dāng)前調(diào)用路徑得到主要耗時在于：DefaultMQPullConsumer構(gòu)造器初始化 + DefaultMQPullConsumer啟動耗時。那么接下來我們繼續(xù)往內(nèi)部跟進(jìn)。

此時我們關(guān)注下DefaultMQPullConsumer構(gòu)造器初始化：

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

從構(gòu)造器初始化入口看，耗時并不大。

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

[E] 開啟正則表達(dá)式匹配，默認(rèn)為通配符匹配

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

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

接著發(fā)現(xiàn)耗時主要是在獲取MQClientInstance實(shí)例。

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; 
} 

可以看到很多賦值操作，這些可以不關(guān)注，只要關(guān)注new ClientConfig()：

trace org.apache.rocketmq.client.ClientConfig <init> 

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

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

到現(xiàn)在，已經(jīng)跟蹤到JDK方法調(diào)用了：NetworkInterface#getNetworkInterfaces。

接著想查看JDK函數(shù)調(diào)用：

trace --skipJDKMethod false java.net.NetworkInterface getNetworkInterfaces 

--skipJDKMethod skip jdk method trace, default value true.

默認(rèn)情況下，trace不會包含jdk里的函數(shù)調(diào)用，如果希望trace jdk里的函數(shù)，需要顯式設(shè)置--skipJDKMethod false。

此時不能跟蹤，那么根據(jù)4點(diǎn)提示排查和issue：https://github.com/alibaba/arthas/issues/47

https://github.com/alibaba/arthas/issues/807

最后確定需要開啟unsafe。

options unsafe true 

開啟完成。

再次執(zhí)行，即可看到j(luò)dk的調(diào)用鏈了。

到這里，算是把rocketMQ console查詢慢的罪魁禍?zhǔn)渍业搅耍涸讷@取本機(jī)網(wǎng)卡接口時，出現(xiàn)耗時時間長。這其實(shí)也算是jdk跟操作系統(tǒng)層面的意思了，與中間件rocketMQ無關(guān)，一開始我是懷疑是不是持久化存儲在加載時慢的可能(基本排除)。

那么為什么會調(diào)用當(dāng)前操作系統(tǒng)的網(wǎng)卡接口時會出現(xiàn)耗時嚴(yán)重呢?

此時關(guān)注到了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; 

可以看到j(luò)dk函數(shù)已經(jīng)調(diào)用到了native方法，也就是jdk底層的實(shí)現(xiàn)(c/c++)了，跟操作系統(tǒng)非常緊密。

接著debug進(jìn)getNetworkInterfaces方法查看到底有哪些網(wǎng)卡接口：

一查發(fā)現(xiàn)竟然有81個!接著查看本機(jī)的網(wǎng)絡(luò)適配器：

本機(jī)Windows上有Wlan、vpn、VMware等網(wǎng)絡(luò)適配器。

最后事實(shí)就是跟他們有關(guān)，我把相應(yīng)的適配器禁用之后，重新調(diào)用NetworkInterface#getNetworkInterfaces，此時耗時從3+秒降到幾百毫秒。

最后，很遺憾還是沒能剖析出為什么Windows下調(diào)用網(wǎng)卡接口native方法會出現(xiàn)那么大耗時。并且肯定跟我的機(jī)器有關(guān)，因?yàn)槠渌麢C(jī)器驗(yàn)證沒有問題。

如果要剖析原因，就得需要有c/c++更加底層的功底才能搞定吧?

如果你有遇過知道怎么解決、或熟悉底層實(shí)現(xiàn)或者有更好的思路麻煩留言指導(dǎo)下。(抱拳)

總結(jié)

• Windows下可能容易出現(xiàn)一些非正常問題，竟然也能給我遇到這個^@^。幸好一般使用Windows還是比較少，除非是開發(fā)機(jī)器較多，Linux(unix)部署rocketMQ等中間件還是很穩(wěn)的。
• 使用Arthas trace可以跟蹤方法的調(diào)用路徑，并且追蹤每一步的耗時，可以方便的排查瓶頸問題。
• -E參數(shù)支持正則表達(dá)式匹配;--skipJDKMethod false支持包含JDK的函數(shù)調(diào)用;跟蹤jdk函數(shù)等，如果找不到對應(yīng)類或者方法，可能需要開啟unsafe。