性能文章>JVM菜鸟进阶高手之路六(JVM每隔一小时执行一次Full GC)>

JVM菜鸟进阶高手之路六(JVM每隔一小时执行一次Full GC)原创

2年前
712900

以为上次问题是rmi的问题就此结束了,但是问题并没有结束,其实本次问题不是rmi问题导致的,但是rmi也的确可能会有sys.gc fullgc问题。
查看GC统计汇总情况:
jstat -gcutil pid 3s30
image.png
参考gc,发现大概一小时运行一次FGC,特别奇怪,笨神一看这样的问题就知道是system gc导致的
image.png

image.png
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  

image.png
笨神告诉我们,如果该线程一旦创建了就会间隔的调用gc了,所以就会存在定时继续full gc问题。一直通过观察居然没有效果,还是会一小时执行一个full gc。通过gc日志可以出出来:
image.png
而且old区6g才占2.5G就background cms gc了
image.png
修改为cms的时候,每次System.gc 一次full gc的时候cms gc还会加2的,触发的是background cms gc如果不是后台就会一次,cms过程如下:
image.png
里面有一些概念比较重要,并行和并发的定义。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();    }

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

请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

不起眼,但是足以让你有收获的JVM内存分析案例
分析 这个问题说白了,就是说有些int[]对象不知道是哪里来的,于是我拿他的例子跑了跑,好像还真有这么回事。点该 dump 文件详情,查看相关的 int[] 数组,点该对象的“被引用对象”,发现所
从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
关于内存溢出,咱再聊点有意思的?
概述 上篇文章讲了JVM在GC上的一个设计缺陷,揪出一个导致GC慢慢变长的JVM设计缺陷,可能有不少人还是没怎么看明白的,今天准备讲的大家应该都很容易看明白 本文其实很犹豫写不写,因为感觉没有
协助美团kafka团队定位到的一个JVM Crash问题
概述 有挺长一段时间没写技术文章了,正好这两天美团kafka团队有位小伙伴加了我微信,然后咨询了一个JVM crash的问题,大家对crash的问题都比较无奈,因为没有现场,信息量不多,碰到这类问题我
又发现一个导致JVM物理内存消耗大的Bug(已提交Patch)
概述 最近我们公司在帮一个客户查一个JVM的问题(JDK1.8.0_191-b12),发现一个系统老是被OS Kill掉,是内存泄露导致的。在查的过程中,阴差阳错地发现了JVM另外的一个Bug。这个B
JVM实战:优化我的IDEA GC
IDEA是个好东西,可以说是地球上最好的Java开发工具,但是偶尔也会卡顿,仔细想想IDEA也是Java开发的,会不会和GC有关,于是就有了接下来对IDEA的GC进行调优 IDEA默认JVM参数: -
不起眼,但是足以让你收获的JVM内存案例
今天的这个案例我觉得应该会让你涨姿势吧,不管你对JVM有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得