背景
打開(kāi)一個(gè)幾年前的老項(xiàng)目，發(fā)現(xiàn)啟動(dòng)巨慢，同樣的代碼沒(méi)動(dòng)過(guò)枢里，當(dāng)年在渣渣 i5 上運(yùn)行也只要十幾秒，現(xiàn)在升了配置反而要好幾分鐘蹂午。
截圖中的項(xiàng)目已經(jīng)精簡(jiǎn)了部分內(nèi)容
問(wèn)題定位
INFO RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true
首先注意到這句報(bào)錯(cuò)栏豺，意思是 RocketMQ 沒(méi)連上 ，按理說(shuō)應(yīng)該沒(méi)影響豆胸，不過(guò)以防萬(wàn)一還是本地啟動(dòng)一下 RocketMQ ：
start mqnamesrv && mqbroker -c ../conf/broker.conf
重啟項(xiàng)目發(fā)現(xiàn)耗時(shí)還是差不多（ 相對(duì)于總時(shí)長(zhǎng)來(lái)說(shuō)幾秒的誤差可以忽略不計(jì) ）奥洼。
再注意到下面的日志， RocketMQListener 注冊(cè)成功之前等待了大約 10 秒的時(shí)間晚胡。
2022-12-19 18:53:21.484 - 42601 [NettyClientSelector_1] INFO RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true
2022-12-19 18:53:32.552 - 53669 [NettyClientSelector_1] INFO RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true
2022-12-19 18:53:32.554 - 53671 [main] INFO org.apache.rocketmq.spring.support.DefaultRocketMQListenerContainer:243 : running container: DefaultRocketMQListenerContainer{consumerGroup='DEFAULT_GROUP', nameServer='127.0.0.1:9876', topic='DEFAULT_TOPIC', consumeMode=CONCURRENTLY, selectorType=TAG, selectorExpression='*', messageModel=CLUSTERING}
2022-12-19 18:53:32.554 - 53671 [main] INFO org.apache.rocketmq.spring.autoconfigure.ListenerContainerConfiguration:107 : Register the listener to container, listenerBeanName:myRocketMQListener, containerBeanName:org.apache.rocketmq.spring.support.DefaultRocketMQListenerContainer_1
為了測(cè)試方便灵奖，之前只保留了一個(gè) RocketMQListener ，其他的都注釋掉了估盘，現(xiàn)在放開(kāi)注釋后發(fā)現(xiàn)瓷患，每個(gè) RocketMQListener 注冊(cè)成功之前都會(huì)等待大約 10 秒。說(shuō)明這部分的代碼是有點(diǎn)問(wèn)題的遣妥，但還不是啟動(dòng)慢的主要原因擅编，繼續(xù)看日志（ 把 RocketMQListener 都先注釋掉 ）：
2022-12-19 18:52:45.440 - 6557 [main] INFO com.Application:658 : The following profiles are active: dev
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.springframework.cglib.core.ReflectUtils$1 (file:/H:/maven/org/springframework/spring-core/5.0.12.RELEASE/spring-core-5.0.12.RELEASE.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of org.springframework.cglib.core.ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2022-12-19 18:53:18.903 - 40020 [main] INFO org.apache.coyote.http11.Http11NioProtocol:180 : Initializing ProtocolHandler ["http-nio-0.0.0.0-3000"]
這部分警告日志的前后間隔了大約 30 秒，說(shuō)明 Spring 初始化有點(diǎn)慢箫踩，但看不到具體的細(xì)節(jié)爱态，需要在 log4j2 配置中放開(kāi)一下 Spring 的 debug 日志：
<AsyncLogger name="org.springframework" level="debug"/>
可以看到每個(gè) Bean 實(shí)例化都挺快的，唯獨(dú)下面兩個(gè)部分卡了一會(huì)兒：
2022-12-19 19:15:29.185 - 7538 [main] INFO org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'rocketmq-org.apache.rocketmq.spring.autoconfigure.RocketMQProperties' of type [org.apache.rocketmq.spring.autoconfigure.RocketMQProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-12-19 19:15:39.070 - 17423 [main] INFO org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'defaultMQProducer' of type [org.apache.rocketmq.client.producer.DefaultMQProducer] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-12-19 19:15:39.120 - 17473 [main] INFO org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'jacksonObjectMapper' of type [com.fasterxml.jackson.databind.ObjectMapper] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2022-12-19 19:16:03.671 - 42024 [main] INFO org.springframework.context.support.PostProcessorRegistrationDelegate$BeanPostProcessorChecker:326 : Bean 'rocketMQTemplate' of type [org.apache.rocketmq.spring.core.RocketMQTemplate] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
這里耗時(shí)大約 30 秒班套，和前面可以對(duì)上肢藐。
由于項(xiàng)目目前用不上 RocketMQ ，可以把 RocketMQAutoConfiguration 配置先屏蔽掉看下：
@SpringBootApplication(exclude = { RocketMQAutoConfiguration.class })
public class Application {
// ...
@Bean
public RocketMQTemplate rocketMQTemplate() {
// 造一個(gè)假的 rocketMQTemplate 避免項(xiàng)目報(bào)錯(cuò)
RocketMQTemplate rocketMQTemplate = new RocketMQTemplate();
rocketMQTemplate.setProducer(new DefaultMQProducer("groupName"));
return rocketMQTemplate;
}
}
重啟項(xiàng)目只需要 20 多秒了吱韭，雖然還是慢但至少能接受吆豹，可以確定是 RocketMQ 的問(wèn)題了。而且所有依賴的中間件都是本地部署的理盆，基本可以忽略網(wǎng)絡(luò)問(wèn)題了（ 后面打臉 ）痘煤，實(shí)在想不通為什么會(huì)慢。
解決方法
拿著 rocketMQTemplate 啟動(dòng)慢 的關(guān)鍵詞去搜問(wèn)題簡(jiǎn)直是大海撈針猿规，不過(guò)運(yùn)氣好找到了一篇文章《 RocketMQ 很慢衷快？引出了一個(gè)未解之謎 》， 里面指出了 NetworkInterface.getNetworkInterfaces 這個(gè) JDK 方法的耗時(shí)問(wèn)題 姨俩，本地測(cè)試了一下果然如此：
public class NetworkInterfaceTest {
public static void main(String[] args) throws SocketException {
long start = System.currentTimeMillis();
Enumeration<NetworkInterface> enumeration = NetworkInterface.getNetworkInterfaces();
long end = System.currentTimeMillis();
ArrayList<NetworkInterface> result = new ArrayList<>();
while (enumeration.hasMoreElements()) {
result.add(enumeration.nextElement());
}
System.out.printf(
"NetworkInterface.getNetworkInterfaces() use %d ms, result size: %d%n",
end - start,
result.size()
);
}
}
真兇果然是它蘸拔，一次調(diào)用耗時(shí)將近 6 秒师郑，不加限制多調(diào)用幾次就能爆炸了〉髑希可以看一下這個(gè)方法的返回結(jié)果是什么：
光看名字就能聯(lián)想到 控制面板\網(wǎng)絡(luò)和 Internet\網(wǎng)絡(luò)連接 中的 網(wǎng)絡(luò)適配器 宝冕，基本能對(duì)上：
之所以有這么多的設(shè)備是因?yàn)橹鞍惭b Genymotion 模擬器的時(shí)候 VirtualBox 給安裝上的，因?yàn)闆](méi)遇到過(guò)其他問(wèn)題也就沒(méi)在意邓萨，沒(méi)想到卻導(dǎo)致了 getNetworkInterfaces 調(diào)用變慢的問(wèn)題地梨。而 getNetworkInterfaces 方法底層調(diào)用的是 getAll 這個(gè) native 方法，所以代碼層面基本沒(méi)得改了缔恳，目前 唯一 的 解決方法 就是 把沒(méi)用的網(wǎng)絡(luò)適配器都禁用掉 宝剖，最后耗時(shí)只要 600 毫秒了（ 不同的網(wǎng)卡耗時(shí)程度不同 ），這種程度基本能接受了歉甚。
把測(cè)試代碼放 VMware 構(gòu)建的純凈系統(tǒng)環(huán)境下又測(cè)了一遍万细，發(fā)現(xiàn)最初調(diào)用只要 31 毫秒，這種程度的耗時(shí)才是正常的铃芦，難怪以前都沒(méi)發(fā)現(xiàn)這個(gè)問(wèn)題雅镊，而安裝 Genymotion 后耗時(shí)果然就顯著增加了。
回到項(xiàng)目還原代碼驗(yàn)證一下刃滓，啟動(dòng)時(shí)間果然恢復(fù)到正常的 8 秒了仁烹。
問(wèn)題復(fù)盤
這個(gè)問(wèn)題得到解決得虧有人用 RocketMQ 的時(shí)候遇到類似的問(wèn)題，不然就只能不了了之了咧虎。不過(guò)和別人說(shuō) getNetworkInterfaces 方法調(diào)用很慢大概率會(huì)被人當(dāng)傻子卓缰，比如有人在 RocketMQ 倉(cāng)庫(kù)提過(guò) 類似問(wèn)題 直接被無(wú)視了。
xxxProducer和xxxConsumer都繼承 ClientConfig 砰诵，因此每實(shí)例化一個(gè)就會(huì)調(diào)用一次getNetworkInterfaces征唬。
繼續(xù)查資料看有沒(méi)有方法可以定位耗時(shí)的代碼塊，在《 SpringBoot 服務(wù)啟動(dòng)慢排查思路 》一文中看到了一張 JProfiler 的方法調(diào)用樹(shù)截圖茁彭，里面清楚標(biāo)紅了耗時(shí)比較長(zhǎng)的方法总寒，但是文章中沒(méi)有具體的操作步驟，只能自己研究下理肺。
后來(lái)才發(fā)現(xiàn)在 JProfiler 幫助文檔 中關(guān)于這部分內(nèi)容已經(jīng)介紹的很詳細(xì)了摄闸。
操作步驟：
在 IDEA 中用 JProfiler 圖標(biāo)啟動(dòng)項(xiàng)目
進(jìn) JProfiler 的 bin 目錄啟動(dòng)主程序 jprofiler.exe
-
Attach > 選擇 背景色標(biāo)綠 的項(xiàng)目進(jìn)程 > 開(kāi)始
配置項(xiàng)一路確定就好了。
許可證密鑰 錯(cuò)誤會(huì)導(dǎo)致 啟動(dòng)報(bào)錯(cuò) 的妹萨，需要選擇 評(píng)估 （ 試用 10 天 ）年枕。
修改系統(tǒng)時(shí)間后重啟 JProfiler 可以繼續(xù)試用。（ 用完了再把系統(tǒng)時(shí)間還原回去 ）
JProfiler> ERROR: Invalid license key. Aborting. JProfiler> Killing process清除已填寫的注冊(cè)碼：
cd /d "%USERPROFILE%/.jprofiler13" && del jprofiler_config.xml -
CPU 視圖 > 調(diào)用樹(shù) > 開(kāi)始記錄
這一步手速要快一點(diǎn)乎完，不然可能會(huì)錯(cuò)過(guò)一些重要的調(diào)用過(guò)程熏兄。當(dāng)然也可以在 會(huì)話啟動(dòng) 的配置窗口中設(shè)置 初始化記錄分析 以自動(dòng)開(kāi)始記錄。
JProfiler 會(huì)話啟動(dòng) -
等待項(xiàng)目啟動(dòng)完成
JProfiler 分析調(diào)用樹(shù)
調(diào)用樹(shù)結(jié)果是有了，但坑爹的是展開(kāi)之后報(bào)紅的線索就斷了摩桶，基本是 1% 以內(nèi)的正常方法調(diào)用桥状，完全看不到里層的慢方法。點(diǎn)擊工具欄中的 分析 按鈕典格，將結(jié)果轉(zhuǎn)為火焰圖看下：
可以看到兩側(cè)缺失了一大片的內(nèi)容芭概，說(shuō)明有一些方法被隱藏了沒(méi)記錄在內(nèi)辛蚊，這時(shí)回到調(diào)用樹(shù)污它，注意到每個(gè)方法前面的圖標(biāo)都不太一樣趾浅，正好工具欄有一個(gè) 顯示圖例 的按鈕意乓，點(diǎn)擊查看內(nèi)容：
這說(shuō)明部分方法被過(guò)濾了菇夸，最后在 會(huì)話設(shè)置 > 調(diào)用樹(shù)過(guò)濾器 > 定義過(guò)濾器 中發(fā)現(xiàn)默認(rèn)配置把一堆第三方庫(kù)都過(guò)濾了：
這里只需要添加被分析的包（ 注意順序悼院，具體配置規(guī)則見(jiàn) 官方文檔 ）即可：
java. // 看情況是否要加
javax.
org.apache.
重啟項(xiàng)目重新開(kāi)始分析就能得到想要的結(jié)果了：
查看火焰圖效果更直觀淮逊，可以看到大部分時(shí)間都花費(fèi)在 getNetworkInterfaces 上了（ 8 次調(diào)用共耗時(shí) 37 秒 ）侠坎，也證實(shí)了前面問(wèn)題定位沒(méi)有錯(cuò)蚁趁。
其他相關(guān)問(wèn)題
解決完這個(gè)問(wèn)題忽然想到前段時(shí)間碰到的另一個(gè)問(wèn)題：用到 JSP 的項(xiàng)目從 JDK1.8 切換到 JDK11 后，第一次訪問(wèn)頁(yè)面很慢实胸，并有警告日志：
WARN 6244 --- [nio-8080-exec-1] o.a.c.util.SessionIdGeneratorBase : Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [6,337] milliseconds.
SecureRandom 的耗時(shí)問(wèn)題 以前在 Docker 容器 中運(yùn)行 Tomcat 時(shí)遇到過(guò)他嫡，但和這次顯然不是一回事，定位到打日志的代碼：
發(fā)現(xiàn)耗時(shí)的地方在 SecureRandom.nextInt() 庐完，只是肉眼去看代碼不好去分析更底層的調(diào)用棧钢属，還好剛學(xué)會(huì)了 JProfiler ，分析結(jié)果一目了然门躯，這個(gè)問(wèn)題同樣也是 getNetworkInterfaces 在搗鬼淆党。
至于為什么 JDK1.8 沒(méi)問(wèn)題，由于調(diào)用棧發(fā)生了變化一時(shí)也查不出原因讶凉，我猜測(cè)可能是其他地方（ 可能無(wú)法被分析器攔截到 ）提前觸發(fā)了 SecureRandom.SeederHolder 的 static 代碼初始化染乌。比如 debug 模式 運(yùn)行項(xiàng)目時(shí)打斷點(diǎn)發(fā)現(xiàn) sun.management.Agent.startAgent() 中就間接調(diào)用了 SecureRandom 。
