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),之前对元空间的理解有些想当然,在实践中发现了与理论(自己理解的理论)的冲突,需要进一步寻找答案,如您刚好了解,还请慷慨解答

推荐阅读更多精彩内容