JVM 故障排查實戰指南
在現代軟件開發中，Java 虛擬機（JVM）作為 Java 應用程序運行的基礎平臺，其穩定性和性能直接影響到應用程序的表現。無論是大型企業系統還是小型應用，JVM 的健康狀況都是確保業務連續性的關鍵因素之一。
然而，在實際生產環境中，JVM 時常會遇到各種各樣的問題，如內存泄漏、垃圾回收頻繁、線程死鎖等。這些問題不僅會導致系統響應變慢，甚至可能引發服務中斷，給企業和用戶帶來嚴重損失。
本指南旨在幫助開發者和運維人員快速定位并解決常見的 JVM 故障。我們將從基礎知識入手，逐步深入到具體的故障現象分析與解決方案，希望能夠為讀者提供一套系統的故障排查方法論。
一、前置儲備
1.jstack簡介
jstack是JVM自帶的工具，用于追蹤Java進程線程id的堆棧信息、鎖信息，或者打印core file，遠程調試Java堆棧信息等。
而我們常用的指令則是下面這條:
# 打印對應java進程的堆棧信息
jstack [ option ] pid 對應的option常見選項如下：
-F 當正常輸出的請求不被響應時，強制輸出線程堆棧
-m 如果調用到本地方法的話，可以顯示C/C++的堆棧
-l 除堆棧外，顯示關于鎖的附加信息，在發生死鎖時可以用jstack -l pid來觀察鎖持有情況2.線程狀態復習
在使用jstack排查問題之前，我們必須了解堆棧中的信息，所以我們首先必須復習一下線程中的六大狀態:
- New:線程處于創建但還未啟動的狀態。
- RUNNABLE:RUNNABLE其實是JVM自定義的一種狀態，如果和操作系統的線程狀態進行等價理解的話，RUNNABLE是處于操作系統Running或者Ready狀態，因為CPU在這兩個狀態間的切換幾乎是瞬時的，所以JVM統一用RUNNABLE表示。
- Waiting:線程處于等待喚醒狀態。
- Timed Waiting:在有限時間內線程等待喚醒。
- Blocked:程序等待進入同步區域，等待監視器鎖中，線程處于阻塞狀態。
- Terminated:線程工作完成，處于結束狀態了。
了解過線程狀態后，我們就可以了解一下jstack導出的dump文件中線程會基于這些狀態出現的各種情況:
runnable:線程處于執行中
deadlock:死鎖（重點關注）
blocked:線程被阻塞 （重點關注）
Parked:停止
locked:對象加鎖
waiting:線程正在等待
waiting to lock:等待上鎖
Object.wait():對象等待中
waiting for monitor entry:等待獲取監視器（重點關注）
Waiting on condition:等待資源（重點關注），最常見的情況是線程在等待網絡的讀寫3.MAT(Memory Analyzer)下載安裝
mat下載地址：https://www.eclipse.org/mat/previousReleases.php
為了后續我們可以查看JVM輸出的hprof日志，我們需要下載一個MAT的工具,如下圖所示，選擇更早版本
以筆者為例，筆者就選擇了1.7版本
完成下載后，雙擊下面這個exe文件能打開就說明一切正常
二、詳解線程死鎖問題排查思路
1.問題代碼
如下所示，筆者寫了一段死鎖的代碼，如下所示，然后將其放到服務器中啟動：
@RestController
public class TestController {
private static Logger logger = LoggerFactory.getLogger(TestController.class);
private Object lock1 = new Object();
private Object lock2 = new Object();
/**
* 模擬一個線程死鎖的請求
*
* @return
*/
@GetMapping("deadLock")
public String deadLock() throws Exception {
Thread t1 = new Thread(() -> {
logger.info("線程1開始工作，先獲取鎖1");
synchronized (lock1) {
try {
Thread.sleep(3000);
} catch (InterruptedException e) {
e.printStackTrace();
}
logger.info("線程1獲得鎖1，嘗試獲得鎖2");
synchronized (lock2) {
logger.info("線程1獲得鎖2成功");
}
}
});
Thread t2 = new Thread(() -> {
logger.info("線程2開始工作，先獲取鎖2");
synchronized (lock2) {
try {
Thread.sleep(3000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lock1) {
logger.info("線程2獲得鎖1成功");
}
}
});
t1.setName("my-thread-1");
t2.setName("my-thread-2");
t1.join();
t2.join();
t1.start();
t2.start();
return "success";
}
}2.復現問題
由于這只是一個demo，我們日常發現這種問題的時候大概率是多線程中的業務沒有結束，所以重現問題也很簡單，通過命令調用一下接口即可
curl http://localhost:8888/deadLock3.排查思路
首先確定當前發生死鎖的java應用，我們通過jps確定進程id,可以看到筆者服務器的進程id為23334，然后通過jstack -l查看鎖以及鎖的附加信息：
jstack -l 23334最終可以在jstack的最下方看到這樣一段信息(Found one Java-level deadlock)，由此確認出現my-thread-1持有0x00000000ec509610等待0x00000000ec509620，my-thread-2反之。
然后我們通過jstack信息即可定位到問題代碼在TestController.java:53以及TestController.java:37。
Found one Java-level deadlock:
=============================
"my-thread-2":
waiting to lock monitor 0x00007f2800ac9318 (object 0x00000000ec509610, a java.lang.Object),
which is held by "my-thread-1"
"my-thread-1":
waiting to lock monitor 0x00007f27e40062c8 (object 0x00000000ec509620, a java.lang.Object),
which is held by "my-thread-2"
Java stack information for the threads listed above:
===================================================
"my-thread-2":
at com.example.jstackTest.TestController.lambda$deadLock$1(TestController.java:53)
- waiting to lock <0x00000000ec509610> (a java.lang.Object)
- locked <0x00000000ec509620> (a java.lang.Object)
at com.example.jstackTest.TestController$$Lambda$582/2089009876.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
"my-thread-1":
at com.example.jstackTest.TestController.lambda$deadLock$0(TestController.java:37)
- waiting to lock <0x00000000ec509620> (a java.lang.Object)
- locked <0x00000000ec509610> (a java.lang.Object)
at com.example.jstackTest.TestController$$Lambda$581/1994255298.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
Found 1 deadlock.三、詳解CPU 飆升問題排查思路
1.問題復現
導致CPU 100%的原因有很多，一般來說都是編碼不當導致的，所以常規的排查思路為:
- 定位進程號，如果是Java進程則查看是哪個線程導致的。
- 定位導致CPU 飆升的線程號，轉為16進制。
- 導致JVM鎖信息日志，使用線程號定位代碼。
- 排查并修復代碼問題。
首先筆者準備了一個導致CPU飆升的問題代碼，可以看到線程池中的線程不會停止不斷工作
private ExecutorService threadPool = Executors.newFixedThreadPool(100);
private static Object lock = new Object();
private static Logger logger = LoggerFactory.getLogger(TestController.class);
public TestController() {
}
@GetMapping({"/test"})
public void test() {
for(int i = 0; i < 100; ++i) {
this.threadPool.execute(() -> {
logger.info("加法線程開始工作");
long sum = 0L;
Object var2 = lock;
synchronized(lock){}
try {
while(true) {
sum += 0L;
}
} finally {
;
}
});
}
}然后我們發起請求：
curl http://localhost:9550/test2.排查過程
此時使用top命令查看，可以看到24411號進程CPU占用百分比飆升。此時我們就需要進一步定位這個進程的哪一個線程出問題了。
所以我們需要進一步定位這個問題是哪一個線程導致的，命令如下所示，使用線程模式查看對應pid的線程情況
top -Hp 24411可以看到25321這個線程CPU占用過高，此時我們就可以通過thread dump定位導致問題的代碼段
鍵入jstack -l 24411 >/tmp/log.txt到處日志，然后將線程號25321轉為16進制，這里筆者使用了一個在線的網站地址
16進制轉換：https://www.sojson.com/hexconvert.html
可以看到25321轉換為16進制值為62e9,所以我們就使用62e9到導出的日志文件中查看這個線程堆棧情況。
使用轉換的值從剛剛導出的日志中定位，可以看到該線程處于運行狀態，很明顯這個線程一直處于運行中，有一段邏輯肯定在不停的消耗CPU資源，所以我們查看代碼位置在TestController.java:32，由此得到問題代碼并修復問題。
四、詳解OOM問題排查思路
1.復現問題
出現OOM問題大抵是有兩個原因:
- 大流量導致服務器創建大量的對象把內存打爆了，面對這種情況我們除了熔斷以外別無他法。
- 程序編寫不規范導致，大流量情況下出現垃圾內存進而出現OOM，筆者本地探討的就是這種情況。
如下所示，筆者初始化了一個程序，創建一個線程池，模擬無數個線程池將不斷將內存寫入4M的數據，并且不清理。
RestController
public class TestController {
final static ThreadPoolExecutor poolExecutor = new ThreadPoolExecutor(100, 100, 1, TimeUnit.MINUTES,
new LinkedBlockingQueue<>());// 創建線程池，通過線程池，保證創建的線程存活
final static ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();// 聲明本地變量
@RequestMapping(value = "/test0")
public String test0(HttpServletRequest request) {
poolExecutor.execute(() -> {
Byte[] c = new Byte[4* 1024* 1024];
localVariable.set(c);// 為線程添加變量
});
return "success";
}
}完成后部署到服務器上，并使用以下命令啟動，可以看到筆者調整的jvm堆內存大小(筆者服務器內存為1g故這里設置為100m)，以及設置OOM輸出參數
java -jar -Xms100m -Xmx100m # 調整堆內存大小
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof # 表示發生OOM時輸出日志文件，指定path為/tmp/heapdump.hprof
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/tmp/heapTest.log # 打印日志、gc時間以及指定gc日志的路徑
demo-0.0.1-SNAPSHOT.jar完成后我們啟動項目使用HTTP接口請求工具進行壓測，可以看到服務器不久之后就出現了OOM問題：
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /tmp/heapdump.hprof ...
Heap dump file created [151939570 bytes in 1.112 secs]
Exception in thread "pool-1-thread-5" java.lang.OutOfMemoryError: Java heap space
at com.example.jstackTest.TestController.lambda$test0$0(TestController.java:25)
at com.example.jstackTest.TestController$$Lambda$582/394910033.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-7" java.lang.OutOfMemoryError: Java heap space
at com.example.jstackTest.TestController.lambda$test0$0(TestController.java:25)
at com.example.jstackTest.TestController$$Lambda$582/394910033.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Exception in thread "pool-1-thread-9" java.lang.OutOfMemoryError: Java heap space2.排查思路
我們直接鎖定java進程號之后，使用top -Hp pid查看進程的線程信息,可以看到這里面的每一個線程基本都把堆區內存打滿了，我們不妨查看任意一個線程:
我們首先使用jstack -l 3721將日志導出，這里就以3873轉為16進制查看線程狀態，可以發現線程處于等待狀態，而且日志中并沒有存在死鎖的信息，所以我們必須進一步查看堆區情況確認是否是因為內存泄漏導致的。
然后使用jmap查看堆區使用情況：
jmap -heap 3721從下面的日志可以看出老年代使用率高達82%，很明顯有一些長期沒有釋放的對象在內存中導致OOM問題。
我們從上文設置的oom日志路徑中找到日志/tmp/heapdump.hprof，導出到本地，使用MAT打開,找到使用率最高的Byte數組，點擊下圖Histogram ，點擊內存占用最高的選項展開。
這里補充一下截圖中看到的兩個選項:
- with incoming references: 表示的是 當前查看的對象,被外部的應用。
- with outGoing references: 表示的是 當前對象，引用了外部對象。
所以我們的選擇with incoming reference:
可以定位到就是我們一個線程池中的threadLocal使用不當導致OOM問題了
小結
通過本指南的學習，我們希望讀者能夠對 JVM 的內部機制有更深入的理解，并掌握一系列有效的故障排查方法和工具。JVM 作為 Java 應用程序的核心組件，其穩定性和性能對于業務的成功至關重要。
在實際工作中，面對復雜的生產環境和多變的應用需求，僅僅依賴于理論知識是遠遠不夠的。因此，我們鼓勵讀者在實踐中不斷積累經驗，結合實際情況靈活運用所學的知識和技術。只有這樣，才能在遇到問題時迅速定位并解決問題，確保系統的高效運行。
