業務服務經常假死故障排查


概述

最近遇到線上故障,具體的情況就是后端服務請求一直 pending,服務經常假死重啟。 但是觀察 整個進程CPU + 內存消耗不是特別大, 沒有明顯的資源泄漏情況。

故障回溯

  1. top -p 40872
    查看進程情況,發現沒有明顯的 內存和 CPU使用率過高

  2. top -Hp 40872 查看進程下的所有線程,沒有明顯的線程 CPU + 內存使用率過高

    備注若遇到 某個線程 資源消耗非常高,可以采取把對應的 線程id轉換為十六進制 , 然后在 線程 dump文件查詢具體的行為。
    printf "%x" 進程號

  3. 到此步驟基本確定沒有明顯的內存泄漏和 線程死鎖故障。但是還是得看下 GC 的情況, 因為經常的 FGC 會影響服務的穩定性,導致服務假死。

打印類加載器信息 執行命令 jmap -clstats 36001
此處主要觀察 是否加載了很多自己的業務 class, 若是則需要考慮是否大量違規使用反射 ;需要調優甚至調大元數據區

顯示堆中對象的統計信息 jmap -histo:live 36001
也是執行觀察整個容器中的 對象的分布情況, 主要觀察是否有非常多余的業務對象,若非常多需要考慮優化;
比如很多業務對象是會很快就銷毀的, 需要考慮增大 Eden區, 盡量在 YGC時釋放掉,避免堆積到 old觸發 FGC 。若這些對象就是比如緩存等, 則需要長時間保存,可以適度考慮調大 old區,減少 FGC的次數。

堆棧掃描 jmap -heap 36001 > ./jmapheap.txt 總體來說這個命令非常有用 可以馬上發現是否有明顯的內存泄漏 ;
如下圖所示基本是健康的, 整個 Eden Space、From Space、To Space、PS Old Generation 占用情況還比較合理,沒有明顯的占滿情況。

生成堆轉儲快照dump文件,以hprof二進制格式轉儲Java堆到指定filename的文件中
jmap -dump:format=b,file=./jmapdump2.hprof 6230 以上文件使用 jhat(Java堆分析工具) 分析
以上文件可以 在 https://gceasy.io 工具中直接上傳分析, 本人在使用過程中發現太大沒法打開,后續可以考慮減少導出的大小

生成 dump文件 一共2種方式:
其一,通過上面介紹的 jmap工具生成,可以生成任意一個java進程的dump文件;
其二,通過配置JVM參數生成,選項“-XX:+HeapDumpOnOutOfMemoryError ”和-“XX:HeapDumpPath”所代表的含義就是當程序出現OutofMemory時,將會在相應的目錄下生成一份dump文件,而如果不指定選項“XX:HeapDumpPath”則在當前目錄下生成dump文件。
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/biapp/m.hprof

接下來分析下實時的 GC情況;具體命令可以參考 https://www.cnblogs.com/yjd_hycf_space/p/7755633.html

打印 進程的 GC 明細 jstat -gc 6230 3000 這個命令呈現的具體的大小單位 KB

jstat -gcutil 30996 3000 這個命令展示是每個區域占用百分比

以上可以發現元數據區 已經快占滿了, 觸發了了 5次 FGC , 元數據是有個初始大小的 默認是 28MB , 當超過時會觸發 FGC 回收掉不需要的 class, 然后回收的比例調節上限,所有若知道當前業務占用比較大的元數據區,可以直接設置一個比較大的元數據區
-XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m 減少FGC的次數
改為之后運行下述命令觀察 , 發現 FGC 已經去除了, 證明了猜想

//只查看年輕代的情況
jstat -gcnew 40872 1000 整個年輕代也是運行正常的

以上基本發現 內存 、GC 沒啥問題,故考慮分析下線程堆棧:
執行如下 命令 jstack 12994 > ./jstack.txt
![](https://img2020.cnblogs.com/blog/646712/202112/646712-20211209194802643-391997802.png
結果如下圖所示,發現很多在獲取 Oracle連接時進行堵塞等待,並且出現了業務邏輯顯示,故豁然開朗大概知道是啥問題了, 瓶頸應該是發生在獲取 Oracle的數據庫連接這塊,於是分析下 每個對應的連接數 ;
獲取本進程監聽的端口被連接的連接數: netstat -nat | grep -i "10.xx:12080" | wc -l
67
獲取 Oracle的連接數 : netstat -nat | grep -i "172.xx:1621" | wc -l
57
獲取 vertical的連接數 : netstat -nat | grep -i "172.xxx:5433" | wc -l
17
結果看代碼,整個這個庫的連接數是 20 , 遂發現可以提高數據庫連接數,能緩解這種問題,然后調成 100 上線,觀察下發現效果明顯有些改善,但是隨后又發現了大量的異常 :

上述異常的根本原因就是操作的時候在堵塞資源,導致客戶端的請求直接超時;所以這種情況不是簡單的增大連接數可以解決的了,隨后在上述線程堆棧的提示追蹤到 慢查詢 SQL ,發現該表的 數據量到達的 一億級別, 之前只有幾千萬,並且查詢沒有使用到索引。
然后我們觀察一下基本都是一個查詢從上述表中取出來 幾十條數據,但是耗時到達 3MIN級別,故最終原因是 ORACLE表數據量暴增,慢SQL引起。 由於最終取出來的結果比較少,我們就采取了最終結果緩存 + 替換 Oracle 為 clickhouse OR vertical的解決方案;
基本億級別數據, 篩選某些列 CK 表的話, 幾十MS 就返回了。此處使用我司強大的數據中台,可以秒級配置化將一個 hive數倉數據導入 任意OLAP異構存儲。未來我也會分享下我司關於數據中台的建設實戰。
以上方案上線后就徹底解決上述問題,沒再出現異常。
至於為啥依賴堵塞會導致 服務重啟,可能是因為 Tomcat 連接線程過多,導致服務假死,重啟。

補充說明

  1. 目前 線程堆棧情況有更強大的分析工具 :
    線程分析工具
    以上具體執行的效果如下: 可以快速發現死鎖

  2. netstat -nat 命令詳解
    Proto Recv-Q Send-Q Local Address Foreign Address State

    Local Address 代表被連接的IP , Foreign Address 代表連接着IP State 代表網絡連接狀態,參考如下:
    TCP連接狀態詳解:
    LISTEN: 偵聽來自遠方的TCP端口的連接請求
    SYN-SENT: 再發送連接請求后等待匹配的連接請求
    SYN-RECEIVED:再收到和發送一個連接請求后等待對方對連接請求的確認
    ESTABLISHED: 代表一個打開的連接
    FIN-WAIT-1: 等待遠程TCP連接中斷請求,或先前的連接中斷請求的確認
    FIN-WAIT-2: 從遠程TCP等待連接中斷請求
    CLOSE-WAIT: 等待從本地用戶發來的連接中斷請求
    CLOSING: 等待遠程TCP對連接中斷的確認
    LAST-ACK: 等待原來的發向遠程TCP的連接中斷請求的確認
    TIME-WAIT: 等待足夠的時間以確保遠程TCP接收到連接中斷請求的確認
    CLOSED: 沒有任何連接狀態
    SYN_RECV表示正在等待處理的請求數;
    ESTABLISHED表示正常數據傳輸狀態;
    TIME_WAIT表示處理完畢,等待超時結束的請求數。

友情鏈接比較不錯的資料:
https://mp.weixin.qq.com/s/mDnDjTWereF_ekLG1NNHRQ
https://mp.weixin.qq.com/s/zBfvjq3gry2zsMoMir6oZA
https://www.cnblogs.com/z-sm/p/6745375.html

其他工具

JProfiler :
是一款性能很強的分析工具,也就是 jconsule 界面的升級版,可以高效的分析線程、內存堆棧。並且還可以和 intellij idea wanmei
JOL(即Java Object Layout):OpenJDK提供的庫,用於查看Java對象的內存布局,這個很有用,可以借助它來跟蹤鎖升級等過程:
openJDK源碼:查看 JDK native 方法的實現
strace:跟蹤程序運行過程發起的系統調用
https://fastthread.io:線程棧分析的網站


免責聲明!

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



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