G1GC评论阶段耗时太长
我的服务器应用程序负载有时没有响应，我发现该问题与很长的“GC备注”有关。 没有实现垃圾收集调整。 我的测试服务器是4核/ 8 GB / 8 GB交换。
这是gc logs的日志输出。
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] 在这种状态下，我尝试关闭交换，但这似乎没有帮助减少注释时间。 还有另一个运行4 GB内存的测试服务器，事情更好，更稳定。
关于如何改善这种情况的任何想法。
======编辑 – 从-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]
现在，软参考占用大部分时间。 我找到了一个代码部分，每秒创建大量的软引用。 我将禁用它，看看它是否有帮助。
==========编辑 – 从代码中删除软引用后==========
通过修复代码删除软引用后，事情已经大大改进，SoftRefernece处理时间现在可以忽略不计！ 。 最后一个问题我仍然看到“JNI弱参考”时间逐渐增加。 我现在将调查这个问题。
我不确定这是不是红鲱鱼，但根据这篇文章 ，备注阶段也会进行参考处理。 因此，如果您的应用程序使用大量的软/弱引用，它可能会使注释阶段膨胀。
如果添加Option -XX：+ PrintGCDetails，您可能会在GC日志中获得更多信息…