作者 | 秋天

【Arthas 官方社區(qū)正在舉行征文活動(dòng)，參加即有獎(jiǎng)品拿~點(diǎn)擊投稿】

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

如下圖：

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

當(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)前是接口的耗時(shí)問題，我們并不知道耗時(shí)主要在哪個(gè)地方，所以使用 Arthas 來跟蹤下調(diào)用鏈的耗時(shí)。

使用 trace 命令：

trace 命令
方法內(nèi)部調(diào)用路徑，并輸出方法路徑上的每個(gè)節(jié)點(diǎn)上耗時(shí)。
trace 命令能主動(dòng)搜索 class-pattern／method-pattern 對(duì)應(yīng)的方法調(diào)用路徑，渲染和統(tǒng)計(jì)整個(gè)調(diào)用鏈路上的所有性能開銷和追蹤調(diào)用鏈路。

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

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

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

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

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

那么接下來再看下 DefaultMQPullConsumer 的啟動(dòng)方法：

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

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

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

接著發(fā)現(xiàn)耗時(shí)主要是在獲取 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>

可以看到主要耗時(shí)在 3~4 秒，并且耗時(shí)主要是這個(gè)工具類方法：

`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 不會(huì)包含 jdk 里的函數(shù)調(diào)用，如果希望 trace jdk 里的函數(shù)，需要顯式設(shè)置–skipJDKMethod false。

此時(shí)不能跟蹤，那么根據(jù) 4 點(diǎn)提示排查和 issue：

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

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

最后確定需要開啟 unsafe。

options unsafe true

開啟完成。

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

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

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

此時(shí)關(guān)注到了 java.net.NetworkInterface#getNetworkInterfaces

public static Enumeration<NetworkInterface> getNetworkInterfaces()throws SocketException {final NetworkInterface[] netifs = getAll();// specified to return null if no network interfacesif (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 函數(shù)已經(jīng)調(diào)用到了 native 方法，也就是jdk底層的實(shí)現(xiàn)(c/c++)了，跟操作系統(tǒng)非常緊密。

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

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

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

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

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

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

總結(jié)：

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

作者 | 秋天，關(guān)注 Java 后端，分布式，微服務(wù)，系統(tǒng)架構(gòu)等。個(gè)人公眾號(hào)《搬運(yùn)工來架構(gòu)》 。

總結(jié)

以上是生活随笔為你收集整理的RocketMQ 很慢？引出了一个未解之谜的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。