Java垃圾收集器——Parallel、G1收集器日志分析及性能调优示范

开发过程中，经常需要对gc的垃圾收集器参数不断的进行动态调整，从而更充分的压榨机器性能，提升应用效率。本文将从常见的parallel/g1垃圾收集器的gc日志着手，分析gc日志的具体含义，以及示范如何根据gc日志调整参数。

1. 准备工作

(1) vm options

应用程序需要设置如下参数，以便将gc信息数值至gc.log文件中，供后续分析。

-xx:+disableexplicitgc -xx:+heapdumponoutofmemoryerror -xx:heapdumppath=./logs -xx:+printgcdetails -xx:+printgctimestamps -xx:+printgcdatestamps -xloggc:./logs/gc.log

(2) gc统计工具
为了更好的统计gc日志信息，我们将借助于gcviewer桌面软件(开源，地址为：https://github.com/chewiebug/gcviewer)，下载之后执行maven clean package -dmaven.test.skip=true即可完成程序的编译，双击target文件夹下的gcviewer-1.36-snapshot.jar（具体名称由下载的gcviewer版本确定）即可执行程序。

原gcviewer于2008年后停止维护，上文提供的仓库为chewiebug维护的fork版本。

(3) 机器信息

本机参数：

jdk版本:java hotspot(tm) 64-bit server vm (25.172-b11) for windows-amd64 jre (1.8.0_172-b11).

(4) 测试程序

自行编写的flink应用（主要优点是：吃内存，加上写文章时正好在家里学习flink...）。

2. parallel收集器

java hotspot(tm) 64-bit server vm (25.172-b11) for windows-amd64 jre (1.8.0_172-b11), built on mar 28 2018 21:21:52 by "java_re" with ms vc++ 10.0 (vs2010)
memory: 4k page, physical 16768628k(8408808k free), swap 33535356k(23695248k free)
commandline flags: -xx:+disableexplicitgc -xx:+heapdumponoutofmemoryerror -xx:heapdumppath=$./logs -xx:initialheapsize=268298048 -xx:maxheapsize=4292768768 -xx:+printgc -xx:+printgcdatestamps -xx:+printgcdetails -xx:+printgctimestamps -xx:+usecompressedclasspointers -xx:+usecompressedoops -xx:-uselargepagesindividualallocation -xx:+useparallelgc 
2019-10-24t15:33:39.513+0800: 2.164: [gc (allocation failure) [psyounggen: 65536k->7875k(76288k)] 65536k->7891k(251392k), 0.0275982 secs] [times: user=0.17 sys=0.00, real=0.03 secs] 
2019-10-24t15:33:41.320+0800: 3.970: [gc (allocation failure) [psyounggen: 73411k->10738k(76288k)] 73427k->12337k(251392k), 0.0147806 secs] [times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-24t15:33:41.772+0800: 4.422: [gc (metadata gc threshold) [psyounggen: 22142k->6329k(76288k)] 23741k->7935k(251392k), 0.0076904 secs] [times: user=0.00 sys=0.00, real=0.01 secs] 
2019-10-24t15:33:41.780+0800: 4.430: [full gc (metadata gc threshold) [psyounggen: 6329k->0k(76288k)] [paroldgen: 1606k->6175k(100352k)] 7935k->6175k(176640k), [metaspace: 20679k->20679k(1067008k)], 0.0334417 secs] [times: user=0.23 sys=0.00, real=0.03 secs] 
2019-10-24t15:33:42.076+0800: 4.726: [gc (allocation failure) [psyounggen: 65536k->10738k(132608k)] 71711k->64480k(232960k), 0.0512660 secs] [times: user=0.06 sys=0.42, real=0.05 secs] 
2019-10-24t15:33:42.164+0800: 4.815: [gc (allocation failure) [psyounggen: 132594k->10738k(141824k)] 186336k->184366k(316416k), 0.1241149 secs] [times: user=0.03 sys=0.94, real=0.12 secs] 
2019-10-24t15:33:42.288+0800: 4.939: [full gc (ergonomics) [psyounggen: 10738k->8672k(141824k)] [paroldgen: 173628k->174573k(399872k)] 184366k->183245k(541696k), [metaspace: 22192k->22192k(1069056k)], 0.0938949 secs] [times: user=0.39 sys=0.13, real=0.09 secs] 
2019-10-24t15:33:42.415+0800: 5.066: [gc (allocation failure) [psyounggen: 139744k->120826k(320000k)] 314317k->312422k(719872k), 0.1433171 secs] [times: user=0.00 sys=1.08, real=0.14 secs] 
2019-10-24t15:33:43.607+0800: 6.257: [gc (gclocker initiated gc) [psyounggen: 319994k->161768k(360960k)] 511592k->392382k(760832k), 0.2255222 secs] [times: user=0.36 sys=1.39, real=0.22 secs] 
2019-10-24t15:33:45.921+0800: 8.572: [gc (metadata gc threshold) [psyounggen: 324597k->172709k(544768k)] 555211k->403387k(944640k), 0.1776332 secs] [times: user=0.03 sys=1.16, real=0.18 secs] 
2019-10-24t15:33:46.099+0800: 8.749: [full gc (metadata gc threshold) [psyounggen: 172709k->0k(544768k)] [paroldgen: 230678k->398712k(628224k)] 403387k->398712k(1172992k), [metaspace: 36781k->36523k(1081344k)], 0.2291498 secs] [times: user=0.20 sys=1.25, real=0.23 secs] 
2019-10-24t15:33:50.564+0800: 13.214: [gc (allocation failure) [psyounggen: 326144k->88922k(569344k)] 790394k->553180k(1197568k), 0.0217578 secs] [times: user=0.02 sys=0.00, real=0.02 secs] 
heap
 psyounggen      total 569344k, used 303805k [0x000000076ab80000, 0x00000007a2800000, 0x00000007c0000000)
  eden space 326144k, 65% used [0x000000076ab80000,0x0000000777d58c70,0x000000077ea00000)
  from space 243200k, 36% used [0x000000077ea00000,0x00000007840d6960,0x000000078d780000)
  to   space 226304k, 0% used [0x0000000794b00000,0x0000000794b00000,0x00000007a2800000)
 paroldgen       total 628224k, used 464258k [0x00000006c0200000, 0x00000006e6780000, 0x000000076ab80000)
  object space 628224k, 73% used [0x00000006c0200000,0x00000006dc760a18,0x00000006e6780000)
 metaspace       used 55000k, capacity 59794k, committed 60032k, reserved 1099776k
  class space    used 8350k, capacity 10033k, committed 10112k, reserved 1048576k

上面所示内容为设置基本vm options，启动应用后的gc日志，查看可知在没有指定垃圾收集器的情况下，jdk默认选择了parallelgc收集器(在没有指定垃圾收集器的时候，并且内存较为充足的情况下，jdk会默认选择parallelgc)。

2.1 young gc

截取一条日志进行分析（为了更好的展示，将单挑日志拆分为三段，并使用上标表示每个字段的位置）：

2019-10-24t15:33:42.076+0800¹: 4.726²:
[gc³ (allocation failure⁴) [psyounggen⁵: 65536k->10738k⁶(132608k⁷)] 71711k->64480k⁸(232960k⁹), 0.0512660 secs¹⁰]
[times: user=0.06 sys=0.42, real=0.05 secs¹¹]

针对此条日志，进行具体分析：

(1) 2019-10-24t15:33:42.076+0800:当前gc事件发生时的utc时间戳；

(2) 4.726: 当前gc发生时，jvm的启动事件(单位为s)；

(3) gc: 用于区分young gc与full gc，当前gc为young gc；

(4) allocation failure: 当前gc的产生原因(新生代中空间不足以为新对象分配空间)；

(5) psyounggen: 垃圾收集器的名称；

(6) 65536k->10738k: gc前后新生代的内存空间使用量；

(7) 132608k: 新生代总内存量；

(8) 71711k->64480k: gc前后应用堆内存的变化情况(包括新生代和老年代)；

(9) 232960k: jvm堆的可用内存；

(10) 0.0512660 secs: 本次gc耗时，单位为s；

(11) [times: user=0.06 sys=0.42, real=0.05 secs]:gc事件的耗时;

• user: 此次gc，所有gc线程消耗的cpu事件总和；
• sys: 此次gc，操作系统调用等事件所消耗的时间总和；
• real: 应用停顿的总时间，在并行的gc中，此数值应该接近(user + sys) / gcthreads，即单核上的平均停顿时间。

综上所述，在gc前总共使用了71711k堆内存，其中新生代使用了65536k，则老年代使用了6175k。gc后，新生代释放了65536-10738=54798k内存，但是堆内存仅释放了71711-64480=7231k内存，说明此次gc，有47567k的对象从新生代升级到了老年代。变化情况如下图所示：

2.2 full gc

截取一条日志进行分析（为了更好的展示，将单挑日志拆分为三段，并使用上标表示每个字段的位置）：

2019-10-24t15:33:46.099+0800¹: 8.749²:
[full gc³ (metadata gc threshold⁴) [psyounggen⁵: 172709k->0k⁶(544768k⁷)] [paroldgen⁸: 230678k->398712k⁹(628224k¹⁰)] 403387k->398712k¹⁰(1172992k¹¹),
[metaspace¹²: 36781k->36523k¹³(1081344k¹⁴)], 0.2291498 secs¹⁵] [times: user=0.20 sys=1.25, real=0.23 secs]¹⁶

针对此条日志，进行具体分析：

(1) 2019-10-24t15:33:46.099+0800: 当前gc事件发生时的utc时间戳；

(2) 8.749: 当前gc发生时，jvm的启动事件(单位为s)；

(3) full gc: 用于区分young gc与full gc，当前gc为full gc；

(4) metadata gc threshold: 当前gc的产生原因(metaspace空间占用达到阈值)；

(5) psyounggen: 新生代垃圾收集器名称；

(6) 172709k->0k: full gc时，新生代内存空间将被清空；

(7) 544768k: 新生代总内存量；

(8) paroldgen: 老年代垃圾收集器名称；

(9) 230678k->398712k: full gc时，老年代内存空间变化情况；

(10) 628224k: 老年代总内存量；

(11) 403387k->398712k: gc前后堆内存的变化情况；

(12) 1172992k: jvm堆的可用内存；

(13) metaspace: metaspace空间；

(14) 36781k->36523k: metaspace空间的变化情况；

(15) 1081344k: metadata的保留空间（metaspace时从jvm进程的虚拟地址空间中分离出来的）；

(16) 0.2291498 secs: 当前gc的耗时，单位为s；

(17) [times: user=0.20 sys=1.25, real=0.23 secs]: 具体含义参见young gc解释。

由以上数据可知，在此次full gc的过程中，young区域的数据被清空，但是old区以及metaspace区均进行扩容以便存放更多数据。

3. g1收集器

并发收集器主要有cms以及g1收集器，因为在jdk 1.8上，g1收集器已经得到较大的完善，因此舍弃cms收集器的日志分析，直接分析g1收集器（在vm options中添加-xx:+useg1gc即可）。如果读者想使用cms收集器，只需要在vm options中添加-xx:+useconcmarksweepgc即可。

2019-10-24t16:52:43.377+0800: 7.865: [gc pause (g1 evacuation pause) (young), 0.0197774 secs]
   [parallel time: 10.9 ms, gc workers: 8]
      [gc worker start (ms): min: 7865.0, avg: 7865.0, max: 7865.1, diff: 0.1]
      [ext root scanning (ms): min: 0.7, avg: 1.7, max: 5.7, diff: 4.9, sum: 13.9]
      [update rs (ms): min: 0.0, avg: 1.0, max: 2.4, diff: 2.4, sum: 7.8]
         [processed buffers: min: 0, avg: 11.3, max: 29, diff: 29, sum: 90]
      [scan rs (ms): min: 0.0, avg: 0.3, max: 0.6, diff: 0.6, sum: 2.7]
      [code root scanning (ms): min: 0.0, avg: 2.1, max: 8.3, diff: 8.3, sum: 16.9]
      [object copy (ms): min: 0.0, avg: 5.4, max: 7.8, diff: 7.8, sum: 43.3]
      [termination (ms): min: 0.0, avg: 0.1, max: 0.2, diff: 0.2, sum: 0.7]
         [termination attempts: min: 1, avg: 2.4, max: 4, diff: 3, sum: 19]
      [gc worker other (ms): min: 0.0, avg: 0.0, max: 0.0, diff: 0.0, sum: 0.2]
      [gc worker total (ms): min: 10.6, avg: 10.7, max: 10.7, diff: 0.1, sum: 85.6]
      [gc worker end (ms): min: 7875.7, avg: 7875.7, max: 7875.8, diff: 0.1]
   [code root fixup: 0.0 ms]
   [code root purge: 0.0 ms]
   [clear ct: 0.3 ms]
   [other: 8.6 ms]
      [choose cset: 0.0 ms]
      [ref proc: 7.6 ms]
      [ref enq: 0.1 ms]
      [redirty cards: 0.2 ms]
      [humongous register: 0.0 ms]
      [humongous reclaim: 0.0 ms]
      [free cset: 0.3 ms]
   [eden: 161.0m(161.0m)->0.0b(182.0m) survivors: 13.0m->21.0m heap: 626.5m(1066.0m)->474.0m(1066.0m)]
 [times: user=0.05 sys=0.00, real=0.02 secs] 

g1的垃圾收集过程，因为其特殊的内存划分，导致存在很多细微的步骤。
我们截取其主要部分进行分析：

(1) [gc pause (g1 evacuation pause) (young), 0.0197774 secs]: 说明当前gc为young gc，cpu耗时0.0197774s；

(2) [parallel time: 10.9 ms, gc workers: 8]: 此次gc停顿的实际时间为10.9ms，共有8个线程参与清理工作；

(3) eden: 161.0m(161.0m)->0.0b(182.0m) survivors: 13.0m->21.0m heap: 626.5m(1066.0m)->474.0m(1066.0m):
此段说明eden区的内存共计161.0m被释放了，有部分对象转移至survivors区导致survivors区内存扩大，堆内存因为eden区释放资源的缘故总量变小(空间未发生变化)。

因为在当前的gc日志抓取中，未存在mixed gc，因此此处就不对mixed gc日志进行分析(感兴趣的读者可以在较大的程序中获取g1 gc日志进行进一步分析)。虽然g1的gc日志虽然步骤很清晰，但是每次gc均会有大量日志产生，不便于根据日志进行分析，因此我推荐使用gcviewer可视化工具辅助进行分析。导入gc日志，信息如下图所示：

图中左侧详细罗列了gc的详细情况，包括gc pause(停顿应用的gc数据)以及concurrent gcs(与应用并发执行的gc数据)。右侧则概要的描述了应用开始执行后的吞吐量(throughput：95.15%)，导致应用停顿的gc次数(number of gc pauses：8)以及gc停顿时间(accumulated pauses: 0.36s)。通过以上信息，就可以对g1收集器在应用执行过程的表现有一个清晰的认识。

3. 性能优化

直接根据gc日志进行针对性调优较为困难(生产环境的gc日志量比较大，尤其是cms/g1的gc日志)，因此建议将gc日志导出，通过图形化工具gcviewer进行汇总统计，得到可靠的报表信息。
使用gcviewer进行调优时，一般关注以下几个指标：throughput(吞吐量)，number of gc pauses(gc停顿数量)以及accumulated pauses(gc停顿总耗时)。

3.1 parallel收集器调优

调优参数：

• -xx:metaspacesize: 在应用启动初期，普遍存在因为metaspace空间达到阈值引发的gc，因此可以合理设置metaspace空间规避此类gc；
• -xx:maxgcpausemillis: 最大gc停顿时间，这是个软目标，jvm将尽可能（但不保证）停顿小于这个时间;
• -xx:gctimeratio: 垃圾收集时间占总时间的比例(假设gctimeratio设置为n，则垃圾收集时间占总时间的比例为1 / (1 + n))

parallel收集器是自适应收集器，一般设置maxgcpausemillis以及gctimeratio，即可由jdk进行动态调整，用户可以根据gc日志得到最佳的停顿时间和吞吐量设置方案。

3.2 g1收集器调优

关于g1垃圾收集器的调优，建议有以下两条：

• 年轻代大小：避免使用-xmn选项或-xx:newratio 等其他相关选项显式设置年轻代大小，因为固定年轻代的大小会覆盖暂停时间目标。
• 暂停时间目标：每当对垃圾回收进行评估或调优时，都会涉及到延迟与吞吐量的权衡。g1是增量垃圾回收器，其吞吐量目标是90% 的应用程序时间和10%的垃圾回收时间。因此，暂停时间目标不要太严苛。目标太过严苛表示您愿意承受更多的垃圾回收开销，而这会直接影响到吞吐量。

如果对于性能有着严苛的要求，可以参照https://toutiao.io/k/8b0dxca的做法，开启g1的所有参数:

-xmx30g -xms30g
-xx:maxdirectmemorysize=30g
-xx:+useg1gc
-xx:+unlockexperimentalvmoptions
-xx:maxgcpausemillis=90
-xx:g1newsizepercent=8
-xx:initiatingheapoccupancypercent=30
-xx:+parallelrefprocenabled
-xx:concgcthreads=4
-xx:parallelgcthreads=16
-xx:maxtenuringthreshold=1
-xx:g1heapregionsize=32m
-xx:g1mixedgccounttarget=64
-xx:g1oldcsetregionthresholdpercent=5

其中重点需要调优的参数有：

• g1newsizepercent ：g1的young区大小是通过算法来自适应确定的, 也就是根据之前young区gc的耗时来确定之后的young大小,如果耗时过长,则调小young区,耗时过短,则调大young区. 这个参数表示young的最小百分比；
• initiatingheapoccupancypercent: 当占用内存超过这个百分比的时候, g1开始执行多次mixed gc来整理老年代内存碎片；
• g1mixedgccounttarget: 当占用内存超过initiatingheapoccupancypercent阀值时, 最多通过多少次mixed gc来将内存控制在阀值之下；
• maxtenuringthreshold: 当一个对象gc的代数超过这个值的时候, 会将对象从young区挪到old区；
• g1heapregionsize: 表示g1将每个region切分成多大, 注意一定要写单位, 例如32m。

逐个调整以上参数并收集gc日志，通过gcviewer收集各项指标，最终根据实际情况挑选满意的g1收集器参数即可。

ps:
如果您觉得我的文章对您有帮助，请关注我的微信公众号，谢谢!