第一次FullGC优化实战 | HeapDump性能社区

关于FullGC，博主只是在一些书中或者博客中，看别人调优过，今天兴起，亲自在本地调了一把本地的项目：

第一步：我首先打开了jvisualvm.exe，在Visual GC 里面发现了今天要讨论的重点：GC

第二部：我在项目启动参数里面配置了：

-XX:+PrintGCApplicationStoppedTime 打印垃圾回收期间程序暂停的时间
-XX:+PrintGCDetails 打印GC详细信息
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-Xloggc:D:/apache-tomcat-7.0.56/logs/gc.log 设置GC输入的文件地址

打印出系统的GC日志

Java HotSpot(TM) 64-Bit Server VM (25.45-b02) for windows-amd64 JRE (1.8.0_45-b14), built on Apr 10 2015 10:34:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8292720k(2030836k free), swap 16583580k(9162992k free)
CommandLine flags: -XX:InitialHeapSize=132683520 -XX:+ManagementServer -XX:MaxHeapSize=2122936320 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
2.629: [GC (Allocation Failure) [PSYoungGen: 33280K->5102K(38400K)] 33280K->6630K(125952K), 0.0435191 secs] [Times: user=0.13 sys=0.02, real=0.04 secs]
3.688: [GC (Allocation Failure) [PSYoungGen: 38382K->5106K(71680K)] 39910K->8379K(159232K), 0.0214437 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
5.310: [GC (Allocation Failure) [PSYoungGen: 71666K->5108K(71680K)] 74939K->19402K(159232K), 0.0254839 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
5.809: [GC (Allocation Failure) [PSYoungGen: 71668K->5117K(138240K)] 85962K->32311K(225792K), 0.0465904 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
6.754: [GC (Allocation Failure) [PSYoungGen: 138237K->5114K(138240K)] 165431K->52655K(225792K), 0.1084693 secs] [Times: user=0.37 sys=0.02, real=0.11 secs]
7.407: [GC (Allocation Failure) [PSYoungGen: 138234K->28656K(287744K)] 185775K->78955K(375296K), 0.1779500 secs] [Times: user=0.53 sys=0.00, real=0.18 secs]
8.649: [GC (Allocation Failure) [PSYoungGen: 287728K->35808K(294912K)] 338027K->102952K(382464K), 0.0374501 secs] [Times: user=0.03 sys=0.06, real=0.04 secs]
8.686: [Full GC (Ergonomics) [PSYoungGen: 35808K->0K(294912K)] [ParOldGen: 67143K->77106K(139264K)] 102952K->77106K(434176K), [Metaspace: 16605K->16601K(1064960K)], 0.0853369 secs] [Times: user=0.25 sys=0.02, real=0.09 secs]
9.604: [GC (Allocation Failure) [PSYoungGen: 259072K->40376K(527872K)] 336178K->117482K(667136K), 0.0322781 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
13.906: [GC (Allocation Failure) [PSYoungGen: 527800K->55795K(553984K)] 604906K->141721K(693248K), 0.1109281 secs] [Times: user=0.28 sys=0.05, real=0.11 secs]
16.148: [GC (Metadata GC Threshold) [PSYoungGen: 240834K->27448K(626176K)] 326759K->119669K(765440K), 0.0510683 secs] [Times: user=0.11 sys=0.05, real=0.05 secs]
16.199: [Full GC (Metadata GC Threshold) [PSYoungGen: 27448K->0K(626176K)] [ParOldGen: 92221K->44337K(111104K)] 119669K->44337K(737280K), [Metaspace: 28010K->28010K(1075200K)], 0.1327017 secs] [Times: user=0.48 sys=0.00, real=0.13 secs]
20.138: [GC (Allocation Failure) [PSYoungGen: 557568K->33844K(591872K)] 601905K->78190K(702976K), 0.0251393 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
21.822: [GC (Metadata GC Threshold) [PSYoungGen: 267021K->7428K(620032K)] 311367K->72586K(731136K), 0.0306468 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
21.853: [Full GC (Metadata GC Threshold) [PSYoungGen: 7428K->0K(620032K)] [ParOldGen: 65158K->59865K(139776K)] 72586K->59865K(759808K), [Metaspace: 46925K->46921K(1091584K)], 0.1655466 secs] [Times: user=0.48 sys=0.00, real=0.16 secs]

然后发现系统在启动的时候产生了三次FullGC,分别是

第一次FullGC: HotSpot VM Ergonomics（HotSpot自动选择和调优引发的FullGC）

第二次FullGC: Metadata GC Threshold（元空间引发的FullGC）

第三次FullGC:Metadata GC Threshold（元空间引发的FullGC）

对于第一次FullGC：拉出了上条GC的日志

发现堆的大小从381440K调整到了431616K，而新生代的大小没有变化，还是293888K，初步定位是老生代的大小进行了调整，然后我加了：

-Xms512m 初始堆大小
-Xmx512m 最大堆大小
-Xmn350m 新生代大小
计算公式：293888/1024*1.2 = 344.4

当然也有人推荐，当你的主机内存不够开拓 512m的时候，使用这种配置方法：

-Xms380m
-Xms380m
-Xmn140m 380*3/8 = 142.5 , 增加Minor GC次数，来避免Major GC

重新启动项目后，发现我们配置的参数生效了,下面是日志详情：

Java HotSpot(TM) 64-Bit Server VM (25.45-b02) for windows-amd64 JRE (1.8.0_45-b14), built on Apr 10 2015 10:34:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8292720k(1994584k free), swap 16583580k(9125356k free)
CommandLine flags: -XX:InitialHeapSize=536870912 -XX:+ManagementServer -XX:MaxHeapSize=536870912 -XX:MaxNewSize=367001600 -XX:NewSize=367001600 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
4.440: [GC (Allocation Failure) [PSYoungGen: 269312K->25243K(313856K)] 269312K->25323K(479744K), 0.0304720 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
5.744: [GC (Allocation Failure) [PSYoungGen: 294555K->44529K(313856K)] 294635K->48267K(479744K), 0.0539652 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
6.702: [GC (Allocation Failure) [PSYoungGen: 313841K->44536K(313856K)] 317579K->63300K(479744K), 0.1339626 secs] [Times: user=0.39 sys=0.05, real=0.13 secs]
7.569: [GC (Allocation Failure) [PSYoungGen: 313848K->44513K(313856K)] 332612K->84479K(479744K), 0.0294841 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
10.057: [GC (Allocation Failure) [PSYoungGen: 313825K->44527K(313856K)] 353791K->109099K(479744K), 0.0944907 secs] [Times: user=0.22 sys=0.02, real=0.10 secs]
13.252: [GC (Metadata GC Threshold) [PSYoungGen: 268310K->44534K(232960K)] 332882K->110623K(398848K), 0.0437343 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
13.296: [Full GC (Metadata GC Threshold) [PSYoungGen: 44534K->0K(232960K)] [ParOldGen: 66089K->44581K(165888K)] 110623K->44581K(398848K), [Metaspace: 20745K->20739K(1069056K)], 0.1651293 secs] [Times: user=0.53 sys=0.00, real=0.16 secs]
16.168: [GC (Allocation Failure) [PSYoungGen: 188416K->17130K(205824K)] 232997K->61720K(371712K), 0.2730902 secs] [Times: user=0.97 sys=0.03, real=0.27 secs]
18.157: [GC (Metadata GC Threshold) [PSYoungGen: 137150K->14541K(266240K)] 181739K->59131K(432128K), 0.0210153 secs] [Times: user=0.11 sys=0.00, real=0.02 secs]
18.178: [Full GC (Metadata GC Threshold) [PSYoungGen: 14541K->0K(266240K)] [ParOldGen: 44589K->44211K(165888K)] 59131K->44211K(432128K), [Metaspace: 34785K->34785K(1081344K)], 0.1043676 secs] [Times: user=0.33 sys=0.00, real=0.10 secs]
19.839: [GC (Allocation Failure) [PSYoungGen: 178176K->11545K(189952K)] 222387K->55765K(355840K), 0.0111689 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
20.370: [GC (Allocation Failure) [PSYoungGen: 189721K->16596K(268800K)] 233941K->60824K(434688K), 0.0351230 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
21.382: [GC (Allocation Failure) [PSYoungGen: 194772K->7345K(267776K)] 239000K->66566K(433664K), 0.0173570 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
22.759: [GC (Allocation Failure) [PSYoungGen: 185521K->5920K(269312K)] 244742K->70824K(435200K), 0.0101250 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
23.941: [GC (Allocation Failure) [PSYoungGen: 185632K->16400K(268800K)] 250536K->86781K(434688K), 0.0326898 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]

只剩下两次Full GC，两次都是元空间引发的FullGC：

第一次Full GC ：[Metaspace: 20687K->20684K(1069056K)]

第二次Full GC：[Metaspace: 34722K->34722K(1081344K)]

此时发现永久带GC前大小跟GC后大小并没有发生变化，且距离最大容量1081344K还有很大的差距。并不应该导致Full GC。最后查阅了阿里-寒泉子大神的JVM Pocket，发现MetaspaceSize的默认大小是21807104b，也就是21296k。而发生GC的时候，我们的元空间已经使用了34722K。从而产生了Full GC。

然后我加了-XX:MetaspaceSize=64m 初始元空间大小，重新启动了项目，发现果然一个一个Full GC都没有，下面是日志信息：

Java HotSpot(TM) 64-Bit Server VM (25.45-b02) for windows-amd64 JRE (1.8.0_45-b14), built on Apr 10 2015 10:34:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8292720k(1984972k free), swap 16583580k(9108972k free)
CommandLine flags: -XX:InitialHeapSize=536870912 -XX:+ManagementServer -XX:MaxHeapSize=536870912 -XX:MaxNewSize=367001600 -XX:MetaspaceSize=67108864 -XX:NewSize=367001600 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
5.597: [GC (Allocation Failure) [PSYoungGen: 269312K->24480K(313856K)] 269312K->24560K(479744K), 0.0362077 secs] [Times: user=0.13 sys=0.02, real=0.04 secs]
7.470: [GC (Allocation Failure) [PSYoungGen: 293792K->44518K(313856K)] 293872K->48309K(479744K), 0.0475818 secs] [Times: user=0.11 sys=0.01, real=0.05 secs]
8.525: [GC (Allocation Failure) [PSYoungGen: 313830K->44528K(313856K)] 317621K->63199K(479744K), 0.0441926 secs] [Times: user=0.14 sys=0.01, real=0.04 secs]
9.370: [GC (Allocation Failure) [PSYoungGen: 313840K->44520K(313856K)] 332511K->84685K(479744K), 0.0951214 secs] [Times: user=0.22 sys=0.02, real=0.10 secs]
11.809: [GC (Allocation Failure) [PSYoungGen: 313832K->44539K(313856K)] 353997K->109848K(479744K), 0.1018675 secs] [Times: user=0.22 sys=0.00, real=0.10 secs]
15.254: [GC (Allocation Failure) [PSYoungGen: 313851K->44526K(233984K)] 379160K->115793K(399872K), 0.0597879 secs] [Times: user=0.13 sys=0.00, real=0.06 secs]
17.961: [GC (Allocation Failure) [PSYoungGen: 233966K->36173K(273920K)] 305233K->120331K(439808K), 0.0290604 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
19.914: [GC (Allocation Failure) [PSYoungGen: 225613K->28715K(273408K)] 309771K->118441K(439296K), 0.0291581 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
20.611: [GC (Allocation Failure) [PSYoungGen: 218155K->21783K(211456K)] 307881K->122471K(377344K), 0.0468763 secs] [Times: user=0.16 sys=0.02, real=0.05 secs]
21.658: [GC (Allocation Failure) [PSYoungGen: 211223K->16130K(271360K)] 311911K->128724K(437248K), 0.0210628 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
23.223: [GC (Allocation Failure) [PSYoungGen: 202498K->5706K(192512K)] 315092K->132341K(358400K), 0.0284473 secs] [Times: user=0.08 sys=0.00, real=0.03 secs]
24.378: [GC (Allocation Failure) [PSYoungGen: 192074K->14495K(271360K)] 318709K->146249K(437248K), 0.0283913 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]

到这为止，我的第一次FullGC优化实战就圆满的告一段落了。

第一次FullGC优化实战原创

打印出系统的GC日志

推荐阅读

专题推荐

本月精选性能专题

本月精选线上案例

本月精选原创好文

联系我们

网媒渠道

友情链接