JAVA HotSpot GC收集器实践记录

本文收录在javaskill.cn中,内有完整的JAVA知识地图,欢迎访问

简介

最近仔细研读了《深入理解JAVA虚拟机:JVM高级特性与最佳实践》的前几章,本文仅仅是本人对理论的一次实践,记录了其中认为比较有参考意义的数据,可能没有太过清晰的主旨,一切尽在数据中,还请各位自行领悟

背景

项目:某中小型P2P平台的开发环境
规模:100+个包,1000+个类
环境:JDK1.8,运行在tomcat7
监控工具:jvisualvm
插件:visual GC
IDE:IDEA
开发机:I5 6代,16G内存,机械硬盘

未调优

image.png

使用IDEA,配置tomcat7,JVM只配置打印GC详情

启动时连续进行了几次GC,有自动扩容

[GC (Allocation Failure) [PSYoungGen: 74450K->10722K(140800K)] 74538K->11500K(314368K), 0.0077791 secs] [Times: user=0.05 sys=0.02, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 140770K->10729K(140800K)] 141548K->29367K(314368K), 0.0131030 secs] [Times: user=0.00 sys=0.06, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 140777K->10727K(270848K)] 159415K->52226K(444416K), 0.2930469 secs] [Times: user=1.01 sys=0.03, real=0.29 secs]
[GC (Allocation Failure) [PSYoungGen: 270823K->10734K(270848K)] 312322K->97056K(444416K), 0.0297877 secs] [Times: user=0.11 sys=0.02, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 270830K->55021K(570368K)] 357152K->141351K(743936K), 0.0301665 secs] [Times: user=0.06 sys=0.03, real=0.03 secs]

紧接着发生了FULL GC

[GC (Metadata GC Threshold) [PSYoungGen: 371716K->19006K(958464K)] 458722K->106020K(1165312K), 0.0602449 secs] [Times: user=0.19 sys=0.02, real=0.06 secs]
[Full GC (Metadata GC Threshold) [PSYoungGen: 19006K->0K(958464K)] [ParOldGen: 87014K->41766K(181760K)] 106020K->41766K(1140224K), [Metaspace: 34608K->34608K(1081344K)], 0.1005065 secs] [Times: user=0.30 sys=0.00, real=0.10 secs]

首次YGC信息如下

[GC (Allocation Failure) [PSYoungGen: 1285211K->55541K(1279488K)] 1382177K->152523K(1532928K), 0.0547766 secs] [Times: user=0.03 sys=0.03, real=0.05 secs]

退出信息:

Heap
PSYoungGen total 1291264K, used 894757K [0x000000076b700000, 0x00000007bf900000, 0x00000007c0000000)
eden space 1214464K, 71% used [0x000000076b700000,0x00000007a0a3d8c0,0x00000007b5900000)
from space 76800K, 30% used [0x00000007bae00000,0x00000007bc48bba8,0x00000007bf900000)
to space 81920K, 0% used [0x00000007b5900000,0x00000007b5900000,0x00000007ba900000)
ParOldGen total 254464K, used 135040K [0x00000006c2400000, 0x00000006d1c80000, 0x000000076b700000)
object space 254464K, 53% used [0x00000006c2400000,0x00000006ca7e0050,0x00000006d1c80000)
Metaspace used 87954K, capacity 90446K, committed 90712K, reserved 1130496K
class space used 8859K, capacity 9284K, committed 9304K, reserved 1048576K

分析

可以看到,默认分配了4G内存,使用了PSY和PS Old收集器,因为使用的是Server版的JVM,如果使用的是Client版,应该是Serial收集器
由于Eden区较大,总共有1.32G,再加上一个Survivor区,接近2G的Eden区,发生回收的时间间隔相对较长
同时也看到Eden区的曲线呈现出不正常的增长状态,可以推断出应用在高并发的时候将会产生频繁的GC,并发数不高。

Serial收集器

在切换成CMS收集器之前,试一下Serial收集器
参数:-XX:+PrintGCDetails -XX:+UseSerialGC -XX:+UseAdaptiveSizePolicy


image.png

GC日志,不停的GC,没有扩容

[GC (Allocation Failure) [DefNew: 78015K->5042K(78016K), 0.0168682 secs] 78680K->12472K(251456K), 0.0169003 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
[GC (Allocation Failure) [DefNew: 74418K->8639K(78016K), 0.0108030 secs] 81848K->20846K(251456K), 0.0108293 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78015K->8640K(78016K), 0.0125506 secs] 90222K->25457K(251456K), 0.0125782 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78016K->8639K(78016K), 0.0106712 secs] 94833K->29123K(251456K), 0.0107017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78015K->8639K(78016K), 0.0103645 secs] 98499K->33091K(251456K), 0.0103934 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78015K->8640K(78016K), 0.0114821 secs] 102467K->38312K(251456K), 0.0115174 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78016K->8640K(78016K), 0.0110741 secs] 107688K->44082K(251456K), 0.0111046 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78016K->8640K(78016K), 0.0152640 secs] 113458K->48616K(251456K), 0.0153218 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
[GC (Allocation Failure) [DefNew: 78016K->8639K(78016K), 0.0122584 secs] 117992K->53902K(251456K), 0.0123065 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78015K->8639K(78016K), 0.0108011 secs] 123278K->58603K(251456K), 0.0108296 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78015K->8640K(78016K), 0.0112143 secs] 127979K->63832K(251456K), 0.0112431 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78016K->8640K(78016K), 0.0115289 secs] 133208K->68550K(251456K), 0.0115565 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78016K->8640K(78016K), 0.0102163 secs] 137926K->73558K(251456K), 0.0102439 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 78143K->7811K(78144K), 0.0102471 secs] 163976K->94333K(251584K), 0.0102773 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 77315K->1221K(78144K), 0.0079635 secs] 163837K->88451K(251584K), 0.0080104 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 70725K->1821K(78144K), 0.0085406 secs] 157955K->89051K(251584K), 0.0085753 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 71325K->2733K(78144K), 0.0096649 secs] 158555K->89963K(251584K), 0.0096944 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 72237K->3278K(78144K), 0.0098166 secs] 159467K->90508K(251584K), 0.0098462 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 72782K->4311K(78144K), 0.0127030 secs] 160012K->91541K(251584K), 0.0127498 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [DefNew: 73815K->8639K(78144K), 0.0150915 secs] 161045K->96460K(251584K), 0.0151364 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

分析

Eden几十M就开始回收,GC频繁,刷新了几次页面就进行了近百次GC,原因是没有指定最大最小堆,初始值较低,GC又一直有效,所以一直没有扩容,并频繁GC

参数:-XX:+PrintGCDetails -XX:+UseSerialGC -Xmx4g -Xms4g -Xmn2g
启动图如下:


image.png

分析

其中进行了几次比较有意思的GC

启动的时候进行了一次GC,可以观察到,新生代已经直接是最大大小(图上也可以看出),刚开始tomcat应该做了大量的操作,产生了大量的对象

[GC (Allocation Failure) [DefNew: 1677824K->142627K(1887488K), 0.0982925 secs] 1677824K->142627K(3984640K), 0.0983339 secs] [Times: user=0.08 sys=0.01, real=0.10 secs]

紧接着进行了一次元空间的GC,从图上可以看出,元空间最大空间1G,但是目前只有70.895M,会自动扩容,以下hi前两次元空间扩容的GC日志
第一次GC收集后,元空间发现GC并没有什么卵用啊,于是扩容,然后又一次扩容(从图片曲线也可以看出,GC发现没有空间可以回收,于是上涨),可以看到,元空间由于不在堆内存中,回收效率很低,第三次扩容的时候,GC时间已经用掉了0.32秒,这个问题将在下面解决,Metaspace这个参数和其他参数的理解有些区别

[Full GC (Metadata GC Threshold) [Tenured: 0K->26956K(2097152K), 0.0652935 secs] 322145K->26956K(3984640K), [Metaspace: 20686K->20686K(1069056K)], 0.0653308 secs] [Times: user=0.11 sys=0.00, real=0.07 secs]
[Full GC (Metadata GC Threshold) [Tenured: 26956K->46283K(2097152K), 0.1143646 secs] 473666K->46283K(3984640K), [Metaspace: 34601K->34601K(1081344K)], 0.1144194 secs] [Times: user=0.27 sys=0.00, real=0.12 secs]
[Full GC (Metadata GC Threshold) [Tenured: 46283K->112018K(2097152K), 0.3179207 secs] 1076966K->112018K(3984640K), [Metaspace: 57697K->57697K(1101824K)], 0.3179794 secs] [Times: user=0.70 sys=0.01, real=0.32 secs]

CMS收集器

直接上最终参数了
参数:-XX:+UseConcMarkSweepGC -Xmx4g -Xms4g -Xmn2500m -XX:SurvivorRatio=12 -XX:MaxMetaspaceSize=1g -XX:MetaspaceSize=1g -XX:+PrintGCDetails


image.png

分析

由图可见,大的Eden空间保证了GC时间间隔,调整Eden和Survivor的比例到12:1避免空间的浪费,由于本应用产生的多数对象都在新生代,老年代对象较少,开发环境又不需要长时间运行,所以大部分空间分配给了新生代,设置元空间大小,避免元空间扩容导致的Full GC,大Eden区回收时间每次约100ms

GC日志

[GC (Allocation Failure) [ParNew: 2194304K->152544K(2377152K), 0.0968802 secs] 2194304K->152544K(4011456K), 0.0969408 secs] [Times: user=0.25 sys=0.05, real=0.10 secs]

Metaspace这个东西很有意思,设置成256M,这里显示也不会低于1G,暂时还没找到答案
关于Metaspace的设置,请参考JVM参数MetaspaceSize的误解,写的很好,这里不再赘述

问题记录

Metaspace不论怎么设置,都不会低于1G,当Max设置成2G的时候,监控中显示还是1G,不解

总结

这次实践,有对理论的印证,也有新的疑惑(Metaspace),之前对元空间的理解有些想当然,在实践中发现了与理论(自己理解的理论)的冲突,需要进一步寻找答案,如您刚好了解,还请慷慨解答

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

推荐阅读更多精彩内容