本文已收錄于《JVM生產環境問題定位與解決實戰》專欄,完整系列見文末目錄
引言
在前六篇博客中,我們系統性地學習了 JVM 生產環境問題定位與解決的全套工具鏈,涵蓋jps
、jmap
、jstat
、jstack
、jcmd
等基礎工具的使用技巧,深入剖析了JConsole
、VisualVM
和 MAT
的高級應用場景,探索了JFR
與JMC
的性能分析能力,并解鎖了Arthas
的在線診斷黑科技。為使讀者能將理論知識轉化為實戰能力,筆者將分享三個真實的線上疑難案例:
- OSSClient 未關閉導致的內存泄漏和 CPU 飆升(本篇詳解)
- 正則表達式回溯導致的 CPU 100%
- JVM 內存區域分配不合理導致的頻繁 Full GC
本文將重點解析首個案例,完整展現從現象捕捉、根因定位到方案優化的全鏈路故障排查過程。
案例一:OSSClient泄漏引發的FullGC風暴
問題現象
某日線上系統突現異常:
- 接口響應延遲:TP99從200ms飆升至5s+,部分請求超時失敗
- 資源指標異常:阿里云ECS服務器CPU持續150%+,Load值突破15
- 堆內存告急:Old Gen占用率>99%且持續高位
- GC風暴:每分鐘觸發3-4次Full GC,單次耗時8-10秒,但回收效率近乎為零
排查過程
1. 系統資源監控(TOP命令分析)
通過top
命令快速鎖定異常進程:
top - 14:32:01 up 45 days, 2:15, 3 users, load average: 15.23, 14.87, 13.65
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13749 app 20 0 26.8g 5.2g 34832 S 207.3 34.6 45:32.19 java
關鍵發現:
- Java進程(PID=13749)CPU占用率突破200%
- 物理內存消耗達5.2GB,存在內存泄漏嫌疑
2. 線程級CPU分析(TOP -H 定位高 CPU 線程)
通過top -H -p <pid>
穿透進程查看線程級資源占用:
top -H -p 13749
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17911 app 20 0 12.9g 8.2g 2.3g R 99.6 26.3 45:67.89 java
17912 app 20 0 12.9g 8.2g 2.3g R 97.2 26.3 44:32.10 java
關鍵發現:
-
多個線程(如17911、17912)CPU占用率接近100%
-
將十進制PID轉為十六進制(
printf "%x\n" 17911
=> 45f7)用于線程堆棧分析#轉換為十六進制:printf "%x\n" 17911 # 輸出:45f7printf "%x\n" 17912 # 輸出:45f8
3. 線程堆棧分析(jstack定位GC線程)
運行jstack <pid>
生成線程堆棧快照,在生成的thread_dump.txt中搜索對應的十六進制線程ID,獲取線程快照并定位熱點線程:
jstack 13749 > thread_dump.txt
在thread_dump.txt
中搜索nid=0x45f7
,發現高CPU線程為GC線程:
Locked ownable synchronizers:
- None"VM Thread" os_prio=0 tid=0x00002b71d00ff800 nid=0x45f9 runnable "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00002b71d0023800 nid=0x45f7 runnable "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00002b71d0025800 nid=0x45f8 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00002b71d034f800 nid=0x4870 waiting on condition
結論:
GC線程持續運行,說明JVM在進行高頻率垃圾回收,但老年代空間無法釋放。
4. GC行為監控(jstat動態觀測)
使用jstat -gcutil
監控GC動態:
jstat -gcutil 13749 5000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 0.00 85.58 99.99 93.67 89.78 5525 805.725 1007 9100.289 9906.014
0.00 0.00 100.00 99.99 93.67 89.78 5525 805.725 1008 9100.289 9906.014
0.00 0.00 100.00 99.99 93.67 89.78 5525 805.725 1008 9100.289 9906.014
0.00 0.00 40.57 99.99 93.66 89.78 5525 805.725 1008 9109.816 9915.541
0.00 0.00 71.48 99.99 93.66 89.78 5525 805.725 1008 9109.816 9915.541
0.00 0.00 90.87 99.99 93.66 89.78 5525 805.725 1008 9109.816 9915.541
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1009 9109.816 9915.541
0.00 0.00 30.91 99.99 93.66 89.78 5525 805.725 1009 9118.757 9924.482
0.00 0.00 55.48 99.99 93.66 89.78 5525 805.725 1009 9118.757 9924.482
0.00 0.00 76.63 99.99 93.66 89.78 5525 805.725 1009 9118.757 9924.482
0.00 0.00 97.42 99.99 93.66 89.78 5525 805.725 1009 9118.757 9924.482
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1010 9118.757 9924.482
0.00 0.00 24.04 99.99 93.66 89.78 5525 805.725 1010 9127.980 9933.705
0.00 0.00 68.32 99.99 93.66 89.78 5525 805.725 1010 9127.980 9933.705
0.00 0.00 91.50 99.99 93.66 89.78 5525 805.725 1010 9127.980 9933.705
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1011 9127.980 9933.705
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1011 9127.980 9933.705
0.00 0.00 50.42 99.99 93.66 89.78 5525 805.725 1011 9137.226 9942.951
0.00 0.00 83.94 99.99 93.66 89.78 5525 805.725 1011 9137.226 9942.951
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1012 9137.226 9942.951
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1012 9137.226 9942.951
0.00 0.00 54.98 99.99 93.66 89.78 5525 805.725 1012 9146.092 9951.817
0.00 0.00 85.01 99.99 93.66 89.78 5525 805.725 1012 9146.092 9951.817
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1013 9146.092 9951.817
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1013 9146.092 9951.817
0.00 0.00 51.21 99.99 93.66 89.78 5525 805.725 1013 9155.524 9961.249
0.00 0.00 89.83 99.99 93.66 89.78 5525 805.725 1013 9155.524 9961.249
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1014 9155.524 9961.249
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1014 9155.524 9961.249
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1014 9155.524 9961.249
0.00 0.00 100.00 99.99 93.66 89.78 5525 805.725 1014 9155.524 9961.249
0.00 0.00 88.08 99.99 93.71 89.72 5525 805.725 1014 9174.692 9980.417
0.00 0.00 100.00 99.99 93.71 89.72 5525 805.725 1015 9174.692 9980.417
0.00 0.00 100.00 99.99 93.71 89.72 5525 805.725 1015 9174.692 9980.417
0.00 0.00 57.17 99.99 93.71 89.72 5525 805.725 1015 9187.097 9992.822
0.00 0.00 100.00 99.99 93.71 89.72 5525 805.725 1016 9187.097 9992.822...(持續增長)
關鍵指標解讀:
- O(老年代Old Gen):持續99.99%,Full GC無法回收
- YGC?(年輕代GC事件發生的次數) : 共 5525 次,但最近未增加。
- ?YGCT?(年輕代GC所花費的總時間):805.725 秒,平均每次 Minor GC 耗時約 0.146 秒。
- FGC(Full GC事件發生的次數):Full GC頻率異常,持續增加,這表明 Old 區已滿,垃圾回收器無法有效回收內存。
- FGCT(Full GC所花費的總時間):Full GC總耗時突破9187秒,平均每次 Full GC 耗時約 9.04 秒。
由于 Full GC 會觸發 “Stop-the-World” 機制,導致應用程序暫停,對系統性能造成顯著影響。結合線程堆棧分析和 GC 行為特征,可以判定請求響應延遲的根源在于頻繁的 Full GC。接下來需要深入分析引發 GC 異常的具體原因,例如內存泄漏、對象生命周期管理不當或大對象分配失控等。
5. 堆內存轉儲(jmap生成hprof文件)
使用jmap -dump:live,format=b,file=heap.hprof <pid>
生成堆轉儲文件,以便分析內存占用情況。
jmap -dump:live,format=b,file=heap.hprof 13749
將heap.hprof下載到本地,利用工具進行分析。
6. 內存泄漏分析(MAT深度解析)
使用Eclipse Memory Analyzer(MAT)分析heap.hprof:
Step 1 - Leak Suspects報告
堆轉儲文件可能包含大量對象,MAT 的 Leak Suspects 報告能快速識別潛在的內存泄漏點,因此首先運行此報告。
報告發現大量 org.apache.http.impl.conn.PoolingHttpClientConnectionManager
實例由 com.aliyun.oss.common.comm.IdleConnectionReaper @ 0x6ce2d8388
線程加載,占用 Old
區內存。這提示我們 Full GC
可能與這些對象有關。
Step 2 - Histogram視圖
Leak Suspects
報告指出了 PoolingHttpClientConnectionManager
的內存占用問題,但需要量化具體類及其內存占用比例,因此查看 Histogram
直方圖。在MAT的Overview
頁面,打開Histogram
直方圖,按Retained Heap
(保留堆大小)倒序排序,發現以下類占用大量內存:
org.apache.http.impl.conn.PoolingHttpClientConnectionManager
com.aliyun.oss.common.comm.DefaultServiceClient
其中,DefaultServiceClient
是阿里云OSS SDK中的類,提示問題可能與OSS相關。
Step 3 - 按包分組分析
Histogram
直方圖確認了具體類的內存占用,但是存在大量的基礎類型(如char[]
、String
)和集合的實例,這些通常不是內存泄漏根源,因此按包分組分析,更容易發現項目自定義類。在 Histogram
視圖中,選擇 Group by package
,查看哪些包的類占用內存較多。結果顯示,com.aliyun.oss
包下的類內存占用顯著,確認問題與阿里云OSS組件相關。
Step 4 - 引用鏈追蹤
按包分組基本確認了阿里云 OSS
相關類的內存占用,但需要明確這些對象為何未被 GC
回收,因此分析其引用關系以找到 GC Root
。查看 org.apache.http.impl.conn.PoolingHttpClientConnectionManager
的引用關系,進行 Path To GC Roots -> exclude all phantom/weak/soft etc. references
操作,得到所有強引用的引用路徑。
發現 com.aliyun.oss.common.comm.IdleConnectionReaper @ 0x6ce2d8388
線程持有對這些對象的引用,與 Leak Suspects
報告一致。
Step 5- 查看線程細節
GC Root
指向 IdleConnectionReaper
線程,非項目自定義類。需要了解該線程的角色和行為以判斷其為何持有這些對象,因此查看線程細節。進一步查看IdleConnectionReaper
線程的Thread Detail
。
查看 IdleConnectionReaper
的 Thread Detail
,確認這是一個守護線程,負責管理連接池。
由于 IdleConnectionReaper
是一個守護線程(is Daemon = true
),它作為 JVM 的一個獨立線程運行,且通常不會隨著用戶線程的結束而終止。守護線程本身可以作為 GC Root
,因為 JVM 必須保持其存活以執行后臺任務(如連接池清理)。這意味著由 IdleConnectionReaper
持有的對象(如 PoolingHttpClientConnectionManager
)可能無法通過常規的引用鏈分析直接查到其創建來源,因為這些對象的 GC Root
是守護線程的靜態變量 connectionManagers
,而不是業務代碼中的直接引用。這增加了定位問題代碼的難度,可能需要結合其他工具(如 Arthas
)來追蹤對象的創建路徑.
Step 6 - 分析源碼
Thread Detail
指向了 IdleConnectionReaper.java:78
,確認了是守護線程,但需要通過源碼了解其如何持有 PoolingHttpClientConnectionManager
以及為何未釋放,因此分析相關源碼。
查看 IdleConnectionReaper.java:78
源碼,發現該線程每隔 5 秒檢查一次連接池,關閉過期和空閑時間超過 60 秒的連接。PoolingHttpClientConnectionManager
實例被添加到靜態變量 ArrayList<HttpClientConnectionManager> connectionManagers 中
,通過 registerConnectionManager()
方法添加,通過 removeConnectionManager()
或 shutdown()
方法釋放.
分析得出:程序通過 IdleConnectionReaper
的 registerConnectionManager()
方法創建了大量 PoolingHttpClientConnectionManager
對象,但未通過 removeConnectionManager()
或 shutdown()
方法釋放,導致這些對象無法被 GC 回收。
Step 7- 分析引用關系
源碼分析確認 IdleConnectionReaper
因未調用釋放方法導致內存泄漏,但仍未定位系統中 PoolingHttpClientConnectionManager
的創建來源,因此需要查看其引用關系以追蹤創建點。
在 Histogram
視圖中,右鍵選擇 incoming/outgoing references
查看 PoolingHttpClientConnectionManager
的引用關系,發現 com.aliyun.oss.common.comm.DefaultServiceClient
也與這些對象相關.
Step 8- 進一步分析 DefaultServiceClient
引用關系顯示 DefaultServiceClient
與 PoolingHttpClientConnectionManager
相關,但需要通過源碼確認其如何創建和管理這些對象,因此分析 DefaultServiceClient
源碼。
查看 DefaultServiceClient
源碼,發現其在構造時調用 IdleConnectionReaper.registerConnectionManager()
,在 shutdown()
方法中調用 IdleConnectionReaper.removeConnectionManager()
.
得出結論:項目中創建了大量 DefaultServiceClient
實例,但未調用 shutdown()
方法釋放資源.
Step 9-代碼溯源(Arthas熱診斷)
問題定位的難點:DefaultServiceClient
分析確認了未調用 shutdown()
的問題,但仍需確定具體業務代碼為何創建大量實例,尤其是在系統長期穩定后突然觸發問題,因此需要進一步追蹤。
至此,已基本確定問題是 OSSClient
未關閉導致的資源泄漏,但需要進一步定位具體業務代碼。MAT 分析顯示 PoolingHttpClientConnectionManager
和 DefaultServiceClient
的 GC root
均為 IdleConnectionReaper
的靜態變量 connectionManagers
,且導出堆轉儲時執行了 GC, OSSClient
實例已被回收,難以直接追溯到具體代碼。
MAT 分析受限于 GC Root 和堆轉儲時的 GC 影響,無法直接定位業務代碼。那么有什么方法能定位到 PoolingHttpClientConnectionManager
是如何創建的嗎?
在第五篇文章《JVM生產環境問題定位與解決實戰(五):Arthas——不可錯過的故障診斷利器》中介紹了stack - 輸出當前方法被調用的調用路徑
,很符合我們的需求。
使用 Arthas 的 stack
命令輸出 PoolingHttpClientConnectionManager
構造方法的調用路徑:
stack org.apache.http.impl.conn.PoolingHttpClientConnectionManage
最終定位:新增的批量處理業務邏輯在 com.controller.TestController.createOSSClient(TestController.java:423)
中創建了大量OSSClient實例,使用后未關閉,導致內存泄漏。
問題原因
綜合排查結果,問題根源如下:
- 業務代碼中批處理業務使用OSSClient訪問阿里云OSS時,未調用shutdown()方法釋放資源。
- 每個OSSClient實例關聯一個PoolingHttpClientConnectionManager對象,這些對象被IdleConnectionReaper的靜態變量connectionManagers持有,無法被垃圾回收。
- 大量未釋放的PoolingHttpClientConnectionManager實例占滿老年代,觸發頻繁的Full GC。
- Full GC為“Stop-the-World”事件,導致應用線程暫停,GC線程占用大量CPU,表現為CPU使用率飆升至200%及請求延遲。
優化建議
-
正確釋放資源:確保在使用
OSSClient
后調用shutdown()
。推薦使用try-finally
或try-with-resources(若SDK支持AutoCloseable)
:OSS ossClient = new OSSClientBuilder().build(endpoint, accessKeyId, accessKeySecret); try {ossClient.putObject(bucketName, key, new File("file.txt")); } finally {ossClient.shutdown(); }
-
單例模式優化:如果
OSSClient
需要重復使用,可通過單例模式或連接池管理,避免頻繁創建和銷毀:public class OSSClientHolder {private static final OSS ossClient = new OSSClientBuilder().build(endpoint, accessKeyId, accessKeySecret);public static OSS getOSSClient() {return ossClient;}public static void shutdown() {ossClient.shutdown();} }
驗證
為驗證優化措施的效果,進行了以下實驗:
- createOSSClient:存在問題的原始代碼,未關閉 OSSClient 實例。
- createOSSClient1:優化后的代碼,使用后調用 shutdown() 釋放 OSSClient 實例。
- createOSSClient2:優化后的代碼,采用單例模式管理單一 OSSClient 實例。
實驗環境與流程
- 環境設置:
- 項目啟動時啟用 JVM GC 日志,配置參數為:
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseSerialGC
。 - 使用
jvisualvm
工具連接到 Java 進程進行監控。 - 使用
JMeter
進行1000次并發請求。
- 項目啟動時啟用 JVM GC 日志,配置參數為:
- 測試流程:
-
對三種方法(
createOSSClient
、createOSSClient1
、createOSSClient2
)分別進行 1000 次壓力測試。 -
在 jvisualvm 的抽樣器(Sampler)界面,設置內存監控,并使用正則表達式篩選以下對象:
(org\.apache\.http\.impl\.conn\.PoolingHttpClientConnectionManager|com\.aliyun\.oss\.OSSClient|com\.aliyun\.oss\.common\.comm\.DefaultServiceClient)
-
分析 GC 日志和 jvisualvm 快照,觀察實例數量和 GC 行為。
-
測試結果
createOSSClient(問題代碼)
-
行為:創建 1000 個 PoolingHttpClientConnectionManager、OSSClient 和 DefaultServiceClient 實例。
-
GC 結果:
- OSSClient 實例最終能夠被垃圾回收。
- 由于 IdleConnectionReaper 的靜態引用,PoolingHttpClientConnectionManager 和 DefaultServiceClient 實例無法被回收,,導致內存泄漏。
-
可視化證據:
createOSSClient1(資源清理)
- 行為:創建 1000 個實例,但在使用后調用 shutdown() 釋放 OSSClient 資源。
- GC 結果:
- 經過兩次 Minor GC,所有 1000 個 PoolingHttpClientConnectionManager、OSSClient 和 DefaultServiceClient 實例被完全回收。
- 第一次 GC:
- OSSClient 實例全部回收。
- PoolingHttpClientConnectionManager 和 DefaultServiceClient 部分回收。
- GC 日志:
2025-04-22T17:20:53.987-0800: 776.023: [GC (Allocation Failure) 2025-04-22T17:20:53.987-0800: 776.023: [DefNew: 148740K->17299K(157248K), 0.0224669 secs] 188299K->59312K(506816K), 0.0225411 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
- 可視化證據:
- 第二次 GC:
- 剩余的 PoolingHttpClientConnectionManager 和 DefaultServiceClient 實例全部回收。
- GC 日志:
2025-04-22T17:24:47.531-0800: 1009.572: [GC (Allocation Failure) 2025-04-22T17:24:47.531-0800: 1009.572: [DefNew: 157075K->5760K(157248K), 0.0193343 secs] 199088K->60437K(506816K), 0.0193803 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
createOSSClient2(單例模式)
-
行為:僅創建 1 個 PoolingHttpClientConnectionManager、OSSClient 和 DefaultServiceClient 實例。
-
GC 結果:
- OSSClient 實例在 Minor GC 后被回收。
- 手動觸發 Full GC 后,PoolingHttpClientConnectionManager 和 DefaultServiceClient 仍保留 1 個實例(符合單例模式預期)。
2025-04-22T18:04:12.163-0800: 141.076: [GC (Allocation Failure) 2025-04-22T18:04:12.163-0800: 141.076: [DefNew: 147843K->17471K(157248K), 0.0190248 secs] 186553K->62863K(506816K), 0.0190696 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 2025-04-22T18:04:24.007-0800: 152.920: [Full GC(手動觸發) (System.gc()) 2025-04-22T18:04:24.007-0800: 152.920: [Tenured: 45391K->59618K(349568K), 0.0779813 secs] 74436K->59618K(506816K), [Metaspace: 48021K->48021K(1093632K)], 0.0782380 secs] [Times: user=0.07 sys=0.00, real=0.08 secs]
-
可視化證據:
結論
實驗結果驗證了問題分析和優化建議的正確性:
- 不調用shutdown()會導致內存泄漏:PoolingHttpClientConnectionManager等關鍵組件無法回收
- 正確調用shutdown()可解決問題:所有資源都能被GC正常回收
- 單例模式是更優方案:既能避免資源泄漏,又能減少重復創建開銷
建議在實際項目中:
- 對于短期使用的OSSClient,必須使用try-finally保證關閉
- 對于頻繁使用的場景,推薦使用單例模式管理
- 定期監控JVM內存和GC情況,及早發現潛在問題
附錄:系列目錄
- JVM生產環境問題定位與解決實戰(一):掌握jps、jmap、jstat、jstack、jcmd等基礎工具
- JVM生產環境問題定位與解決實戰(二):JConsole、VisualVM到MAT的高級應用
- JVM生產環境問題定位與解決實戰(三):揭秘Java飛行記錄器(JFR)的強大功能
- JVM生產環境問題定位與解決實戰(四):使用JMC進行JFR性能分析指南
- JVM生產環境問題定位與解決實戰(五):Arthas——不可錯過的故障診斷利器
- JVM生產環境問題定位與解決實戰(六):總結篇——問題定位思路與工具選擇策略
- ?? 當前:JVM 生產環境問題定位與解決實戰(七):實戰篇——OSSClient泄漏引發的FullGC風暴
🔥 下篇預告:《JVM 生產環境問題定位與解決實戰(八):實戰篇——正則表達式回溯導致的 CPU 100%》
🚀 關注作者,獲取實時更新通知!有問題歡迎在評論區交流討論~