rocketMQ 很慢？引出了一個(gè)未解之謎
本文轉(zhuǎn)載自微信公眾號(hào)「 搬運(yùn)工來(lái)架構(gòu)」，轉(zhuǎn)載本文請(qǐng)聯(lián)系 搬運(yùn)工來(lái)架構(gòu)公眾號(hào)。
前段時(shí)間發(fā)現(xiàn)，在使用rockerMQ console時(shí)，查詢消息的時(shí)候出現(xiàn)很慢，查詢耗時(shí)大于10秒，少則5、6秒，多則14+秒。
如下圖：
這到底是為什么?查詢消息為啥會(huì)出現(xiàn)這么大的耗時(shí)?
當(dāng)前使用的開(kāi)發(fā)環(huán)境：操作系統(tǒng)是Windows10，JDK8，rocketMQ為4.5.2。
在其它機(jī)器上則沒(méi)有此問(wèn)題，也在本機(jī)器上的虛擬機(jī)VMware上安裝的Linux部署了rocketMQ 和 console，并且驗(yàn)證是沒(méi)問(wèn)題的。
那么到底我的機(jī)器是怎么了???
由于當(dāng)前是接口的耗時(shí)問(wèn)題，我們并不知道耗時(shí)主要在哪個(gè)地方，所以使用Arthas來(lái)跟蹤下調(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)用鏈路上的所有性能開(kāi)銷和追蹤調(diào)用鏈路。
trace org.apache.rocketmq.console.service.impl.MessageServiceImpl queryMessageByTopic
從當(dāng)前調(diào)用路徑得到主要耗時(shí)在于：DefaultMQPullConsumer構(gòu)造器初始化 + DefaultMQPullConsumer啟動(dòng)耗時(shí)。那么接下來(lái)我們繼續(xù)往內(nèi)部跟進(jìn)。
此時(shí)我們關(guān)注下DefaultMQPullConsumer構(gòu)造器初始化：
- trace org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>
從構(gòu)造器初始化入口看，耗時(shí)并不大。
那么接下來(lái)再看下DefaultMQPullConsumer的啟動(dòng)方法：
[E] 開(kāi)啟正則表達(dá)式匹配，默認(rèn)為通配符匹配
- trace -E org.apache.rocketmq.client.consumer.DefaultMQPullConsumer start
trace -E org.apache.rocketmq.client.consumer.DefaultMQPullConsumer
接著發(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
默認(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
最后確定需要開(kāi)啟unsafe。
- options unsafe true
開(kāi)啟完成。
再次執(zhí)行，即可看到j(luò)dk的調(diào)用鏈了。
到這里，算是把rocketMQ console查詢慢的罪魁禍?zhǔn)渍业搅耍涸讷@取本機(jī)網(wǎng)卡接口時(shí)，出現(xiàn)耗時(shí)時(shí)間長(zhǎng)。這其實(shí)也算是jdk跟操作系統(tǒng)層面的意思了，與中間件rocketMQ無(wú)關(guān)，一開(kāi)始我是懷疑是不是持久化存儲(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 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個(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+秒降到幾百毫秒。
最后，很遺憾還是沒(méi)能剖析出為什么Windows下調(diào)用網(wǎng)卡接口native方法會(huì)出現(xiàn)那么大耗時(shí)。并且肯定跟我的機(jī)器有關(guān)，因?yàn)槠渌麢C(jī)器驗(yàn)證沒(méi)有問(wèn)題。
如果要剖析原因，就得需要有c/c++更加底層的功底才能搞定吧?
如果你有遇過(guò)知道怎么解決、或熟悉底層實(shí)現(xiàn)或者有更好的思路麻煩留言指導(dǎo)下。(抱拳)
總結(jié)
- Windows下可能容易出現(xiàn)一些非正常問(wèn)題，竟然也能給我遇到這個(gè)^@^。幸好一般使用Windows還是比較少，除非是開(kāi)發(fā)機(jī)器較多，Linux(unix)部署rocketMQ等中間件還是很穩(wěn)的。
- 使用Arthas trace可以跟蹤方法的調(diào)用路徑，并且追蹤每一步的耗時(shí)，可以方便的排查瓶頸問(wèn)題。
- -E參數(shù)支持正則表達(dá)式匹配;--skipJDKMethod false支持包含JDK的函數(shù)調(diào)用;跟蹤jdk函數(shù)等，如果找不到對(duì)應(yīng)類或者方法，可能需要開(kāi)啟unsafe。
