JVM 排查問題實戰

經過使用 JVM 自帶的工具 jstack，jmap，jstat 排查java程序佔用內存或cpu負載太高的問題。

理論部分

jstack - Prints Java thread stack traces for a Java process, core file, or remote debug server.

打印線程堆棧信息

命令行使用：

jstack <pid> 獲取到 jvm 進程的全部堆棧信息

 

jmap - Prints shared object memory maps or heap memory details for a process, core file, or remote debug server.

打印內存中的對象以及堆內存信息

命令行使用：

jmap -heap <pid> 獲取 jvm 進程的堆內存配置以及使用狀況

jmap -histo <pid> 獲取 jvm 進程的在內存中建立的對象數量

jmap -dump:format=b,file=heap.bin <pid> 導出內存文件，這個文件能夠經過導入eclipse的MemoryAnalyzer來分析

 

jstat - Monitors Java Virtual Machine (JVM) statistics.

監控 jvm 獲取一些統計信息，classloader，compiler，gc相關

命令行使用：

jstat [option] <pid>

參數列表(上面那個 option)：

-class：統計class loader行爲信息 
-compile：統計編譯行爲信息 
-gc：統計jdk gc時heap信息 
-gccapacity：統計不一樣的generations（不知道怎麼翻譯好，包括新生區，老年區，permanent區）相應的heap容量狀況 
-gccause：統計gc的狀況，（同-gcutil）和引發gc的事件 
-gcnew：統計gc時，新生代的狀況 
-gcnewcapacity：統計gc時，新生代heap容量 
-gcold：統計gc時，老年區的狀況 
-gcoldcapacity：統計gc時，老年區heap容量 
-gcpermcapacity：統計gc時，permanent區heap容量 
-gcutil：統計gc時，heap狀況

輸出內容：

S0  — Heap上的 Survivor space 0 區已使用空間的百分比 
S0C：S0當前容量的大小 
S0U：S0已經使用的大小 
S1  — Heap上的 Survivor space 1 區已使用空間的百分比 
S1C：S1當前容量的大小 
S1U：S1已經使用的大小 
E   — Heap上的 Eden space 區已使用空間的百分比 
EC：Eden space當前容量的大小 
EU：Eden space已經使用的大小 
O   — Heap上的 Old space 區已使用空間的百分比 
OC：Old space當前容量的大小 
OU：Old space已經使用的大小 
P   — Perm space 區已使用空間的百分比 
OC：Perm space當前容量的大小 
OU：Perm space已經使用的大小 
YGC — 從應用程序啓動到採樣時發生 Young GC 的次數 
YGCT– 從應用程序啓動到採樣時 Young GC 所用的時間(單位秒) 
FGC — 從應用程序啓動到採樣時發生 Full GC 的次數 
FGCT– 從應用程序啓動到採樣時 Full GC 所用的時間(單位秒) 
GCT — 從應用程序啓動到採樣時用於垃圾回收的總時間(單位秒)，它的值等於YGC+FGC 

 

實戰部分

線上環境存在一臺服務器（centos 7）cpu使用率一直處於報警狀態。

在使用上面3個命令的時候若是出現

Error attaching to process: sun.jvm.hotspot.runtime.VMVersionMismatchException: Supported vertion are 25.65-b01. Target VM is 25.121-b13

說明工具的版本和啓動程序的jvm版本不一致，去oracle官網下載對應版本的jdk工具 傳送門，我使用的是jdk1.8 紅色部分是須要下載的小的版本 號 即jdk1.8_121

 

使用 top 命令查看cpu使用率

發現一個 pid 爲 30996 的cpu使用率特別高，再次使用 top -Hp 30996 命令查看這個進程的線程使用狀況

31036 這個就是有問題的線程，使用 printf "%x\n" 31036 轉換成16進制（下面有用）

接着就可使用 jstack 命令查看這個線程的堆棧狀況 jstack 30996 | grep -A 10 793c (30996是剛纔查到有問題的進程 793c爲16進制線程號 grep -A 10 爲查到793c那一行以後向下再打印10行)

這個 nid=0x793c 的 Thread-14 線程就是問題線程，屢次執行命令查看以後發現代碼一直運行在 MasterEngine.java 48行。而後就能夠去查看代碼了。

看上去在迭代一個map，循環刪除。

再看下其餘地方

執行 jmap -histo 30996 | head -n 20 看下內存中建立類top20的狀況

連續調用4次發現 java.util.concurrent.ConcurrentHashMap$EntryIterator 實例數量在不斷增大而後忽然又變小了。猜想是實例被 gc 快速回收掉了。

那麼再用 jstat -gcutil 30996 2000 20 看下 gc 執行狀況 （2000 200 是指每隔2秒執行一次 一共執行20次）

看YGC這一列（從右邊往左第五列），young gc 執行了 2千8百萬屢次。

再用 gccapacity 參數看一下堆的狀況

只有Eden space （第6列）的大小在發生變化

再看下 jvm 堆的配置狀況 jmap -heap 30996

配置了最大堆大小（MaxHeapSize）是 4g，Eden Space 45%， From Space 18%，To Space 0%，Old Generation 73%

再看下服務器負載狀況，命令就是一個 w

最後三個數字表示服務器最近 1分鐘 5分鐘 15分鐘 的平均負載，超過cpu核數*1（4核就是4 8核就是8）表示服務器負載很是大。如今這個數字看上去服務器負載比較小仍是可以應對。

總結

結合以上各類跡象，基本能夠判定問題就出在對map進行迭代刪除的代碼，頻繁建立 ConcurrentHashMap$EntryIterator 實例，頻繁觸發 young gc，是致使 cpu 佔用太高的緣由。堆大小的佔用狀況還能夠，負載還能接受，內存硬盤都正常（忘記截圖了），full gc 次數沒有特別多。更加具體的緣由還須要瞭解代碼做者的用意。

因此，只要會使用 jmap jstack jstat 這3個工具，還有一些linux的基本命令（檢查磁盤 網絡 等等），就能夠從容應對由於 代碼寫得太爛 形成程序異常的狀況。