网站持久代引发Full GC问题分析

现状：

Dragoon（监控系统）的日报显示trade_us_wholelsale（美国wholesale集群），日均Young GC次数25w次左右，应用暂停295w毫秒（相当于40多分钟），Full GC次数600次左右，应用暂停190w毫秒（相当于30多分钟）。

GC，尤其是Full GC，每次都会导致JVM暂停工作，处理垃圾回收任务，短时间内无法响应用户请求，大量的Full GC会导致系统响应速度降低，而且引来OOM的巨大风险。

分析：

启动参数：

trade_us_wholesale应用的JVM启动参数如下：

-Xmx2g -Xms2g -Xmn256m -XX:PermSize=128m -Xss256k-XX:+UseConcMarkSweepGC

新生代：256M

旧生代：1792M（2G-256M）

持久代：128M

栈内存：256KB

新生代回收方式：并行回收

旧生代回收方式：并发回收（CMS）

实时数据分析：

数据来源于Dragoon平台

l  分代内存占比

 

JVM分代	使用内存量	内存总量
持久代	117M-125M	128M
新生代	220M-225M	256M
旧生代	800M-1G	1792M

注：明显看出，新生代以及持久代，内存使用较为紧张，旧生代较为宽裕。

l  Young GC

Young GC频繁，由于并行GC采用多线程回收方式，但是考虑到GC次数很高，由于GC每次都会暂停应用，因此对应用的影响是不可忽视的。

l  Full GC

Full GC是指新生代、旧生代、持久代一起进行GC。

引起Full GC的原因主要有三种：

1. 旧生代内存不足
2. 持久代内存不足
3. 统计新生代 GC晋升到旧生代的平均大小大于旧生代的剩余空间

Full GC回收成本高，应用会因此暂停更长时间，无法响应用户的请求。

l  Class Load情况

绿线表示卸载类的数量的累加总数，红线表示总共装载过的类的数量的累加总数，蓝线表示当前装载的类的数量的累加总数。绿线和红线的发展趋势是极其一 致的，即有大量的类被加载之后，又被卸载。加载类的信息存放在持久代。这也就从某方面印证了，持久代可能是在反复的加载类和卸载类，什么原因造成这种现 象，GC的可能性较大，我们接着看后续的分析。

GC Log情况

我们截取线上GC log的中的一段进行分析：

2011-08-23T04:24:27.413-0700: 611.162: [Full GC 611.162: [CMS: 985319K->721699K(1835008K), 2.9525910 secs] 1152585K->721699K(2070976K), [CMS Perm : 131071K->103472K(131072K)], 2.9528010 secs] [Times: user=2.87 sys=0.08, real=2.96 secs]

l  解释：

持久代：131071K->103472K 总空间：131072K

旧生代：985319K->721699K 总空间：1835008K

堆内存：1152585K->721699K 总空间：2070976K

此次Full GC时间花费2.96秒，在用户态（user）占用CPU百分比2.87，系统态（sys）占用百分比0.08。

l  分析：

数据很清晰了，持久代的GC是导致Full GC的原因，这和我们之前看到的类信息的加载之后又卸载之后又加载的现象是相符的。持久代空间不够，引起GC，GC回收类的信息，但是由于回收的类信息 JVM之后还需要，因此JVM又去加载这些信息。JVM就在这反复加载和卸载中消耗着资源，无暇响应用户的请求。

 

Unloading Log情况

我们继续观察显示控制台打出的unload的日志，这里打印出卸载类的情况。

sun.reflect.GeneratedSerializationConstructorAccessor这是sun的反射机使用到的类，当 事业反射newInstance()时，JVM会根据-Dsun.reflect.noInflation和 -Dsun.reflect.inflationThreshold判断是使用本地代码的反射构造器还是使用动态生成字节码构造出来的构造器，默认配置是 将会使用后者，这种方式的构造上更慢，但运行速度更快，对于使用大量反射的框架来言，后者更加合适。 GeneratedSerializationConstructorAccessor就是动态生成字节码构造出来的，后面的数字是表示累计创建类的数 量。针对一个类，同一个类加载构造器，反射的ConstructorAccessor只有一个。

可是wholesale短短启动不到3小时，怎么会有这么多ConstructorAccessor产生而且还被卸载呢？这些类是为了反射什么类而创建的呢？继续分析，下面只能dump jvm，看看内存中的情况具体是怎样了？

还有一点，线上的预发布机没有这种现象，没有大量的unloading日志，没有Full GC，他们的硬件和软件都是一样的，唯一不同的就是PV，这点很重要。

Dump JVM

我们去线上dump下来jvm的信息，使用MAT打开，看classloader Explorer，发现更多信息。

我们看到大量的DelegatingClassLoader，而且看到了GeneratedSerializationConstructorAccessor，

我们查看都有哪些类被加载，很明显JVM当中有大量的GeneratedSerializationConstructorAccessor+count类。

这说明JVM当中有很多ConstructorAccessor一大部分被卸载了，一小部分被留在JVM当中。而且，大家注意每个 ConstructorAccessor类都有自己独立的classloader，类信息的卸载规则是按照classloader来卸载，只有这个 loader中加载的所有类都不被使用，这些类信息才能被卸载。线上的信息好像就这么多了，我们看看DelegatingClassLoader能不能在 测试环境中debug到，看看具体是什么问题。

测试环境日志

我们在测试环境搭建一套wholesale环境，使用Jmeter小幅度压测wholesale的detail页面，随着wholesale稳 定，load日志出现明显的规律性现象。每次访问detail页面，都会有 GeneratedSerializationConstructorAccessor类

上图就是在10个线程并发访问wholesaledetail页面，load日志中的内容，问题应该是出现在这些类的加载上。我们debug一下，看看具体情况。

我们debug Classloader这个类的构造器，一次访问是有哪些classloader构造出来，最终debug到 DelegatingClassLoader，结合load日志，发现这个classloader加载后就会有 GeneratedSerializationConstructorAccessor被加载。依据堆栈查看调用信息。

我们看到ReflectionConverter的中的一段代码：

final Object result = instantiateNewInstance(context, reader.getAttribute(mapper.attributeForReadResolveField()));

ReflectionConverter是XStream的反射转换器，转换器是用来编码或解码Java对象的，也就是负责java对象和xml直 接的转换。instantiateNewInstance使用来初始化类的实例的，其中 reader.getAttribute(mapper.attributeForReadResolveField())就是 WholesaleProductPriceXstreamDTO类。

instantiateNewInstance方法中会先去context当中取这个类的实例，如果没有将会使用反射构造出类的实例，在构造实例时，他们创建新的类加载器，并执行下面的一段代码：

Constructor customConstructor = reflectionFactory.newConstructorForSerialization(type, javaLangObjectConstructor);

这段代码就是动态字节码创建类构造器的代码，我们debug发现customConstructor对象中正好包含sun.reflect.GeneratedSerializationConstructorAccessor对象。

而这段代码是在我们的业务二方库biz.wsproduct中调用的：

XStream xstream = new XStream();

xstream.alias(“root”, List.class);

xstream.alias(“record”, WholesaleProductPriceXstreamDTO.class);

问题很清楚了，就是这个XStream，业务代码中错误的new这个类，造成每次执行到这段代码都需要执行上面讲述的一段逻辑，都会load GeneratedSerializationConstructorAccessor类。

而且众所周知，wholesale detail pv巨大（200w以上），大量的类被加载，应该是造成PermGen使用吃紧的原因，而且由于是创造一个新的类加载器，这样一来一次访问结束，就可以回 收这个类加载器，回收其中的类信息，释放部分PermGen空间。这样我们就看到大量的unload出现，而且PermGen虽然空间紧张，但是从未 OOM的问题也就很容易解释了。

整体的堆栈信息如下（部分堆栈信息省略）：

Daemon Thread [TP-Processor39] (Suspended)

DelegatingClassLoader(ClassLoader).<init>(ClassLoader) line: 207

DelegatingClassLoader.<init>(ClassLoader) line: 54

…

MethodAccessorGenerator.generate(Class, String, Class[], Class, Class[], int, boolean, boolean, Class) line: 377

MethodAccessorGenerator.generateSerializationConstructor(Class, Class[], Class[], int, Class) line: 95

ReflectionFactory.newConstructorForSerialization(Class, Constructor) line: 313

Sun14ReflectionProvider.getMungedConstructor(Class) line: 61

Sun14ReflectionProvider.newInstance(Class) line: 40

ReflectionConverter.instantiateNewInstance(UnmarshallingContext, String) line: 145

ReflectionConverter.unmarshal(HierarchicalStreamReader, UnmarshallingContext) line: 87

…

XStream.unmarshal(HierarchicalStreamReader, Object, DataHolder) line: 521

XStream.unmarshal(HierarchicalStreamReader, Object) line: 509

XStream.fromXML(Reader) line: 475

XStream.fromXML(String) line: 468

WholesaleProductPriceXstreamHelper.convertXmlToWholesaleProductPriceDtoList(String) line: 55

WholesaleDetailUtil.getPriceDetailDTOFormProduct(WsProductDO, String) line: 404

WholesaleDetailUtil.getProductInfoDTOFromProduct(WsProductDO, String) line: 158

WholesaleProductDetail.process(RunData, TemplateContext) line: 282

WholesaleProductDetail(BaseDetailScreen).execute(RunData, TemplateContext) line: 73

WholesaleProductDetail(TemplateModule).execute(RunData) line: 38

…

解决方案：

解决方案比较简单，我们将XStream的设置成static变量，保证JVM当中只有一个这样的实例，在static块当中初始化，代码如下：

    private static XStream xstream = null;

    static {

        xstream = new XStream();

        xstream.alias(“root”, List.class);

 xstream.alias(“record”, WholesaleProductPriceXstreamDTO.class);

    }

 

解决效果：

根据最新的Dragoon监控日报显示：

Full GC的次数由原先的647次降至157次，

应用暂停时间由原来的1943232.0 ms （30分钟左右）降至488444.0 ms （8分钟左右），大大缩短了集群的暂停时间，基本解决问题。