258
JVM源碼分析之自定義類加載器如何拉長YGC
概述
本文重點講述畢玄大師在其公眾號上發的一個GC問題一個jstack/jmap等不能用的case，對於畢大師那篇文章，題目上沒有提到GC的那個問題，不過進入到文章裏可以看到，既然文章提到了jstack/jmap的問題，這裏也簡單回答下jstack/jmap無法使用的問題，其實最常見的場景是使用jstack/jmap的用戶和目標進程不是同一個用戶，哪怕你執行jstack/jmap的動作是root用戶也無濟於事，不過畢大師這裏主要提到的是jmap -heap/histo這兩個參數帶來的問題，如果使用-heap/histo的參數，其實和大家使用-F參數是一樣的，底層都是通過serviceability agent來實現的，並不是jvm attach的方式，通過sa連上去之後會掛起進程，在serviceability agent裏存在bug可能導致detach的動作不會被執行，從而會讓進程一直掛著，可以通過top命令驗證進程是否處於T狀態，如果是說明進程被掛起了，如果進程被掛起了，可以通過kill -CONT [pid]來恢複。
再回到那個GC的問題，用的參數如下：
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGCdemo程序如下：
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;
}
}
}執行效果如下
2016-03-14T22:48:01.502+0800: [GC [ParNew: 327680K->4258K(368640K), 0.0179071 secs] 327680K->4258K(1007616K), 0.0179448 secs] [Times: user=0.06 sys=0.01, real=0.01 secs]
2016-03-14T22:48:05.975+0800: [GC [ParNew: 331938K->10239K(368640K), 0.0336279 secs] 331938K->10239K(1007616K), 0.0336593 secs] [Times: user=0.13 sys=0.02, real=0.03 secs]
2016-03-14T22:48:12.215+0800: [GC [ParNew: 337919K->14444K(368640K), 0.0471005 secs] 337919K->14444K(1007616K), 0.0471257 secs] [Times: user=0.19 sys=0.02, real=0.05 secs]
2016-03-14T22:48:21.768+0800: [GC [ParNew: 342124K->19088K(368640K), 0.0605017 secs] 342124K->19088K(1007616K), 0.0605295 secs] [Times: user=0.26 sys=0.03, real=0.06 secs]
2016-03-14T22:48:35.180+0800: [GC [ParNew: 346768K->20633K(368640K), 0.0993470 secs] 346768K->25248K(1007616K), 0.0993777 secs] [Times: user=0.34 sys=0.04, real=0.09 secs]發現gc的時間越來越長，但是gc觸發的時機以及回收的效果都差不多，那問題究竟在哪裏呢？
Demo分析
雖然這個demo代碼邏輯很簡單，但是其實這是一個特殊的demo，並不簡單，如果我們將XStream對象換成Object對象，會發現不存在這個問題，既然如此那有必要進去看看這個XStream的構造函數：
public XStream() {
this((ReflectionProvider)null, (Mapper)((Mapper)null), (HierarchicalStreamDriver)(new XppDriver()));
}
/** @deprecated */
public XStream(ReflectionProvider reflectionProvider, Mapper mapper, HierarchicalStreamDriver driver) {
this(reflectionProvider, driver, (ClassLoader)(new CompositeClassLoader()), mapper);
}
/** @deprecated */
public XStream(ReflectionProvider reflectionProvider, HierarchicalStreamDriver driver, ClassLoader classLoader, Mapper mapper) {
this(reflectionProvider, driver, new ClassLoaderReference(classLoader), mapper, new DefaultConverterLookup());
}
public XStream(ReflectionProvider reflectionProvider, HierarchicalStreamDriver driver, ClassLoaderReference classLoader, Mapper mapper, final DefaultConverterLookup defaultConverterLookup) {
this(reflectionProvider, driver, (ClassLoaderReference)classLoader, mapper, new ConverterLookup() {
public Converter lookupConverterForType(Class type) {
return defaultConverterLookup.lookupConverterForType(type);
}
}, new ConverterRegistry() {
public void registerConverter(Converter converter, int priority) {
defaultConverterLookup.registerConverter(converter, priority);
}
});
}
/** @deprecated */
public XStream(ReflectionProvider reflectionProvider, HierarchicalStreamDriver driver, ClassLoader classLoader, Mapper mapper, ConverterLookup converterLookup, ConverterRegistry converterRegistry) {
this(reflectionProvider, driver, (ClassLoaderReference)(new ClassLoaderReference(classLoader)), mapper, converterLookup, converterRegistry);
}
public XStream(ReflectionProvider reflectionProvider, HierarchicalStreamDriver driver, ClassLoaderReference classLoaderReference, Mapper mapper, ConverterLookup converterLookup, ConverterRegistry converterRegistry) {
if(reflectionProvider == null) {
reflectionProvider = JVM.newReflectionProvider();
}
this.reflectionProvider = reflectionProvider;
this.hierarchicalStreamDriver = driver;
this.classLoaderReference = classLoaderReference;
this.converterLookup = converterLookup;
this.converterRegistry = converterRegistry;
this.mapper = mapper == null?this.buildMapper():mapper;
this.setupMappers();
this.setupSecurity();
this.setupAliases();
this.setupDefaultImplementations();
this.setupConverters();
this.setupImmutableTypes();
this.setMode(1003);
}這個構造函數還是很複雜的，裏麵會創建很多的對象，上麵還有一些方法實現我就不貼了，總之都是在不斷構建各種大大小小的對象，一個XStream對象構建出來的時候大概好像有12M的樣子。
那到底是哪些對象會導致ygc不斷增長呢，於是可能想到逐步替換上麵這些邏輯，比如將最後一個構造函數裏的那些邏輯都禁掉，然後我們再跑測試看看還會不會讓ygc不斷惡化，最終我們會發現，如果我們直接使用如下構造函數構造對象時，如果傳入的classloader是AppClassLoader，那會發現這個問題不再出現了。
public XStream(ReflectionProvider reflectionProvider, HierarchicalStreamDriver driver, ClassLoader classLoader, Mapper mapper) {
this(reflectionProvider, driver, new ClassLoaderReference(classLoader), mapper, new DefaultConverterLookup());
}測試代碼如下：
public static void main(String[] args) throws Exception {
int i=0;
while (true) {
XStream xs = new XStream(null,null, new ClassLoaderReference(XStreamTest.class.getClassLoader()),null, new DefaultConverterLookup());
xs.toString();
xs=null;
}
}gc日誌如下：
2016-03-14T23:10:33.537+0800: [GC [ParNew: 327680K->758K(368640K), 0.0019803 secs] 327680K->758K(1007616K), 0.0020182 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2016-03-14T23:10:35.189+0800: [GC [ParNew: 328438K->1066K(368640K), 0.0018641 secs] 328438K->1066K(1007616K), 0.0019055 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-03-14T23:10:36.465+0800: [GC [ParNew: 328746K->1156K(368640K), 0.0010304 secs] 328746K->1156K(1007616K), 0.0010519 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T23:10:37.767+0800: [GC [ParNew: 328836K->1065K(368640K), 0.0011329 secs] 328836K->1065K(1007616K), 0.0011543 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T23:10:39.035+0800: [GC [ParNew: 328745K->351K(368640K), 0.0043387 secs] 328745K->1127K(1007616K), 0.0043700 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-03-14T23:10:40.324+0800: [GC [ParNew: 328031K->160K(368640K), 0.0011579 secs] 328807K->936K(1007616K), 0.0011793 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2016-03-14T23:10:41.610+0800: [GC [ParNew: 327840K->31K(368640K), 0.0007010 secs] 328616K->826K(1007616K), 0.0007219 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-03-14T23:10:42.919+0800: [GC [ParNew: 327711K->24K(368640K), 0.0011246 secs] 328506K->819K(1007616K), 0.0011450 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2016-03-14T23:10:44.196+0800: [GC [ParNew: 327704K->24K(368640K), 0.0006797 secs] 328499K->819K(1007616K), 0.0007586 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]是不是覺得很神奇，由此可見，這個classloader至關重要。
不得不說的類加載器
這裏著重要說的兩個概念是初始類加載器和定義類加載器。舉個栗子說吧，AClassLoader->BClassLoader->CClassLoader，表示AClassLoader在加載類的時候會委托BClassLoader類加載器來加載，BClassLoader加載類的時候會委托CClassLoader來加載，假如我們使用AClassLoader來加載X這個類，而X這個類最終是被CClassLoader來加載的，那麼我們稱CClassLoader為X類的定義類加載器，而AClassLoader和BClassLoader分別為X類的初始類加載器，JVM在加載某個類的時候對這三種類加載器都會記錄，記錄的數據結構是一個叫做SystemDictionary的hashtable，其key是根據ClassLoader對象和類名算出來的hash值，而value是真正的由定義類加載器加載的Klass對象，因為初始類加載器和定義類加載器是不同的classloader，因此算出來的hash值也是不同的，因此在SystemDictionary裏會有多項值的value都是指向同一個Klass對象。
那麼JVM為什麼要分這兩種類加載器呢，其實主要是為了快速找到已經加載的類，比如我們已經通過AClassLoader來觸發了對X類的加載，當我們再次使用AClassLoader這個類加載器來加載X這個類的時候就不需要再委托給BClassLoader去找了，因為加載過的類在JVM裏有這個類加載器的直接加載的記錄，隻需要直接返回對應的Klass對象即可。
Demo中的類加載器是否會加載類
我們的demo裏發現構建了一個CompositeClassLoader的類加載器，那到底有沒有用這個類加載器加載類呢，我們可以設置一個斷點在CompositeClassLoader的loadClass方法上，於是看到下麵的堆棧：
main@1, prio=5, in group 'main', status: 'RUNNING'
at com.thoughtworks.xstream.core.util.CompositeClassLoader.loadClass(CompositeClassLoader.java:53)
at java.lang.Class.forName0(Class.java:-1)
at java.lang.Class.forName(Class.java:249)
at com.thoughtworks.xstream.XStream.buildMapperDynamically(XStream.java:191)
at com.thoughtworks.xstream.XStream.buildMapper(XStream.java:170)
at com.thoughtworks.xstream.XStream.<init>(XStream.java:142)
at com.thoughtworks.xstream.XStream.<init>(XStream.java:116)
at com.BBBB.main(BBBB.java:15)可見確實有類加載的動作，根據類加載委托機製，在這個demo中我們能肯定類是交給AppClassLoader來加載的，這樣一來CompositeClassLoader就變成了初始類加載器，而AppClassLoader會是定義類加載器，都會在SystemDictionary裏存在，因此當我們不斷new XStream的時候會不斷new CompositeClassLoader對象，加載類的時候會不斷往SystemDictionary裏插入記錄，從而使SystemDictionary越來越膨脹，那自然而然會想到如果GC過程不斷去掃描這個SystemDictionary的話，那隨著SystemDictionary不斷膨脹，那麼GC的效率也就越低，抱著驗證下猜想的方式我們可以使用perf工具來看看，如果發現cpu占比排前的函數如果都是操作SystemDictionary的，那就基本驗證了我們的說法，下麵是perf工具的截圖，基本證實了這一點。
【image】
SystemDictionary為什麼會影響GC過程
想象一下這麼個情況，我們加載了一個類，然後構建了一個對象(這個對象在eden裏構建)當一個屬性設置到這個類裏，如果gc發生的時候，這個對象是不是要被找出來標活才行，那麼自然而然我們加載的類肯定是我們一項重要的gc root，這樣SystemDictionary就成為了gc過程中的被掃描對象了，事實也是如此，可以看vm的具體代碼：
void SharedHeap::process_strong_roots(bool activate_scope,
bool collecting_perm_gen,
ScanningOption so,
OopClosure* roots,
CodeBlobClosure* code_roots,
OopsInGenClosure* perm_blk) {
StrongRootsScope srs(this, activate_scope);
// General strong roots.
assert(_strong_roots_parity != 0, "must have called prologue code");
// _n_termination for _process_strong_tasks should be set up stream
// in a method not running in a GC worker. Otherwise the GC worker
// could be trying to change the termination condition while the task
// is executing in another GC worker.
if (!_process_strong_tasks->is_task_claimed(SH_PS_Universe_oops_do)) {
Universe::oops_do(roots);
// Consider perm-gen discovered lists to be strong.
//將perm gen的非強引用標記為root的一部分
perm_gen()->ref_processor()->weak_oops_do(roots);
}
// Global (strong) JNI handles
if (!_process_strong_tasks->is_task_claimed(SH_PS_JNIHandles_oops_do))
JNIHandles::oops_do(roots);
// All threads execute this; the individual threads are task groups.
if (ParallelGCThreads > 0) {
Threads::possibly_parallel_oops_do(roots, code_roots);
} else {
Threads::oops_do(roots, code_roots);
}
if (!_process_strong_tasks-> is_task_claimed(SH_PS_ObjectSynchronizer_oops_do))
ObjectSynchronizer::oops_do(roots);
if (!_process_strong_tasks->is_task_claimed(SH_PS_FlatProfiler_oops_do))
FlatProfiler::oops_do(roots);
if (!_process_strong_tasks->is_task_claimed(SH_PS_Management_oops_do))
Management::oops_do(roots);
if (!_process_strong_tasks->is_task_claimed(SH_PS_jvmti_oops_do))
JvmtiExport::oops_do(roots);
if (!_process_strong_tasks->is_task_claimed(SH_PS_SystemDictionary_oops_do)) {
if (so & SO_AllClasses) {
SystemDictionary::oops_do(roots);
} else if (so & SO_SystemClasses) {
SystemDictionary::always_strong_oops_do(roots);
}
}
if (!_process_strong_tasks->is_task_claimed(SH_PS_StringTable_oops_do)) {
//JavaObjectsInPerm為false，那麼String intern的對象已經class對象都是存在heap裏的，否則都存在perm裏
if (so & SO_Strings || (!collecting_perm_gen && !JavaObjectsInPerm)) {
//雖然不回收perm，但是interned的String對象不在perm裏，那麼還是需要遍曆下StringTable裏的String對象，因為這些對象在heap裏
StringTable::oops_do(roots);
}
if (JavaObjectsInPerm) {
// Verify the string table contents are in the perm gen
NOT_PRODUCT(StringTable::oops_do(&assert_is_perm_closure));
}
}
if (!_process_strong_tasks->is_task_claimed(SH_PS_CodeCache_oops_do)) {
if (so & SO_CodeCache) {
// (Currently, CMSCollector uses this to do intermediate-strength collections.)
assert(collecting_perm_gen, "scanning all of code cache");
assert(code_roots != NULL, "must supply closure for code cache");
if (code_roots != NULL) {
CodeCache::blobs_do(code_roots);
}
} else if (so & (SO_SystemClasses|SO_AllClasses)) {
if (!collecting_perm_gen) {
// If we are collecting from class statics, but we are not going to
// visit all of the CodeCache, collect from the non-perm roots if any.
// This makes the code cache function temporarily as a source of strong
// roots for oops, until the next major collection.
//
// If collecting_perm_gen is true, we require that this phase will call
// CodeCache::do_unloading. This will kill off nmethods with expired
// weak references, such as stale invokedynamic targets.
CodeCache::scavenge_root_nmethods_do(code_roots);
}
}
// Verify that the code cache contents are not subject to
// movement by a scavenging collection.
DEBUG_ONLY(CodeBlobToOopClosure assert_code_is_non_scavengable(&assert_is_non_scavengable_closure, /*do_marking=*/ false));
DEBUG_ONLY(CodeCache::asserted_non_scavengable_nmethods_do(&assert_code_is_non_scavengable));
}
if (!collecting_perm_gen) {
//如果是不回收perm，那找出所有perm指向new的對象
// All threads perform this; coordination is handled internally.
rem_set()->younger_refs_iterate(perm_gen(), perm_blk);//perm的level是-1
}
_process_strong_tasks->all_tasks_completed();
}看上麵的SH_PS_SystemDictionary_oops_do task就知道了，這個就是對SystemDictionary進行掃描。
但是這裏要說的是雖然有對SystemDictionary進行掃描，但是ygc的過程並不會對SystemDictionary進行處理，如果要對它進行處理需要開啟類卸載的vm參數，CMS算法下，CMS GC和Full GC在開啟CMSClassUnloadingEnabled的情況下是可能對類做卸載動作的，此時會對SystemDictionary進行清理，所以當我們在跑上麵demo的時候，通過jmap -dump:live,format=b,file=heap.bin <pid>命令執行完之後，ygc的時間瞬間降下來了，不過又會慢慢回去，這是因為jmap的這個命令會做一次gc，這個gc過程會對SystemDictionary進行清理。
修改VM代碼驗證
很遺憾hotspot目前沒有對ygc的每個task做一個時間的統計，因此無法直接知道是不是SH_PS_SystemDictionary_oops_do這個task導致了ygc的時間變長，為了證明這個結論，我特地修改了一下代碼，在上麵的代碼上加了一行：
if (!_process_strong_tasks->is_task_claimed(SH_PS_SystemDictionary_oops_do)) {
GCTraceTime t("SystemDictionary_OOPS_DO",PrintGCDetails,true,NULL);
if (so & SO_AllClasses) {
SystemDictionary::oops_do(roots);
} else if (so & SO_SystemClasses) {
SystemDictionary::always_strong_oops_do(roots);
}
}然後重新編譯，跑我們的demo，測試結果如下：
2016-03-14T23:57:24.293+0800: [GC2016-03-14T23:57:24.294+0800: [ParNew2016-03-14T23:57:24.296+0800: [SystemDictionary_OOPS_DO, 0.0578430 secs]
: 81920K->3184K(92160K), 0.0889740 secs] 81920K->3184K(514048K), 0.0900970 secs] [Times: user=0.27 sys=0.00, real=0.09 secs]
2016-03-14T23:57:28.467+0800: [GC2016-03-14T23:57:28.468+0800: [ParNew2016-03-14T23:57:28.468+0800: [SystemDictionary_OOPS_DO, 0.0779210 secs]
: 85104K->5175K(92160K), 0.1071520 secs] 85104K->5175K(514048K), 0.1080490 secs] [Times: user=0.65 sys=0.00, real=0.11 secs]
2016-03-14T23:57:32.984+0800: [GC2016-03-14T23:57:32.984+0800: [ParNew2016-03-14T23:57:32.984+0800: [SystemDictionary_OOPS_DO, 0.1075680 secs]
: 87095K->8188K(92160K), 0.1434270 secs] 87095K->8188K(514048K), 0.1439870 secs] [Times: user=0.90 sys=0.01, real=0.14 secs]
2016-03-14T23:57:37.900+0800: [GC2016-03-14T23:57:37.900+0800: [ParNew2016-03-14T23:57:37.901+0800: [SystemDictionary_OOPS_DO, 0.1745390 secs]
: 90108K->7093K(92160K), 0.2876260 secs] 90108K->9992K(514048K), 0.2884150 secs] [Times: user=1.44 sys=0.02, real=0.29 secs]我們會發現YGC的時間變長的時候，SystemDictionary_OOPS_DO的時間也會相應變長多少，因此驗證了我們的說法。
最後更新：2017-04-11 19:32:01