周期性Full GC的异常排查

2021-08-13 04:53:20

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生成报告

码农公寓