Java進程故障排查(CPU資源占用高,接口響應超時,功能接口停滯等)


故障分析

# 導致系統不可用情況(頻率較大):

    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 "%x\n" 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_name\G

# 詢問研發,確認數據不重要,檢查字段由時間字段,根據時間確認只保留一個月的數據;

> 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

說明:FGCFull 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命令查看到死鎖狀態,則可檢查產生死鎖的線程的具體阻塞點,進而相應處理。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM