G1GC标记阶段耗时过长。

Question

G1GC标记阶段耗时过长。

4

我的服务器应用程序在负载下有时会变得无响应，我发现问题与非常长的“GC Remark”有关。没有进行垃圾收集调优。我的测试服务器是4核/8 GB / 8 GB交换空间。

这是来自GC日志的日志输出。

2014-04-06T04:39:58.426+0530: 67263.405: [GC remark, 46.7308340 secs]
2014-04-06T04:40:45.167+0530: 67310.146: [GC cleanup 1951M->1750M(2954M), 0.0037930 secs]
2014-04-06T04:40:45.174+0530: 67310.153: [GC concurrent-cleanup-start]
2014-04-06T04:40:45.175+0530: 67310.154: [GC concurrent-cleanup-end, 0.0002800 secs]
2014-04-06T04:40:45.633+0530: 67310.612: [GC pause (young) 2451M->1546M(2954M), 0.0764360 secs]
2014-04-06T04:40:45.815+0530: 67310.794: [GC pause (young) (initial-mark) 1672M->1554M(2954M), 0.0687640 secs]
2014-04-06T04:40:45.884+0530: 67310.863: [GC concurrent-root-region-scan-start]
2014-04-06T04:40:45.912+0530: 67310.891: [GC concurrent-root-region-scan-end, 0.0285320 secs]
2014-04-06T04:40:45.912+0530: 67310.891: [GC concurrent-mark-start]
2014-04-06T04:40:46.919+0530: 67311.898: [GC pause (young) 2590M->1622M(2954M), 0.0752180 secs]
2014-04-06T04:40:47.231+0530: 67312.210: [GC concurrent-mark-end, 1.3191870 secs]
2014-04-06T04:40:47.239+0530: 67312.218: [GC remark, 46.6353020 secs]

在这种情况下，我尝试关闭Swap，但似乎并没有帮助减少响应时间。另外还有一个测试服务器，它运行着4GB内存，并且那里的情况更好、更稳定。

你有什么想法可以改善这种情况吗？

====== 编辑 - 添加来自-XX:+PrintGCDetails的日志信息 =========

2014-04-06T09:45:30.953+0530: 7777.585: [GC remark 2014-04-06T09:45:30.959+0530: 7777.590: [GC ref-proc, 24.9282110 secs], 24.9556400 secs]
 [Times: user=24.89 sys=0.06, real=24.96 secs]
2014-04-06T09:45:55.921+0530: 7802.553: [GC cleanup 2053M->1822M(2954M), 0.0039070 secs]
 [Times: user=0.01 sys=0.00, real=0.01 secs]
2014-04-06T09:45:55.928+0530: 7802.560: [GC concurrent-cleanup-start]
2014-04-06T09:45:55.929+0530: 7802.560: [GC concurrent-cleanup-end, 0.0003390 secs]
2014-04-06T09:45:56.254+0530: 7802.885: [GC pause (young), 0.0770030 secs]
   [Parallel Time: 70.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7802888.9, Avg: 7802889.0, Max: 7802889.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 22.2, Avg: 24.2, Max: 26.5, Diff: 4.2, Sum: 96.7]
      [Update RS (ms): Min: 13.8, Avg: 15.9, Max: 18.2, Diff: 4.4, Sum: 63.7]
         [Processed Buffers: Min: 177, Avg: 183.2, Max: 189, Diff: 12, Sum: 733]
      [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 1.2]
      [Object Copy (ms): Min: 29.2, Avg: 29.6, Max: 30.4, Diff: 1.2, Sum: 118.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 70.0, Avg: 70.1, Max: 70.2, Diff: 0.1, Sum: 280.5]
      [GC Worker End (ms): Min: 7802959.0, Avg: 7802959.1, Max: 7802959.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 6.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.4 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 1.1 ms]
   [Eden: 766.0M(766.0M)->0.0B(101.0M) Survivors: 28.0M->46.0M Heap: 2359.1M(2954.0M)->1610.6M(2954.0M)]
 [Times: user=0.29 sys=0.00, real=0.07 secs]
2014-04-06T09:45:56.434+0530: 7803.066: [GC pause (mixed), 0.0560090 secs]
   [Parallel Time: 50.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7803069.3, Avg: 7803069.3, Max: 7803069.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 20.9, Avg: 23.2, Max: 26.1, Diff: 5.3, Sum: 92.6]
      [Update RS (ms): Min: 1.4, Avg: 4.0, Max: 6.6, Diff: 5.2, Sum: 16.1]
         [Processed Buffers: Min: 29, Avg: 38.0, Max: 49, Diff: 20, Sum: 152]
      [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.0, Sum: 0.9]
      [Object Copy (ms): Min: 22.4, Avg: 22.8, Max: 23.6, Diff: 1.1, Sum: 91.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 50.2, Avg: 50.3, Max: 50.3, Diff: 0.1, Sum: 201.0]
      [GC Worker End (ms): Min: 7803119.6, Avg: 7803119.6, Max: 7803119.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 5.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 101.0M(101.0M)->0.0B(934.0M) Survivors: 46.0M->5120.0K Heap: 1727.6M(2954.0M)->1608.3M(2954.0M)]
 [Times: user=0.20 sys=0.00, real=0.05 secs]
2014-04-06T09:45:56.612+0530: 7803.244: [GC pause (young) (initial-mark), 0.0612000 secs]
   [Parallel Time: 54.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7803247.0, Avg: 7803248.2, Max: 7803252.0, Diff: 5.0]
      [Ext Root Scanning (ms): Min: 19.9, Avg: 24.1, Max: 28.7, Diff: 8.8, Sum: 96.3]
      [Update RS (ms): Min: 12.4, Avg: 15.0, Max: 17.4, Diff: 5.1, Sum: 60.2]
         [Processed Buffers: Min: 48, Avg: 63.8, Max: 79, Diff: 31, Sum: 255]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Object Copy (ms): Min: 12.3, Avg: 13.5, Max: 16.6, Diff: 4.2, Sum: 54.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Total (ms): Min: 49.1, Avg: 52.8, Max: 54.0, Diff: 5.0, Sum: 211.1]
      [GC Worker End (ms): Min: 7803301.0, Avg: 7803301.0, Max: 7803301.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 6.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.0 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 134.0M(934.0M)->0.0B(927.0M) Survivors: 5120.0K->16.0M Heap: 1741.7M(2954.0M)->1618.8M(2954.0M)]
 [Times: user=0.22 sys=0.00, real=0.07 secs]
2014-04-06T09:45:56.675+0530: 7803.306: [GC concurrent-root-region-scan-start]
2014-04-06T09:45:56.685+0530: 7803.316: [GC concurrent-root-region-scan-end, 0.0100810 secs]
2014-04-06T09:45:56.685+0530: 7803.316: [GC concurrent-mark-start]
2014-04-06T09:45:57.759+0530: 7804.391: [GC pause (young), 0.0648020 secs]
   [Parallel Time: 55.0 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 7804393.8, Avg: 7804393.9, Max: 7804393.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 21.4, Avg: 23.8, Max: 26.5, Diff: 5.1, Sum: 95.0]
      [SATB Filtering (ms): Min: 0.0, Avg: 0.4, Max: 1.7, Diff: 1.7, Sum: 1.7]
      [Update RS (ms): Min: 13.3, Avg: 15.4, Max: 18.3, Diff: 5.0, Sum: 61.7]
         [Processed Buffers: Min: 110, Avg: 165.8, Max: 224, Diff: 114, Sum: 663]
      [Scan RS (ms): Min: 0.3, Avg: 0.4, Max: 0.4, Diff: 0.0, Sum: 1.4]
      [Object Copy (ms): Min: 14.4, Avg: 14.8, Max: 15.5, Diff: 1.1, Sum: 59.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 54.7, Avg: 54.8, Max: 54.9, Diff: 0.1, Sum: 219.3]
      [GC Worker End (ms): Min: 7804448.7, Avg: 7804448.7, Max: 7804448.7, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 9.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 4.5 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 1.2 ms]
   [Eden: 916.0M(927.0M)->0.0B(853.0M) Survivors: 16.0M->25.0M Heap: 2592.4M(2954.0M)->1685.9M(2954.0M)]
 [Times: user=0.24 sys=0.00, real=0.07 secs]
2014-04-06T09:45:58.330+0530: 7804.961: [GC concurrent-mark-end, 1.6449220 secs]
2014-04-06T09:45:58.335+0530: 7804.967: [GC remark 2014-04-06T09:45:58.339+0530: 7804.970: [GC ref-proc, 26.3976280 secs], 26.4233450 secs]
 [Times: user=26.28 sys=0.14, real=26.42 secs]

在添加了-XX:+PrintReferenceGC和-XX:+ParallelRefProcEnabled之后，需要进行编辑。

[GC remark : 
    [GC ref-proc: 
        [SoftReference, 122658 refs, 11.4784560 secs]
        [WeakReference, 714 refs, 0.1420020 secs]
        [FinalReference, 32 refs, 0.0145060 secs]
        [PhantomReference, 37 refs, 0.0144000 secs]
        [JNI Weak Reference, 1.2714530 secs]
    , 12.9211700 secs]
, 12.9469960 secs]

现在，软引用占用了大部分时间。我已经发现一个代码段，每秒钟创建大量的软引用。我将禁用它并查看是否有所帮助。

========== 编辑 - 删除代码中的软引用后 ==========

通过修复代码删除软引用后，情况有了巨大改善，软引用处理时间现在可以忽略不计了！但我仍然看到一个问题，“JNI弱引用”的时间逐渐增加。我现在会调查这个问题。

- Atul Soman

1个回答

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- Stephen C · Accepted Answer

7

我不确定这是否是一个误导，但根据这篇文章的说法，注释阶段也会进行引用处理。因此，如果您的应用程序使用大量软/弱引用，可能会增加注释阶段的负担。

如果您添加选项 -XX：+PrintGCDetails，则可能会在GC日志中获得更多信息...

- Stephen C

46秒内使用不到6GB的堆？我怀疑那不是原因。 - Eugene

谢谢Stephen，我已经添加了-XX：+PrintGCDetails并重新启动了我的测试服务器。目前它需要8秒钟进行标记，但随着时间的推移，它将增长到一分钟左右。 - Atul Soman

@StephenC 在 ref-proc 阶段花费了很长时间，开启 -XX:+ParallelRefProcEnabled 可能会有所帮助。 - Eugene

@Eugene/@StephenC，我现在正在使用-XX：+PrintReferenceGC和-XX：+PrintGCDetails运行。希望这能更清楚地解决问题。我稍后还会尝试使用ParallelRefProcEnabled，看看是否有所帮助。 - Atul Soman

@Atulsm，我看到这篇帖子很旧了，但是你在 JNI 弱引用方面有什么成功经验吗？我使用了 -XX:+ParallelRefProcEnabled 但是我经常看到 JNI 处理 >20s。虽然我的应用程序没有直接使用 JNI，但我使用的库大量使用 nio。 - kelaban

显示剩余2条评论