Java進程故障排查（CPU資源佔用高，介面響應超時，功能介面停滯等）
- 2019 年 10 月 3 日
- 筆記
故障分析
# 導致系統不可用情況（頻率較大）：
1）程式碼中某個位置讀取數據量較大，導致系統記憶體耗盡，進而出現Full GC次數過多，系統緩慢；
2）程式碼中有比較消耗CPU的操作，導致CPU過高，系統運行緩慢；
# 導致某功能運行緩慢（不至於導致系統不可用）：
3）程式碼某個位置有阻塞性的操作，導致調用整體比較耗時，但出現比較隨機；
4）某執行緒由於某種原因進入WAITTING狀態，此時該功能整體不可用，但無法復現；
5）由於鎖使用不當，導致多個執行緒進入死鎖狀態，導致系統整體比較緩慢。
# 說明
對於後三種情況而言，是具有一定阻塞性操作，CPU和系統記憶體使用情況都不高，但功能卻很慢，所以通過查看資源使用情況是無法查看出具體問題的！
應急處理
### 對於線上系統突然產生的運行緩慢問題，如果導致線上系統不可用。首先要做的是導出jstack和記憶體資訊，重啟伺服器，儘快保證系統的高可用。
### 導出jstack資訊
為避免重複贅述，此操作將在後面的”排查步驟“章節中體現！
### 導出記憶體堆棧資訊
# 查看要導出的Java項目的pid
# jps -l
or
# ps -ef |grep java
# 導出記憶體堆棧資訊
jmap -dump:live,format=b,file=heap8 <pid> # heap8是自定義的文件名
# 運行導出的堆棧文件
# ls
heap8
# hostname -I
10.2.2.162
# jhat -port 9998 heap8
# 瀏覽器訪問http://10.2.2.162:9998/
排查步驟
# 環境說明
因平台做了線上推廣，導致管理平台門戶網頁進統計頁面請求超時，隨進伺服器作業系統查看負載資訊，load average超過了4，負載較大，PID為7163的進程cpu資源佔用較高。
# 定位故障
# 處理思路：
找出CPU佔用率高的執行緒，再通過執行緒棧資訊找出該執行緒當時正在運行的問題程式碼段。
# 操作如下：
# 查看高佔用的”進程”中佔用高的”執行緒”
# top -Hbp 7163 | awk ‘/java/ && $9>50’
# 將16298的執行緒ID轉換為16進位的執行緒ID
# printf “%xn” 16298
3faa
# 通過jvm的jstack查看進程資訊並保存以供研發後續分析
# jstack 7163 | grep “3faa” -C 20 > 7163.log
# 重點說明
通過排查步驟，可得排查問題需要掌握的資訊如下：
1）資源佔用高對應的進程a的PID;
2）進程a對應的資源佔用高且最頻繁的執行緒b的ID；
3）將執行緒b的ID轉換為16進位的ID。
資料庫問題引發的資源佔用過高
## 通過”排查步驟“章節可基本定位問題，後續請見下文！
確認問題及處理
# jstack $pid | grep “3faa” -C 20 # 3faa指的是高佔用進程中的高佔用的執行緒對應的16進位id；
# 查看到是資料庫的問題，排查思路：先列印所有在跑的資料庫執行緒，檢查後發現並跟進情況找到問題表；
# 列印MySQL現有進程資訊文件
# mysql -uroot -p -e “show full processlist” > mysql_full_process.log
# 過濾出查詢最多的表
grep Query mysql_full_process.log
# 統計查詢最多的表的數據量
> use databases_name；
> select count(1) from table_name；
# 結合MySQL日誌資訊，可判斷問題是查詢時間過長導致，排查後發現表未創建索引；
> show create table table_nameG
# 詢問研發，確認數據不重要，檢查欄位由時間欄位，根據時間確認只保留一個月的數據；
> delete from table_name where xxxx_time < ‘2019-07-01 00:00:00’ or xxxx_time is null;
# 創建索引
> alter table table_name add index (device_uuid);
# 確認索引是否創建
> show create table table_name;
總結
處理後進程的CPU佔用降至正常水平，本次排查主要用到了jvm進程查看及dump進程詳細資訊的操作，確認是由資料庫問題導致的原因，並對資料庫進行了清理並創建了索引。
在處理問題後，又查詢了一下資料庫相關問題的優化，通常的優化方法還是添加索引。該方法添加參數具體如下：
innodb_buffer_pool_size=4G
Full GC次數過多
## 通過”排查步驟“章節可基本定位問題，後續請見下文！
確認問題及處理
# 特徵說明
對於Full GC較多的情況，有以下特徵：
1）進程的多個執行緒的CPU使用率都超過100%，通過jstack命令可看到大部分是垃圾回收執行緒；
2）通過jstat查看GC情況，可看到Full GC次數非常多，並數值在不斷增加。
# 3faa指的是高佔用進程中的高佔用的執行緒對應的16進位id；
# jstack $pid | grep “3faa” -C 20
說明：VM Thread指垃圾回收的執行緒。故基本可確定，當前系統緩慢的原因主要是垃圾回收過於頻繁，導致GC停頓時間較長。
# 查看GC情況（1000指間隔1000ms，4指查詢次數）
# jstat -gcutil $pid 1000 4
說明：FGC指Full GC數量，其值一直在增加，圖中顯現高達6783，進一步證實是由於記憶體溢出導致的系統緩慢。
# 因筆者是運維，故確認了問題後，Dump記憶體日誌後交由研發解決程式碼層面問題！
總結
# 對於Full GC次數過大，主要有以下兩種原因：
1）程式碼中一次性獲取大量對象，導致記憶體溢出（可用Eclipse的Mat工具排查）；
2）記憶體佔用不高，但Full GC數值較大，可能是顯示的System.gc()調用GC次數過多，可通過添加 -XX:+DisableExplicitGC 來禁用JVM 對顯示 GC 的響應。
服務不定期出現介面響應緩慢
情況說明
某個介面訪問經常需要3~4s甚至更長時間才能返回。一般而言，其消耗的CPU和記憶體資源不多，通過上述方式排查問題無法行通。
由於介面耗時較長問題不定時出現，導致通過jstack命令得到執行緒訪問的堆棧資訊，根據其資訊也不一定能定位到導致耗時操作的執行緒（概率事件）。
定位思路
在排除網路因素後，通過壓測工具對問題介面不斷加大訪問力度。當該介面中有某個位置是比較耗時的，由於訪問的頻率高，將導致大多數的執行緒都阻塞於該阻塞點。
通過分析多個執行緒日誌，能得到相同的TIMED_WAITING堆棧日誌，基本上就可定位到該介面中較耗時的程式碼的位置。
# 示例
# 程式碼中有比較耗時的阻塞操作，通過壓測工具得到的執行緒堆棧日誌，如下：
說明：由圖可得，多個執行緒都阻塞在了UserController的第18行，說明此時一個阻塞點，也是導致該介面較緩慢的原因。
大總結
# 總體性的分析思路
當Java應用出現問題時，處理步驟如下：
通過 top 命令定位異常進程pid，再 top -Hp <pid> 命令定位出CPU資源佔用較高的執行緒的id，並將其執行緒id轉換為十六進位的表現形式，再通過 jstack <pid> | grep <id> 命令查看日誌資訊，定位具體問題。
# 此處根據日誌資訊分析，可分為兩種情況，如下：
# A情況
A.a）若用戶執行緒正常，則通過該執行緒的堆棧資訊查看比較消耗CPU的具體程式碼區域；
A.b）若是VM Thread，則通過 jstat -gcutil <pid> <interval> <times> 命令查看當前GC狀態，然後通過 jmap -dump:live,format=b,file=<filepath> <pid> 導出當前系統記憶體數據，用Eclipse的Mat工具進行分析，進而針對比較消耗記憶體的程式碼區進行相關優化。
# B情況
若通過top命令查看到CPU和記憶體使用率不高，則可考慮以下三種情況。
B.a）若是不定時出現介面耗時過長，則可通過壓測方式增大阻塞點出現的概率，從而通過jstack命令查看堆棧資訊，找到阻塞點；
B.b）若是某功能訪問時突然出現停滯（異常）狀況，重啟後又正常了，同時也無法復現。此時可通過多次導出jstack日誌的方式，對比並定位出較長時間處於等待狀態的用戶執行緒，再從中篩選出問題執行緒；
B.c）若通過jstack命令查看到死鎖狀態，則可檢查產生死鎖的執行緒的具體阻塞點，進而相應處理。
