背景
打開一個幾年前的老項目，發(fā)現(xiàn)啟動巨慢，同樣的代碼沒動過，當(dāng)年在渣渣 i5 上運行也只要十幾秒，現(xiàn)在升了配置反而要好幾分鐘。
截圖中的項目已經(jīng)精簡了部分內(nèi)容
問題定位
INFO RocketmqRemoting:95 : closeChannel: close the connection to remote address[] result: true
首先注意到這句報錯，意思是 RocketMQ 沒連上 ，按理說應(yīng)該沒影響，不過以防萬一還是本地啟動一下 RocketMQ ：
start mqnamesrv && mqbroker -c ../conf/broker.conf
重啟項目發(fā)現(xiàn)耗時還是差不多（ 相對于總時長來說幾秒的誤差可以忽略不計 ）。
再注意到下面的日志， RocketMQListener 注冊成功之前等待了大約 10 秒的時間。
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
為了測試方便，之前只保留了一個 RocketMQListener ，其他的都注釋掉了，現(xiàn)在放開注釋后發(fā)現(xiàn)，每個 RocketMQListener 注冊成功之前都會等待大約 10 秒。說明這部分的代碼是有點問題的，但還不是啟動慢的主要原因，繼續(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 秒，說明 Spring 初始化有點慢，但看不到具體的細節(jié)，需要在 log4j2 配置中放開一下 Spring 的 debug 日志：
<AsyncLogger name="org.springframework" level="debug"/>
可以看到每個 Bean 實例化都挺快的，唯獨下面兩個部分卡了一會兒：
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)
這里耗時大約 30 秒，和前面可以對上。
由于項目目前用不上 RocketMQ ，可以把 RocketMQAutoConfiguration 配置先屏蔽掉看下：
@SpringBootApplication(exclude = { RocketMQAutoConfiguration.class })
public class Application {
// ...
@Bean
public RocketMQTemplate rocketMQTemplate() {
// 造一個假的 rocketMQTemplate 避免項目報錯
RocketMQTemplate rocketMQTemplate = new RocketMQTemplate();
rocketMQTemplate.setProducer(new DefaultMQProducer("groupName"));
return rocketMQTemplate;
}
}
重啟項目只需要 20 多秒了，雖然還是慢但至少能接受，可以確定是 RocketMQ 的問題了。而且所有依賴的中間件都是本地部署的，基本可以忽略網(wǎng)絡(luò)問題了（ 后面打臉 ），實在想不通為什么會慢。
解決方法
拿著 rocketMQTemplate 啟動慢 的關(guān)鍵詞去搜問題簡直是大海撈針，不過運氣好找到了一篇文章《 RocketMQ 很慢？引出了一個未解之謎 》， 里面指出了 NetworkInterface.getNetworkInterfaces 這個 JDK 方法的耗時問題 ，本地測試了一下果然如此：
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)用耗時將近 6 秒，不加限制多調(diào)用幾次就能爆炸了?？梢钥匆幌逻@個方法的返回結(jié)果是什么：
光看名字就能聯(lián)想到 控制面板\網(wǎng)絡(luò)和 Internet\網(wǎng)絡(luò)連接 中的 網(wǎng)絡(luò)適配器 ，基本能對上：
之所以有這么多的設(shè)備是因為之前安裝 Genymotion 模擬器的時候 VirtualBox 給安裝上的，因為沒遇到過其他問題也就沒在意，沒想到卻導(dǎo)致了 getNetworkInterfaces 調(diào)用變慢的問題。而 getNetworkInterfaces 方法底層調(diào)用的是 getAll 這個 native 方法，所以代碼層面基本沒得改了，目前 唯一 的 解決方法 就是 把沒用的網(wǎng)絡(luò)適配器都禁用掉 ，最后耗時只要 600 毫秒了（ 不同的網(wǎng)卡耗時程度不同 ），這種程度基本能接受了。
把測試代碼放 VMware 構(gòu)建的純凈系統(tǒng)環(huán)境下又測了一遍，發(fā)現(xiàn)最初調(diào)用只要 31 毫秒，這種程度的耗時才是正常的，難怪以前都沒發(fā)現(xiàn)這個問題，而安裝 Genymotion 后耗時果然就顯著增加了。
回到項目還原代碼驗證一下，啟動時間果然恢復(fù)到正常的 8 秒了。
問題復(fù)盤
這個問題得到解決得虧有人用 RocketMQ 的時候遇到類似的問題，不然就只能不了了之了。不過和別人說 getNetworkInterfaces 方法調(diào)用很慢大概率會被人當(dāng)傻子，比如有人在 RocketMQ 倉庫提過 類似問題 直接被無視了。
xxxProducer和xxxConsumer都繼承 ClientConfig ，因此每實例化一個就會調(diào)用一次getNetworkInterfaces。
繼續(xù)查資料看有沒有方法可以定位耗時的代碼塊，在《 SpringBoot 服務(wù)啟動慢排查思路 》一文中看到了一張 JProfiler 的方法調(diào)用樹截圖，里面清楚標紅了耗時比較長的方法，但是文章中沒有具體的操作步驟，只能自己研究下。
后來才發(fā)現(xiàn)在 JProfiler 幫助文檔 中關(guān)于這部分內(nèi)容已經(jīng)介紹的很詳細了。
操作步驟：
在 IDEA 中用 JProfiler 圖標啟動項目
進 JProfiler 的 bin 目錄啟動主程序 jprofiler.exe
-
Attach > 選擇 背景色標綠 的項目進程 > 開始
配置項一路確定就好了。
許可證密鑰 錯誤會導(dǎo)致 啟動報錯 的，需要選擇 評估 （ 試用 10 天 ）。
修改系統(tǒng)時間后重啟 JProfiler 可以繼續(xù)試用。（ 用完了再把系統(tǒng)時間還原回去 ）
JProfiler> ERROR: Invalid license key. Aborting. JProfiler> Killing process清除已填寫的注冊碼：
cd /d "%USERPROFILE%/.jprofiler13" && del jprofiler_config.xml -
CPU 視圖 > 調(diào)用樹 > 開始記錄
這一步手速要快一點，不然可能會錯過一些重要的調(diào)用過程。當(dāng)然也可以在 會話啟動 的配置窗口中設(shè)置 初始化記錄分析 以自動開始記錄。
JProfiler 會話啟動 -
等待項目啟動完成
JProfiler 分析調(diào)用樹
調(diào)用樹結(jié)果是有了，但坑爹的是展開之后報紅的線索就斷了，基本是 1% 以內(nèi)的正常方法調(diào)用，完全看不到里層的慢方法。點擊工具欄中的 分析 按鈕，將結(jié)果轉(zhuǎn)為火焰圖看下：
可以看到兩側(cè)缺失了一大片的內(nèi)容，說明有一些方法被隱藏了沒記錄在內(nèi)，這時回到調(diào)用樹，注意到每個方法前面的圖標都不太一樣，正好工具欄有一個 顯示圖例 的按鈕，點擊查看內(nèi)容：
這說明部分方法被過濾了，最后在 會話設(shè)置 > 調(diào)用樹過濾器 > 定義過濾器 中發(fā)現(xiàn)默認配置把一堆第三方庫都過濾了：
這里只需要添加被分析的包（ 注意順序，具體配置規(guī)則見 官方文檔 ）即可：
java. // 看情況是否要加
javax.
org.apache.
重啟項目重新開始分析就能得到想要的結(jié)果了：
查看火焰圖效果更直觀，可以看到大部分時間都花費在 getNetworkInterfaces 上了（ 8 次調(diào)用共耗時 37 秒 ），也證實了前面問題定位沒有錯。
其他相關(guān)問題
解決完這個問題忽然想到前段時間碰到的另一個問題：用到 JSP 的項目從 JDK1.8 切換到 JDK11 后，第一次訪問頁面很慢，并有警告日志：
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 的耗時問題 以前在 Docker 容器 中運行 Tomcat 時遇到過，但和這次顯然不是一回事，定位到打日志的代碼：
發(fā)現(xiàn)耗時的地方在 SecureRandom.nextInt() ，只是肉眼去看代碼不好去分析更底層的調(diào)用棧，還好剛學(xué)會了 JProfiler ，分析結(jié)果一目了然，這個問題同樣也是 getNetworkInterfaces 在搗鬼。
至于為什么 JDK1.8 沒問題，由于調(diào)用棧發(fā)生了變化一時也查不出原因，我猜測可能是其他地方（ 可能無法被分析器攔截到 ）提前觸發(fā)了 SecureRandom.SeederHolder 的 static 代碼初始化。比如 debug 模式 運行項目時打斷點發(fā)現(xiàn) sun.management.Agent.startAgent() 中就間接調(diào)用了 SecureRandom 。
