JVMTI的對象標記對GC的影響

本文主要是想分析下為什么Plumbr代理在特定的場景下會對GC的暫停時間產生影響，以及影響究竟有多大。在排查這個故障的過程中，我們還發現，在GC暫停的時候，JVMTI（JVM Tool Interface）的打標記操作存在一些有趣的現象。

問題定位

我們的一位客戶抱怨說當他們的應用程序連接上我們的Plumbr代理之后響應速度會明顯變慢。在檢查了GC日志之后，我們發現GC的時間存在異常。下面是沒有使用Plumbr的情況下從JVM中提取出來的GC日志 ：

2015-01-30T17:19:08.965-0200: 182.816: [Full GC (Ergonomics) 
[PSYoungGen: 524800K->0K(611840K)] 
[ParOldGen: 1102620K->1103028K(1398272K)] 1627420K->1103028K(2010112K), 
[Metaspace: 2797K->2797K(1056768K)], 0.9563188 secs] 
[Times: user=7.32 sys=0.01, real=0.96 secs]

而下面是連接了Plumbr代理之后的日志：

2015-02-02T17:40:35.872-0200: 333.166: [Full GC (Ergonomics) 
[PSYoungGen: 524800K->0K(611840K)] 
[ParOldGen: 1194734K->1197253K(1398272K)] 1719534K->1197253K(2010112K), 
[Metaspace: 17710K->17710K(1064960K)], 1.9900624 secs] 
[Times: user=7.94 sys=0.01, real=1.99 secs]

異常就隱藏在這消逝的時間背后。實際時間（real time）指的是實際所消耗的時間。你可以看下你手上的腕表，實際時間對應的就是這個時間。而用戶時間（user time，算上系統時間）指的是測量中消耗的總的CPU時間。如果有多個線程在多個核上同時工作的話，這個時間是要比實際時間長的。因此，對于 Parallel GC而言，實際時間大約是等于（用戶時間/線程數）。在我的機器上這個比率應該是接近7，而在沒有使用Plumbr代理的情況下確實如此。但用了 Plumbr之后，這個比率就明顯下降了。看來確實是存在問題的！

初步調查

根據情況來看，我們很容易可以得出下面的推測：

1. Plumbr使得JVM在每次GC之后都做了一些比較重的單線程操作
2. Plumbr使得JVM用來進行GC的線程變少了

不過光看一行GC日志實在是很難得出什么結論，因此我們將前面提到的那個比率給可視化了一下：

link

當Plumbr發現內存泄露時，圖中的比率便恰好出現了下跌。Plumbr進行根對象分析時的確是會給GC增加了一些額外的負擔，但是對GC的暫停時間造成這種持續性的影響肯定不是我們設計這款代理工具的初衷。從現象來看，應該更傾向于第一種假設，因為我們這個代理應該不至于能影響到運行時的GC線程數。

要編寫一個獨立的測試用例還是挺費時間的。，不過如果增加了下面這些約束條件的話，倒也沒那么困難：

1. 應用程序必須能夠產生Plumbr可以檢測得到的內存泄露
2. 應用程序必須頻繁地中斷來執行GC操作
3. 。。還有就是，應用程序的存活對象集要足夠大，也就是說能堅持過一輪Full GC的對象的數量必須得足夠多。

開發完這個迷你的測試用例之后，現在我們可以開始排查問題了。將Plumbr代理的各個特性依次打開/關閉，然后再看一下問題是否能夠重現，這聽起來是個不錯的主意。

通過這么一個簡單的方法，我們最終將問題定位到了Plumbr代理所執行的一個操作上。在JVMTI的開關關掉之后，問題便消失了。我們在分析GC根對象及其引用的對象鏈的過程中，將堆中的每一個對象都打上了標記。顯然，我們所打的這些標記或多或少地對GC產生了影響。

揪出問題的根源

但是，我們還是沒搞清楚為什么GC的暫停時間會變長。垃圾回收已經足夠快了，并且絕大多數標記過的對象也是符合回收的標準的。不過我們發現了一個問題，就是由于存活對象太多了(這也正是內存泄露的一個特征)，導致有許多不應該回收的都被打了標記。

不過，即便是存活對象集中的所有對象都打上了標記，也不應該會對GC時間產生線性的影響。GC完成之后，我們會收到關于這些打上標記且又被回收掉的對象的通知信息，不過存活對象并不在其列。這讓我們不禁懷疑，Hotspot是否出于某種原因的考慮，在每次GC后都遍歷了一次這些標記過的對象。

要想證實這一猜測可能你得讀一下hotspot的源碼。經過了一番鉆研之后，我們最終在JvmtiTagMap::doweakoops中找到了這么一段代碼，這里的確是遍歷了所有的標記對象，并執行了許多并不是那么廉價的操作。更糟糕的是，這些操作還是順序執行的，沒有并行化。在GC完成后的調用鏈中發現的確是調用到了這一方法之后，最后的一個疑點也終于解開了。（至于JVM說什么要這么做，以及為什么要對弱引用進行這個操作已經超出了本文講述的范圍）。

在Parallel GC中居然有一個順序執行的如此昂貴的操作看起來像是個設計缺陷。不過再仔細想一下，JVMTI的設計者估計也沒想到有人會把堆中的所有對象都打上標記，因此他也沒有想過要去優化這個操作，或者說將它作并行 化。畢竟嘛，你永遠也不可能知道用你這個特性的人是怎么使用它的，因此，檢查下GC完成后的這些操作有沒有必要進行并行化看來還是有點必要的。

那么為了解決這個問題，我們需要將那些不再需要的標記給清除掉。只要在我們的JVMTI回調中加入三行代碼就能解決這個問題了：

+ if(isGenerated(*tag_ptr)) { + *tag_ptr = 0; + } 

還有你看，在完成一遍分析掃描后，我們的數據已經基本恢復正常了。正如下面這個截圖所示，在檢測內存泄露過程中有一個短暫的性能抖動，同時分析完成之后也有點輕微的性能下降：

link

結束語

這個補丁已經打出來了，Plumbr檢測出內存泄露之后所導致的GC暫停時間增加的故障也得到了解決。現在你可以獲取我們更新后的Plumbr代理來進行性能問題的追蹤了。

順便說一句，我建議在進行一些昂貴的標記操作時還是要謹慎一些，因為在某些個例中，“廉價”的標記累積起來所導致的性能損耗也是挺大的。如果想確認你自己是否濫用了這個標記特性，你可以打開-XX:+TraceJVMTIObjectTagging這個診斷開關。它會告訴你標記映射表到底消耗了多少本地內存以及遍歷堆究竟花了多少時間。。。

原創文章轉載請注明出處：JVMTI的對象標記對GC的影響

英文原文鏈接