JAVA HotSpot GC收集器实践记录

最新推荐文章于 2021-04-05 12:06:30 发布

Tick-Tock

最新推荐文章于 2021-04-05 12:06:30 发布

阅读量192

点赞数

本文链接：https://blog.csdn.net/leo2115339/article/details/81199615

版权

简介

最近仔细研读了《深入理解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的误解，写的很好，这里不再赘述