rocketMQ 很慢？引出了一個未解之謎
本文轉載自微信公眾號「 搬運工來架構」，轉載本文請聯系 搬運工來架構公眾號。
前段時間發現，在使用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
接著發現耗時主要是在獲取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
默認情況下，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。
