应用周期性fullgc问题排查(1)

一、背景

图1 生产环境某应用A的 heap-usage

图1 生产环境某应用B的 heap-usage

由图1、图2可见heap和permGen使用率都不高，但是inquiry-center2台机器基本上每天会进行2次fullgc；

二、问题排查

 -Xms2g 
 -Xmx2g
 -Xmn448m
 -XX:SurvivorRatio=5
 -XX:+UseParNewGC
 -XX:+UseConcMarkSweepGC
 -XX:+CMSClassUnloadingEnabled
 -XX:+UseCMSCompactAtFullCollection
 -XX:CMSFullGCsBeforeCompaction=0
 -XX:+ExplicitGCInvokesConcurrent
 -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
 -XX:CMSInitiatingOccupancyFraction=75
 -XX:+UseCMSInitiatingOccupancyOnly
 -XX:+HeapDumpOnOutOfMemoryError
 -XX:MetaspaceSize=300M
 -XX:MaxMetaspaceSize=300M

   查看真线JVM配置参数CMSInitiatingOccupancyFraction=75，配置的内存是2g，实际堆内存维持在570M左右，老年代内存1.5625g，老年代内存使用率也低于75%，达不到触发fullGc的条件；基本上每次fullgc前后，堆内存也无明显变化；
   排查讨论，判断可能由于System.gc 引起的fullgc，根据pinpoint 触发fullgc的时间点，查看对应时间段的gc-log，确实是由于System.gc引起的fullgc；
   排除掉项目中的程序调用System.gc,判断可能是由于nio包调用的System.gc，但是没有找到具有参考价值的日志, 无法定位到具体的调用方法；
   通过反复观察gc日志，发现这些fullgc日志都是周期性的，且周期为10小时，如图3所示；根据GC日志分析可知，应用每10小时触发Full GC的现象大概率是外部组件调用引起的，根据这个线索，开始排查问题，了解到tomcat、nio、cxf部分版本可能会有类似周期性full gc问题。查看相关资料看到几篇博客 https://blog.csdn.net/qq_35963057/article/details/85236268，同样的也是每隔10小时full gc一次；因此大概率判断是由于apache的cxf包引起的full gc；

图3

三、定位分析

根据上述分析，查看应用的maven依赖，如图4，果然在应用中由于依赖了公司二方包，从而间接引入了apache-cxf包；

图4 项目maven依赖树

由于在apache-cxf下的JDKBugHacks利用反射调用了sun.misc.GC中的requestLatency方法如图5所示，调用该方法会创建一个守护线程如图6；

图5 JDKBugHacks类的doHacks方法

图6 GC类中创建守护线程

图7 run方法

   由图7可知，正是由于在守护线程的run方法中调用了System.gc方法导致了fullGc，同时由GC.lock.wait可知，var1是图5 反射调用传入的36000000ms即10小时，当一次fullgc后，var4会变成0，因此锁的等待时间是10小时，到这里就基本确定了在线询价真线是就是由于Apache的cxf包下的JDKBugHacks反射调用导致的；这个GC线程是为了预防部分组件造成的内存泄露问题(如javax.management.remote.rmi.RMIConnectorServer等会分配堆外内存)，通过调用sun.misc.GC类中requestLatency创建周期为10小时的GC守护线程，定期通知JVM去回收垃圾。
   这个线程会先判断是否已有其他组件通过requestLatency来创建了GC线程，如果创建了就跳过，否则新建守护进程。根据类名JDKBugHacks，也能猜测这个类是为了修复一些JDK或组件已有的问题，但这个定期FGC在本应用并不需要；
   由于是依赖的公司二方包引入的，项目中没有显式的调用相关类，需要继续排查是什么地方调用了JDKBugHacks这个类；
   排查发现是由于spring框架在初始化的时候进行了调用，如图8、图9所示(中间省略了几个调用节点，感兴趣的可以debug查看)；

图8 PostProcessorRegistrationDelegate类

图9 LogUtils类

四、解决方案

1、由图5可知，可以通过控制判断条件，让其不执行if 里面的逻辑
直接在启动项目的JVM参数中加入
-Dorg.apache.cxf.JDKBugHacks.gcRequestLatency=true 来使JDKBugHacks中的判断为false，然后跳过这段逻辑。
2、由于该包是保证金引入的，实际调用保证金接口并没有使用到该包，将Apache-cxf包排除,如图10所示；

如图10 pom文件

本次修改采用第二种解决方案；

图11 生产环境堆内存

真线19号20:00 发版以后，观察近三天确实不在出现fullgc；

五、其他

5.1、本次排查该问题，也发现了一些比较好的方案，虽然本次没有使用这些方案，但是记录下来，或许以后会用的到
如果希望把调用system.gc的方法，通过日志打印出来，就可以准确的定位到问题代码：
方法：
1)、通过lightTrace 该方法代码中如果有system.gc的调用会打印出调用的堆栈 (github地址：https://github.com/xpbob/lightTrace )
2)、通过btrace 编写代码追踪system.gc的调用方法 (github地址: https://github.com/btraceio/btrace)；
5.2、通过本次问题的排查，建议公司规范二方包的提供，应该尽量提供比较干净的二方包，除了本次导致fullgc问题，在项目开发中还经常会发生由于依赖的二方包引入了其他依赖，导致项目无法启动，这类问题通常比较隐蔽，很难快速准确的定位到；

应用周期性fullgc问题排查(1)