Java 應用線上問題排查思路、工具小結

時間 2020-05-01

標籤 java 應用線上問題排查思路工具小結欄目 Java 简体版

原文原文鏈接

原文地址： Java 應用線上問題排查思路、工具小結
原創不易，轉載請註明出處。html

前言

本文總結了一些常見的線上應急現象和對應排查步驟和工具。分享的主要目的是想讓對線上問題接觸少的同窗有個預先認知，省得在遇到實際問題時手忙腳亂。畢竟做者本身也是從手忙腳亂時走過來的。java

只不過這裏先提示一下。在線上應急過程當中要記住，只有一個整體目標：儘快恢復服務，消除影響。無論處於應急的哪一個階段，咱們首先必須想到的是恢復問題，恢復問題不必定可以定位問題，也不必定有完美的解決方案，也許是經過經驗判斷，也許是預設開關等，但均可能讓咱們達到快速恢復的目的，而後保留部分現場，再去定位問題、解決問題和覆盤。git

在大多數狀況下，咱們都是先優先恢復服務，保留下當時的異常信息（內存dump、線程dump、gc log等等，在緊急狀況下甚至能夠不用保留，等到過後去復現），等到服務正常，再去覆盤問題。github

好，如今讓咱們進入正題吧。sql

常見現象：CPU 利用率高/飆升

場景預設：shell

監控系統忽然告警，提示服務器負載異常。數據庫

預先說明：安全

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

這個腳原本自於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進程中找出最消耗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 命令便可。

> curl -O https://arthas.gitee.io/arthas-boot.jar # 下載

要注意的是，arthas的cpu佔比，和前面兩種cpu佔比統計方式不一樣。前面兩種針對的是Java進程啓動開始到如今的cpu佔比狀況，arthas這種是一段採樣間隔內，當前JVM裏各個線程所佔用的cpu時間佔總cpu時間的百分比。
具體見官網：https://alibaba.github.io/art...

後續

經過第一步，找出有問題的代碼以後，觀察到線程棧以後。咱們就要根據具體問題來具體分析。這裏舉幾個例子。

狀況一：發現使用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阻塞
等待內核態鎖，如 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幫助分析，獲得可視化的圖表分析結果。

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'

4、常見問題恢復

這一部份內容參考自此篇文章

對於上文提到的一些問題，這裏總結了一些恢復的方法。

5、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官方文檔。

另外，Arthas裏的還集成了 ognl 這個輕量級的表達式引擎，經過ognl，你能夠用arthas 實現不少的「騷」操做。

其餘的這裏就很少說了，感興趣的能夠去看看arthas的官方文檔、github issue。

6、涉及工具

再說下一些工具。

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 內存分析等等，若是基礎不紮實，看了更多的是一頭霧水。另外就是，多看看網上一些有實際場景的關於異常排查的經驗文章，學習他們解決排查問題的思路和工具。這樣即便本身暫時遇不到，可是會在腦海裏面慢慢總結出一套解決相似問題的結構框架，到時候真的遇到了，也就是舉一反三的事情罷了。

若是本文有幫助到你，但願能點個贊，這是對個人最大動力🤝🤝🤗🤗。

參考

https://developer.aliyun.com/...
Arthas 3.2.0 文檔
《分佈式服務架構：原理、設計與實戰》

附錄

top 命令顯示的指示符的含義

指示符	含義
PID	進程id
USER	進程全部者
PR	進程優先級
NI	nice值。負值表示高優先級，正值表示低優先級
VIRT	進程使用的虛擬內存總量，單位kb。VIRT=SWAP+RES
RES	進程使用的、未被換出的物理內存大小，單位kb。RES=CODE+DATA
SHR	共享內存大小，單位kb
S	進程狀態。D=不可中斷的睡眠狀態 R=運行 S=睡眠 T=跟蹤/中止 Z=殭屍進程
%CPU	上次更新到如今的CPU時間佔用百分比
%MEM	進程使用的物理內存百分比
TIME+	進程使用的CPU時間總計，單位1/100秒
COMMAND	進程名稱（命令名/命令行）