记一次每隔一小时 [Full GC (System.gc())问题的解决过程

1. 现象

最近在查看线上gc日志时,发现有一个系统通过System.gc()调用而导致频繁Full GC。而且这个调用是周期性的(每隔一个小时),详细大家可以参看以下日志截图(图1):

图-1

2. 分析过程

从(图1)中,我们可以发现:

1. Full GC每隔一个小时被触发一次,而且FULL GC的原因是因为系统有地方显示的调用了System.gc()方法

2. 这个触发是周期性的。通过日志可以发现很明显,每隔一个小时就GC一次 

3. 堆内存一切都正常,系统设置了2G的堆内存,老生代100M+远没有达到Gc的触发阈值

根据以上的分析,找问题的基本方向就比较直接: 系统的某个地方有人显式创建了一个线程调用了System.gc()方法,而这个很有可能是引入了三方JAR包或则是框架引起的。所以,立马就Google一把,通过关键字: 'Full GC', 'one hour', 'System.gc()'等信息,可以很容易的过滤出一些信息,如果你对系统代码很熟悉,基本就可以定位到问题的根源。 通过google,我们可以发现:如果系统中使用了JAVA RMI框架,那么它会引起 Full GC 并且频率默认刚刚好是一个小时。正好,我们系统由于要动态修改日志级别,使用了JAVA RMI框架。解决方法:

1. 可以设置 sun.rmi.dgc.client.gcIntervalsun.rmi.dgc.server.gcInterval -D变量修改这个间隔频率

2. -XX:-DisableExplicitGC 通过使用该JVM参数来禁止显式调用System.gc()

好了,分析到这里,我们似乎已经把问题解决了(确实,通过以上2点的修改,我们能解决这个问题)。

但是。。。。 作为一个码农,总觉得这种解决方法太肤浅了,根本就没有找到root cause,比如:

1. 这个参数'sun.rmi.dgc.client.gcInterval' 在哪里被用到了?

2. 这个定时每隔1小时调用一次的线程到底在哪里?是如何被创建的?我们怎么找到他?

如果就此把电脑合上,那我肯定会睡不着觉。。。

所以,我们继续哈。。。

由于和线程相关,所以,我们就先dump出当前JVM的线程堆栈:

DUMP出来的堆栈有几十个线程,没用工具,直接打开VScode浏览了几遍,发现有一个叫'GC Daemon'的线程疑点最大,我们来看一下它的堆栈(图2):

图-2

所以,我们需要查看sun.misc.GC类的源码,由于自带的JDK8没有这个包的源码,大家可以通过这里去下载OPENJDK的源代码,截取一段代码(图3):

图-3

果然,这里起了一个线程,然后线程里面有显式的调用System.gc()。这个类中,关键是一个阈值'latencyTarget' 它决定了gc的频率,所以,一定有一个地方设置了这个值,并且通过GC.create()方法创建了这个线程,我们得找出来。好,那么我们继续看线程堆栈,可以发现有个线程名'RMI RenewClean'跟GC有点关系(图4):

图-4

好,我们查看DGCClient中RenewCleanThread的源码(图-5),对就是这里:GC.requestLatency()这个方法调用,创建了图3的daemon线程(大家可以跟代码去看下最后调用到了GC.create()),而这个间隔值 'gcInterval' 正好取值自-D变量 ( 图6)'sun.rmi.dgc.client.gcInterval' (sun.rmi.dgc.server.gcInterval变量似乎没用到哈)

图-5
图-6

3. 结论

到此,我想我已经找出了问题的根源,解决方法可以通过适当的增大这个-D变量来防止频繁FULL GC。第二个选项(DisableExplicitGC),个人觉得处理比较粗暴,粒度太大。

*** 推荐我的另外几篇文章 ***

1. MySQL 5.6 5.7 如何自定义行锁超时等待

2. 微服务化遇坑之(一)- ZuulRoute, stripPrefix

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 216,402评论 6 499
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,377评论 3 392
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 162,483评论 0 353
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,165评论 1 292
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,176评论 6 388
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,146评论 1 297
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,032评论 3 417
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,896评论 0 274
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,311评论 1 310
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,536评论 2 332
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,696评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,413评论 5 343
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,008评论 3 325
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,659评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,815评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,698评论 2 368
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,592评论 2 353

推荐阅读更多精彩内容