G1GC备注阶段耗时过长 [英] G1GC remark phase is taking too long
本文介绍了G1GC备注阶段耗时过长的处理方法，对大家解决问题具有一定的参考价值，需要的朋友们下面随着小编来一起学习吧！
问题描述
我的服务器应用程序在某些时候无法响应，我发现问题与很长的GC备注有关。没有实施垃圾收集调整。我的测试服务器是一个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清理1951M-> 1750M（2954M），0.0037930秒]
2014-04-06T04：40：45.174 + 0530：67310.153：[GC并发清理开始]
2014-04 -06T04：40：45.175 + 0530：67310.154：[GC并发清理结束，0.0002800秒]
2014-04-06T04：40：45.633 + 0530：67310.612：[GC暂停（年轻）2451M-> 1534M（2954M），0.0764360秒]
2014-04-06T04：40：45.815 + 0530：67310.794：[GC暂停（年轻）（初始标记）1672M-> 1554M（2954M），0.0687640秒] b $ b 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 - 根区域扫描结束，0.0285320秒]
2014-04-06T04：40：45.912 + 0530：67310.891：[GC并发标记开始]
2014-04-06T04：40： 46.919 + 0530：67311.898：[GC暂停（youn g）2590M-> 1622M（2954M），0.0752180秒]
2014-04-06T04：40：47.231 + 0530：67312.210：[GC并发标记结束，1.3191870秒]
2014-04 -06T04：40：47.239 + 0530：67312.218：[GC备注，46.6353020秒]
，我试图关掉掉线，但这似乎并没有帮助减少评论时间。还有另一台运行4 GB内存的测试服务器，其中的东西更好，更稳定。
任何关于如何改善这种情况的想法。
======编辑 - 添加日志from -XX：+ PrintGCDetails =========
2014-04-06T09：45：30.953 + 0530 ：7777.585：[GC备注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秒时间：用户= 0.01系统= 0.00，实际时间= [秒钟]
2014-04-06T09：45：55.921 + 0530：7802.553：[GC清理2053M-> 1822M（2954M），0.0039070秒] = 0.01秒]
2014-04-06T09：45：55.928 + 0530：7802.560：[GC并发清理开始]
2014-04-06T09：45：55.929 + 0530：7802.560：[GC并发清理结束，0.0003390秒]
2014-04-06T09：45：56.254 + 0530：7802.885：[GC暂停（年轻），0.0770030秒]
[并行时间：70.3毫秒，GC工作人员：4]
[GC工作开始时间（ms）：最小值：7802888.9，平均值：7802889.0，最大值：7802889.0，Diff：0.1]
[Ext Root Scanning（ms）：Min：22.2，Avg：24.2 ，Max：26.5，Diff：4.2，Sum：96.7]
[更新RS（ms）：最小值：13.8，平均值：15.9，最大值：18.2，Diff：4.4，总和值：63.7]
[已处理的缓冲区：最小值：177，平均值：183.2，最大值：189， ，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 ，平均值：29.6，最大值：30.4，比较值：1.2，总和值：118.4]
[终止值（毫秒）：最小值：0.0，平均值：0.0，最大值：0.1，差值：0.1，总和值：0.2] GC工作人员总数（ms）：最小值：70.0，平均值：70.1，最大值：最大值：0.1，差值：0.1，总和：0.3] ：70.2，Diff：0.1，Sum：280.5]
[GC工作结束时间（ms）：最小值：7802959.0，平均值：7802959.1，最大值：7802959.1，Diff：0.1]
[Code Root Fixup：0.0 ms ]
[Clear CT：0.2 ms]
[其他：6.5 ms]
[选择CSet：0.0 ms]
[Ref Proc：1.4 ms]
[Ref [Eden：766.0M（766.0M） - > 0.0B（101.0M）幸存者：28.0M-> 46.0M堆：2359.1 M（2954.0M） - > 1610.6M（2954.0M）]
[时间：用户= 0.29 sys = 0.00，实际= 0.07秒]
2014-04-06T09：45：56.434 + 0530：7803.066：[GC暂停（混合），0.0560090秒]
[Parallel Time ：50.4 ms，GC Workers：4]
[GC Worker Start（ms） ：20.9，Avg：23.2，Max：26.1，Diff：5.3，Sum：92.6]
[更新RS（ms）：最小值：1.4，平均值：4.0，最大值：6.6，Diff：5.2，总和：16.1]
[已处理的缓冲区：最小值：29，平均值：38.0，最大值：49，比较值：20，总和值：152]
[扫描RS（ms）：最小值：0.2，平均值：0.2，最大值：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]
[ GC工作其他（毫秒）：最小值：0.0，平均值：0.0，最大值：0.1，差值：0.0，总和：0.0，平均值：0.0，最大值：0.0，差值：0.0， 0.2]
[GC工人总数（毫秒）：最小值：50.2，平均值：50.3，最大值：50.3，差值：0.1，总和：201.0]
[GC工作结束时间（毫秒）：最小值：7803119.6，平均：7803119。 6，Max：7803119.6，Diff：0.0]
[Code Root Fixup：0.0 ms]
[Clear CT：0.1 ms]
[Other：5.5 ms]
[ ：0.0 ms]
[Ref Proc：1.1 ms]
[Ref Enq：0.0 ms]
[Free CSet：0.4 ms]
[Eden：101.0M（101.0M） （934.0M）幸存者：46.0M-> 5120.0K堆：1727.6M（2954.0M）→1608.3M（2954.0M）]
[次数：用户= 0.20 sys = 0.00，实际= 0.05秒]
2014-04-06T09：45：56.612 + 0530：7803.244：[GC暂停（年轻）（初始标记），0.0612000秒]
[并行时间：54.2 ms，GC （MS）：最小：7803247.0，平均：7803248.2，最大：7803252.0，Diff：5.0]
[Ext Root Scanning（ms）：Min：19.9，Avg： [更新RS（ms）：最小值：12.4，平均值：15.0，最大值：17.4，差值：5.1，总和值：60.2]
[最大值：28.7，差值：8.8，总和：96.3]处理的缓冲区：最小48，平均63.8，最大79，差值31，总和255]
[扫描RS（ms）：最小值：0.0，平均值：0.1，最大值：0.1，总和：0.2]
[Object Co py（ms）：Min：12.3，Avg：13.5，Max：16.6，Diff：4.2，Sum：54.2]
[终止（毫秒）：最小值：0.0，平均值：0.0，最大值：0.0，差值：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，平均值：52.8，最大值：54.0，差值：5.0，总和：211.1]
[GC工作结束时间（ms）：最小值：7803301.0，平均值：7803301.0，最大值：7803301.1，Diff：0.1] b [Code Root Fixup：0.0 ms]
[Clear CT：0.1 ms]
[Other：6.8 ms]
[选择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）幸存者：5120.0K - > 16.0M堆：1741.7M（2954.0M） - > 1618.8M（2954.0M）]
[时间：用户= 0.22 sys = 0.00，实际= 0.07秒]
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-结束，0.0100810秒]
2014-04-06T09：45：56.685 +0530：7803.316：[GC并发标记开始]
2014-04-06T09：45：57.759 + 0530：7804.391：[GC暂停（年轻），0.0648020秒]
[并行时间：55.0 ms，GC Worker：4]
[GC Worker Start（ms）：Min：7804393.8，Avg：7804393.9，Max：7804393.9，Diff：0.1]
[Ext Root Scanning（ms）：Min：21.4 ，平均值：23.8，最大值：26.5，比较值：5.1，总和值：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]
[已处理的缓冲区：最小值：110，平均值：165.8，最大值：224， ：114，Sum：663]
[Scan RS（ms）：Min：0.3，Avg：0.4，Max：0.4，Diff：0.0，Sum：1.4]
[ ：14.4，平均值：14.8，最大值：15.5，差值：1.1，总和值：59.1]
[终止值（毫秒）：最小值：0.0，平均值：0.0，最大值：0.0，差值：0.0，总和：0.0] $ b $ GC工作人员总数（ms）：最小值：54.7，平均值：54.8 b $ b [GC工作人员其他（毫秒）：最小值：0.0，平均值：0.1，最大值：0.1，差值：0.1，总和：0.3] ，最大：5 [代码根固定：0.0ms] 4.9，Diff：0.1，Sum：219.3]
[GC工作结束时间（ms）：最小值：7804448.7，平均值：7804448.7，最大值：7804448.7，Diff：0.1]
[Clear CT：0.3 ms]
[其他：9.6 ms]
[选择CSet：0.0 ms]
[Ref Proc：4.5 ms]
[Ref Enq ：0.0ms]
[Free CSet：1.2ms]
[Eden：916.0M（927.0M） - > 0.0B（853.0M）幸存者：16.0M-> 25.0M堆：2592.4M （2954.0M） - > 1685.9M（2954.0M）]
[时间：用户= 0.24 sys = 0.00，实际= 0.07秒]
2014-04-06T09：45：58.330 + 0530：7804.961 ：[GC并发标记结束，1.6449220秒]
2014-04-06T09：45：58.335 + 0530：7804.967：[GC备注2014-04-06T09：45：58.339 + 0530：7804.970：[GC ref
$ / code $ / pre $ b $ [bc = 26.3976280 secs]，26.4233450 secs]
[Times：user = 26.28 sys = 0.14，real = 26.42 secs] b
====编辑添加-XX：+ PrintReferenceGC和-XX：+ ParallelRefProcEnabled ======
[GC评论：
[GC ref-proc：
[SoftReference，122658
[WeakReference，714 refs，0.1420020 secs]
[FinalReference，32 refs，0.0145060 secs]
[PhantomReference，37 refs，0.0144000 secs]
[JNI弱参考，1.2714530秒]
，12.9211700秒]
，12.9469960秒]
现在，大部分时间都在进行软测量。我找到了一个代码段，每秒创建大量的softreferences。我会禁用它，看看它是否有帮助。
==========编辑 - 从代码中删除softreference之后==========
通过修复代码删除软引用后，事情已经大大改善，并且SoftRefernece处理时间现在可以忽略不计！ 。最后一个问题，我仍然看到JNI弱参考时间逐渐增加。我现在要调查这个问题。 我不确定这是不是红鲱鱼，但是根据这篇文章评论阶段也做参考处理。因此，如果您的应用程序使用大量软/弱引用，它可能会夸大注释阶段。
如果您添加Option -XX：+ PrintGCDetails，您可能会获得更多信息在GC日志中...
My server application under load some times goes unresponsive and i found the issue to be related to very long "GC Remark". There is no garbage collection tuning implemented. My test server is a 4 core/8 gb/8 GB swap.
This is the log output from 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]
In this state, i tried turn off swap, but that doesnt seems to help reduce the remark time. There is another test server which runs 4 gb memory and there things are better and stable.
Any thoughts on how i can improve this situation.
====== EDIT - Adding logs from -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]
==== Edit After adding -XX:+PrintReferenceGC and -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]
Now softreference is taking most of the time. I have found a code section which creates a large number of softreferences per second. I will disable that and see if it helps.
========== EDIT - After Removing softreference from code ==========
After removing soft references by fixing code, things have vastly improved and SoftRefernece processing time is negligible now !!! . One last problem i still see "JNI Weak Reference" time gradually increasing. I will investigate that issue now.
解决方案 I'm not sure if this is a red-herring, but according to this article the remark phase also does reference processing. So if your application is using huge numbers of soft/weak references, it could inflate the remark phase.
If you add Option -XX:+PrintGCDetails you might get more info in the GC log ...
这篇关于G1GC备注阶段耗时过长的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
查看全文
