今天斷斷續續的收到管理平臺的異常報警,cpu佔用過高和jvm old佔用過高,這個時候趕緊去排查原因,下面記錄了我的排查過程,可能裡面還有不正確的地方,歡迎各位大佬指正,也歡迎大家關於類似的案例一起交流,下面就看我關於這次排查的過程把
cpu使用率過高報警,接近100%
後續又來了jvm old過高報警
首先打開監控平臺看報警節點的cpu使用情況
登錄伺服器找到佔用 cpu過高線程堆棧信息
①通過 top 命令找到佔用cpu最高的 pid[進程id]
定位到pid是 1469
②通過 top -Hp pid 查看進程中佔用cpu過高的 tid[線程id]
③通過 printf '%x/n' tid 把線程id轉化為十六進位
④通過 jstack pid | grep tid -A 30 定位線程堆棧信息
佔用cpu過高的線程有兩個,其中一個是列印異常日誌的(會new 對象),還有gc線程
列印異常堆棧
這個佔用cpu根據堆棧信息就可以定位,看下代碼,可以發現new 對象,且列印全棧信息
其中ExceptionUtils.getFullStackTrace(e) 屬於commons.lang包
可以發現上面兩個方法會創建很多對象且列印堆棧信息佔用內存
gc線程
可以發現佔用cpu過高的線程進行大量的gc
通過 jstat -gcutil pid 時間間隔 查看 jc 信息
可以發現伊甸園區和老年代都已經滿了,且進行了大量的FGC
指標介紹
S0:年輕代第一個倖存區(survivor)使用容量佔用百分比
S1:年輕代第二個倖存區(survivor)使用容量佔用百分比
E:年輕代伊甸園區(eden)使用容量佔用百分比
O:老年代使用容量佔用百分比
P:perm代使用容量佔用百分比
YGC:從應用程式啟動到當前採樣時年輕代gc的次數
YGCT:從應用程式啟動到當前採樣時年輕代gc的時間
FGC:從應用程式啟動到當前採樣時老年代gc的次數
FGCT:從應用程式啟動到當前採樣時老年代gc的時間
GCT:從應用程式啟動到當前採樣時gc總耗時
導出dump文件,使用jdk自帶的jvisualvm.exe分析
使用 jmap -dump:format=b,file=name.dump pid 導出dump文件,一般dump文件會比較大【我的這個2.94G】,然後下載【可以用 sz name.dump】到本地用jvisualvm【jdk自帶的,在bin目錄下】分析
首先看下dump文件的概要
看看這些大對象都是什麼
發現前面幾個大對象都和 ElastaicSearchStatusException對象有關,然後這個管理平臺用到es的地方只有一處,就是做數據漏鬥,記錄廣告檢索在哪些步驟過濾掉,方便產品和運營查看廣告被過濾的原因,然後翻開代碼
其中 RestClientFactory.getRestClient().search(searchRequest)的 search方法一步一步跟進,發現拋ElasticSearchStatusException的地方
其中parseResponseException方法會拋出ElasticSearchStatusException異常,至於這兩個地方具體是哪個步驟拋的,可以繼續研究es代碼判斷或者 遠程debug判定,我這裡先不管了,反正我們能知道es出問題了
其實正是因為這裡拋異常才會導致創建大量對象,因為異常在上面提到的列印異常日誌的地方也會創建對象,老年代佔用過高,導致大量fgc
但es這裡為何會有異常?
我登錄到es的管理平臺查看es的索引,發現有的索引沒有創建,索引的創建是有任務去創建並實時寫入數據的,發現那個任務已經停了。
找到相關的任務重新啟動,並找任務停止的原因,修復,並把丟失的索引創建並修複數據
在異常日誌列印那最好加入流控【用Guava.RateLimiter控制】
top 查看佔用cpu的進程 pid
top -Hp pid 查看進程中佔用cpu過高的線程id tid
printf '%x/n' tid 轉化為十六進位
jstack pid |grep tid的十六進位 -A 30 查看堆棧信息定位
top查看佔用cpu高的進程
jstat -gcutil pid 時間間隔 查看gc狀況
jmap -dump:format=b,file=name.dump pid 導出dump文件
用visualVM分析dump文件
之前寫過的兩篇關於jvm的文章
GC算法和垃圾收集器
內存分配與回收策略