周期性Full GC的异常排查-阿里云开发者社区

1. 问题

近期发现线上应用的垃圾收集出现定时Full GC的异常现象，如下图所示：

图1 周期性Full GC(横坐标为时刻，纵坐标为gc耗时)

1）每隔10小时触发一次Full GC；
2）每次Full GC持续时间约为2~3秒；
3）与环境无关，线上环境、测试环境都会出现此问题；

集群批量发布后，此问题会导致各个机器执行FULL GC的频率和时间点大致相同，若FULL GC时间过长，会让负载均衡器觉得各个机器服务不可用，可能导致整个服务下线。

日常有了解到tomcat、nio、cxf部分版本可能会有类似周期性full gc问题^[1,2]。

2. 排查工具

gceasy.io^[3]
findBugs & ant
jstack

3. 环境与现象梳理

JVM内存分配中，堆内存为2G，永久代为256M，采用Parallel垃圾收集器，具体参数如下：

-XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxPermSize=268435456 -XX:PermSize=268435456 -XX:+UseParallelGC

为了获取更详细的垃圾收集信息，需要添加其他配置参数，：

-XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+PrintTenuringDistribution

以上JVM参数后续会另起一文详细介绍。

应用运行一段时间后观察GC.log，发现造成Full GC是由System.gc()方法引起的，说明是外部组件调用发起，而不是垃圾收集器因回收需要发起的。

{Heap before GC invocations=194 (full 1):
 PSYoungGen      total 691712K, used 518231K [0x00000007d5500000, 0x0000000800000000, 0x0000000800000000)
  eden space 688128K, 74% used [0x00000007d5500000,0x00000007f4c7df40,0x00000007ff500000)
  from space 3584K, 74% used [0x00000007ffc80000,0x00000007fff18000,0x0000000800000000)
  to   space 5632K, 0% used [0x00000007ff500000,0x00000007ff500000,0x00000007ffa80000)
 ParOldGen       total 1398272K, used 670385K [0x000000077ff80000, 0x00000007d5500000, 0x00000007d5500000)
  object space 1398272K, 47% used [0x000000077ff80000,0x00000007a8e2c7c8,0x00000007d5500000)
 PSPermGen       total 262144K, used 125738K [0x000000076ff80000, 0x000000077ff80000, 0x000000077ff80000)
  object space 262144K, 47% used [0x000000076ff80000,0x0000000777a4a938,0x000000077ff80000)
2017-01-17T00:02:23.510+0800: 36005.849: [GC (System.gc())
Desired survivor size 5767168 bytes, new threshold 1 (max 15)
 [PSYoungGen: 518231K->2816K(693760K)] 1188617K->673417K(2092032K), 0.0274540 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
Heap after GC invocations=194 (full 1):
 PSYoungGen      total 693760K, used 2816K [0x00000007d5500000, 0x0000000800000000, 0x0000000800000000)
  eden space 688128K, 0% used [0x00000007d5500000,0x00000007d5500000,0x00000007ff500000)
  from space 5632K, 50% used [0x00000007ff500000,0x00000007ff7c0010,0x00000007ffa80000)
  to   space 5632K, 0% used [0x00000007ffa80000,0x00000007ffa80000,0x0000000800000000)
 ParOldGen       total 1398272K, used 670601K [0x000000077ff80000, 0x00000007d5500000, 0x00000007d5500000)
  object space 1398272K, 47% used [0x000000077ff80000,0x00000007a8e627e8,0x00000007d5500000)
 PSPermGen       total 262144K, used 125738K [0x000000076ff80000, 0x000000077ff80000, 0x000000077ff80000)
  object space 262144K, 47% used [0x000000076ff80000,0x0000000777a4a938,0x000000077ff80000)
}

通过gceasy.io能直观地显示JVM内存与垃圾回收信息：
1）由数据表可看出，老年代中分配了1.33GB内存，但峰值只到了695MB内存。
内存分配

                                          <center> 图2 JVM内存分配与占用情况</center>

2）新生代在GC前基本都达到了配置内存的上线，GC后基本清空了整个新生代；

                                          <center> 图3 新生代内存GC前后情况</center>

3）老年代GC前后内存变化不大，而且发生FGC时，老年代占用量还不到分配的一半；

                                          <center> 图4 老年代内存GC前后情况</center>

4）永久代GC前后无明显变化；

                                        <center>  图5 永久代内存GC前后情况</center>

5）由下图可知，造成GC的原因有3种：

图6 导致GC的原因

System.gc() calls，表示System.gc()或者Runtime.getRuntime().gc()方法调用的次数，大部分的System.gc()会触发Full GC;
GCLocker Initiated GC，JNI临界区释放时会触发GC；
Allocaion Failure，当在新生代中没有足够空间分配对象时会发生Allocaion Failure，触发Young GC;

4. 顺藤摸瓜

根据GC日志分析可知，应用每10小时触发Full GC的现象大概率是外部组件调用引起的，于是开始顺藤摸瓜排查问题。
在确认项目自身代码没有显式调用System.gc()后，需要排查依赖组件，通过findBugs与ant工具来实现。

4.1 思路一：findBugs与ant工具排查依赖组件

项目由Maven管理，会依赖很多外部组件，无法通过搜索各个jar包源代码的方式来排查。此时FindGugs工具就派上用场了，众所周知，FindGugs是一个静态代码分析工具，主要用于找出代码中疑似的Bug，如空指针、没合理关闭资源、无正确初始化等。
其中有一类缺陷名是“DM_GC”，表示在代码中显式的调用垃圾回收命名，此操作知识建议JVM去回收，并不强制。在过去，有人在关闭操作或者finalize方法中调用垃圾回收方法，会导致很多性能浪费，同时大规模回收对象会造成处理器运行缓慢。
编写ant脚本并运行^[4]，在生成的报告中查找DM_GC相关记录，节选部分如下：

序号	类型	详情
1	DM	org.apache.xmlbeans.impl.jam.internal.parser.ParserClassBuilder $MainTool.parse(ParserClassBuilder, File) forces garbage collection; extremely dubious except in benchmarking codeBug type DM_GC
2	DM	org.apache.cxf.helpers.FileUtils.delete(File, boolean) forces garbage collection; extremely dubious except in benchmarking codeBug type DM_GC

根据findBugs查找出来的DM_GC记录，查阅相关组件源码，发现相关System.gc()调用场景与调用频率都不吻合。
　　

4.2 思路二：通过jstack查看JVM线程

通过监控与GC日志，发现应用每隔10小时会触发一次Full GC，间隔固定也相对平均，猜测是一个线程循环调用造成的。通过Jstack工具获取JVM线程，发现一个可疑线程：

"GC Daemon" daemon prio=10 tid=0x00007f41c1935000 nid=0x3495 in Object.wait() [0x00007f4192e83000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000d0423ef8> (a sun.misc.GC$LatencyLock)
    at sun.misc.GC$Daemon.run(GC.java:117)
    - locked <0x00000000d0423ef8> (a sun.misc.GC$LatencyLock)

一个名为GC Daemon的守护线程，由sun.misc.GC触发，与其他周期性触发Full GC的组件调用方法一致。
此时基本确定是此线程导致周期性Full GC的，但目前难点在于如何确定是哪个组件启动了这个守护进程。
比较合适的方法是，查看历史GC监控，找到第一次出现此现象的日期，并找到该短时间的发布功能，确认是哪个改动引起的。若没有历史GC监控，只能逐个依赖排查。
通过历史数据，发现当CXF升级到2.3.11版本后，应用开始出现周期性的Full GC。Apache CXF 是一个开源的 Services 框架，在该版本的CXF版本中，找到了GC Daemon守护进程创建的代码：

JDKBugHacks.java：
// Several components end up calling:
// sun.misc.GC.requestLatency(long)
//
// Those libraries / components known to trigger memory leaks due to
// eventual calls to requestLatency(long) are:
// - javax.management.remote.rmi.RMIConnectorServer.start()
try {
    if (!skipHack("org.apache.cxf.JDKBugHacks.gcRequestLatency")) {
        Class<?> clazz = Class.forName("sun.misc.GC");
        Method method = clazz.getDeclaredMethod("currentLatencyTarget");
        Long l = (Long)method.invoke(null);
        if (l != null && l.longValue() == 0) {
            //something already set it, move on
            method = clazz.getDeclaredMethod("requestLatency",
                new Class[] {Long.TYPE});
            method.invoke(null, Long.valueOf(36000000)); // 十小时
        }
    }                    
} catch (Throwable e) {
    //ignore
}

由上，JDKBugHacks会调用sun.misc.GC类的requestLatency方法，而该方法最终会创建一个名为“GC Daemon”、周期为传参10小时的守护线程，主要任务是定期完成垃圾收集，具体代码如下所示：

    public static LatencyRequest requestLatency(long l)
    {
        return new LatencyRequest(l);
    }

    private static class Daemon extends Thread
    {
        public void run()
        {
           // GC算法
           .....
        }
        public static void create()
        {
           .....
           public Void run()
           {
               // 创建线程相关信息
               .....
           }
           .....
        }
        private Daemon(ThreadGroup threadgroup)
        {
            super(threadgroup, "GC Daemon");
        }
    }

这个GC线程是为了预防部分组件造成的内存泄露问题(如javax.management.remote.rmi.RMIConnectorServer等会分配堆外内存)，通过调用sun.misc.GC类中requestLatency创建周期为10小时的GC守护线程，定期通知JVM去回收垃圾。
这个线程会先判断是否已有其他组件通过requestLatency来创建了GC线程，如果创建了就跳过，否则新建守护进程。根据类名JDKBugHacks，也能猜测这个类是为了修复一些JDK或组件已有的问题。但这个定期FGC在本应用并不需要，同时对性能也有很大影响。

5. 解决方案

到此，问题基本梳理清楚了，为了得到系统最优性能，有以下几点：

为了避免CXF组件引起的周期性Full GC，增加JVM启动参数可避免GC守护进程的创建，-Dorg.apache.cxf.JDKBugHacks.gcRequestLatency=true；
不能使用参数：-XX:+DisableExplicitGC；
为了降低Full GC时间，改用CMS并指定GC时使用并行回收；

附录参考文献

[1] The JreMemoryLeakPreventionListener causes a full GC every hour when gcDaemonProtection=true
[2] JVM每小时执行一次FULL GC问题
[3] GC日志可视化分析工具gceasy
[4] 利用findBugs插件来扫描代码，并用ant生成报告

周期性Full GC的异常排查

1. 问题

2. 排查工具

3. 环境与现象梳理

4. 顺藤摸瓜

4.1 思路一：findBugs与ant工具排查依赖组件

4.2 思路二：通过jstack查看JVM线程

5. 解决方案

附录参考文献

热门文章

最新文章

相关课程

相关电子书

周期性Full GC的异常排查

1. 问题

2. 排查工具

3. 环境与现象梳理

4. 顺藤摸瓜

4.1 思路一：findBugs与ant工具排查依赖组件

4.2 思路二：通过jstack查看JVM线程

5. 解决方案

附录 参考文献

热门文章

最新文章

相关课程

相关电子书

附录参考文献