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

Posted 2020-11-27 PerfMa

本文来自: PerfMa技术社区

PerfMa(笨马网络)官网

 

问题概述

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

问题初步定位

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

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

Demo复现

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

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

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

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

问题分析

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

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

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

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

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

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

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

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

这个时间的获取也是一样的，使用的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篇】

一次“诡异”的JVM缓存加载问题排查