Labs 導讀
作為JAVA開發者,在日常工作中經常會碰到Java服務端程序無法響應客戶端的請求,輕則影響用戶體驗,重則會造成重大故障。這種無法響應客戶端的請求就是常說的服務“假死”、“卡住了”。那么,在這種“假死”的背后到底發生了什么事,本該正常響應客戶端請求的進程、線程又在做什么呢?本文帶你來揭曉這一答案。
Part 01、 程序“假死”的跡象
服務端程序卡死之后,最常見的現象是無法響應客戶端請求,結果返回特別慢直至超時。如果是網頁服務,那么用戶會發現該頁面會無法訪問,或者一直加載不出來。
如果此時深入查看Http協議,其返回狀態碼一般是504(Gateway Timeout),提示網關超時。如果該程序對應的進程還在存活在操作系統中,在排除了網絡、服務器問題后,可以認為該程序已經“假死”,無法再繼續提供服務。有些程序在假死后過一段時間可以自己恢復,然而更多的時候需要人工介入重啟程序才能恢復正常。
Part 02、如何定位假死問題
接下來我們看一下當碰到程序假死問題時,應該從哪些方面著手處理,如何快速定位到根本原因。
2.1 常用的工具
工欲善其事必先利其器,我們首先來看下一些常用的診斷問題的工具。
2.1.1 top命令
top命令是linux下常用的性能分析工具,能夠實時顯示系統中各個進程的資源占用狀況,操作系統自帶。在終端中輸入top即可看到正在運行的所有進程占用的CPU、內存、運行時間等,也能夠大致知曉當前服務器的運行狀態。
top命令結果
以上是一張典型的top命令結果圖,可以看出java進程進行占用了 44.7%的內存,118.8%的CPU(多核的CPU使用率會超過100%),但系統1分鐘的平均負載(load average)只有0.92,運行較為穩定。
2.1.2 jstat命令
jstat 是用于監控虛擬機各種運行狀態信息的命令行工具,包括了對Heap size和垃圾回收狀況的監控,由JDK提供。當需要了解JVM的運行狀態時它是首選工具。比如需要每秒查看一次JVM的垃圾回收狀態,可以使用:
jstat -gcutil PID 1000 #注:PID請更換為java進程號
|
jstat命令結果
上圖是進程號為4417的JVM進程的內存使用情況,S0和S1是新生代中幸存區使用比例,E是伊甸園區空間使用比例,O是老年代空間使用比例;YGC是新生代垃圾回收次數,YGCT是新生代垃圾回收總時間;FGC是老年代垃圾回收次數,FGCT是老年代垃圾回收總時間,GCT是垃圾回收總時間。當出現內存不夠用時,O會出現100%,并且FGC和FGCT持續增加,比較容易辨別。
2.1.3 jmap命令
jmap是JDK提供的一個可以生成JVM的堆轉儲快照dump文件的命令行工具。除此以外,jmap命令還可以查看finalize執行隊列、Java堆和方法區的詳細信息,比如空間使用率、當前使用的什么垃圾回收器、分代情況等等。當出現內存問題時,就需要jmap命令將內存堆轉儲成文件進行詳細的分析了。常用的命令如下:
jmap -dump:live,format=b,file=memory.hprof PID
|
該命令將堆轉儲成名為memory.hprof的文件,后續可以使用堆內存分析工具(如Eclipse Memory Analyzer)等進行詳細分析,在此不再展開。
2.1.4 jstack命令
jstack是JDK提供的一個可以生成JVM當前時刻的線程快照信息的命令行工具,可以探查在命令執行那一刻JVM中每個線程都在做什么。在實際使用中,可以每隔10秒鐘執行一次,連續執行幾次再對比分析,實際中的輸出內多會比較多,建議轉存到文件中方便分析。常用的命令如下:
jstack -l PID >> stack.log #結果輸出到stack.log文件中
|
jstack命令部分結果
上圖是jstack命令的部分結果,顯示名為logback-8的線程此刻正在等待狀態,未執行實際的任務。
2.2 診斷三把斧
JVM進程假死其實就是線程不夠用了,忙不過來,用以下三把斧依次施行,基本上能夠覆蓋90%以上場景。
2.2.1 看進程
首先,使用top命令對服務器的負載和進程的資源使用做一個評估。尤其關注top命令中的負載指標和進程的CPU、內存使用率。負載代表服務器的繁忙程度,它綜合了CPU、IO等指標,負載/CPU數 > 1 代表服務器非常繁忙。當系統負載高時,而每一個進程的CPU都不高時,要考慮服務器是否已經過載,比如運行進程過多、IO瓶頸等。當某個進程的CPU使用高時,問題大概率出在該進程中,即可對該進程進行探查。(本文只討論JVM,故進程特指JVM進程)
2.2.2 看內存
使用jstat命令查看JVM的內存狀態。當JVM內存泄漏導致堆內存無法回收、堆內存不夠用從而觸發頻繁的Full GC時,JVM會停頓程序的執行進行全面的垃圾回收(stop the world),此時程序將無法響應請求,GC線程會占用大量的CPU時間。當這種情況發生時,會出現進程CPU使用率很高,接近系統極限。堆內存中老年代空間使用比例接近或達到100%,FGC、FGCT在持續地上升(正常情況下Full GC幾小時甚至幾天才執行一次)。
當判斷為進程因內存問題而一直在Full GC時,可以使用jmap命令將內存dump下來進行進一步的分析,查找內存泄漏的對象,進而進一步找到內存泄漏點。此外,值得注意的一點是如果堆內存本身設得很小,而程序需要的內存又很多,JVM會嘗試去回收內存,也會出現頻繁的Full GC而導致CPU使用率升高的情況。這就需要具體問題具體分析了。
2.2.3 看線程
使用jstack命令查看線程狀態。當操作系統、堆內存都無明顯異常情況下,需要進一步探查每一個線程都在做什么。線程無法處理更多任務,要么是線程都很忙(單核 CPU 100%),要么是都在等待(CPU使用率不高),極少數是處于死鎖狀態,而這些都可以從jstack的命令結果中看出來。
jstack會顯示每個線程當前所處的程序棧。如果多個線程處在同一個程序棧,那么要引起高度注意,可以通過連續幾個間隔10秒左右的jstack結果查看該線程是否一直處于同一位置,如果是那么大概率是卡在了這里。如果是死循環,那么CPU使用率會很高,如果是等待IO,那么CPU使用率會很低。通過卡住的程序棧,可以較容易定位到代碼行并進行進一步的分析了。
Part 03、 案例實戰
了解完基本的理論知識,下面通過實際工作中碰到的案例來使用三把斧進行分析。
3.1 案例一:IO等待
系統表現:界面無響應,請求API也無響應。
看進程:top命令顯示系統負載很低,進程CPU、內存使用也無異常。
看內存:jstat命令顯示堆內存表現正常:
jstat顯示堆內存狀態正常
看線程:jstack命令顯示絕大部分線程都卡在同一個地方:
出現io等待的線程
通過進一步檢查AbstractProvinceServiceImpl.sendPost方法,發現是使用java原生的HttpUrlConnection來實現Http請求的方法,而該方法未設置超時時間,如果被調用方未返回會一直等待。
有缺陷的代碼
至此,問題原因查明:因代碼缺陷,在發起http請求時未設置超時時間,而恰好此時被調用方系統故障,無法及時返回,從而導致線程都卡在這里等待IO,無更多的線程來響應其他請求了。
3.2 案例二:死循環
系統表現:系統響應很慢,api請求有一定的錯誤率。
看進程:top命令顯示系統負載較高(1核CPU),進程CPU達到190%,系統過載。
負載較高,進程CPU使用率較高
看內存:jstat命令顯示堆內存表現正常,無明顯的內存問題。
看線程:多次間隔執行jstack命令,發現一部分進程一直卡在同一個地方:
出現死循環的線程
通過查看相關代碼發現這里有個死循環,當變量cur一直不為null時,程序無法跳出循環。通過更進一步的分析,最終找數據庫中的一條數據其CateParentId是自己,從而觸發這個死循環的bug。
...
while (Objects.nonNull(cur)) {
allCateName.insert(0, "/");
allCateName.insert(0, cur.getCateName());
cur = goodsCatePOMap.get(cur.getCateParentId());
}
...
- 1.
- 2.
- 3.
- 4.
- 5.
- 6.
- 7.
- 8.
- 9.
- 10.
- 11.
Part 04、 總結
對于Java服務端假死,可以通過本文介紹的三把斧,利用一些常用工具來對程序內部的運行狀態進行分析。掌握這個方法后,基本上可以定位到工作中碰到的90%以上的java程序假死問題。下表是對可能的假死原因做一個簡單的歸納總結:
假死原因 |
系統負載 |
進程CPU使用率 |
問題定位方案 |
內存泄漏/內存不夠 |
高 |
高 |
jstat確認內存問題,jmap堆轉儲定位內存問題 |
死循環 |
高 |
高 |
jstat確認內存正常,jstack定位代碼行 |
IO等待 |
低 |
低 |
jstack定位代碼行 |
死鎖 |
低 |
低 |
jstack定位死鎖代碼行 |