Java 應(yīng)用最常見的3個問題排查思路
來源：https://ricstudio.top/archives/java-online-question-probe
本文總結(jié)了一些常見的線上應(yīng)急現(xiàn)象和對應(yīng)排查步驟和工具。分享的主要目的是想讓對線上問題接觸少的同學(xué)有個預(yù)先認(rèn)知，免得在遇到實際問題時手忙腳亂。畢竟作者自己也是從手忙腳亂時走過來的。
只不過這里先提示一下。在線上應(yīng)急過程中要記住，只有一個總體目標(biāo)：盡快恢復(fù)服務(wù)，消除影響。不管處于應(yīng)急的哪個階段，我們首先必須想到的是恢復(fù)問題，恢復(fù)問題不一定能夠定位問題，也不一定有完美的解決方案，也許是通過經(jīng)驗判斷，也許是預(yù)設(shè)開關(guān)等，但都可能讓我們達(dá)到快速恢復(fù)的目的，然后保留部分現(xiàn)場，再去定位問題、解決問題和復(fù)盤。
在大多數(shù)情況下，我們都是先優(yōu)先恢復(fù)服務(wù)，保留下當(dāng)時的異常信息（內(nèi)存dump、線程dump、gc log等等，在緊急情況下甚至可以不用保留，等到事后去復(fù)現(xiàn)），等到服務(wù)正常，再去復(fù)盤問題。
好，現(xiàn)在讓我們進(jìn)入正題吧。
常見現(xiàn)象1：CPU 利用率高/飆升
場景預(yù)設(shè)：
監(jiān)控系統(tǒng)突然告警，提示服務(wù)器負(fù)載異常。
預(yù)先說明：
CPU飆升只是一種現(xiàn)象，其中具體的問題可能有很多種，這里只是借這個現(xiàn)象切入。
注：CPU使用率是衡量系統(tǒng)繁忙程度的重要指標(biāo)。但是CPU使用率的安全閾值是相對的，取決于你的系統(tǒng)的IO密集型還是計算密集型。一般計算密集型應(yīng)用CPU使用率偏高load偏低，IO密集型相反。
常見原因：
頻繁 gc 死循環(huán)、線程阻塞、io wait...etc
模擬
這里為了演示，用一個最簡單的死循環(huán)來模擬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之后，在服務(wù)器上運行。java -jar cpu-reaper.jar &
第一步：定位出問題的線程
方法 a: 傳統(tǒng)的方法
top?定位CPU 最高的進(jìn)程執(zhí)行
top命令，查看所有進(jìn)程占系統(tǒng)CPU的排序，定位是哪個進(jìn)程搞的鬼。在本例中就是咱們的java進(jìn)程。PID那一列就是進(jìn)程號。(對指示符含義不清楚的見【附錄】)
top -Hp pid?定位使用 CPU 最高的線程
printf '0x%x' tid?線程 id 轉(zhuǎn)化 16 進(jìn)制
>?printf?'0x%x'?12817>?0x3211
jstack pid | grep tid?找到線程堆棧
>?jstack?12816?|?grep?0x3211?-A?30
方法 b: show-busy-java-threads
這個腳本來自于github上一個開源項目，項目提供了很多有用的腳本，show-busy-java-threads就是其中的一個。使用這個腳本，可以直接簡化方法A中的繁瑣步驟。如下，
>?wget?--no-check-certificate?https://raw.github.com/oldratlee/useful-scripts/release-2.x/bin/show-busy-java-threads
>?chmod?+x?show-busy-java-threads
>?./show-busy-java-threads
show-busy-java-threads
#?從所有運行的Java進(jìn)程中找出最消耗CPU的線程（缺省5個），打印出其線程棧
#?缺省會自動從所有的Java進(jìn)程中找出最消耗CPU的線程，這樣用更方便
#?當(dāng)然你可以手動指定要分析的Java進(jìn)程Id，以保證只會顯示你關(guān)心的那個Java進(jìn)程的信息
show-busy-java-threads?-p?<指定的Java進(jìn)程Id>
show-busy-java-threads?-c?<要顯示的線程棧數(shù)>
方法 c: arthas?thread
阿里開源的arthas現(xiàn)在已經(jīng)幾乎包攬了我們線上排查問題的工作，提供了一個很完整的工具集。在這個場景中，也只需要一個thread -n命令即可。
>?curl?-O?https://arthas.gitee.io/arthas-boot.jar?#?下載
要注意的是，arthas的cpu占比，和前面兩種cpu占比統(tǒng)計方式不同。前面兩種針對的是Java進(jìn)程啟動開始到現(xiàn)在的cpu占比情況，arthas這種是一段采樣間隔內(nèi)，當(dāng)前JVM里各個線程所占用的cpu時間占總cpu時間的百分比。
具體見官網(wǎng)：https://alibaba.github.io/arthas/thread.html
后續(xù)
通過第一步，找出有問題的代碼之后，觀察到線程棧之后。我們就要根據(jù)具體問題來具體分析。這里舉幾個例子。
情況一：發(fā)現(xiàn)使用CPU最高的都是GC 線程。
GC?task?thread#0?(ParallelGC)"?os_prio=0?tid=0x00007fd99001f800?nid=0x779?runnableGC?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 排查的內(nèi)容較多，所以我決定在后面單獨列一節(jié)講述。
情況二：發(fā)現(xiàn)使用CPU最高的是業(yè)務(wù)線程
io wait 比如此例中，就是因為磁盤空間不夠?qū)е碌膇o阻塞 等待內(nèi)核態(tài)鎖，如 synchronized jstack -l pid | grep BLOCKED?查看阻塞態(tài)線程堆棧dump 線程棧，分析線程持鎖情況。 arthas提供了 thread -b，可以找出當(dāng)前阻塞其他線程的線程。針對 synchronized 情況
常見現(xiàn)象2：頻繁 GC
1. 回顧GC流程
在了解下面內(nèi)容之前，請先花點時間回顧一下GC的整個流程。
接前面的內(nèi)容，這個情況下，我們自然而然想到去查看gc 的具體情況。
方法a : 查看gc 日志 方法b :? jstat -gcutil 進(jìn)程號 統(tǒng)計間隔毫秒 統(tǒng)計次數(shù)（缺省代表一致統(tǒng)計方法c : 如果所在公司有對應(yīng)用進(jìn)行監(jiān)控的組件當(dāng)然更方便（比如Prometheus + Grafana）
這里對開啟 gc log 進(jìn)行補充說明。一個常常被討論的問題（慣性思維）是在生產(chǎn)環(huán)境中GC日志是否應(yīng)該開啟。因為它所產(chǎn)生的開銷通常都非常有限，因此我的答案是需要開啟。但并不一定在啟動JVM時就必須指定GC日志參數(shù)。
HotSpot JVM有一類特別的參數(shù)叫做可管理的參數(shù)。對于這些參數(shù)，可以在運行時修改他們的值。我們這里所討論的所有參數(shù)以及以“PrintGC”開頭的參數(shù)都是可管理的參數(shù)。這樣在任何時候我們都可以開啟或是關(guān)閉GC日志。比如我們可以使用JDK自帶的jinfo工具來設(shè)置這些參數(shù)，或者是通過JMX客戶端調(diào)用
HotSpotDiagnostic MXBean的setVMOption方法來設(shè)置這些參數(shù)。這里再次大贊arthas??，它提供的
vmoption命令可以直接查看，更新VM診斷相關(guān)的參數(shù)。
獲取到gc日志之后，可以上傳到GC easy幫助分析，得到可視化的圖表分析結(jié)果。
2. GC 原因及定位
prommotion failed
從S區(qū)晉升的對象在老年代也放不下導(dǎo)致 FullGC（fgc 回收無效則拋 OOM）。
可能原因：
survivor 區(qū)太小，對象過早進(jìn)入老年代
查看 SurvivorRatio 參數(shù)
大對象分配，沒有足夠的內(nèi)存
dump 堆，profiler/MAT 分析對象占用情況
old 區(qū)存在大量對象
dump 堆，profiler/MAT 分析對象占用情況
你也可以從full GC 的效果來推斷問題，正常情況下，一次full GC應(yīng)該會回收大量內(nèi)存，所以?正常的堆內(nèi)存曲線應(yīng)該是呈鋸齒形。如果你發(fā)現(xiàn)full gc 之后堆內(nèi)存幾乎沒有下降，那么可以推斷：**堆中有大量不能回收的對象且在不停膨脹，使堆的使用占比超過full GC的觸發(fā)閾值，但又回收不掉，導(dǎo)致full GC一直執(zhí)行。換句話來說，可能是內(nèi)存泄露了。
一般來說，GC相關(guān)的異常推斷都需要涉及到內(nèi)存分析，使用jmap之類的工具dump出內(nèi)存快照（或者 Arthas的heapdump）命令，然后使用MAT、JProfiler、JVisualVM等可視化內(nèi)存分析工具。
至于內(nèi)存分析之后的步驟，就需要小伙伴們根據(jù)具體問題具體分析啦。
常見現(xiàn)象3：線程池異常
場景預(yù)設(shè)：
業(yè)務(wù)監(jiān)控突然告警，或者外部反饋提示大量請求執(zhí)行失敗。
異常說明：
Java 線程池以有界隊列的線程池為例，當(dāng)新任務(wù)提交時，如果運行的線程少于 corePoolSize，則創(chuàng)建新線程來處理請求。如果正在運行的線程數(shù)等于 corePoolSize 時，則新任務(wù)被添加到隊列中，直到隊列滿。當(dāng)隊列滿了后，會繼續(xù)開辟新線程來處理任務(wù)，但不超過 maximumPoolSize。當(dāng)任務(wù)隊列滿了并且已開辟了最大線程數(shù)，此時又來了新任務(wù)，ThreadPoolExecutor 會拒絕服務(wù)。
常見問題和原因
這種線程池異常，一般可以通過開發(fā)查看日志查出原因，有以下幾種原因：
下游服務(wù) 響應(yīng)時間（RT）過長
這種情況有可能是因為下游服務(wù)異常導(dǎo)致的，作為消費者我們要設(shè)置合適的超時時間和熔斷降級機制。
另外針對這種情況，一般都要有對應(yīng)的監(jiān)控機制：比如日志監(jiān)控、metrics監(jiān)控告警等，不要等到目標(biāo)用戶感覺到異常，從外部反映進(jìn)來問題才去看日志查。
數(shù)據(jù)庫慢 sql 或者數(shù)據(jù)庫死鎖
查看日志中相關(guān)的關(guān)鍵詞。
Java 代碼死鎖
jstack –l pid | grep -i –E 'BLOCKED | deadlock'
常見問題恢復(fù)
對于上文提到的一些問題，這里總結(jié)了一些恢復(fù)的方法。
- END -
精彩文章推薦：
Jenkins自動化發(fā)布Java項目實戰(zhàn)
Nginx實現(xiàn)高效負(fù)載均衡器就是這么簡單！
部署一套完整的Kubernetes高可用集群（二進(jìn)制）
點亮，服務(wù)器三年不宕機
