JVM 故障排查實(shí)戰(zhàn)指南
在現(xiàn)代軟件開發(fā)中，Java 虛擬機(jī)（JVM）作為 Java 應(yīng)用程序運(yùn)行的基礎(chǔ)平臺，其穩(wěn)定性和性能直接影響到應(yīng)用程序的表現(xiàn)。無論是大型企業(yè)系統(tǒng)還是小型應(yīng)用，JVM 的健康狀況都是確保業(yè)務(wù)連續(xù)性的關(guān)鍵因素之一。
然而，在實(shí)際生產(chǎn)環(huán)境中，JVM 時(shí)常會遇到各種各樣的問題，如內(nèi)存泄漏、垃圾回收頻繁、線程死鎖等。這些問題不僅會導(dǎo)致系統(tǒng)響應(yīng)變慢，甚至可能引發(fā)服務(wù)中斷，給企業(yè)和用戶帶來嚴(yán)重?fù)p失。
本指南旨在幫助開發(fā)者和運(yùn)維人員快速定位并解決常見的 JVM 故障。我們將從基礎(chǔ)知識入手，逐步深入到具體的故障現(xiàn)象分析與解決方案，希望能夠?yàn)樽x者提供一套系統(tǒng)的故障排查方法論。
一、前置儲備
1.jstack簡介
jstack是JVM自帶的工具，用于追蹤Java進(jìn)程線程id的堆棧信息、鎖信息，或者打印core file，遠(yuǎn)程調(diào)試Java堆棧信息等。
而我們常用的指令則是下面這條:
# 打印對應(yīng)java進(jìn)程的堆棧信息
jstack [ option ] pid 對應(yīng)的option常見選項(xiàng)如下：
-F 當(dāng)正常輸出的請求不被響應(yīng)時(shí)，強(qiáng)制輸出線程堆棧
-m 如果調(diào)用到本地方法的話，可以顯示C/C++的堆棧
-l 除堆棧外，顯示關(guān)于鎖的附加信息，在發(fā)生死鎖時(shí)可以用jstack -l pid來觀察鎖持有情況2.線程狀態(tài)復(fù)習(xí)
在使用jstack排查問題之前，我們必須了解堆棧中的信息，所以我們首先必須復(fù)習(xí)一下線程中的六大狀態(tài):
- New:線程處于創(chuàng)建但還未啟動的狀態(tài)。
- RUNNABLE:RUNNABLE其實(shí)是JVM自定義的一種狀態(tài)，如果和操作系統(tǒng)的線程狀態(tài)進(jìn)行等價(jià)理解的話，RUNNABLE是處于操作系統(tǒng)Running或者Ready狀態(tài)，因?yàn)镃PU在這兩個狀態(tài)間的切換幾乎是瞬時(shí)的，所以JVM統(tǒng)一用RUNNABLE表示。
- Waiting:線程處于等待喚醒狀態(tài)。
- Timed Waiting:在有限時(shí)間內(nèi)線程等待喚醒。
- Blocked:程序等待進(jìn)入同步區(qū)域，等待監(jiān)視器鎖中，線程處于阻塞狀態(tài)。
- Terminated:線程工作完成，處于結(jié)束狀態(tài)了。
了解過線程狀態(tài)后，我們就可以了解一下jstack導(dǎo)出的dump文件中線程會基于這些狀態(tài)出現(xiàn)的各種情況:
runnable:線程處于執(zhí)行中
deadlock:死鎖（重點(diǎn)關(guān)注）
blocked:線程被阻塞 （重點(diǎn)關(guān)注）
Parked:停止
locked:對象加鎖
waiting:線程正在等待
waiting to lock:等待上鎖
Object.wait():對象等待中
waiting for monitor entry:等待獲取監(jiān)視器（重點(diǎn)關(guān)注）
Waiting on condition:等待資源（重點(diǎn)關(guān)注），最常見的情況是線程在等待網(wǎng)絡(luò)的讀寫3.MAT(Memory Analyzer)下載安裝
mat下載地址：https://www.eclipse.org/mat/previousReleases.php
為了后續(xù)我們可以查看JVM輸出的hprof日志，我們需要下載一個MAT的工具,如下圖所示，選擇更早版本
以筆者為例，筆者就選擇了1.7版本
完成下載后，雙擊下面這個exe文件能打開就說明一切正常
二、詳解線程死鎖問題排查思路
1.問題代碼
如下所示，筆者寫了一段死鎖的代碼，如下所示，然后將其放到服務(wù)器中啟動：
@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.復(fù)現(xiàn)問題
由于這只是一個demo，我們?nèi)粘０l(fā)現(xiàn)這種問題的時(shí)候大概率是多線程中的業(yè)務(wù)沒有結(jié)束，所以重現(xiàn)問題也很簡單，通過命令調(diào)用一下接口即可
curl http://localhost:8888/deadLock3.排查思路
首先確定當(dāng)前發(fā)生死鎖的java應(yīng)用，我們通過jps確定進(jìn)程id,可以看到筆者服務(wù)器的進(jìn)程id為23334，然后通過jstack -l查看鎖以及鎖的附加信息：
jstack -l 23334最終可以在jstack的最下方看到這樣一段信息(Found one Java-level deadlock)，由此確認(rèn)出現(xiàn)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.問題復(fù)現(xiàn)
導(dǎo)致CPU 100%的原因有很多，一般來說都是編碼不當(dāng)導(dǎo)致的，所以常規(guī)的排查思路為:
- 定位進(jìn)程號，如果是Java進(jìn)程則查看是哪個線程導(dǎo)致的。
- 定位導(dǎo)致CPU 飆升的線程號，轉(zhuǎn)為16進(jìn)制。
- 導(dǎo)致JVM鎖信息日志，使用線程號定位代碼。
- 排查并修復(fù)代碼問題。
首先筆者準(zhǔn)備了一個導(dǎo)致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 {
;
}
});
}
}然后我們發(fā)起請求：
curl http://localhost:9550/test2.排查過程
此時(shí)使用top命令查看，可以看到24411號進(jìn)程CPU占用百分比飆升。此時(shí)我們就需要進(jìn)一步定位這個進(jìn)程的哪一個線程出問題了。
所以我們需要進(jìn)一步定位這個問題是哪一個線程導(dǎo)致的，命令如下所示，使用線程模式查看對應(yīng)pid的線程情況
top -Hp 24411可以看到25321這個線程CPU占用過高，此時(shí)我們就可以通過thread dump定位導(dǎo)致問題的代碼段
鍵入jstack -l 24411 >/tmp/log.txt到處日志，然后將線程號25321轉(zhuǎn)為16進(jìn)制，這里筆者使用了一個在線的網(wǎng)站地址
16進(jìn)制轉(zhuǎn)換：https://www.sojson.com/hexconvert.html
可以看到25321轉(zhuǎn)換為16進(jìn)制值為62e9,所以我們就使用62e9到導(dǎo)出的日志文件中查看這個線程堆棧情況。
使用轉(zhuǎn)換的值從剛剛導(dǎo)出的日志中定位，可以看到該線程處于運(yùn)行狀態(tài)，很明顯這個線程一直處于運(yùn)行中，有一段邏輯肯定在不停的消耗CPU資源，所以我們查看代碼位置在TestController.java:32，由此得到問題代碼并修復(fù)問題。
四、詳解OOM問題排查思路
1.復(fù)現(xiàn)問題
出現(xiàn)OOM問題大抵是有兩個原因:
- 大流量導(dǎo)致服務(wù)器創(chuàng)建大量的對象把內(nèi)存打爆了，面對這種情況我們除了熔斷以外別無他法。
- 程序編寫不規(guī)范導(dǎo)致，大流量情況下出現(xiàn)垃圾內(nèi)存進(jìn)而出現(xiàn)OOM，筆者本地探討的就是這種情況。
如下所示，筆者初始化了一個程序，創(chuàng)建一個線程池，模擬無數(shù)個線程池將不斷將內(nèi)存寫入4M的數(shù)據(jù)，并且不清理。
RestController
public class TestController {
final static ThreadPoolExecutor poolExecutor = new ThreadPoolExecutor(100, 100, 1, TimeUnit.MINUTES,
new LinkedBlockingQueue<>());// 創(chuàng)建線程池，通過線程池，保證創(chuàng)建的線程存活
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";
}
}完成后部署到服務(wù)器上，并使用以下命令啟動，可以看到筆者調(diào)整的jvm堆內(nèi)存大小(筆者服務(wù)器內(nèi)存為1g故這里設(shè)置為100m)，以及設(shè)置OOM輸出參數(shù)
java -jar -Xms100m -Xmx100m # 調(diào)整堆內(nèi)存大小
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof # 表示發(fā)生OOM時(shí)輸出日志文件，指定path為/tmp/heapdump.hprof
-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/tmp/heapTest.log # 打印日志、gc時(shí)間以及指定gc日志的路徑
demo-0.0.1-SNAPSHOT.jar完成后我們啟動項(xiàng)目使用HTTP接口請求工具進(jìn)行壓測，可以看到服務(wù)器不久之后就出現(xiàn)了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進(jìn)程號之后，使用top -Hp pid查看進(jìn)程的線程信息,可以看到這里面的每一個線程基本都把堆區(qū)內(nèi)存打滿了，我們不妨查看任意一個線程:
我們首先使用jstack -l 3721將日志導(dǎo)出，這里就以3873轉(zhuǎn)為16進(jìn)制查看線程狀態(tài)，可以發(fā)現(xiàn)線程處于等待狀態(tài)，而且日志中并沒有存在死鎖的信息，所以我們必須進(jìn)一步查看堆區(qū)情況確認(rèn)是否是因?yàn)閮?nèi)存泄漏導(dǎo)致的。
然后使用jmap查看堆區(qū)使用情況：
jmap -heap 3721從下面的日志可以看出老年代使用率高達(dá)82%，很明顯有一些長期沒有釋放的對象在內(nèi)存中導(dǎo)致OOM問題。
我們從上文設(shè)置的oom日志路徑中找到日志/tmp/heapdump.hprof，導(dǎo)出到本地，使用MAT打開,找到使用率最高的Byte數(shù)組，點(diǎn)擊下圖Histogram ，點(diǎn)擊內(nèi)存占用最高的選項(xiàng)展開。
這里補(bǔ)充一下截圖中看到的兩個選項(xiàng):
- with incoming references: 表示的是 當(dāng)前查看的對象,被外部的應(yīng)用。
- with outGoing references: 表示的是 當(dāng)前對象，引用了外部對象。
所以我們的選擇with incoming reference:
可以定位到就是我們一個線程池中的threadLocal使用不當(dāng)導(dǎo)致OOM問題了
小結(jié)
通過本指南的學(xué)習(xí)，我們希望讀者能夠?qū)?JVM 的內(nèi)部機(jī)制有更深入的理解，并掌握一系列有效的故障排查方法和工具。JVM 作為 Java 應(yīng)用程序的核心組件，其穩(wěn)定性和性能對于業(yè)務(wù)的成功至關(guān)重要。
在實(shí)際工作中，面對復(fù)雜的生產(chǎn)環(huán)境和多變的應(yīng)用需求，僅僅依賴于理論知識是遠(yuǎn)遠(yuǎn)不夠的。因此，我們鼓勵讀者在實(shí)踐中不斷積累經(jīng)驗(yàn)，結(jié)合實(shí)際情況靈活運(yùn)用所學(xué)的知識和技術(shù)。只有這樣，才能在遇到問題時(shí)迅速定位并解決問題，確保系統(tǒng)的高效運(yùn)行。
