性能文章>聊一个可能有惊喜的System GC知识点>

聊一个可能有惊喜的System GC知识点原创

2年前
8598111

问题概述

昨天晚上同事突然找我看个问题,有个系统一启动怎么就发生了System GC(从GC日志里看到了GC Cause是System GC),按照我的经验,这十有八九是堆外内存不够所致,但是启动就不够,这似乎不太可能,于是我又说是不是自己调用了,搜了下没有地方调。

image.png

问题初步定位

既然这样我就说要不你直接debug吧,断点设置在System.gc方法上,这样当调用这个方法的时候就可以看到调用栈了,这么操作下来果然看到了,是sun.misc.GC的一个叫做Daemon的内部类的run方法里调用的

image.png

当然如果是生产环境,不能随便让你debug,我们可以通过btrace之类的工具也可以照样看到调用栈,办法还是很多的

Demo复现

看到调用栈,我立马想到RMI,我们系统确实有用到RMI,因为这个系统会去和远程进程通过RMI通信,按照我的经验,RMI是会定期进行System GC的,时间默认是一个小时,控制这个间隔的参数是下面两个:

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

为了让问题更加简单排查,于是我写了一个demo来模拟

image.png

为了跑上面的程序,我们在本地随便先运行一个java进程,然后拿到对应的进程号,作为第一个程序参数传给上面的程序,我们可以加上几个JVM参数打印GC日志,整个启动的命令大概是

image.png

问题分析

通过上面的Demo,果然立马就复现了,不是默认1个小时才System GC吗,怎么一上来就System GC了?

估计有些人猜到了RMI,也知道上面的参数可以控制GC间隔,至于为什么会立马就触发一次System GC也感到疑惑,我之前这块也没注意,不过经过分析下来,真正的情况还远不是你看到的这种情况,真实情况是既可以立马发生,也可能不定时发生,取决于你的GC算法,取决于你的操作系统重启的时间,听到这里是不是感觉越来越有意思了?

OK,那开始我们的分析之旅,先来看我们的Daemon的run方法

image.png

其中maxObjectInspectionAge是一个native方法,第一次执行的时候,可以认为latencyTarget的值就是一个小时,也就是36000000,那是不是触发Sysmte GC就是看maxObjectInspectionAge返回的值是不是比一个小时大了,如果超过了一个小时,立马触发System GC,那现在的重点就是看maxObjectInspectionAge这个native方法了

image.png

从上面的逻辑大概是看这个堆最后一次gc的时候是什么时候,为了方便分析,我直接使用CMS GC下的逻辑吧,其他GC算法也类似

image.png

首先取了纳秒时间,这个纳秒的时间的获取还和操作系统有关,我举例linux下的情况

image.png

如果linux支持CLOCK_MONOTONIC,那返回的值是从操作系统启动的时间到现在的相对纳秒数,关于CLOCK_MONOTONIC我就不多说了,大家可以去搜下POSIX定义的几种clock,我们测试跑的系统是支持这种的,所以直接会返回的是相对操作系统启动的纳秒数

接着遍历新生代和老生代各自最后的一次GC的时间

image.png

image.png

这个时间的获取也是一样的,使用的os::javaTimeNanos获取的,大概的意思就是取新生代和老生代各自被回收的那个时间相对早期的时间,比如说我先做了老生代的GC,会更新老生代的_time_of_last_gc变量为当前纳秒数,后面又做了新生代的GC,会更新新生代的_time_of_last_gc变量为当前纳秒书,那返回的这个时间会是老生代的_time_of_last_gc变量值,这个时间暂时取名t2,所以上面那个maxObjectInspectionAge的native方法返回的是当前时间的纳秒数和t2的时间差,所以当这个两个时间差超过1个小时的时候就会进行System GC

那问题就来了,如果我们之前一直什么GC都没发生,或者只发生了一方的GC,比如只做了YGC,或者只做了Old GC,那上面的t2的值就和GC算法有关了,在PS GC下会默认初始化设置值为0,

jlong               PSParallelCompact::_time_of_last_gc = 0;
jlong               PSMarkSweep::_time_of_last_gc   = 0;

但是在CMS GC下我们看到其实并没有做初始化,没有做初始化,这个值就不确定了,和编译器有关

所以我这里以比较确定的PS算法为例

  • 如果操作系统已经运行一个多小时了,那立马就会触发第一次System GC

  • 如果操作系统运行了20分钟,那40分钟后会触发第一次Sysmte GC

问题结论

所以当我们看到System GC触发的时候,除了我们熟悉的几种场景外,RMI场景下第一次System GC的触发也是有很多因素决定的,希望这篇文章能让大家受益

说起System GC,我相信有些人会想到DisableExplicitGC这个JVM参数,通过打开这个参数来禁掉System GC的发生,不过我不建议大家设置这个参数,既然JVM想做System GC了,那一定是需要做了才做,直接禁掉带来的风险可能会更大,为了让大家更好地了解JVM参数的实现原理,近期在PerfMa社区,给大家开一个JVM参数详解的课程。

大家一起来学习吧PerfMa KO 系列之 JVM 参数【Memory篇】

请先登录,再评论

大佬,我只想弱弱地问问:头发得掉多少才能学到您这个水平?😰😰😰

2年前
回复 一根腊肠:

我头发还挺多啊😅

2年前回复

为你推荐

不起眼,但是足以让你有收获的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有多熟悉,看到这篇文章,应该还是会有点小惊讶的,不过我觉得这个案例我分享出来,是想表达不管多么奇怪的现象请一定要追究下去,会让你慢慢变得强大起来,
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得