由exception引起的promotion failed问题的排查与解决

web系统间歇性抽疯问题排查与解决

 

最近发现维护的web系统经常不定期出现持续时间很短的不可访问的问题（502错误）。问题出现时间不定，持续时间大概在1-2分钟左右。

 

1.问题定位：

出现问题的第一反应是系统挂了，但是过了2分钟左右还没来得及重启系统，就恢复正常了，所以排除系统挂了的原因。第二反应是可能当时的流量较大，恰好自己的请求没有来不及响应。但是根据当时的流量，并没有发生显著提高，另外如果流量大的话，不停的刷新请求，总有一个能够被响应，但是在出问题的那段时间内没有一条请求被响应，于是可以排除这个原因。最后一个可能的原因就是full gc了。于是把gc log拉下看，一看惊呆了，发现cms 基本几分钟一次，而且80% 的cms 发生了concurrent promotion failure。还有几次young gc发生了promotion failed。promotion failed 发生后 并行young gc将会变成 串行 young gc,而串行yong gc 期间会暂停用户线程，不响应用户请求。下图是一次promotion failed的时间。

 

图1：Promtion failed

通过gc 日志可以看出，一次promotion failed导致的full gc的时间长达113秒，这近2分钟时间里，服务器基本暂停服务了，相当于服务器挂了2分钟。而这也是导致服务器不定时抽风1,2分钟的直接原因。

 

2.根本原因定位与分析

promtiom failed是导致服务器抽风的直接原因，但是为什么会promtiom failed呢？gc 发生promtion failed的原因是发生young gc的时候，eden区和survior区的from块里面存活的对象要复制到survior区的to块里面。如果to块满了，那么yong gc的悲观策略将使还存活的对象移到old 区。但是此时 old区也满了，对象放不进去，于是导致promtiom failed了。这种问题的出现一般有2个：一般是survior区太小，另个是调低old区触发cms gc的阈值。

 

2.1调整jvm参数

为了解决promtion failed，所以先了解了下服务器的系统内存大小和jvm设置。目前服务器的内存大小为4G，jvm主要参数如下-Xms2560m -Xmx2560m -Xss256k -XX:PermSize=128m -XX:MaxPermSize=384m -XX:NewSize=1024m -XX:MaxNewSize=1024m -XX:SurvivorRatio=22 -XX:+UseParNewGC -XX:ParallelGCThreads=4 -XX:MaxTenuringThreshold=9 -XX:+UseConcMarkSweepGC -XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+ScavengeBeforeFullGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSParallelRemarkEnabled -XX:CMSFullGCsBeforeCompaction=9 -XX:CMSInitiatingOccupancyFraction=60 -XX:+CMSClassUnloadingEnabled -XX:SoftRefLRUPolicyMSPerMB=0 -XX:-ReduceInitialCardMarks -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingPermOccupancyFraction=70 -XX:+ExplicitGCInvokesConcurrent

通过jvm参数发现survior区确实稍微小了些于是把-XX:SurvivorRatio改为了10，-XX:CMSInitiatingOccupancyFraction=60也已经比较小了，再调小的话，也容易使cms gc频繁。通过日志中发现preclean与sweep之间的时间间隔比较长，时间长的话，一方面还在接收请求消耗内存，另一方面old区快满了并且还没开始清理，这个阶段容易导致concurrent promotion failure。下图就发现有的cms sweep阶段发生concurrent promotion failure。

图2：preclean与sweep时间太长

于是添加了一个参数-XX: CMSMaxAbortablePrecleanTime=1000，来限制preclean的时间。最后通过top命令观察服务器的内存使用率，4G的内存只剩下200M左右的free memory了，没有办法再增大heap了。

在一台机器上加上-XX:SurvivorRatio=10，XX: CMSMaxAbortablePrecleanTime=1000 这两个参数之后观察，发现concurrent promotion failure情况并没有改善，cms gc次数也没有减少，而且young gc还频繁了些，（这是调大survior区降低了eden区导致的）。机器内存有限，heap不能调大，survior区也不可能无限增大。所以调整jvm没有办法解决问题。也说明问题不在jvm参数上。

 

2.2 应用系统分析

于是到应用系统本身上定位原因。再仔细分析gc log 发现，每次young区满的时候，晋升到old的内存有几十M甚至超过100M，young gc的频率大概1秒一次，而且单机的tps也不高 ，平均也就4,5的样子。这相当于一次请求有30M左右的对象创建，而且晋升到old区的对象那么多，没有在young gc的时候回收掉，难道有内存泄露？

为了解决上面的疑惑，先用jprofier在本地上分析每次请求的内存大小。如下图所示，发现每次请求大概20-30M左右的对象被创建。这个临时对象创建确实有点多。

图3：单次请求内存消耗

为了定位是不是存在内存泄露，从线上dump内存，用Mat进行分析，通过几次不同时间的dump，发现old区常驻内存大小都是150M左右，这说明不存在内存泄露。下图是dump内存分析图。

图4：dump内存分析图

没有内存泄露，那为什么每次会有那么大对象晋升到old区？再回过头来分析gc log，看看是什么情况下young 区有那么多对象晋升到old区的。这一看还真发现一个问题，每次对象晋升的时候，survior区使用率都是基本都是100%。如下图所示：

这说明这些对象不是生命周期长自然晋升的，而是young区的悲观策略导致的，即survior区满了，对象放不下而直接晋升到old区的。

到目前为止，可以得出以下结论：jvm参数没有太大问题；不存在内存泄露，单次请求消耗内存太大，很多临时对象没有活过年龄就晋升到old区了。那么old区到底有什么东西？但是通过上面的dump图，都是些常驻内存的对象。dump下来文件有700多兆，为什么分析只剩下150M了呢？于是查资料发现mat默认分析的是活着的对象，需要选择unreachable objects再分析。

      通过domintor_tree发现，里面有很多10MB左右的大字符串，而这个字符串是只是一个exception。这说明应用系统里抛出了某个exception，而这个exception字符串居然需要10MB内存。不管这个exception是不是最终的罪魁祸首，都需要先解决才能再进行下一步分析，因为只要解决了这个问题，一次请求就可以减少10M的临时对象创建。

 

2.3 exception问题的定位和解决

为什么一个exception会需要那么大的内存呢？于是对应用系统的log进行了分析，发现代码里某个地方抛出了空指针exception，这个空指针exception没有及时捕获，于是会进行往外层调用抛出，由最近的一个捕获exception的方法捕获，而这个方法是系统应用调用的公司内部的一个处理页面公共框架的方法捕获并在应用打印出异常，这个打印异常的方法会把整个页面用的所有对象打印出来。所以打印异常创建的字符串非常大。解决这个exception的方法：

1.修复空指针异常，并及时在代码里加上异常捕获代码，及时捕获异常，以免异常向外层传递而引发一些不可控的问题。

2.这个问题也暴露出应用的一个bug，即页面本身的数据对象太大了，需要把没有用的数据对象抛弃。

解决了该异常之后，再观察gc log，发现gc日志终于恢复正常，full gc完全消除了，同时 young gc的频率也减少了5倍。说明这个exception就是导致问题的罪魁祸首。

现在回过头来总结下系统不定期发生1-2分钟无法访问的问题发生的整个原因：应用系统中某个地方抛出异常，该异常没有及时被捕获而逃逸到外面，被外层的个方法捕获并打印到日志中。这个方法会把一个很大的字符串打印出来，所以需要创建一个10M左右的临时对象。由于这个临时对象非常大，导致young 区 young gc非常频繁，并且经常由于在young 区分配失败而直接在old 区分配，从而使得old区 gc也非常频繁。频繁创建大临时对象可能导致的另一个非常严重的后果是，gc没有及时回收垃圾而使得内存分配失败，从而发生 promtion failed 或 concurrent promotion failure，这使得 并行 gc 转为串行 full gc，使系统长时间暂停用户请求。

 

3.Jvm调优

系统问题解决了，虽然并不是jvm参数引发的。但是也发现了jvm参数中可以进行了优化的地方。主要是下面三个方面：

1.设置-XX:SurvivorRatio=10，增加了survior区的大小，这样虽然 会导致young gc频率亏快一些，但是可以让临时对象尽量可能在young 区回收，减少old gc 的压力。同时减少yong gc时还存活的对象能尽可能的在survior区创建，而不是直接移到old 区，减少发生 concurrent promotion failure。

2.增加参数-XX: CMSMaxAbortablePrecleanTime=1000。减少 preclean与cms-sweep之间时间过长，而导致 concurrent promotion failure的概率。

3.增加-XX:+UseCompressedOops。该参数是的作用是在64位机中对普通指针进行压缩。从而可以节约内存使用空间。通过加与不加该参数进行内存对比，大小内存可以节约10%，在内存有限的机器上，算比较可观了。

4. 总结

通过对整个问题的分析定位到解决，可以有以下收获：

1.关于异常要妥善处理，有抛异常的地方需要及时捕获处理。

2.应用系统日志和gc 日志是非常重要的资料，它们反映了系统的健康状况，也是分析问题解决问题的主要依据。

3.内存分析是解决问题的一种非常有效的方法。