每隔一小时执行一次 Full GC 分析排查

[jiangxinlingdu]

上次分析详细地址在：JVM 菜鸟进阶高手之路五 以为上次问题是 rmi 的问题就此结束了，但是问题并没有结束，其实本次问题不是 rmi 问题导致的，但是 rmi 也的确可能会有 sys.gc fullgc 问题。 查看 GC 统计汇总情况：

jstat -gcutil pid  3s 30 

参考 gc，发现大概一小时运行一次 FGC，特别奇怪，笨神一看这样的问题就知道是 system gc 导致的System.gc()的默认效果是引发一次 stop-the-world 的 full GC，对整个 GC 堆做收集。用 -XX:+DisableExplicitGC参数后，System.gc()的调用就会变成一个空调用，完全不会触发任何 GC。

问题来了 如果直接使用-XX:+DisableExplicitGC 就没有下面的任何事情了，在测试过程中的确使用了该参数，的确不会有 full gc 了。但是有写堆外空间的释放是需要涉及到 System.gc 的，如果禁用可能见到 direct memory 的 OOM 类似的异常，由于各种原因我们的环境没有禁用。由于没有禁用，添加参数**-XX:+ExplicitGCInvokesConcurrent** 该方法可以指定 System.gc()采用 CMS 算法，FGC 时停机时间会变短，但是 CMS GC 次数不会变。通过该参数 经过观察日志效果比 Full GC 要好些。

看到这里一切都挺完美，后面开始要到高潮了，纠结…………看上篇文章里面有说一直以为是 rmi 问题，就查找资料想让时间延迟下执行，

-Dsun.rmi.dgc.client.gcInterval=36000000 
-Dsun.rmi.dgc.server.gcInterval=36000000

单位是毫秒，可适当延长触发 FGC 的定时时间间隔。 文中配置为 10 小时。通过 jstack 查看 JVM 线程

   GC Daemon" daemon prio=10 tid=0x00007f91bcccf800 nid=0x37f0 in Object.wait() [0x00007f9182706000]  
   java.lang.Thread.State: TIMED_WAITING (on object monitor)  
    at java.lang.Object.wait(Native Method)  
    - waiting on <0x0000000600021a48> (a sun.misc.GC$LatencyLock)  
    at sun.misc.GC$Daemon.run(GC.java:117)  
    - locked <0x0000000600021a48> (a sun.misc.GC$LatencyLock)  
  
   Locked ownable synchronizers:  
    - None  

笨神告诉我们，如果该线程一旦创建了就会间隔的调用 gc 了，所以就会存在定时继续 full gc 问题。一直通过观察居然没有效果，还是会一小时执行一个 full gc。通过 gc 日志可以出出来： 而且 old 区 6g 才占 2.5G 就 background cms gc 了修改为 cms 的时候，每次 System.gc 一次 full gc 的时候 cms gc 还会加 2 的，触发的是 background cms gc 如果不是后台就会一次，cms 过程如下：里面有一些概念比较重要，并行和并发的定义。gc 这个场景下 你可以这么记 并发表示 gc 线程可以和业务线程同时跑 并行表示 gc 线程跑的时候业务线程都全不能跑 。

在 Java 9 中将 Java 8 默认的 GC 从 Parallel GC 改为 G1，cms 不是和 ps 比速度的，cms 是低延时垃圾回收器。

开始纠结了笨神告诉需要通过 btrace 跟踪下就很容易定位到问题那里调用了 System.gc,根据 ak 大神提供的地址，之后阿飞给了我关于 btrace 新的 github 地址： https://github.com/btraceio/btrace。 以及一些 Sample 参考： https://github.com/btraceio/btrace/tree/master/samples。github 官网很多参考样例，基本上能覆盖常用的需求编写了查看 gc 代码如下：

@OnMethod(clazz = "java.lang.System", method = "gc")    
    public static void onSystemGC() {    
        println("entered System.gc()");    
        jstack();    
} 

在本地调用模拟结果如下：放到环境进行观察，也获取到了结果如下：打印到这里 知道是 sun.misc.GC 调用的，在这里走了很多弯路了，后来我把 rmi 去掉了，但是还是一小时一次通过日志观察，后来搜索发现 tomcat 文章，的确有，开始也没有注意，以为是这个原因，修改了重试还是不行，后是一波折过程，后来查看 jar 文件，的确不是一小时了， 后来又看见以为这个包问题，又是一波修改，发现还是一小时执行一次通过日志观察，此时我已经无语了，不过还好在我的坚持下，还是把问题找到了，由于我把项目去掉跑不会有，那么感觉和项目有关，但是代码里面的确没有调用，我怀疑是否是其他 jar 里面的问题呢？我把所有的 jar 都查了一遍，的确发现问题了。查看该 jar由于包的确有点老了，里面的确是这样，和上面的 tomcat 那个 bug 很像，我下载了一个新版本查看，发现的确优化了。新版本里面变成了 10 个小时一次了，而且可以通过 jvm 参数让其进行关闭， -Dorg.apache.cxf.JDKBugHacks.gcRequestLatency=true即可。这次的这个一小时问题排除就结束了，还需要修改代码，后续继续观察，在此过程中，ak 大神和阿飞都告诉我关于 ygc 时间问题，的确这个还一直在实验，希望优化的更好，内容很多一直也在学习，定位问题就是需要大胆的猜之后试之后优化修改记录。后续会分享关于 ygc 时间长问题，推荐一款在线分析 gc 的好工具析，http://gceasy.io 。 非常棒，在此再次感谢笨神，阿飞哥，ak 大神的指导。