原文地址: https://mp.weixin.qq.com/s/xGFUTaeZTLyEvadRTojLjQ
前言
本文總結了一些Java應用線上常見問題的定位步驟,分享的主要目的是想讓對線上問題接觸少的同學有個預先認知,免得在遇到實際問題時手忙腳亂。畢竟作者自己也是從手忙腳亂時走過來的。
只不過這里先提示一下。在線上應急過程中要記住,只有一個總體目標:「盡快恢復服務,消除影響」。不管處於應急的哪個階段,我們首先必須想到的是恢復問題,恢復問題不一定能夠定位問題,也不一定有完美的解決方案,也許是通過經驗判斷,也許是預設開關等,但都可能讓我們達到快速恢復的目的,然后保留部分現場,再去定位問題、解決問題和復盤。
好,現在讓我們進入正題吧。
一、CPU 利用率高/飆升
❝注:CPU使用率是衡量系統繁忙程度的重要指標。但是「CPU使用率的安全閾值是相對的,取決於你的系統的IO密集型還是計算密集型」。一般計算密集型應用CPU使用率偏高load偏低,IO密集型相反。
❞
「常見原因:」
- 頻繁 gc
- 死循環、線程阻塞、io wait...etc
模擬
這里為了演示,用一個最簡單的死循環來模擬CPU飆升的場景,下面是模擬代碼,
在一個最簡單的SpringBoot Web 項目中增加CpuReaper
這個類,
/** * 模擬 cpu 飆升場景 * @author Richard_yyf */ @Component public class CpuReaper { @PostConstruct public void cpuReaper() { int num = 0; long start = System.currentTimeMillis() / 1000; while (true) { num = num + 1; if (num == Integer.MAX_VALUE) { System.out.println("reset"); num = 0; } if ((System.currentTimeMillis() / 1000) - start > 1000) { return; } } } }
打包成jar之后,在服務器上運行。java -jar cpu-reaper.jar &
第一步:定位出問題的線程
方法 a: 傳統的方法
top
定位CPU 最高的進程
執行top
命令,查看所有進程占系統CPU的排序,定位是哪個進程搞的鬼。在本例中就是咱們的java進程。PID那一列就是進程號。
top -Hp pid
定位使用 CPU 最高的線程
printf '0x%x' tid
線程 id 轉化 16 進制
printf '0x%x' 12817 0x3211
jstack pid | grep tid
找到線程堆棧
jstack 12816 | grep 0x3211 -A 30
方法 b: show-busy-java-threads
https://raw.github.com/oldratlee/useful-scripts/release-2.x/bin/show-busy-java-threads
這個腳本來自於github上一個開源項目,項目提供了很多有用的腳本,show-busy-java-threads
就是其中的一個。使用這個腳本,可以直接簡化方法A中的繁瑣步驟。如下,
show-busy-java-threads # 從所有運行的Java進程中找出最消耗CPU的線程(缺省5個),打印出其線程棧 # 缺省會自動從所有的Java進程中找出最消耗CPU的線程,這樣用更方便 # 當然你可以手動指定要分析的Java進程Id,以保證只會顯示你關心的那個Java進程的信息 show-busy-java-threads -p <指定的Java進程Id> show-busy-java-threads -c <要顯示的線程棧數>
方法 c: arthas thread
阿里開源的arthas現在已經幾乎包攬了我們線上排查問題的工作,提供了一個很完整的工具集。在這個場景中,也只需要一個thread -n
命令即可。擴展:阿里問題定位神器 Arthas 操作實踐,定位線上BUG,超給力
https://github.com/alibaba/arthas
curl -O https://arthas.gitee.io/arthas-boot.jar # 下載
要注意的是,arthas的cpu占比,和前面兩種cpu占比統計方式不同。前面兩種針對的是Java進程啟動開始到現在的cpu占比情況,arthas這種是一段采樣間隔內,當前JVM里各個線程所占用的cpu時間占總cpu時間的百分比。 具體見官網:https://alibaba.github.io/arthas/thread.html
后續
通過第一步,找出有問題的代碼之后,觀察到線程棧之后。我們「就要根據具體問題來具體分析」。這里舉幾個例子。
情況一:發現使用CPU最高的都是GC 線程。
GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fd99001f800 nid=0x779 runnable
GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fd990021800 nid=0x77a runnable
GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fd990023000 nid=0x77b runnable
GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fd990025000 nid=0x77c runnabl
gc 排查的內容較多,所以我決定在后面單獨列一節講述。
情況二:發現使用CPU最高的是業務線程
- io wait
- 比如此例中,就是因為磁盤空間不夠導致的io阻塞
https://blog.csdn.net/lonyness/article/details/82628988
- 等待內核態鎖,如 synchronized
jstack -l pid | grep BLOCKED
查看阻塞態線程堆棧- dump 線程棧,分析線程持鎖情況。
- arthas提供了
thread -b
,可以找出當前阻塞其他線程的線程。針對 synchronized 情況
二、頻繁 GC
1. 回顧GC流程
在了解下面內容之前,請先花點時間回顧一下GC的整個流程。
接前面的內容,這個情況下,我們自然而然想到去查看gc 的具體情況。
- 方法a : 查看gc 日志
- 方法b :
jstat -gcutil 進程號 統計間隔毫秒 統計次數(缺省代表一致統計
- 方法c : 如果所在公司有對應用進行監控的組件當然更方便(比如Prometheus + Grafana)
這里對開啟 gc log 進行補充說明。一個常常被討論的問題(慣性思維)是在生產環境中GC日志是否應該開啟。因為它所產生的開銷通常都非常有限,因此我的答案是需要「開啟」。但並不一定在啟動JVM時就必須指定GC日志參數。
❝HotSpot JVM有一類特別的參數叫做可管理的參數。對於這些參數,可以在運行時修改他們的值。我們這里所討論的所有參數以及以“PrintGC”開頭的參數都是可管理的參數。這樣在任何時候我們都可以開啟或是關閉GC日志。比如我們可以使用JDK自帶的jinfo工具來設置這些參數,或者是通過JMX客戶端調用
HotSpotDiagnostic MXBean的
setVMOption方法來設置這些參數。這里再次大贊arthas❤️,它提供的
❞vmoption
命令可以直接查看,更新VM診斷相關的參數。
獲取到gc日志之后,可以上傳到GC easy幫助分析,得到可視化的圖表分析結果。
http://gceasy.io/
2. GC 原因及定位
「prommotion failed」
從S區晉升的對象在老年代也放不下導致 FullGC(fgc 回收無效則拋 OOM)。
可能原因:
-
「survivor 區太小,對象過早進入老年代」
查看 SurvivorRatio 參數
-
「大對象分配,沒有足夠的內存」
dump 堆,profiler/MAT 分析對象占用情況
-
「old 區存在大量對象」
dump 堆,profiler/MAT 分析對象占用情況
你也可以從full GC 的效果來推斷問題,正常情況下,一次full GC應該會回收大量內存,所以 「正常的堆內存曲線應該是呈鋸齒形」。如果你發現full gc 之后堆內存幾乎沒有下降,那么可以推斷:「堆中有大量不能回收的對象且在不停膨脹,使堆的使用占比超過full GC的觸發閾值,但又回收不掉,導致full GC一直執行。「換句話來說,可能是」內存泄露」了。
一般來說,GC相關的異常推斷都需要涉及到「內存分析」,使用jmap
之類的工具dump出內存快照(或者 Arthas的heapdump
)命令,然后使用MAT、JProfiler、JVisualVM等可視化內存分析工具。
至於內存分析之后的步驟,就需要小伙伴們根據具體問題具體分析啦。
三、線程池異常
Java 線程池以有界隊列的線程池為例,當新任務提交時,如果運行的線程少於 corePoolSize,則創建新線程來處理請求。如果正在運行的線程數等於 corePoolSize 時,則新任務被添加到隊列中,直到隊列滿。當隊列滿了后,會繼續開辟新線程來處理任務,但不超過 maximumPoolSize。當任務隊列滿了並且已開辟了最大線程數,此時又來了新任務,ThreadPoolExecutor 會拒絕服務。
常見問題和原因
這種線程池異常,一般有以下幾種原因:
-
「下游服務 響應時間(RT)過長」
這種情況有可能是因為下游服務異常導致的,作為消費者我們要設置合適的超時時間和熔斷降級機制。
另外針對這種情況,一般都要有對應的監控機制:比如日志監控、metrics監控告警等,不要等到目標用戶感覺到異常,從外部反映進來問題才去看日志查。
-
「數據庫慢 sql 或者數據庫死鎖」
查看日志關鍵詞
-
「Java 代碼死鎖」
jstack –l pid | grep -i –E 'BLOCKED | deadlock'
上述前兩種問題的排查辦法,一般都是通過查看日志或者一些監控組件。
四、常見問題恢復
❝這一部分內容參考自此篇文章
https://developer.aliyun.com/article/757655
❞
五、Arthas
這里還是想單獨用一節安利一下Arthas這個工具。
Arthas 是阿里巴巴開源的Java 診斷工具,基於 Java Agent 方式,使用 Instrumentation 方式修改字節碼方式進行 Java 應用診斷。
-
dashboard :系統實時數據面板, 可查看線程,內存,gc 等信息
-
thread :查看當前線程信息,查看線程的堆棧,如查看最繁忙的前 n 線程
-
getstatic:獲取靜態屬性值,如
getstatic className attrName
可用於查看線上開關真實值 -
sc:查看 jvm 已加載類信息,可用於排查 jar 包沖突
-
sm:查看 jvm 已加載類的方法信息
-
jad:反編譯 jvm 加載類信息,排查代碼邏輯沒執行原因
-
logger:查看logger信息,更新logger level
-
watch:觀測方法執行數據,包含出參、入參、異常等
-
trace:方法內部調用時長,並輸出每個節點的耗時,用於性能分析
-
tt:用於記錄方法,並做回放
❝以上內容節選自Arthas官方文檔。
https://alibaba.github.io/arthas/commands.html
❞
另外,Arthas里的 還集成了 ognl 這個輕量級的表達式引擎,通過ognl,你可以用arthas 實現很多的“騷”操作。
其他的這里就不多說了,感興趣的可以去看看arthas的官方文檔、github issue。
六、涉及工具
再說下一些工具。
- Arthas(超級推薦❤️❤️)
- useful-scripts
- GC easy
- Smart Java thread dump analyzer - thread dump analysis in seconds
- PerfMa - Java虛擬機參數/線程dump/內存dump分析
- Linux 命令
- Java N 板斧
- MAT、JProfiler...等可視化內存分析工具
結語
我知道我這篇文章對於線上異常的歸納並不全面,還有「網絡(超時、TCP隊列溢出...)」、堆外內存等很多的異常場景沒有涉及。主要是因為自己接觸很少,沒有深刻體會研究過,強行寫出來免不得會差點意思,更怕的是誤了別人😅。
還有想說的就是,Java 應用線上排查實際非常考究一個人基礎是否扎實、解決問題能力是否過關。比如線程池運行機制、gc分析、Java 內存分析等等,如果基礎不扎實,看了更多的是一頭霧水。另外就是,多看看網上一些好的關於異常排查的經驗文章,這樣即使自己暫時遇不到,但是會在腦海里面慢慢總結出一套解決類似問題的結構框架,到時候真的遇到了,也就是觸類旁通的事情罷了。