记：一次young gc优化记录

最新推荐文章于 2023-08-25 16:42:39 发布

学无止境-逆流而上

最新推荐文章于 2023-08-25 16:42:39 发布

阅读量485

点赞数

文章标签： java jvm 算法内存泄漏多线程

本文链接：https://blog.csdn.net/ITbasketplayer/article/details/115322034

版权

通过对G1垃圾收集器的配置调整，如-Xmx8g、-XX:MaxGCPauseMillis=100、-XX:G1NewSizePercent=10等，成功将平均暂停时间从137.7ms降低到69ms，最大暂停间隔时间从35.9s减少到19.5s。优化主要集中在减少UpdateRS、ScanRS和ObjectCopy阶段的耗时，从而改善服务响应速度和用户体验。

摘要由CSDN通过智能技术生成

优化结果

平均暂停时间137.7ms->69ms，最大暂停时间690.2ms->480ms【效果提升】
平均暂停间隔35.9s->19.5s【效果降低】

注：gc优化追求最小暂停时间&最大暂停间隔时间(比如ygc 10s以上触发一次，每次50ms以下就还可以)，两者在不优化代码情况下，呈负相关。此次优化不涉及代码优化。

服务gc现状

分配内存：12G
gc算法：G1
gc情况：无Full gc，96.4%STW由Young gc引起，1.9%STW由mixed gc引起，平均STW耗时137.7ms，最大STW耗时610.2ms，平均STW间隔时间35.9s，最大STW间隔时间214.6s
内存使用情况：老年代5.3G，年轻代5.5G(由G1自由分配)，平均闲置内存5-6G

gcviewer查看优化前gc日志

分析

内存开的比较多(12G)，搜索QPS高峰每台机大概2-3左右，非常少，可以调小
没有Full gc比较正常，因为内存很足。ygc STW平均间隔35.9s，也算不错，但平均137ms暂停时间，比较大

gc日志看ygc耗时在哪里：

/* 0.1616325 secs是本次GC的暂停时间*/

2021-03-25T11:51:20.677+0800: 162504.861: [GC pause (G1 Evacuation Pause) (young), 0.1616325 secs]

/*12个线程开始的时间，Min表示最早开始的线程时间，Avg表示平均开始时间，Max表示的是最晚开始时间，Diff为最早和最晚的时间差。这个值越大说明线程启动时间越不均衡。线程启动的时间依赖于GC进入安全点的情况*/

 [Parallel Time: 156.4 ms, GC Workers: 12]

      [GC Worker Start (ms):  162504861.9  162504861.9  162504861.9  162504862.0  162504862.0  162504862.0  162504862.0  162504862.0  162504862.0  162504862.0  162504862.0  162504862.0
       Min: 162504861.9, Avg: 162504862.0, Max: 162504862.0, Diff: 0.1]

   /*根处理的时间，这个时间包含了所有强根的时间，分为Java根，分别为Thread、JNI、CLDG；和JVM根下面的StringTable、Universe、JNI Handles、ObjectSynchronizer、FlatProfiler、Management、SystemDictionary、JVMTI*/
      [Ext Root Scanning (ms):  2.7  2.6  2.5  2.5  2.8  2.5  2.5  2.5  2.5  2.5  2.5  2.5
       Min: 2.5, Avg: 2.5, Max: 2.8, Diff: 0.3, Sum: 30.4]

     /*Java线程处理时间，主要是线程栈。这个时间包含了根直接引用对象的复制时间，如果根超级大，这个时间可能会增加*/
         [Thread Roots (ms):  0.5  1.8  1.9  1.8  1.8  1.8  1.8  1.8  1.8  1.8  1.7  1.7
          Min: 0.5, Avg: 1.7, Max: 1.9, Diff: 1.4, Sum: 20.1]
         [StringTable Roots (ms):  0.9  0.9  0.8  0.9  0.0  0.9  0.8  0.9  0.9  0.9  0.2  0.9
          Min: 0.0, Avg: 0.7, Max: 0.9, Diff: 0.9, Sum: 8.6]
         [Universe Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [JNI Handles Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [ObjectSynchronizer Roots (ms):  0.0  0.0  0.0  0.0  1.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.1, Max: 1.1, Diff: 1.1, Sum: 1.1]
         [FlatProfiler Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [Management Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SystemDictionary Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.7  0.0
          Min: 0.0, Avg: 0.1, Max: 0.7, Diff: 0.7, Sum: 0.7]
         [CLDG Roots (ms):  1.4  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.1, Max: 1.4, Diff: 1.4, Sum: 1.4]
         [JVMTI Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

     /*CodeCache Roots实际上是在处理Rset的时候的统计值，它包含下面的UpdateRS，ScanRS和Code Root Scanning*/
         [CodeCache Roots (ms):  24.3  24.3  24.3  24.4  24.2  24.4  24.3  24.3  24.4  24.4  24.4  24.3
          Min: 24.2, Avg: 24.3, Max: 24.4, Diff: 0.2, Sum: 291.8]
         [CM RefProcessor Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Wait For Strong CLD (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Weak CLD Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SATB Filtering (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

      /*允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区(dirty card)，保证Rset最新，这里差不多10%是合理的*/
      [Update RS (ms):  16.2  16.1  16.1  16.1  15.9  16.3  16.1  16.1  16.2  16.1  16.1  16.1
       Min: 15.9, Avg: 16.1, Max: 16.3, Diff: 0.3, Sum: 193.6]
         [Processed Buffers:  81  74  85  79  132  134  90  83  101  110  75  59
          Min: 59, Avg: 91.9, Max: 134, Diff: 75, Sum: 1103]

      /*扫描每个新生代分区的RSet，找出有多少指向当前分区的引用来自CSet*/
      [Scan RS (ms):  8.1  8.2  8.1  8.3  8.3  8.1  8.1  8.1  8.2  8.3  8.2  8.2
       Min: 8.1, Avg: 8.2, Max: 8.3, Diff: 0.2, Sum: 98.1]
      [Code Root Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

      /*在疏散暂停期间，所有在CSet中的分区必须被转移疏散，Object Copy就负责将当前分区中存活的对象拷贝到新的分区，说明有大量存活对象*/
      [Object Copy (ms):  129.2  129.3  129.4  129.3  129.2  129.2  129.3  129.3  129.2  129.2  129.2  129.3
       Min: 129.2, Avg: 129.3, Max: 129.4, Diff: 0.3, Sum: 1551.1]

      /*GC线程结束的时间信息*/
      [Termination (ms):  0.1  0.1  0.0  0.0  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.0
       Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
         [Termination Attempts:  61  83  57  1  75  55  59  65  74  66  69  59
          Min: 1, Avg: 60.3, Max: 83, Diff: 82, Sum: 724]

      /*这个是并行处理时其他处理所花费的时间，通常是由于JVM析构释放资源等*/
      [GC Worker Other (ms):  0.0  0.0  0.1  0.0  0.1  0.1  0.0  0.1  0.1  0.1  0.0  0.1
       Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]

      /*并行GC花费的总体时间*/
      [GC Worker Total (ms):  156.3  156.2  156.3  156.2  156.2  156.2  156.2  156.3  156.2  156.2  156.1  156.2
       Min: 156.1, Avg: 156.2, Max: 156.3, Diff: 0.1, Sum: 1874.7]
      [GC Worker End (ms):  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2  162505018.2
       Min: 162505018.2, Avg: 162505018.2, Max: 162505018.2, Diff: 0.1]

[Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 4.5 ms]
      [Choose CSet: 0.0 ms]

      /*引用处理的时间，这个时间是发现哪些引用对象可以清除，这个是可以并行处理的，太长的话加上 -XX:+ParallelRefProcEnabled */

      [Ref Proc: 0.6 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
         [Parallel Redirty:  0.5  0.5  0.5  0.5  0.5  0.5  0.5  0.5  0.5  0.5  0.5  0.5
          Min: 0.5, Avg: 0.5, Max: 0.5, Diff: 0.1, Sum: 5.9]
         [Redirtied Cards:  30711  29285  27392  29302  25344  28213  28416  23772  27460  28416  23348  27117
          Min: 23348, Avg: 27398.0, Max: 30711, Diff: 7363, Sum: 328776]

      /*大对象处理时间，和-XX:G1HeapRegionSize=4m有关*/
      [Humongous Register: 0.1 ms]

         /*大对象87个*/
         [Humongous Total: 87]

         /*可回收15个*/
         [Humongous Candidate: 15]

      /*大对象回收耗时和个数*/
      [Humongous Reclaim: 0.1 ms]
         [Humongous Reclaimed: 0]

      /*释放CSet中的分区花费的时间，有新生代的信息和老生代的信息*/
      [Free CSet: 1.0 ms]
         [Young Free CSet: 1.0 ms]
         [Non-Young Free CSet: 0.0 ms]
   [Eden: 2312.0M(2124.0M)->0.0B(4304.0M) Survivors: 260.0M->216.0M Heap: 6334.8M(12.0G)->4126.2M(12.0G)]
 [Times: user=1.88 sys=0.00, real=0.16 secs]

主要耗时：

Update RS (Remembered Set or RSet) ：【16ms耗时】允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区(dirty card)，保证Rset最新。-XX:MaxGCPauseMillis参数是限制G1的暂停时间，一般RSet更新的时间小于10%的目标暂停时间是比较可取的。如果花费在RSetUpdate的时间过长，可以修改其占用总暂停时间的百分比-XX:G1RSetUpdatingPauseTimePercent。这个参数的默认值是10。
Scan RS ：【8ms耗时】扫描每个新生代分区的RSet，找出有多少指向当前分区的引用来自CSet
Object Copy ：【130ms耗时】在疏散暂停期间，所有在CSet中的分区必须被转移疏散，Object Copy就负责将当前分区中存活的对象拷贝到新的分区(说明大量存活对象)

分析结论：

gc暂停耗时，基本由ygc导致
ygc 95%以上的暂停耗时，在Update RS (Remembered Set or RSet) ，Scan RS，Object Copy这3个阶段，可能原因有年轻代分配太多内存、年轻代比例太高、XX:MaxGCPauseMillis设置太高等

优化及效果

-Xmx8g \
-Xms8g \

由12G变成8G，大内存会减少STW间隔时间，但也会增加每次ygc STW的耗时

-XX:MaxGCPauseMillis=100 \

由200变成100，在不增加Full gc情况下，尽可能追求低延时

-XX:G1NewSizePercent=10 \
-XX:G1MaxNewSizePercent=45 \

此应用是新生代产生特别快的场景，G1NewSizePercent默认5变成10加速分配，G1MaxNewSizePercent默认60变成45可以早点进入ygc，但量少了可能会快，即牺牲间隔时间换取低延时

-XX:G1HeapRegionSize=4m \

最大内存8G，G1HeapRegionSize=4m，可以保证比较合理的region size(接近2048)

-XX:+ParallelRefProcEnabled \

优化Ref Proc时间，这里优化空间不大，只有0.x毫秒

gcviewer查看优化后gc日志

老年代回收-并发标记周期步骤(引用博客文章内容，与当前问题排查无关，仅备忘)

// 把YHR中Survivor分区作为根，开始并发标记根扫描
100.146: [GC concurrent-root-region-scan-start]
// 并发标记根扫描结束，花费了0.0196297，注意扫描和Mutator是并发进行，同时有多个线程并行
100.165: [GC concurrent-root-region-scan-end, 0.0196297 secs]
// 开始并发标记子阶段，这里从所有的根引用：包括Survivor和强根如栈等出发，对整个堆进行标记
100.165: [GC concurrent-mark-start]
// 标记结束，花费0.08848s
100.254: [GC concurrent-mark-end, 0.0884800 secs]
// 这里是再标记子阶段，包括再标记、引用处理、类卸载处理信息
100.254: [GC remark 100.254: [Finalize Marking, 0.0002228 secs] 100.254: 
  [GC ref-proc, 0.0001515 secs] 100.254: [Unloading, 0.0004694 secs], 
  0.0011610 secs]
  [Times: user=0.00 sys=0.00, real=0.00 secs]
// 清除处理，这里的清除仅仅回收整个分区中的垃圾
// 这里还会调整RSet，以减轻后续GC中RSet根的处理时间
100.255: [GC cleanup 86M->86M(128M), 0.0005376 secs]
  [Times: user=0.00 sys=0.00, real=0.00 secs]

初始标记init-mark
并发标记concurrent-mark
重新标记remark(STW)
清理阶段(STW)

学无止境-逆流而上

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
记：一次young gc优化记录

优化结果平均暂停时间137.7ms->69ms，最大暂停时间690.2ms->480ms【效果提升】平均暂停间隔35.9s->19.5s【效果降低】注：gc优化追求最小暂停时间&最大暂停间隔时间(比如ygc 10s以上触发一次，每次50ms以下就还可以)，两者在不优化代码情况下，呈负相关。此次优化不涉及代码优化。服务gc现状分配内存：12Ggc算法：G1gc情况：无Ful...
复制链接

扫一扫