专栏首页程序猿杂货铺JVM性能调优实践(二)——G1 垃圾收集器分析、调优篇

JVM性能调优实践(二)——G1 垃圾收集器分析、调优篇

1前言

关于G1 GC以及其他垃圾收集器的介绍可以参考前一篇JVM性能调优实践——G1 垃圾收集器介绍篇。了解了G1垃圾收集器的运行机制之后,就可以针对一些GC相关参数来调整内存分配以及运行策略。下文的调优主要针对G1垃圾收集器进行介绍,以及会分析一下G1 GC的日志格式。

2G1 GC日志分析

在执行具体的调优任务前,需要结合GC日志以及应用本身的特点。打印详细GClog,需要添加如下启动参数:

-XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCDateStamps

本文使用的Java version:

java version "1.8.0_60"
Java(TM) SE Runtime Environment (build 1.8.0_60-b27)
Java HotSpot(TM) 64-Bit Server VM (build 25.60-b23, mixed mode) 

下面截取gc.log 中的一次YoungGC和一次MixedGC。

2018-05-26T19:51:45.808-0800: 127.031: [GC pause (G1 Evacuation Pause) (young), 0.0063650 secs]
   [Parallel Time: 5.5 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 127030.7, Avg: 127030.7, Max: 127030.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.3, Max: 1.5, Diff: 0.4, Sum: 5.3]
      [Update RS (ms): Min: 1.3, Avg: 1.4, Max: 1.4, Diff: 0.1, Sum: 5.4]
         [Processed Buffers: Min: 3, Avg: 12.5, Max: 24, Diff: 21, Sum: 50]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.7, Diff: 0.5, Sum: 1.3]
      [Object Copy (ms): Min: 2.2, Avg: 2.4, Max: 2.5, Diff: 0.4, Sum: 9.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 5.4, Avg: 5.4, Max: 5.4, Diff: 0.1, Sum: 21.6]
      [GC Worker End (ms): Min: 127036.1, Avg: 127036.1, Max: 127036.1, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 39.0M(39.0M)->0.0B(2048.0K) Survivors: 3072.0K->4096.0K Heap: 111.4M(128.0M)->72.9M(128.0M)]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 

2018-05-26T19:57:20.534-0800: 461.748: [GC pause (G1 Evacuation Pause) (mixed), 0.0685311 secs]
   [Parallel Time: 67.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 461748.1, Avg: 461748.1, Max: 461748.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.8, Avg: 2.6, Max: 7.5, Diff: 6.6, Sum: 10.5]
      [Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 1.4]
         [Processed Buffers: Min: 0, Avg: 9.2, Max: 35, Diff: 35, Sum: 37]
      [Scan RS (ms): Min: 29.7, Avg: 34.3, Max: 36.1, Diff: 6.5, Sum: 137.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.5, Max: 0.8, Diff: 0.8, Sum: 2.0]
      [Object Copy (ms): Min: 28.8, Avg: 29.3, Max: 29.8, Diff: 1.0, Sum: 117.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 67.1, Avg: 67.1, Max: 67.1, Diff: 0.0, Sum: 268.5]
      [GC Worker End (ms): Min: 461815.2, Avg: 461815.2, Max: 461815.2, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.4 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.2 ms]
   [Eden: 5120.0K(5120.0K)->0.0B(57.0M) Survivors: 1024.0K->1024.0K Heap: 64.3M(128.0M)->55.8M(128.0M)]
 [Times: user=0.07 sys=0.11, real=0.07 secs] 

两个收集过程的日志格式相似。先以young gc为例,分析一下日志信息。

3GC并行任务

并行任务部分主要包含Parallel Time这一行以及其下面的详细任务信息。

[Parallel Time: GC Workers]

[Parallel Time: 5.9 ms, GC Workers: 4] 这一行标记着并行阶段的汇总信息。总共花费时间以及GC的工作线程数。

后续的这两行,start-end是时间戳信息。Diff是偏移平均时间的值。Diff越小越好,说明每个工作线程的速度都很均匀,如果Diff值偏大,就要看下面具体哪一项活动产生的波动。Avg代表平均时间值。如果Avg跟Min,Max偏差不大是比较正常的,否则也要详细分析具体的偏差值大的任务。

[GC Worker Start (ms): Min: 127030.7, Avg: 127030.7, Max: 127030.7, Diff: 0.0]
[GC Worker End (ms): Min: 127036.1, Avg: 127036.1, Max: 127036.1, Diff: 0.0]

下一段显示的是详细的并行阶段的GC活动。

[Ext Root Scanning (ms): Min: 1.1, Avg: 1.3, Max: 1.5, Diff: 0.4, Sum: 5.3]
      [Update RS (ms): Min: 1.3, Avg: 1.4, Max: 1.4, Diff: 0.1, Sum: 5.4]
         [Processed Buffers: Min: 3, Avg: 12.5, Max: 24, Diff: 21, Sum: 50]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.7, Diff: 0.5, Sum: 1.3]
      [Object Copy (ms): Min: 2.2, Avg: 2.4, Max: 2.5, Diff: 0.4, Sum: 9.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 5.4, Avg: 5.4, Max: 5.4, Diff: 0.1, Sum: 21.6]

Ext Root Scanning

外部根区扫描。外部根是堆外区。JNI引用,JVM系统目录,Classloaders等。后面跟着具体的时间信息。

RSet的处理

log中RS指的是RSet。RSet详细信息可以看G1 GC介绍。

  • UpdateRS:更新RSet的时间信息。-XX:MaxGCPauseMillis参数是限制G1的暂停之间,一般RSet更新的时间小于10%的目标暂停时间是比较可取的。如果花费在RSetUpdate的时间过长,可以修改其占用总暂停时间的百分比-XX:G1RSetUpdatingPauseTimePercent。这个参数的默认值是10。
  • Processed Buffers:已处理缓冲区。这个阶段处理的是在优化线程中处理dirty card分区扫描时记录的日志缓冲区。
  • Scan RS:前一篇文章也提到了,关于RSet的粒度。如果RSet中的Bitmap是粗粒度的,那么就会增加RSet扫描的时间。如下所示的扫描时间,说明还没有粗化的RSet
  • Code Root Scanning:代码跟的扫描。只有在分区的RSet有强代码根时会检查CSet的对内引用,例如常量池。
 [Update RS (ms): Min: 1.3, Avg: 1.4, Max: 1.4, Diff: 0.1, Sum: 5.4]
         [Processed Buffers: Min: 3, Avg: 12.5, Max: 24, Diff: 21, Sum: 50]

   [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.7, Diff: 0.5, Sum: 1.3]  

如果观察到RS的处理时间较长,可以使用-XX:+G1SummarizeRSetStats参数,在GC结束后打印RSet的详细信息。一般在debug环境排查用。还有一个辅助参数G1SummarizeRSetStatsPeriod=0用来控制第几次GC后统计一次RSet信息。

Object Copy

Object Copy:该任务主要是对CSet中存活对象进行转移(复制)。对象拷贝的时间一般占用暂停时间的主要部分。如果拷贝时间和”预测暂停时间“有相差很大,也可以调整年轻代尺寸大小。

 [Object Copy (ms): Min: 2.2, Avg: 2.4, Max: 2.5, Diff: 0.4, Sum: 9.5] 

Termination

这里的终止主要是终止工作线程。Work线程在工作终止前会检查其他工作线程的任务,如果其他work线程有没完成的任务,会抢活。如果终止时间较长,额能是某个work线程在某项任务执行时间过长。

GC Worker Other

花在GC之外的工作线程的时间,比如因为JVM的某个活动,导致GC线程被停掉。这部分消耗的时间不是真正花在GC上,只是作为log的一部分记录。

GC Work Total

并行阶段的GC汇总,包含了GC以及GC Worker Other的总时间。

GC 串行活动

一下是串行的GC活动。包括代码根的更新和扫描。Clear的时候还要清理RSet相应去除的Card Table信息。G1 GC在扫描Card信息时会有一个标记记录,防止重复扫描同一个Card。

   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]

GC Other活动

剩余的部分就是其他GC活动了。主要包含:选择CSet、引用处理和排队、卡片重新脏化、回收空闲巨型分区以及在收集之后释放CSet。

[Other: 0.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
  • Choose CSet:选择CSet,因为年轻代的所有分区都会被收集,所以CSet不需要选择,消耗时间都是0ms。Choose CSet任务一般都是在mixed gc的过程中触发。
  • Ref Proc、Enq: 引用处理主要针对弱引用,软引用,徐引用,final,JNI引用。将这些引用排列到相应的reference队列中。
  • Redirty Cards:重新脏化卡片。排队引用可能会更新RSet,所以需要对关联的Card重新脏化(Redirty Cards)。
  • Humongous Register、Reclaim主要是对巨型对象回收的信息,youngGC阶段会对RSet中有引用的短命的巨型对象进行回收,巨型对象会直接回收而不需要进行转移(转移代价巨大,也没必要)。
  • Free CSet:释放CSet,其中也会清理CSet中的RSet

4垃圾结果收集统计

如下对比了一次youngGC和一次mixedGC的垃圾收集结果:

young: [Eden: 39.0M(39.0M)->0.0B(2048.0K) Survivors: 3072.0K->4096.0K Heap: 111.4M(128.0M)->72.9M(128.0M)]

mixed: [Eden: 5120.0K(5120.0K)->0.0B(57.0M) Survivors: 1024.0K->1024.0K Heap: 64.3M(128.0M)->55.8M(128.0M)]
  • Eden: 39.0M(39.0M)->0.0B(2048.0K): Eden分区GC前39M,GC后是0。括号里面的分别是GC前后Eden分区的总大小。可以看到在一次GC后,Eden的空间做了调整。G1 GC的暂停时间是可预测的,所以YoungGC之后,会根据pause time的目标重新计算需要的Eden分区数,进行动态调整。
  • Survivors: 3072.0K->4096.0K。Survivors空间的变化,空间增长了,说明有存活对象E区晋升到S区。
  • Heap: 111.4M(128.0M)->72.9M(128.0M)。整个堆区的GC前后空间数据,G1 GC会动态调整堆区,但这次回收中没有改变堆区的容量。

5G1 CC相关参数

G1 GC是垃圾收集优先的垃圾收集器,同时有着”可预期的暂停时间“,垃圾收集过程是分代的,但堆空间是基于分区进行分配。所以整体的空间利用率,时间效率都有更大的提升。G1的YoungGC和MixedGC以及并发标记阶段都有很多机制可以控制触发时机,一般情况是不建议过度更改官方建议参数。但默认参数不一定适用于所有应用,调优前需要有明确的目标,或者问题处理思路。

以下先整理下G1垃圾收集器可以调整的重要参数:

  • -XX:+UseG1GC:启用 G1 (Garbage First) 垃圾收集器
  • -XX:MaxGCPauseMillis:设置允许的最大GC停顿时间(GC pause time),这只是一个期望值,实际可能会超出,可以和年轻代大小调整一起并用来实现。默认是200ms。
  • -XX:G1HeapRegionSize:每个分区的大小,默认值是会根据整个堆区的大小计算出来,范围是1M~32M,取值是2的幂,计算的倾向是尽量有2048个分区数。比如如果是2G的heap,那region=1M。16Gheap,region=8M。
  • -XX:MaxTenuringThreshold=n:晋升到老年代的“年龄”阀值,默认值为 15。
  • -XX:InitiatingHeapOccupancyPercent:一般会简写IHOP,默认是45%,这个占比跟并发周期的启动相关,当空间占比达到这个值时,会启动并发周期。如果经常出现FullGC,可以调低该值,尽早的回收可以减少FullGC的触发,但如果过低,则并发阶段会更加频繁,降低应用的吞吐。
  • -XX:G1NewSizePercent:年轻代最小的堆空间占比,默认是5%。
  • -XX:G1MaxNewSizePercent:年轻代最大的堆空间占比,默认是60%。
  • -XX:ConcGCThreads:并发执行的线程数,默认值接近整个应用线程数的1/4。
  • -XX:-XX:G1HeapWastePercent:允许的浪费堆空间的占比,默认是5%。如果并发标记可回收的空间小于5%,则不会触发MixedGC。
  • -XX:G1MixedGCCountTarget:一次全局并发标记之后,后续最多执行的MixedGC次数。 默认值是8.

6G1 CC 相关调优建议

01

年轻代调优

因为G1 GC是启发式算法,会动态调整年轻代的空间大小。目标也就是为了达到接近预期的暂停时间。年轻代调优中比较重要的就是对暂停时间的处理。一般都是根据MaxGCPauseMillis以及年轻代占比G1NewSizePercent、G1MaxNewSizePercent,结合应用的特点和GC数据进行接近期望pause time的调整。为了能观察到详细的暂停时间信息,可以添加调试的启动参数-XX:+PrintAdaptiveSizePolicy。

下面摘取一段youngGC gc log的输出:

 26.139: [GC pause (G1 Evacuation Pause) (young) 26.139: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3484, predicted base time: 5.51 ms, remaining time: 194.49 ms, target pause time: 200.00 ms]
 26.139: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 54 regions, survivors: 9 regions, predicted young region time: 5.98 ms]
 26.139: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 54 regions, survivors: 9 regions, old: 0 regions, predicted pause time: 11.49 ms, target pause time: 200.00 ms]
, 0.0163685 secs]

target也即目标是200ms,实际的pause time是16ms。远远小于目标暂停时间。并且再CSet中的分区数是“eden: 54 regions, survivors: 9 regions”,可以适当增加CSet中的年轻代分区,也可以适当缩短暂停时间,让实际值和期望值不断接近。

02

并发标记和MiniGC调优

InitiatingHeapOccupancyPercent就是触发并发标记的一个决定阀值。当Java堆空间占用到45%便开启并发周期。并发标记的初始标记阶段伴随着一次YoungGC的暂停。会看到如下log记录:

2018-05-26T19:50:57.256-0800: 78.480: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0076560 secs] 

IHOP如果阀值设置过高,可能会遇到转移失败的风险,比如对象进行转移时空间不足。如果阀值设置过低,就会使标记周期运行过于频繁,并且有可能混合收集期回收不到空间。 IHOP值如果设置合理,但是在并发周期时间过长时,可以尝试增加并发线程数,调高ConcGCThreads。

03

引用处理

G1 GC对于虚引用、弱引用、软引用的处理会比一般对象多一些收集任务。如果在引用处理占用了很长时间,需要更进一步排查。在并发标记的Remark阶段会记录引用的处理,日志信息如下:

如下:

[GC remark 2018-05-26T19:50:57.386-0800: 78.610: [Finalize Marking, 0.0002675 secs] 2018-05-26T19:50:57.386-0800: 78.611: [GC ref-proc, 0.0001091 secs] 2018-05-26T19:50:57.386-0800: 78.611: [Unloading, 0.0204521 secs], 0.0212793 secs]

可以通过-XX:+PrintReferenceGC打印更详细的引用计数信息:

 [SoftReference, 0 refs, 0.0000482 secs]2018-06-03T20:52:03.887-0800: 18.033: [WeakReference, 116 refs, 0.0000321 secs]2018-06-03T20:52:03.887-0800: 18.033: [FinalReference, 1073 refs, 0.0009571 secs]2018-06-03T20:52:03.888-0800: 18.034: [PhantomReference, 0 refs, 1 refs, 0.0000211 secs]2018-06-03T20:52:03.888-0800: 18.034: [JNI Weak Reference, 0.0000192 secs], 0.0084976 secs]

一般在Ref Proc时间超过GC暂停时间的10%时就要关注。Ref Proc的信息打印在每次垃圾收集的Other信息模块:

[Other: 0.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]

如果SoftReference过多,会有频繁的老年代收集。-XX:SoftRefLRUPolicyMSPerMB参数,可以指定每兆堆空闲空间的软引用的存活时间,默认值是1000,也就是1秒。可以调低这个参数来触发更早的回收软引用。如果调高的话会有更多的存活数据,可能在GC后堆占用空间比会增加。

对于软引用,还是建议尽量少用,会增加存活数据量,增加GC的处理时间

7总结

本文简单介绍了一下G1 GC的调优参数以及G1 GC的日志内容。在具体调优过程,可以增加一些调优的参数,如-XX:+G1SummarizeRSetStats、-XX:+PrintReferenceGC、-XX:+PrintAdaptiveSizePolicy等。每次调参后还要密切关注GC log,最好能模拟生产环境进行全链路的测试。没有一个参数的调整是可以普适任何应用的,如果没有GC问题,就不需要为了优化而优化。但是对于GC的知识储备和更新,是每个应用开发工程师必备的知识模块。

---------------------

本文分享自微信公众号 - 程序猿杂货铺(zhoudl_l),作者:马猴烧酒啊虾虾虾

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2018-10-20

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • Quartz原理解密

    quartz是一个用java实现的开源任务调度框架,可以用来创建简单或者复杂的任务调度,并且可以提供许多企业级的功能,比如JTA以及集群等,是当今比较流行的JA...

    周三不加班
  • 一次Java内存泄漏调试的有趣经历

    人人都会犯错,但一些错误是如此的荒谬,我想不通怎么会有人犯这种错误。更没想到的是,这种事竟发生在了我们身上。当然,这种东西只有事后才能发现真相。接下来,我将讲述...

    周三不加班
  • MYSQL 数据库时间字段 INT,TIMESTAMP,DATETIME 性能效率比较

    在数据库设计的时候,我们经常会需要设计时间字段,在 MYSQL 中,时间字段可以使用 int、timestamp、datetime 三种类型来存储,那么这三种类...

    周三不加班
  • Unreal Engine(二) - 初识UE4

    雷潮
  • 分叉最后关头,币圈大佬预测新比特币的价格走势

    12月对数字货币来说具有重要意义,这一月迎来了比特币的分叉热潮,众多人的目光聚焦于此,各路分叉币粉墨登场,每天都在上演“夺嫡”之战。一个名为新比特币(BTN)的...

    企鹅号小编
  • 乐卓科技运营总监廖亮:大数据助力游戏精细化运营实践(内附视频&PPT)

    数据猿导读 现在时代飞速的发展,人们获取信息的渠道非常多。在这个过程中,渠道整合所带来的竞争压力是所有的手机游戏发行行业共同面临的一个难题。渠道占据了大部分的用...

    数据猿
  • 四则运算核心算法(开源)

    前言                                                                              ...

    ^_^肥仔John
  • 金山云正式推出GPU云服务器实例

    近日,金山云正式推出GPU云服务器实例P3I实例,目前已在金山云官网上线。P3I实例是业内首款采用英伟达高性能计算卡Tesla P4的云服务器产品,单实例负载能...

    GPUS Lady
  • 每个CMDB系统都存在的5个数据质量问题

    CMDB的好坏取决于其数据的质量。不幸的是,大多数CMDB都充满了过时的、不一致的或不完整的数据。

    boypoo
  • Go语言入门(七)goroutine和channel

    需要注意<-是在chan关键字的位置,<-在chan左侧表示只读,在右侧表示只写

    alexhuiwang

扫码关注云+社区

领取腾讯云代金券