JVM：帶你查看常見的問題，以及分析處方法

一.前言

各位開發和運維同窗，在項目實施落地的過程當中，尤爲是使用EDAS、DRDS、MQ這些java中間件時，確定會遇到很多JAVA程序運行和JVM的問題。我結合過去遇到的各類各樣的問題和實際處理經驗，總結了JAVA問題的處理方式，但願能幫助到你們。

二.問題處理整體歸納

以下圖所示：

 

問題處理分爲三大類：

1.問題發生後的緊急處理原則

2.問題歸類和分析

3.分析排查工具和命令

一般來講，最後的解決方式有兩種，第一種是最廣泛的，絕大部分的最終問題緣由能夠定位到代碼層面，修改代碼後問題解決。

第二種，調整某些JVM參數，緩解問題發生的頻率和時間，可是治標不治本，因此本篇分析文檔並未涉及JVM參數的優化調整。

三.緊急處理原則

問題發生後，第一時間是快速保留問題現場供後面排查定位，而後儘快恢復服務。保留現場的具體操做：

• 打印堆棧信息，命令行：jstat -l 'java進程PID'
• 打印內存鏡像，命令行：jmap -dump:format=b,file=hprof 'java進程PID'
• 生成core文件，命令行：gcore 'java進程PID'
• 保留gc日誌文件
• 保留業務日誌文件
• 查看JAVA堆內存運行分配：命令行：jstat -gcutil 'java進程PID' 1000
• 完成以上操做後，儘快重啓JAVA進程或回滾，恢復服務。

四.問題歸類和分析

當應用系統運行緩慢，頁面加載時間變長，後臺長時間無影響時，均可以參考如下歸類的解決方法。絕大部分的JAVA程序運行時異常都是Full GC、OOM(java.lang.OutOfMemoryError)、線程過多。主要分這麼幾大類：

• 持續發生Full GC，可是系統不拋出OOM錯誤
• 堆內存溢出：java.lang.OutOfMemoryError：Java heap space
• 線程過多：java.lang.OutOfMemoryError：unable to create new native thread
• JAVA進程退出
• CPU佔用太高

一般來講，能夠用一些經常使用的命令行來打印堆棧、內存使用分配、打印內存鏡像文件來分析，好比jstack、jstat、jmap等。可是某些時刻，仍是須要引入更高階的代碼級分析工具（好比btrace）才能定位到具體緣由。針對每一種問題，我會依據具體的case來詳細說明解決方式。

五.分析排查工具和命令

問題排查，除了最重要的解決思路外，合理的運用工具也能達到事半功倍的效果，某些時候用好了工具，甚至能直接定位到致使問題的具體代碼。

JDK自帶工具

Jstat

實時查看gc的情況，經過jstat -gcutil 能夠查看new區、old區等堆空間的內存使用詳情，以及gc發生的次數和時間

Jstack

很重要的命令，jstack能夠用來查看Java進程裏的線程都在幹什麼，對於應用沒反應、響應很是慢等場景都有很大的幫助。幾乎全部java問題排查時，我第一選擇都是使用jstack命令打印線程信息。

Jmap

jmap -dump用於保存堆內存鏡像文件，供後續MAT或其餘的內存分析工具使用。jmap -histo:live也能夠強制執行full gc。

Jinfo

一般我用它來查看Java的啓動參數

gcore

我一般會使用gcore命令來保留問題現場，速度很是快。某些時候執行jstack或jmap會報錯，加-F也不行，這個時候就能夠用gcore命令，gcore javapid 能夠生成core文件，能夠經過jstack和jmap命令從core文件裏導出線程和內存鏡像文件。

堆內存分析工具

MAT

eclipse官方推出的本地內存分析工具，運行須要大量內存，從使用角度來說，並不方便。我如今已經不多使用。

ZProfiler

阿里中間件出品的在線堆內存分析工具，連接是：zprofiler.alibaba-inc.com，不須要拷貝鏡像文件，直接在線分析。

EagleEye-MProf

也是阿里中間件團隊推出的，適用於複雜雲環境的輕量級java堆內存分析工具，很是好用。在公共雲或者專有云的機器上，運行的是客戶的機器。因爲權限或者網絡的關係，咱們很難去執行jmap進行heap dump，或者scp上傳dump文件。這個工具能夠直接在ECS上分析，而不用下載dump文件。

代碼跟蹤工具

Btrace

Java代碼動態跟蹤神器。少數的問題能夠mat後直接看出，而多數會須要再用btrace去動態跟蹤。好比排查線程建立過多的場景，經過btrace能夠直接定位到哪段代碼建立了大量線程。

比較麻煩的就是要自行編寫腳本，不過現成的腳本也有很多，能夠直接使用。

六.案例分析一：持續出現Full GC

處理原則

若是發現cms gc或full gc後，存活的對象始終不少，這種狀況下能夠經過jmap -dump來獲取下內存dump文件，也能夠經過gcore命令生成core文件，再用jmap從core裏導出dump文件。而後經過MAT、ZProfile、EagleEye-MProf來分析內存鏡像分佈。若是還不能定位，最後使用btrace來定位到具體的緣由。對於cms gc而言，還有可能會出現promotion failed或concurrent mode failure問題。

分析過程

1. 查看GC日誌：

發現應用系統一直在作full gc，並且還有報錯「concurrent mode failure」，這表示在執行gc過程當中，有對象要晉升到舊生代，而此時舊生代空間不足形成的。

 

2. 查看應用訪問日誌：

有條很可疑的訪問記錄，響應時間特別長，達到了60S，直接超時了。

 

3. 查看JVM內存分配詳情：

如何判斷JVM垃圾回收是否正常，我一般會使用jstat命令，jstat是JDK自帶的一個輕量級小工具。全稱「Java Virtual Machine statistics monitoring tool」，它位於java的bin目錄下，主要利用JVM內建的指令對Java應用程序的資源和性能進行實時的命令行的監控，包括了對Heap size和垃圾回收情況的監控。可見，jstat是輕量級的、專門針對JVM的工具，很是適用。jstat工具特別強大，有衆多的可選項，詳細查看堆內各個部分的使用量，以及加載類的數量。使用時，需加上查看進程的進程id，和所選參數。

執行：cd $JAVA_HOME/bin中執行jstat，注意jstat後必定要跟參數。

具體命令行：jstat -gcutil 'java進程PID' 1000

 

如圖所示，發現Eden區、Old區都滿了，此時新建立的對象沒法存放，晉升到Old區的對象也沒法存放，因此係統持續出現Full GC了。

4. 分析內存鏡像：

這種問題比較直觀，須要dump內存鏡像，而後用MAT或者Zprofiler工具分析heapdump文件。

MAT(Memory Analyzer Tool)，一個基於 Eclipse 的內存分析工具，是一個快速、功能豐富的 JAVA heap 分析工具，它能夠幫助咱們查找內存泄漏問題。

Zprofiler是阿里中間件團隊推出的在線JAVA內存分析工具，不用在本地運行，訪問 http://zprofiler.alibaba-inc.com/ 便可。

保存內存鏡像的命令：jmap -dump:format=b,file=hprof 'java進程PID'，一般來說這個文件會比較大，通常都會有好幾個G。

用MAT或ZProfile分析結果以下，基本定位了問題的緣由

 

 

 

很明顯，LinkedHashMap佔用了91.41%的內存，裏面有大量的ThRoomQuotaDO的引用對象，頗有多是死循環形成了這樣的現象。不過要尋找真實緣由，還得看看具體的代碼。

5. 查看源代碼

查詢ThRoomQuotaDO類的源代碼，發現了致使死循環的代碼，以下：

代碼段一：

`if(start == null || end == null || start.before(now)){

start = CalendarUtil.addDate(now, 1);
 end = CalendarUtil.addDate(start,1);`

這裏的start和end就是以前應用訪問日誌裏的那條get請求帶進來的，請求的url以下：

 

請注意start=2010-04-031061，原本這個start的值是不規範的，但代碼仍是經過SimpleDateFormat把start解析成的Date爲(Fri Apr 15 00:00:00 CST 2095)，因此不會進入代碼段一的if塊中去。

代碼段二：

`Map roomQuotaMapFull = new LinkedHashMap();

for (Date d = hotelQuery.getStart(); d.compareTo(hotelQuery.getEnd()) != 0; d = CalendarUtil.addDate(d, 1)) {

ThRoomQuotaDO rq = new ThRoomQuotaDO();
 rq.setTheDate(d);
 rq.setMock();
 roomQuotaMapFull.put(d, rq);

}`

這裏就是最終致使full gc的代碼：d.compareTo(hotelQuery.getEnd()) != 0，顯然start和end是不相等的，因此陷入死循環中，以至把內存塞滿了。

所以，最終的緣由獲得了定位，要解決起來那就很容易了。

6. 解決

代碼段一：

修改致使問題的代碼（標紅處是修改後的）

if(start == null || end == null || start.before(now))||start.after(end)){

start = CalendarUtil.addDate(now, 1);
 end = CalendarUtil.addDate(start,1);

}

代碼段二：

for (Date d = hotelQuery.getStart();d.compareTo(hotelQuery.getEnd()) <= 0;d = CalendarUtil.addDate(d, 1)) {

ThRoomQuotaDO rq = new ThRoomQuotaDO();
 rq.setTheDate(d);
 rq.setMock();
 roomQuotaMapFull.put(d, rq);

}

從新打包發佈後，內存恢復正常，再也沒有發生此類問題。

案例分析二：OOM：unable to create new native thread

處理原則

在日誌中可能會看到java.lang.OutOfMemoryError: Unable to create new native thread，能夠先統計下目前的線程數(例如ps -eLf | grep java -c)，而後能夠看看ulimit -u的限制值是多少，如線程數已經達到限制值，如限制值可調整，則可經過調整限制值來解決；如不能調限制值，或者建立的線程已經不少了，那就須要看看線程都是哪裏建立出來的，首先用jstack命令打印線程堆棧信息，統計線程狀態，而後經過btrace來查出是哪裏建立的線程。

若是jstack執行失敗的話，可使用gcore命令生成core文件：gcore javapid > core.**

而後再用jstack和jmap能夠導出堆棧和內存鏡像文件。

具體命令：jstack $JAVA_HOME/bin/java core.** > jstack.log

分析過程

1. 查看GC日誌：

發現gc都正常，沒有full gc，new區，old區都正常，肯定不是heap堆出問題。

2. 查看應用訪問日誌：

發現業務日誌中有不少錯誤：

 

3. 查看線程堆棧：

查看jstack.log堆棧信息發現一共有8204個線程，其中blocked的有8169個，明顯不正常。經過堆棧信息不能看出是什麼致使建立了這麼多線程，可是至少能肯定致使oom的緣由了：線程建立太多，且所有block了。下面就須要用btrace工具跟進分析具體是什麼代碼建立了這麼多的線程。

4. 使用Btrace工具分析：

編寫btrace腳本ThreadStart.java，內容以下：

`import static com.sun.btrace.BTraceUtils.*;

import com.sun.btrace.annotations.*;

@BTrace public class Trace{

@OnMethod(

clazz="java.lang.Thread",
 method="start"

)

public static void traceExecute(){

jstack();

}

}`

執行命令：./btrace javapid ThreadStart.java > thread.log

查看thread.log，到這裏能夠肯定問題所在了，基本上全部的線程都在這個類裏建立：com.taobao.et.web.ie.module.action.IeOrderCheckAction.doMileageMeta

 

5. 查看源代碼

從代碼裏能夠看到，每次執行doMileageMeta都會建立一個線程池，可是沒有shutdown釋放資源。

 

問題緣由就清楚了:應用啓動後，每次請求都會建立一個包含3個線程的線程池，可是從不釋放資源，漲到8000多個之後，達到線程上限，拋出了"unable to create new native thread"。

6. 解決

修改代碼：每次建立線程池後，調用shutdown方法來釋放資源，具體代碼就不帖出來了。

案例分析三：OOM：java heap space

處理原則

java.lang.OutOfMemoryError: java heap size也是常見的現象。最重要的是dump出內存，一種方法是經過在啓動參數上增長-XX:+HeapDumpOnOutOfMemoryError，另外一種方法是在當出現OOM時，經過jmap -dump獲取到內存dump，在獲取到內存dump文件後，可經過MAT進行分析，但一般來講僅僅靠MAT可能還不能直接定位到具體應用代碼中哪一個部分形成的問題，例如MAT有可能看到是某個線程建立了很大的ArrayList，但這樣是不足以解決問題的，因此一般還須要藉助btrace來定位到具體的代碼。

案例分析四：Java進程退出

處理原則

對於Java進程退出，最重要的是要讓系統自動生成coredump文件，須要設置ulimit -c unlimited，表示core文件爲不限制大小，一般會加到java應用的啓動腳本里。當進程crash發生時，找到coredump文件，core文件一般位於 /應用部署目錄/target (core文件通常在程序工做區產生)下。有可能的緣由是代碼中出現了無限遞歸或死循環，可經過jstack來提取出Java的線程堆棧，從而具體定位到具體的代碼。

若是以上方法無效時，能夠嘗試dmesg命令，看看系統出了什麼問題，有多是系統主動殺掉了Java進程（例如內存超出限制）

分析過程

1.生成coredump文件

在將出現crash的服務器上打開ulimit,等待生成core文件，執行命令：ulimit -c unlimited 。

2.分析coredump文件

執行命令：gdb -c $JAVA_HOME/bin/java coredump_file

鍵入：info threads ----- 獲取core文件中線程信息

其中*號前表明是crash時，當前正在運行的線程

即當前正在運行的線程爲 9406

 

3.使用jstack命令分析core文件，獲取指定線程id對應的代碼信息

具體命令：jstack $JAVA_HOME/bin/java coredump_file > jstack.log，搜索剛纔獲得的線程編號 9406，發現問題以下：

 

緣由就是代碼裏出現了無限遞歸，致使了爆棧。

案例分析五：CPU佔用太高

處理原則

從經驗上來講，有些時候是因爲頻繁cms gc或fgc形成的，在gc log是記錄的狀況下（-Xloggc:），可經過gc log看看，若是沒打開gc log，可經過jstat -gcutil來查看，如是gc頻繁形成的，則可跳到後面的內存問題 | GC頻繁部分看排查方法。

如不是上面的緣由，可以使用top -H查看線程的cpu消耗情況，這裏有可能會看到有個別線程是cpu消耗的主體，這種狀況一般會比較好解決，可根據top看到的線程id進行十六進制的轉換，用轉換出來的值和jstack出來的java線程堆棧的nid=0x[十六進制的線程id]進行關聯，便可看到此線程到底在作什麼動做，這個時候須要進一步的去排查究竟是什麼緣由形成的，例若有多是正則計算，有多是很深的遞歸或循環，也有多是錯誤的在併發場景使用HashMap等。

分析過程

這裏分享下如何查看具體致使CPU高的線程名稱

1.找到最耗CPU資源的java線程TID

執行命令：ps H -eo user,pid,ppid,tid,time,%cpu,cmd | grep java | sort -k6 -nr |head -1

2.將找到的線程TID進行十六進制的轉換

printf "%xn" tid

3.從堆棧文件裏找到對應的線程名稱

經過命令導出堆棧文件：jstack javapid > jstack.log，根據上一步獲得的線程TID，搜索堆棧文件，便可看到此線程到底在作什麼動做。