故障分析
# 導致系統不可用情況(頻率較大):
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
說明: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命令查看到死鎖狀態,則可檢查產生死鎖的線程的具體阻塞點,進而相應處理。