深入JVM徹底剖析ygc越來越慢的原因（上）

今天一個同學問我：“我排查問題時總是遇到，jmap -heap或-histo 不能用，是不是我們機器配置有啥問題哇？ ”

分享下這個case的解決過程。

登上同學說的那臺不能用的機器，執行jstack，報錯： get_thread_regs failed for a lwp ，這個問題以前碰到過，但忘了當時是什么原因了，執行其他的 jmap -histo 什么也卡著不動。

既然jstack沒法弄，就pstack看看進程到底什么狀況吧，于是pstack [pid]看，發現有一個線程的堆棧信息有點奇怪：

\#0  0x00000038e720cd91 in sem_wait ()

對系統函數不太懂，但總覺得 sem_wait 這個有點奇怪，于是Google之，基本明白了這個是由于進程在等信號，這個時候通常會block住其他所有的線程，于是立刻ps看了下進程的狀態，果然進程的狀態變成了T，那上面碰到的所有現象都很容易解釋了，于是執行： kill -CONT [pid] ，一切恢復正常。

繼續查為什么進程狀態會變成T，問問題的同學告訴了下我他在機器上執行過的一些命令，我看到其中一個很熟悉的命令： jmap -heap ，看過我之前文章的同學估計會記得我很早以前分享過，在用cms gc的情況下，執行 jmap -heap 有些時候會導致進程變T，因此強烈建議別執行這個命令，如果想獲取內存目前每個區域的使用狀況，可通過 jstat -gc 或 jstat -gccapacity 來拿到。

到此為止，問題終于搞定，以后碰到jstack/jmap等不能用的時候，可以先看看進程的狀態，因此還是那句話，執行任何一句命令都要清楚它帶來的影響。

手頭還有另外一個case，折騰了一個多星期了還是沒太有頭緒，case的現象是ygc越來越慢，但可以肯定不是由于cms gc碎片問題造成的，感興趣的同學可以拿這個case去玩玩，如果能告訴我原因就更好了:)，執行下面的代碼，啟動參數可以為“-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC：”

import com.thoughtworks.xstream.XStream;

public class XStreamTest {

    public static void main(String[] args) throws Exception {
        while(true){
            XStream xs = new XStream();
            xs.toString();
            xs = null;
        }
    }

}

應該就可以看到ygc的速度從10+ms一直增長到100+ms之類的…

針對這個case，有位同學看到這個后周末時間折騰了下，把原因給分析出來了，分析過程很贊。非常感謝這位同學（阿里的一位同事，花名叫彥貝），在征求他的同意后，我把他寫的整個問題的分析文章轉載到這里。

上分析工具VisualVM

在解決很多問題的時候，工具起的作用往往是巨大，很多時候通過工具分析，很快便能找到原因，但是這次并沒有，下圖是VisualVM觀察到Heap上的GC圖表。

從圖標中可以看出，Perm區空間基本水平，但是Old區空間成增長態勢與YGCT時間增長的倍率基本一直。熟悉YGC的朋友都知道YGC主要分為標記和收回兩個階段，YGCT也是基于這2個階段統計的。由于每次回收的空間大小差不多，所以懷疑是標記階段使用的時間比較長，下面回顧一下JVM的垃圾標記方式。

JVM垃圾回收的標記方法：枚舉根節點

在Java語言里面，可作為GC Roots的節點主要在全局性的引用（例如常量或類靜態屬性）與執行上下文（例如棧幀中的本地變量表）中。如果要使用可達性分析來判斷內存是否可回收的，那分析工作必須在一個能保障一致性的快照中進行——這里“一致性”的意思是整個分析期間整個執行系統看起來就像被凍結在某個時間點上，不可以出現分析過程中，對象引用關系還在不斷變化的情況，這點不滿足的話分析結果準確性就無法保證。這點也是導致GC進行時必須“Stop The World”的其中一個重要原因，即使是號稱（幾乎）不會發生停頓的CMS收集器中，枚舉根節點時也是必須要停頓的。

由于目前的主流JVM使用的都是準確式GC，所以當執行系統停頓下來之后，并不需要一個不漏地檢查完所有執行上下文和全局的引用位置，虛擬機應當是有辦法直接得到哪些地方存放著對象引用。在HotSpot的實現中，是使用一組成為OopMap的數據結構來達到這個目的，在類加載完成的時候，HotSpot就把對象內什么偏移量上是什么類型的數據計算出來，在JIT編譯過程中，也會在特定的位置記錄下棧里和寄存器里哪些位置是引用。這樣GC在掃描時就就可以直接得知這些信息了。上面這段引用自《深入理解Java虛擬機》，用個圖簡單表示一下，當然圖也是源于書中：

基于對GC Roots的懷疑，猜測Old區中存在越來越多的gc root節點，那什么樣的對象是root節點呢？不懂的我趕緊google了一下。

（不要看我紅色圈出來了，第一次看到這幾個嫌疑犯時我也拿不準是哪個）

為了進一步驗證是Old區的GC Roots造成YGCT 增加的，我們來做一次full gc，干掉Old區。代碼如下：

public class SlowYGC {  
public static void main(String[] args) throws Exception {  
int i= 0;  
while (true) {  
XStream xs = new XStream();  
xs.toString();  
xs = null;  
if(i++ % 10000 == 0)  
{  
System.gc();  
}  
}  
}  
}

可以看出Full GC后 YGCT銳減到初始狀態。那是Full GC到底回收了哪些對象？進入到下一步，增加VM參數。

增加VM參數

為了看到Full GC前后對象的回收情況，我們增加下面2個VM參數

-XX:+PrintClassHistogramBeforeFullGC
-XX:+PrintClassHistogramAfterFullGC 。

重新運行上面的代碼，可以觀察到下面的日志：

(點擊放大圖像)

上圖左邊是FGC前的對象情況，右邊是FGC后的情況，結合我之前給出的GC Root候選人中的Monitor鎖，相信你很快就找到20026個 Ljava.util.concurrent.ConcurrentHashMap$Segment 對象幾乎被全部回收了，ConcurrentHashMap中正是通過Segment來實現分段鎖的。那什么邏輯會導致出現大量的Segment鎖對象。繼續看Full GC日志 com.thoughtworks.xstream.core.util.CompositeClassLoader 這個對象也差不多在FGC的時候全軍覆沒，所以懷疑是ClassLoader引起的鎖競爭，下面在ClassLoader的源碼中繼續查找。

ClassLoader中的ConcurrentHashMap

這里有個拿鎖的動作，跟進去看看唄。

為了驗證走到這塊邏輯下了一個斷點。剩下的就是putIfAbsent方法（這里就不詳細分析實現了）有興趣的同學可以看看源碼中CAS和tryLock的使用。

至此基本分析和定位出了YGCT原因，在去看看Xstream的構造函數。

可以看出每次 new XstreamI() 的同時會new一個新的ClassLoader，基本上證明了上述懷疑和猜測。

推導一下按照上述分析，應該是所有自定義的ClassLoader都會YGCT變長的時間問題，于是手寫一個ClassLoader驗證一下。Java代碼如下：

public class TestClassLoader4YGCT {  
public static void main(String[] args) throws Exception{  
while(true)  
{  
Object obj = newObject();  
obj.toString();  
obj = null;  
}  
}

private static Object newObject() throws Exception  
{  
ClassLoader classLoader = new ClassLoader() {  
@Override  
public Class
<!--?--> loadClass(String s) throws ClassNotFoundException {  
try{  
String fileName = s.substring(s.lastIndexOf(“.”) + 1)+ “.class”;  
InputStream inputStream = getClass().getResourceAsStream(fileName);  
if(inputStream == null){  
return super.loadClass(s);  
}  
byte[] b = new byte[inputStream.available()];  
inputStream.read(b);  
return defineClass(s,b,0,b.length);  
}catch (Exception e)  
{  
System.out.println(e);  
return null;  
}  
}  
};  
Class
<!--?--> obj = classLoader.loadClass(“jvmstudy.classload.TestClassLoader4YGCT”);  
return obj.newInstance();  
}  
}  
VM 參數-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC

GC日志

(點擊放大圖像)

結論

當大量new自定義的ClassLoader來加載時，會產生大量ClassLoader對象以及parallelLockMap（ConcurrentHashMap）對象，導致產生大量的Segment分段鎖對象，大大增加了GC Roots的數量，導致YGC中的標記時間變長。如果能直接看到YGCT的詳細使用情況，這個結論會顯得更加嚴謹。這只是我自己的一個推導，并不一定是正確答案。

來自： http://www.infoq.com/cn/articles/thorough-jvm-thorough-analysis-ygc-part01