java - G1启动并发标记周期时年轻GC时间较长

Question

JDK版本:

java version "1.7.0_91"
OpenJDK Runtime Environment (IcedTea 2.6.3) (7u91-2.6.3-0ubuntu0.14.04.1)
OpenJDK 64-Bit Server VM (build 24.91-b01, mixed mode)

GC/Mem 参数:

-Xms24g -Xmx24g -Xss256k -Djava.awt.headless=true -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxGCPauseMillis=10000 -XX:InitiatingHeapOccupancyPercent=30 -XX:+ParallelRefProcEnabled -XX:G1HeapWastePercent=5 -XX:G1OldCSetRegionThresholdPercent=20 -XX:G1HeapRegionSize=16m -XX:G1MixedGCLiveThresholdPercent=80 -XX:+PrintFlagsFinal -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintAdaptiveSizePolicy

偶尔，我会看到 young gc 暂停时间超过 1 分钟。我检查了GC日志，发现它们都出现了混合GC事件的并发标记周期初始化。由于 young gc 的估计暂停非常快，我的猜测是并发标记周期正在影响正常的 young gc 性能。我怎样才能减少影响？我检查了 gc 日志。大部分并发标记周期对young gc没有影响，只有极少数有较大影响。 gc日志是这样的:

   [Eden: 10.8G(10.8G)->0.0B(10.3G) Survivors: 160.0M->432.0M Heap: 21.3G(24.0G)->10.9G(24.0G)]
 [Times: user=3.61 sys=0.76, real=0.35 secs] 
 505008.424: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
505008.424: [GC pause (young) (initial-mark) 505008.425: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 151866, predicted base time: 65.35 ms, remaining time: 9934.65 ms, target pause time: 10000.00 ms]
 505008.425: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 659 regions, survivors: 27 regions, predicted young region time: 206.46 ms]
 505008.425: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 659 regions, survivors: 27 regions, old: 0 regions, predicted pause time: 271.81 ms, target pause time: 10000.00 ms]
, 90.8122050 secs]
   [Parallel Time: 90688.1 ms, GC Workers: 23]
      [GC Worker Start (ms): Min: 505008426.7, Avg: 505008427.4, Max: 505008427.9, Diff: 1.2]
      [Ext Root Scanning (ms): Min: 2.7, Avg: 7.8, Max: 18.4, Diff: 15.7, Sum: 179.8]
      [Code Root Marking (ms): Min: 0.0, Avg: 0.3, Max: 4.2, Diff: 4.2, Sum: 7.2]
      [Update RS (ms): Min: 33.8, Avg: 47.4, Max: 61.1, Diff: 27.3, Sum: 1090.1]
         [Processed Buffers: Min: 22, Avg: 40.2, Max: 107, Diff: 85, Sum: 924]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.5, Sum: 5.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 85537.6, Avg: 87188.8, Max: 90638.2, Diff: 5100.6, Sum: 2005342.7]
      [Termination (ms): Min: 0.0, Avg: 3441.6, Max: 5092.4, Diff: 5092.4, Sum: 79155.8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 0.8, Diff: 0.8, Sum: 10.1]
      [GC Worker Total (ms): Min: 90685.8, Avg: 90686.6, Max: 90687.3, Diff: 1.5, Sum: 2085790.9]
      [GC Worker End (ms): Min: 505099113.5, Avg: 505099113.9, Max: 505099114.3, Diff: 0.8]
   [Code Root Fixup: 0.2 ms]
   [Code Root Migration: 0.3 ms]
   [Clear CT: 1.6 ms]
   [Other: 122.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 105.3 ms]
      [Ref Enq: 4.8 ms]
      [Free CSet: 3.0 ms]
   [Eden: 10.3G(10.3G)->0.0B(128.0M) Survivors: 432.0M->1376.0M Heap: 21.2G(24.0G)->12.7G(24.0G)]
 [Times: user=82.22 sys=7.54, real=90.81 secs] 
505099.236: [GC concurrent-root-region-scan-start]
505099.311: [GC pause (young)505099.331: [GC concurrent-root-region-scan-end, 0.0943260 secs]
505099.331: [GC concurrent-mark-start]
 505099.331: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 322026, predicted base time: 159.64 ms, remaining time: 9840.36 ms, target pause time: 10000.00 ms]
 505099.331: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 8 regions, survivors: 86 regions, predicted young region time: 6030.20 ms]
 505099.331: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 8 regions, survivors: 86 regions, old: 0 regions, predicted pause time: 6189.84 ms, target pause time: 10000.00 ms]
 505101.745: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 28.00 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
, 2.4339110 secs]
   [Root Region Scan Waiting: 19.4 ms]
   [Parallel Time: 2385.4 ms, GC Workers: 23]
      [GC Worker Start (ms): Min: 505099330.9, Avg: 505099331.2, Max: 505099331.4, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 3.5, Avg: 12.8, Max: 17.0, Diff: 13.5, Sum: 295.5]
      [SATB Filtering (ms): Min: 0.0, Avg: 0.1, Max: 1.7, Diff: 1.7, Sum: 1.7]
      [Update RS (ms): Min: 2222.6, Avg: 2229.1, Max: 2266.2, Diff: 43.5, Sum: 51268.7]
         [Processed Buffers: Min: 41, Avg: 65.8, Max: 120, Diff: 79, Sum: 1514]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.1, Sum: 0.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 104.2, Avg: 141.5, Max: 147.9, Diff: 43.7, Sum: 3254.6]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 3.6]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 9.7, Diff: 9.7, Sum: 12.6]
      [GC Worker Total (ms): Min: 2383.9, Avg: 2384.3, Max: 2384.8, Diff: 0.8, Sum: 54837.8]
      [GC Worker End (ms): Min: 505101715.3, Avg: 505101715.4, Max: 505101715.7, Diff: 0.4]
   [Code Root Fixup: 0.3 ms]
   [Code Root Migration: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 28.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 19.7 ms]
      [Ref Enq: 0.3 ms]
      [Free CSet: 4.6 ms]
   [Eden: 128.0M(128.0M)->0.0B(1024.0M) Survivors: 1376.0M->192.0M Heap: 12.8G(24.0G)->12.9G(24.0G)]
 [Times: user=3.79 sys=1.10, real=2.43 secs] 
505103.032: [GC concurrent-mark-end, 3.7007580 secs]
505103.176: [GC remark 505103.181: [GC ref-proc, 0.0819490 secs], 0.0989750 secs]
 [Times: user=1.10 sys=0.15, real=0.10 secs] 
505103.278: [GC cleanup 13G->13G(24G), 0.0293890 secs]
 [Times: user=0.21 sys=0.14, real=0.03 secs] 
505103.308: [GC concurrent-cleanup-start]
505103.308: [GC concurrent-cleanup-end, 0.0001760 secs]
505104.534: [GC pause (young) 505104.538: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 623522, predicted base time: 2265.93 ms, remaining time: 7734.07 ms, target pause time: 10000.00 ms]
 505104.538: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 64 regions, survivors: 12 regions, predicted young region time: 5414.13 ms]
 505104.538: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 64 regions, survivors: 12 regions, old: 0 regions, predicted pause time: 7680.06 ms, target pause time: 10000.00 ms]
 505104.660: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 31.31 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
 505104.660: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 13706985472 bytes, allocation request: 0 bytes, threshold: 7730941110 bytes (30.00 %), source: end of GC]
 505104.660: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 290 regions, reclaimable: 1891629432 bytes (7.34 %), threshold: 5.00 %]
, 0.1258480 secs]
   [Parallel Time: 86.7 ms, GC Workers: 23]
      [GC Worker Start (ms): Min: 505104538.0, Avg: 505104538.4, Max: 505104538.5, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 3.3, Avg: 7.6, Max: 19.2, Diff: 15.9, Sum: 175.1]
      [Update RS (ms): Min: 53.4, Avg: 64.9, Max: 69.0, Diff: 15.6, Sum: 1491.9]
         [Processed Buffers: Min: 76, Avg: 120.3, Max: 149, Diff: 73, Sum: 2766]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.8, Avg: 13.5, Max: 14.1, Diff: 4.3, Sum: 310.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.4]
      [GC Worker Total (ms): Min: 85.9, Avg: 86.1, Max: 86.4, Diff: 0.5, Sum: 1979.9]
      [GC Worker End (ms): Min: 505104624.4, Avg: 505104624.4, Max: 505104624.5, Diff: 0.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Migration: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 38.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 32.0 ms]
      [Ref Enq: 0.6 ms]
      [Free CSet: 0.6 ms]
   [Eden: 1024.0M(1024.0M)->0.0B(1056.0M) Survivors: 192.0M->160.0M Heap: 13.7G(24.0G)->12.9G(24.0G)]
 [Times: user=1.56 sys=0.23, real=0.12 secs] 

Answer 1

尽快更新到 Java 8 - 自 Java 7 以来，G1 已经进行了大量修复和改进。可能包括这个问题 - 我在 CSet 构建期间看到的预测总体上是准确的。如果有的话，他们认为 GC 会花费比实际更长的时间。另外，性能差异是白天和黑夜，尤其是对于 G1。

此时您已经掌握了我推荐的大部分设置，但有一个需要注意:考虑使用 -XX:G1NewSizePercent=10 增加 eden 大小 - 理论上这会增加年轻 GC 周期的时间，但实际上它可能会起到相反的作用(通过减少旧集大小并使对象更容易收集)。

这也会让我担心:

[Times: user=82.22 sys=7.54, real=90.81 secs] [Times: user=1.56 sys=0.23, real=0.12 secs]

这是一个非常多的系统时间 - 也许正在发生分页或类似的情况？