G1 gc日志不会显示长时间暂停的线索 [英] G1 gc log doesn't show clue for long gc pause
本文介绍了G1 gc日志不会显示长时间暂停的线索的处理方法，对大家解决问题具有一定的参考价值，需要的朋友们下面随着小编来一起学习吧！
问题描述
-server -Xms1G -Xmx3000M -XX：+ UseG1GC -XX：+ PrintGC -XX：+ PrintGCDetails -XX：+ PrintGCDateStamps -XX：+ PrintGCApplicationStoppedTime -XX：+ PrintTenuringDistribution -XX：+ PrintHeapAtGC -XX：MaxGCPauseMillis = 50 -Xloggc：$ HAZELCAST_HOME /记录/ gclog.txt -verbose：GC
$ b
在2014-08-21T16：32：16.032中，GC导致超过33秒的长暂停（gc
日志片段如下）：2014-08-21T16：32：16.032-0700：798408.606：应用程序线程已停止的总
时间：33.7010420秒
我挖掘了gc日志（以及应用程序日志），并没有看到为什么发生这种33秒长的停顿的明确线索。是否有任何方法让G1转储更多细节以显示长时间停顿的原因（以及对于什么事件的长暂停的细分，例如用于扫描RS的xxxms等）。
我附上gc日志几分钟。您是否看到GC日志中存在任何问题以及是否需要进行JVM gc调优？
非常感谢！
GC日志
2014-08-21T16：24：47.996-0700：797960.570：应用程序线程停止的总时间：0.0005740秒
{GC调用前堆= 4957（全0）：
垃圾第一堆总1048576K，使用535899K [0x000000073f600000，0x000000077f600000，0x00000007fae00000）
区域大小1024K，275年轻（281600K），6名幸存者（6144K）
压实烫发根总20480K，使用16858K [0x00000007fae00000 ，0x00000007fc200000，0x0000000800000000）
空间20480K，已使用82％[0x00000007fae00000，0x00000007fbe76ad8，0x00000007fbe76c00，0x00000007fc200000）
未配置共享空间。
2014-08-21T16：25：35.830-0700：798008.405：[GC暂停（年轻）
希望的幸存者大小15204352字节，新阈值15（最多15）
- 年龄1：1490920字节，1490920 total
- age 2：1041336 bytes，2532256 total
- age 3：1462192 bytes，3994448 total
- age 4：669528 bytes，4663976 total
- age 5 ：600560字节，5264536总计
，0.0387690秒]
[并行时间：36.9毫秒，GC工作人员：2]
[GC工作起始时间（ms）：最小值：798008405.0，平均值：798008405.0，最大值：798008405.0，差值：0.0]
[外部根扫描（毫秒）：最小值：5.1，平均值：5.4，最大值：5.7，差值：0.6，总和：10.8] ：Min：6.3，Avg：6.7，Max：7.1，Diff：0.8，Sum：13.4]
[Processed Buffers：Min：5，Avg：14.0，Max：23，Diff：18，Sum：28]
[Scan RS（ms）：Min：8.5，Avg：9.3，Max：10.0，Diff：1.5，Sum：18.5]
[Object Copy（ms）：Min：15.4，Avg：15.4，Max ：15.5，Diff：0.1，Sum：30.9]
[终止（毫秒） ：最小值：0.0，平均值：0.0，最大值：0.0，差值：0.0，总和：0.0]
[GC Worker Other（ms）：Min：0.0，Avg：0.0，Max：0.0，Diff：0.0，Sum ：0.1]
[GC工人总数（毫秒）：最小值：36.8，平均值：36.8，最大值：36.8，差值：0.0，总和：73.6]
[GC工作结束时间（毫秒）：最小值：798008441.8
[Clear CT：0.6 ms]
[Other：1.3 ms]
[Ref Enq：0.0 ms]
[Free CSet：0.7 ms]
[Ese：0.2 ms] 224.0M） - > 0.0B（606.0M）幸存者：6144.0K-> 8192.0K堆：523.3M（1024.0M） - > 255.8M（1024.0M）]
GC调用后的堆= 4958（全0）：
垃圾第一堆总1048576K，使用261979K [0x000000073f600000，0x000000077f600000，0x00000007fae00000）
区域大小1024K，8年轻（8192K），8名幸存者（8192K）
压实烫发根总计20480K，使用16858K [0x00000007fae00000，0x00000007fc200000，0x0000000800000000）
空间20480K，使用率为82％[0x00000007fae00000，0x00000007fbe76ad8，0x00000007fbe76c00，0x00000007fc200000）
未配置共享空间。
}
[Times：user = 0.09 sys = 0.00，real = 0.03 secs]
2014-08-21T16：25：35.869-0700：798008.444：停止应用程序线程的总时间：0.0395820秒
2014-08-21T16：25：47.806-0700：798020.380：应用程序线程停止的总时间：0.0004770秒
2014-08-21T16：26：43.565-0700：798076.139：应用程序线程停止的总时间：0.0004730秒
2014-08-21T16：26：47.960-0700：798080.535：应用程序线程停止的总时间：0.0004790秒
2014-08-21T16： 27：47.180-0700：798139.754：应用程序线程停止的总时间：0.0006050秒
2014-08-21T16：27：47.474-0700：798140.048：应用程序线程停止的总时间：0.0004160秒
2014-08-21T16：28：13.565-0700：798166.140：应用程序线程停止的总时间：0.0006670秒
2014-08-21T16：28：43.565-0700：798196.139：应用程序的总时间线程已停止：0 .0004590秒
2014-08-21T16：28：47.880-0700：798200.454：应用程序线程停止的总时间：0.0004490秒
2014-08-21T16：29：12.924-0700：798225.499：应用程序线程停止的总时间：0.0004600秒
2014-08-21T16：29：12.925-0700：798225.499：应用程序线程停止的总时间：0.0001880秒
2014-08-21T16： 29：12.925-0700：798225.499：应用程序线程停止的总时间：0.0002230秒
2014-08-21T16：29：12.928-0700：798225.502：应用程序线程停止的总时间：0.0011150秒
2014-08-21T16：29：12.932-0700：798225.506：应用程序线程停止的总时间：0.0011190秒
2014-08-21T16：29：13.565-0700：798226.140：应用程序的总时间线程停止：0.0005240秒
{堆GC调用前堆= 4958（全0）：
垃圾堆首堆总数1048576K，使用536411K [0x000000073f600000，0x000000077f600000 ，0x00000007fae00000）
区域大小1024K，276年轻（282624K），8名幸存者（8192K）
压实烫发根总20480K，使用16858K [0x00000007fae00000，0x00000007fc200000，0x0000000800000000）
中的空间20480K，82已使用％[0x00000007fae00000，0x00000007fbe76ad8，0x00000007fbe76c00，0x00000007fc200000）
未配置共享空间。
2014-08-21T16：29：16.945-0700：798229.519：[GC暂停（年轻）
希望的幸存者大小14680064字节，新的阈值15（最多15）
- 年龄1：1751568 bytes，1751568 total
- age 2：1108160 bytes，2859728 total
- age 3：997960 bytes，3857688 total
- age 4：1449136 bytes，5306824 total
- age 5 ：662736字节，5969560总计
- 年龄6：595944字节，6565504总计
，0.0454900秒]
[并行时间：43.6毫秒，GC工作人员：2]
[GC Worker开始（ms）：最小值：798229519.7，平均值：798229519.7，最大值：798229519.7，Diff：0.0]
[Ext Root Scanning（ms）：Min：5.0，Avg：5.1，Max：5.2，Diff：0.2，Sum ：10.2]
[更新RS（ms）：最小值：4.7，平均值：4.8，最大值：4.9，Diff：0.2，总和值：9.7]
[Processed Buffers：Min：7，Avg：14.5， [最大值：22，差值：15，总和：29]
[Scan RS（ms）：Min：11.9，Avg：12.0，Max：12.0，Diff：0.1，Sum：23.9]
[ （毫秒）：最小：21.6，平均：21.6，最大：21.6 （ms）：Min：0.0，Avg：0.0，Max：0.0，Diff：0.0，Sum：0.0]
[GC Worker其他（ms），Diff：0.1，Sum：43.2] ：最小值：0.0，平均值：0.0，最大值：0.0，差值：0.0，总和值：0.1]
GC工作总数（毫秒）：最小值：43.5，平均值：43.5，最大值：43.5， ：87.1]
[GC工作终点（毫秒）：最小值：798229563.2，平均值：798229563.2，最大值：798229563.2，差值：0.0]
[代码根修正：0.0 ms]
[ ：0.6毫秒]
[其他：1.3毫秒]
[选择CSet：0.0 ms]
[Ref Proc：0.2 ms]
[Ref Enq：0.0 ms]
[免费CSet：0.7ms]
[伊甸园：268.0M（210.0M） - > 0.0B（576.0M）幸存者：8192.0K-> 9216.0K堆：523.8M（1024.0M） - > 257.3M（1024.0M）]
GC调用后的堆= 4959（全0）：
垃圾优先堆总计1048576K，使用263515K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K， 9名年轻人（9216K），9名幸存者（9216K）
压缩烫发总数20480K，用过16858K [0x00000007fae00 000，0x00000007fc200000，0x0000000800000000）
空间20480K，已使用82％[0x00000007fae00000，0x00000007fbe76ad8，0x00000007fbe76c00，0x00000007fc200000）
未配置共享空间。
}
[Times：user = 0.09 sys = 0.00，real = 0.04 secs]
2014-08-21T16：29：16.991-0700：798229.565：停止应用程序线程的总时间：0.0462520秒
2014-08-21T16：29：35.008-0700：798247.583：应用程序线程停止的总时间：0.0005370秒
2014-08-21T16：29：35.098-0700：798247.673：应用程序线程停止的总时间：0.0003950秒
2014-08-21T16：29：35.099-0700：798247.673：应用程序线程停止的总时间：0.0001400秒
2014-08-21T16： 29：43.566-0700：798256.140：应用程序线程停止的总时间：0.0006050秒
2014-08-21T16：29：47.791-0700：798260.365：应用程序线程停止的总时间：0.0004690秒
2014-08-21T16：30：33.232-0700：798305.806：应用程序线程停止的总时间：0.0025060秒
2014-08-21T16：30：34.233-0700：798306.807：应用程序的总时间线程已停止：0 .0006220秒
2014-08-21T16：31：12.342-0700：798344.917：应用程序线程停止的总时间：0.0013470秒
2014-08-21T16：31：17.500-0700：798350.074：应用程序线程停止的总时间：0.0005640秒
2014-08-21T16：31：17.501-0700：798350.076：应用程序线程停止的总时间：0.0002760秒
2014-08-21T16： 31：38.506-0700：798371.080：应用程序线程停止的总时间：0.0013400秒
2014-08-21T16：32：16.032-0700：798408.606：应用程序线程停止的总时间：33.7010420秒
2014-08-21T16：32：56.183-0700：798448.758：应用程序线程停止的总时间：0.0120100秒
2014-08-21T16：32：56.185-0700：798448.759：应用程序的总时间线程已停止：0.0006060秒
2014-08-21T16：32：56.201-0700：798448.775：应用程序线程停止的总时间：0.0014260秒
2014-08-21T16：32： 56.203-0700：798448.777：应用程序线程停止的总时间：0.0006110秒
2014-08-21T16：32：56.204-0700：798448.778：应用程序线程停止的总时间：0.0004730秒
2014-08-21T16：33：16.026-0700：798468.601：应用程序线程停止的总时间：0.0021260秒
2014-08-21T16：33：50.414-0700：798502.988：应用程序线程的总时间停止：0.0014210秒
2014-08-21T16：34：47.479-0700：798560.054：应用程序线程停止的总时间：0.0015890秒
{GC调用前堆= 4959（全0）：
垃圾优先堆总计1048576K，使用657755K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K，394年轻（403456K），9个幸存者（9216K）
压缩烫发电池总计20480K，使用16898K [0x00000007fae00000,0x00000007fc200000,0x0000000800000000）
空间20480K，使用82％[0x00000007fae00000，0x00000007fbe80ab0， 0x00000007fbe80c00，0x00000007fc200000）
没有配置共享空间。
2014-08-21T16：35：19.033-0700：798591.607：[GC暂停（年轻）
希望的幸存者大小5767168字节，新的阈值5（最大15）
- 年龄1：2254608字节，2254608 total
- age 2：1409360 bytes，3663968 total
- age 3：1058280 bytes，4722248 total
- age 4：987544 bytes，5709792 total
- age 5 ：1435864 bytes，7145656 total
- age 6：658560 bytes，7804216 total
- age 7：593592 bytes，8397808 total
，0.0751810 secs]
[Parallel Time：71.2 ms ，GC Workers：2]
[GC Worker Start（ms）：Min：798591607.4，Avg：798591607.4，Max：798591607.4，Diff：0.0]
[Ext Root Scanning（ms） [更新RS（ms）：最小值：8.3，平均值：8.8，最大值：9.3，差值：0.9，总和值：17.6]
[已处理的缓冲区：最小值：11，平均值：16.0，最大值：21，差值：10，总和值：32]
[Scan RS（ms）：Min：13.6，Avg：13.7，Max：13.9，Diff： 0.3，总和：27.4]
[对象拷贝（ms）：最小值：41.9，平均值：41.9，最大值：41.9，差值：0.0，总和：83.8]
[终止值（ms）：最小值：0.0，平均值：0.0，最大值：0.0， GC工作人员总数（ms）：0.0，总和：0.0]
[GC工作人员其他（ms）：最小值：0.1，平均值：0.1，最大值：0.1，差值：0.1，总和：0.2] ：最小值：71.0，平均值：71.0，最大值：71.0，差值：0.0，总和：142.0]
[GC工作结束时间（ms）：最小值：798591678.4，平均值：798591678.4，最大值：798591678.4，Diff：0.0]
[Code Root Fixup：0.0 ms]
[Clear CT：0.8 ms]
[Other：3.3 ms]
[选择CSet：0.0 ms]
[Ref Proc $ 0.2 $]
[Ref Enq：0.0 ms]
[Free CSet：2.4 ms]
[Eden：385.0M（74.0M） - > 0.0B（73.0M）幸存者： 9216.0K-> 8192.0K堆：642.3M（1024.0M） - > 258.4M（1024.0M）]
GC调用后的堆= 4960（全0）：
垃圾优先堆总数1048576K ，使用264569K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K，8个年轻人（8192K），8个幸存者（8192K）
压缩pe总共20480K，使用16898K [0x00000007fae00000,0x00000007fc200000,0x0000000800000000）
空间20480K，已使用82％[0x00000007fae00000,0x00000007fbe80ab0,0x00000007fbe80c00,0x00000007fc200000）
未配置共享空间。
}
[Times：user = 0.16 sys = 0.00，real = 0.07 secs]
2014-08-21T16：35：19.108-0700：798591.682：停止应用程序线程的总时间：0.0762870秒
2014-08-21T16：35：47.699-0700：798620.273：应用程序线程停止的总时间：0.0010630秒
{GC调用前堆= 4960（全0）：
垃圾优先堆总计1048576K，使用339321K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K，81个年轻人（82944K），8个幸存者（8192K）
压缩烫发电池总计20480K，使用16898K [ 0x00000007fae00000,0x00000007fc200000,0x0000000800000000）
空间20480K，已使用82％[0x00000007fae00000,0x00000007fbe80ab0,0x00000007fbe80c00,0x00000007fc200000）
未配置共享空间。
2014-08-21T16：36：30.675-0700：798663.249：[GC暂停（年轻）
希望的幸存者大小5767168字节，新的阈值4（最大15）
- 年龄1：2632352字节，2632352 total
- age 2：1093712 bytes，3726064 total
- age 3：1028456 bytes，4754520 total
- age 4：1044688 bytes，5799208 total
- age 5 ：977400字节，6776608共
，0.0444430秒]
[并行时间：43.2毫秒，GC工作人员：2]
[GC工作起始时间（ms）：最小值：798663249.6，平均值：798663249.6，最大值：798663249.7，差值：0.0]
[Ext Root Scanning（ms）：Min：5.0，Avg：5.4，Max：5.8，Diff：0.8，Sum：10.9]
[ ：Min：5.8，Avg：6.3，Max：6.7，Diff：0.9，Sum：12.5]
[Processed Buffers：Min：11，Avg：13.0，Max：15，Diff：4，Sum：26]
[Scan RS（ms）：Min：11.1，Avg：11.1，Max：11.1，Diff：0.0，Sum：22.2]
[对象复制（ms）：Min：20.3，Avg：20.3，Max ：20.4，Diff：0.1，Sum：40.7]
[终止（毫秒） ：最小值：0.0，平均值：0.0，最大值：0.0，差值：0.0，总和：0.0]
[GC Worker其他（ms）：最小值：0.0，平均值：0.0，最大值：0.0， ：0.1]
[GC工作人员总数（毫秒）：最小值：43.2，平均值：43.2，最大值：43.2，差值：0.0，总和：86.4]
[GC工作结束时间（ms）：最小值：798663292.8 ，平均：798663292.8，最大值：798663292.8，差值：0.0]
[代码根修正：0.0 ms]
[清除CT：0.1 ms]
[其他：1.1 ms]
[选择CSet：0.0 ms]
[Ref Proc：0.2 ms]
[Ref Enq：0.0 ms]
[Free CSet：0.5 ms]
[Eden：73.0M 73.0M）→0.0B（100.0M）幸存者：8192.0K-> 6144.0K堆：331.4M（1024.0M）→259.0M（1024.0M）〕
GC调用后的堆= 4961（全0）：
垃圾优先堆总数1048576K，使用265216K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K，6个年轻人（6144K），6个幸存者（6144K）
压缩烫发总计20480K，使用16898K [0x00000007fae00000，0x00000007fc200000，0x0000000800000000）
t他空间20480K，使用82％[0x00000007fae00000，0x00000007fbe80ab0，0x00000007fbe80c00，0x00000007fc200000）
没有配置共享空间。
}
[Times：user = 0.10 sys = 0.00，real = 0.04 secs]
2014-08-21T16：36：30.720-0700：798663.294：停止应用程序线程的总时间：0.0453210秒
2014-08-21T16：36：47.997-0700：798680.572：应用程序线程停止的总时间：0.0007030秒
2014-08-21T16：37：47.460-0700：798740.034：应用程序线程停止的总时间：0.0007800秒
2014-08-21T16：37：48.932-0700：798741.506：应用程序线程停止的总时间：0.0006490秒
{GC调用之前的堆=
区域大小1024K，106个年轻人（108544K），6个幸存者（6144K）
压缩率（％）4961（全0）：
垃圾优先堆总计1048576K，使用367616K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）使用16898K [0x00000007fae00000，0x00000007fc200000，0x0000000800000000）
空间20480K，使用82％[0x00000007fae00000，0x00000007fbe80ab0，0x00000007fbe80c00，0x00000007fc200000）
没有配置共享空间。
2014-08-21T16：38：05.883-0700：798758.457：[GC暂停（年轻）
希望的幸存者大小7340032字节，新的阈值15（最大15）
- 年龄1：535816字节，535816 total
- age 2：2490064 bytes，3025880 total
- age 3：1060536 bytes，4086416 total
- age 4：1024088 bytes，5110504 total
，0.0365490 secs ]
[并行时间：35.5毫秒，GC工作人员：2]
[GC工作起始时间（毫秒）：最小值：798758457.2，平均值：798758457.2，最大值：798758457.3，差值：0.0] Ext Root Scanning（ms）：Min：5.2，Avg：6.4，Max：7.6，Diff：2.4，Sum：12.8]
[更新RS（ms）：最小值：5.2，平均值：6.5，最大值：7.7， Diff：2.4，Sum：12.9]
[处理的缓冲区：Min：0，Avg：12.0，Max：24，Diff：24，Sum：24]
[Scan RS（ms）：Min：8.6 ，平均值：8.7，最大值：8.8，差值：0.2，总和：17.4]
[Object Copy（ms）：Min：13.7，Avg：13.8，Max：13.9，Diff：0.2，Sum：27.7]
[终止（毫秒）：最小值：0.0，平均值：0.0，最大值：0.0，差值：0.0，总和：0.0]
[GC Worker Other（ms）：Min：0.0，Avg：0.0，Max：0.0，Diff：0.0，Sum：0.1]
[GC Worker Total（ms） [GC Worker End（ms）：Min：798758492.6，Avg：798758492.6，Max：798758492.6，Diff：0.0]
[Code Root Fixup（35.4，Max：35.4，Diff：0.0，Sum：70.8] ：0.0 ms]
[Clear CT：0.1 ms]
[其他：0.9 ms]
[选择CSet：0.0 ms]
[Ref Proc：0.1 ms]
[Eden：100.0M（100.0M） - > 0.0B（178.0M）幸存者：6144.0K-> 7168.0K [Ref Enq：0.0ms]堆：359.0M（1024.0M） - > 259.5M（1024.0M）]
GC调用后的堆= 4962（全0）：
垃圾优先堆总计1048576K，使用265728K [0x000000073f600000，0x000000077f600000 ，0x00000007fae00000）
区域大小1024K，7个年轻人（7168K），7个幸存者（7168K）
压缩烫发发电总量20480K，使用16898K [0x00000007fae00000,0x00000007fc200000,0x0000000800000000）
空间20480K，82使用％[0x00000007fae00000，0x0 0000007fbe80ab0，0x00000007fbe80c00，0x00000007fc200000）
未配置共享空间。
}
[Times：user = 0.08 sys = 0.00，real = 0.04 secs]
2014-08-21T16：38：05.920-0700：798758.494：停止应用程序线程的总时间：0.0375420秒
2014-08-21T16：38：26.099-0700：798778.673：应用程序线程停止的总时间：0.0010220秒
2014-08-21T16：38：47.342-0700：798799.916：应用程序线程停止的总时间：0.0036430秒
2014-08-21T16：39：47.317-0700：798859.892：应用程序线程停止的总时间：0.0008300秒
2014-08-21T16： 39：56.099-0700：798868.674：应用程序线程停止的总时间：0.0006290秒
2014-08-21T16：40：47.760-0700：798920.334：应用程序线程停止的总时间：0.0006050秒
{GC调用前堆= 4962（全0）：
垃圾优先堆总计1048576K，使用448000K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K，185青年（189440K），7幸存者使用16898K [0x00000007fae00000，0x00000007fc200000，0x0000000800000000）
空间20480K，已使用82％[0x00000007fae00000,0x00000007fbe80ab0,0x00000007fbe80c00,0x00000007fc200000）
没有共享空间（7168K）
压缩烫发电池总量20480K，配置。
2014-08-21T16：41：06.971-0700：798939.546：[GC暂停（年轻）
所需的幸存者大小12582912字节，新阈值15（最大值15）
- 年龄1：660960字节，660960共计
- 年龄2：447312字节，1108272共计
- 年龄3：2380256字节，3488528共计
- 年龄4：1043336字节，4531864共计
- 年龄5 ：1019096字节，5550960美元总计
，0.0459440美元]
[并行时间：43.9毫秒，GC工作人员：2]
[GC工作起始时间（毫秒）：最小值：798939545.8，平均值：798939545.8， （ms）：最小值：6.4，平均值：6.4，最大值：6.4，差值：0.0，总和：12.8]
[更新RS（ms） ：Min：7.9，Avg：9.3，Max：10.6，Diff：2.7，Sum：18.5]
[Processed Buffers：Min：12，Avg：14.0，Max：16，Diff：4，Sum：28]
[Scan RS（ms）：Min：7.5，Avg：8.8，Max：10.2，Diff：2.8，Sum：17.7]
[对象复制（ms）：Min：19.2，Avg：19.3，Max ：19.3，Diff：0.1，Sum：38.5]
[终止（ms ）：Min：0.0，Avg：0.0，Max：0.0，Diff：0.0，Sum：0.0]
[GC Worker Other（ms）总和：0.1]
[GC工作人员总数（毫秒）：最小值：43.7，平均值：43.8，最大值：43.8，差值：0.1，总和：87.5] 798939589.6，平均值：798939589.6，最大值：798939589.6，差值：0.0]
[Code Root Fixup：0.0 ms]
[Clear CT：0.6 ms]
[Other：1.4 ms]
[选择CSet：0.0 ms]
[Ref Proc：0.2 ms]
[Ref Enq：0.0 ms]
[Free CSet：0.7 ms]
[Eden：178.0M （178.0M）→0.0B（193.0M）幸存者：7168.0K→7168.0K堆：437.5M（1024.0M）→259.5M（1024.0M）〕
GC调用后的堆= 4963 （全0）：
垃圾优先堆总计1048576K，使用265728K [0x000000073f600000,0x000000077f600000,0x00000007fae00000）
区域大小1024K，7个年轻人（7168K），7个幸存者（7168K）
压缩烫发总共20480K，使用16898K [0x00000007fae00000，0x00000007fc200000，0x0000000800000000）
空间20480K，使用率为82％[0x00000007fae00000，0x00000007fbe80ab0，0x00000007fbe80c00，0x00000007fc200000）
未配置共享空间。
}
[Times：user = 0.10 sys = 0.00，real = 0.05 secs]
2014-08-21T16：41：07.018-0700：798939.592：停止应用程序线程的总时间：0.0471700秒
2014-08-21T16：41：47.416-0700：798979.990：应用程序线程停止的总时间：0.0006110秒
2014-08-21T16：42：26.100-0700：799018.674：应用程序线程停止的总时间：0.0008380秒
2014-08-21T16：42：47.463-0700：799040.037：应用程序线程停止的总时间：0.0008070秒
2014-08-21T16： 43：26.100-0700：799078.675：应用程序线程停止的总时间：0.0009130秒
2014-08-21T16：43：47.648-0700：799100.222：应用程序线程停止的总时间：0.0006330秒
2014-08-21T16：43：48.700-0700：799101.274：应用程序线程停止的总时间：0.0006050秒
2014-08-21T16：44：18.539-0700：799131.113：应用程序的总时间线程停止： 0.0006640秒
解决方案
这与垃圾收集无关。根据日志，暂停发生在GC循环之外。
应用程序线程停止的总时间消息是在每个安全点后打印。由于OS冻结，通常可以看到非常长的安全点时间。这可能是因为密集磁盘I / O，或者系统开始交换时，或者另一个高优先级进程占用所有CPU时间。要找出原因检查您的操作系统性能计数器。
I have a distributed cache application (memory bound, with networking I/O due to interaction with other nodes in the cluster) running in JVM 1.7.0_51 with G1 garbage collector. Here is the JVM configuration:
-server -Xms1G -Xmx3000M -XX:+UseG1GC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:MaxGCPauseMillis=50 -Xloggc:$HAZELCAST_HOME/logs/gclog.txt -verbose:gc
At 2014-08-21T16:32:16.032, GC caused a long pause over 33 seconds (gc log snippet as below): 2014-08-21T16:32:16.032-0700: 798408.606: Total time for which application threads were stopped: 33.7010420 seconds
I dug into the gc logs (and also the application logs) and didn't see a clear clue why that 33-second long pause happened. Is there any way to have the G1 dump more details to show reason for the long pause (and the breakdown of the long pause for what event, e.g. xxxms for scanning RS, etc.).
I enclosed the gc logs for a few minutes. Do you see any issue in the GC log and any need for JVM gc tuning? Thanks a lot!
GC logs
2014-08-21T16:24:47.996-0700: 797960.570: Total time for which application threads were stopped: 0.0005740 seconds
{Heap before GC invocations=4957 (full 0):
garbage-first heap total 1048576K, used 535899K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 275 young (281600K), 6 survivors (6144K)
compacting perm gen total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:25:35.830-0700: 798008.405: [GC pause (young)
Desired survivor size 15204352 bytes, new threshold 15 (max 15)
- age 1: 1490920 bytes, 1490920 total
- age 2: 1041336 bytes, 2532256 total
- age 3: 1462192 bytes, 3994448 total
- age 4: 669528 bytes, 4663976 total
- age 5: 600560 bytes, 5264536 total
, 0.0387690 secs]
[Parallel Time: 36.9 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 798008405.0, Avg: 798008405.0, Max: 798008405.0, Diff: 0.0]
[Ext Root Scanning (ms): Min: 5.1, Avg: 5.4, Max: 5.7, Diff: 0.6, Sum: 10.8]
[Update RS (ms): Min: 6.3, Avg: 6.7, Max: 7.1, Diff: 0.8, Sum: 13.4]
[Processed Buffers: Min: 5, Avg: 14.0, Max: 23, Diff: 18, Sum: 28]
[Scan RS (ms): Min: 8.5, Avg: 9.3, Max: 10.0, Diff: 1.5, Sum: 18.5]
[Object Copy (ms): Min: 15.4, Avg: 15.4, Max: 15.5, Diff: 0.1, Sum: 30.9]
[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.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 36.8, Avg: 36.8, Max: 36.8, Diff: 0.0, Sum: 73.6]
[GC Worker End (ms): Min: 798008441.8, Avg: 798008441.8, Max: 798008441.8, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 1.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 269.0M(224.0M)->0.0B(606.0M) Survivors: 6144.0K->8192.0K Heap: 523.3M(1024.0M)->255.8M(1024.0M)]
Heap after GC invocations=4958 (full 0):
garbage-first heap total 1048576K, used 261979K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 8 young (8192K), 8 survivors (8192K)
compacting perm gen total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
}
[Times: user=0.09 sys=0.00, real=0.03 secs]
2014-08-21T16:25:35.869-0700: 798008.444: Total time for which application threads were stopped: 0.0395820 seconds
2014-08-21T16:25:47.806-0700: 798020.380: Total time for which application threads were stopped: 0.0004770 seconds
2014-08-21T16:26:43.565-0700: 798076.139: Total time for which application threads were stopped: 0.0004730 seconds
2014-08-21T16:26:47.960-0700: 798080.535: Total time for which application threads were stopped: 0.0004790 seconds
2014-08-21T16:27:47.180-0700: 798139.754: Total time for which application threads were stopped: 0.0006050 seconds
2014-08-21T16:27:47.474-0700: 798140.048: Total time for which application threads were stopped: 0.0004160 seconds
2014-08-21T16:28:13.565-0700: 798166.140: Total time for which application threads were stopped: 0.0006670 seconds
2014-08-21T16:28:43.565-0700: 798196.139: Total time for which application threads were stopped: 0.0004590 seconds
2014-08-21T16:28:47.880-0700: 798200.454: Total time for which application threads were stopped: 0.0004490 seconds
2014-08-21T16:29:12.924-0700: 798225.499: Total time for which application threads were stopped: 0.0004600 seconds
2014-08-21T16:29:12.925-0700: 798225.499: Total time for which application threads were stopped: 0.0001880 seconds
2014-08-21T16:29:12.925-0700: 798225.499: Total time for which application threads were stopped: 0.0002230 seconds
2014-08-21T16:29:12.928-0700: 798225.502: Total time for which application threads were stopped: 0.0011150 seconds
2014-08-21T16:29:12.932-0700: 798225.506: Total time for which application threads were stopped: 0.0011190 seconds
2014-08-21T16:29:13.565-0700: 798226.140: Total time for which application threads were stopped: 0.0005240 seconds
{Heap before GC invocations=4958 (full 0):
garbage-first heap total 1048576K, used 536411K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 276 young (282624K), 8 survivors (8192K)
compacting perm gen total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:29:16.945-0700: 798229.519: [GC pause (young)
Desired survivor size 14680064 bytes, new threshold 15 (max 15)
- age 1: 1751568 bytes, 1751568 total
- age 2: 1108160 bytes, 2859728 total
- age 3: 997960 bytes, 3857688 total
- age 4: 1449136 bytes, 5306824 total
- age 5: 662736 bytes, 5969560 total
- age 6: 595944 bytes, 6565504 total
, 0.0454900 secs]
[Parallel Time: 43.6 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 798229519.7, Avg: 798229519.7, Max: 798229519.7, Diff: 0.0]
[Ext Root Scanning (ms): Min: 5.0, Avg: 5.1, Max: 5.2, Diff: 0.2, Sum: 10.2]
[Update RS (ms): Min: 4.7, Avg: 4.8, Max: 4.9, Diff: 0.2, Sum: 9.7]
[Processed Buffers: Min: 7, Avg: 14.5, Max: 22, Diff: 15, Sum: 29]
[Scan RS (ms): Min: 11.9, Avg: 12.0, Max: 12.0, Diff: 0.1, Sum: 23.9]
[Object Copy (ms): Min: 21.6, Avg: 21.6, Max: 21.6, Diff: 0.1, Sum: 43.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.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 43.5, Avg: 43.5, Max: 43.5, Diff: 0.0, Sum: 87.1]
[GC Worker End (ms): Min: 798229563.2, Avg: 798229563.2, Max: 798229563.2, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 1.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 268.0M(210.0M)->0.0B(576.0M) Survivors: 8192.0K->9216.0K Heap: 523.8M(1024.0M)->257.3M(1024.0M)]
Heap after GC invocations=4959 (full 0):
garbage-first heap total 1048576K, used 263515K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 9 young (9216K), 9 survivors (9216K)
compacting perm gen total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
}
[Times: user=0.09 sys=0.00, real=0.04 secs]
2014-08-21T16:29:16.991-0700: 798229.565: Total time for which application threads were stopped: 0.0462520 seconds
2014-08-21T16:29:35.008-0700: 798247.583: Total time for which application threads were stopped: 0.0005370 seconds
2014-08-21T16:29:35.098-0700: 798247.673: Total time for which application threads were stopped: 0.0003950 seconds
2014-08-21T16:29:35.099-0700: 798247.673: Total time for which application threads were stopped: 0.0001400 seconds
2014-08-21T16:29:43.566-0700: 798256.140: Total time for which application threads were stopped: 0.0006050 seconds
2014-08-21T16:29:47.791-0700: 798260.365: Total time for which application threads were stopped: 0.0004690 seconds
2014-08-21T16:30:33.232-0700: 798305.806: Total time for which application threads were stopped: 0.0025060 seconds
2014-08-21T16:30:34.233-0700: 798306.807: Total time for which application threads were stopped: 0.0006220 seconds
2014-08-21T16:31:12.342-0700: 798344.917: Total time for which application threads were stopped: 0.0013470 seconds
2014-08-21T16:31:17.500-0700: 798350.074: Total time for which application threads were stopped: 0.0005640 seconds
2014-08-21T16:31:17.501-0700: 798350.076: Total time for which application threads were stopped: 0.0002760 seconds
2014-08-21T16:31:38.506-0700: 798371.080: Total time for which application threads were stopped: 0.0013400 seconds
2014-08-21T16:32:16.032-0700: 798408.606: Total time for which application threads were stopped: 33.7010420 seconds
2014-08-21T16:32:56.183-0700: 798448.758: Total time for which application threads were stopped: 0.0120100 seconds
2014-08-21T16:32:56.185-0700: 798448.759: Total time for which application threads were stopped: 0.0006060 seconds
2014-08-21T16:32:56.201-0700: 798448.775: Total time for which application threads were stopped: 0.0014260 seconds
2014-08-21T16:32:56.203-0700: 798448.777: Total time for which application threads were stopped: 0.0006110 seconds
2014-08-21T16:32:56.204-0700: 798448.778: Total time for which application threads were stopped: 0.0004730 seconds
2014-08-21T16:33:16.026-0700: 798468.601: Total time for which application threads were stopped: 0.0021260 seconds
2014-08-21T16:33:50.414-0700: 798502.988: Total time for which application threads were stopped: 0.0014210 seconds
2014-08-21T16:34:47.479-0700: 798560.054: Total time for which application threads were stopped: 0.0015890 seconds
{Heap before GC invocations=4959 (full 0):
garbage-first heap total 1048576K, used 657755K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 394 young (403456K), 9 survivors (9216K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:35:19.033-0700: 798591.607: [GC pause (young)
Desired survivor size 5767168 bytes, new threshold 5 (max 15)
- age 1: 2254608 bytes, 2254608 total
- age 2: 1409360 bytes, 3663968 total
- age 3: 1058280 bytes, 4722248 total
- age 4: 987544 bytes, 5709792 total
- age 5: 1435864 bytes, 7145656 total
- age 6: 658560 bytes, 7804216 total
- age 7: 593592 bytes, 8397808 total
, 0.0751810 secs]
[Parallel Time: 71.2 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 798591607.4, Avg: 798591607.4, Max: 798591607.4, Diff: 0.0]
[Ext Root Scanning (ms): Min: 6.1, Avg: 6.4, Max: 6.8, Diff: 0.6, Sum: 12.9]
[Update RS (ms): Min: 8.3, Avg: 8.8, Max: 9.3, Diff: 0.9, Sum: 17.6]
[Processed Buffers: Min: 11, Avg: 16.0, Max: 21, Diff: 10, Sum: 32]
[Scan RS (ms): Min: 13.6, Avg: 13.7, Max: 13.9, Diff: 0.3, Sum: 27.4]
[Object Copy (ms): Min: 41.9, Avg: 41.9, Max: 41.9, Diff: 0.0, Sum: 83.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
[GC Worker Total (ms): Min: 71.0, Avg: 71.0, Max: 71.0, Diff: 0.0, Sum: 142.0]
[GC Worker End (ms): Min: 798591678.4, Avg: 798591678.4, Max: 798591678.4, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.8 ms]
[Other: 3.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 2.4 ms]
[Eden: 385.0M(74.0M)->0.0B(73.0M) Survivors: 9216.0K->8192.0K Heap: 642.3M(1024.0M)->258.4M(1024.0M)]
Heap after GC invocations=4960 (full 0):
garbage-first heap total 1048576K, used 264569K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 8 young (8192K), 8 survivors (8192K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
[Times: user=0.16 sys=0.00, real=0.07 secs]
2014-08-21T16:35:19.108-0700: 798591.682: Total time for which application threads were stopped: 0.0762870 seconds
2014-08-21T16:35:47.699-0700: 798620.273: Total time for which application threads were stopped: 0.0010630 seconds
{Heap before GC invocations=4960 (full 0):
garbage-first heap total 1048576K, used 339321K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 81 young (82944K), 8 survivors (8192K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:36:30.675-0700: 798663.249: [GC pause (young)
Desired survivor size 5767168 bytes, new threshold 4 (max 15)
- age 1: 2632352 bytes, 2632352 total
- age 2: 1093712 bytes, 3726064 total
- age 3: 1028456 bytes, 4754520 total
- age 4: 1044688 bytes, 5799208 total
- age 5: 977400 bytes, 6776608 total
, 0.0444430 secs]
[Parallel Time: 43.2 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 798663249.6, Avg: 798663249.6, Max: 798663249.7, Diff: 0.0]
[Ext Root Scanning (ms): Min: 5.0, Avg: 5.4, Max: 5.8, Diff: 0.8, Sum: 10.9]
[Update RS (ms): Min: 5.8, Avg: 6.3, Max: 6.7, Diff: 0.9, Sum: 12.5]
[Processed Buffers: Min: 11, Avg: 13.0, Max: 15, Diff: 4, Sum: 26]
[Scan RS (ms): Min: 11.1, Avg: 11.1, Max: 11.1, Diff: 0.0, Sum: 22.2]
[Object Copy (ms): Min: 20.3, Avg: 20.3, Max: 20.4, Diff: 0.1, Sum: 40.7]
[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.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 43.2, Avg: 43.2, Max: 43.2, Diff: 0.0, Sum: 86.4]
[GC Worker End (ms): Min: 798663292.8, Avg: 798663292.8, Max: 798663292.8, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 1.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.5 ms]
[Eden: 73.0M(73.0M)->0.0B(100.0M) Survivors: 8192.0K->6144.0K Heap: 331.4M(1024.0M)->259.0M(1024.0M)]
Heap after GC invocations=4961 (full 0):
garbage-first heap total 1048576K, used 265216K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 6 young (6144K), 6 survivors (6144K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
[Times: user=0.10 sys=0.00, real=0.04 secs]
2014-08-21T16:36:30.720-0700: 798663.294: Total time for which application threads were stopped: 0.0453210 seconds
2014-08-21T16:36:47.997-0700: 798680.572: Total time for which application threads were stopped: 0.0007030 seconds
2014-08-21T16:37:47.460-0700: 798740.034: Total time for which application threads were stopped: 0.0007800 seconds
2014-08-21T16:37:48.932-0700: 798741.506: Total time for which application threads were stopped: 0.0006490 seconds
{Heap before GC invocations=4961 (full 0):
garbage-first heap total 1048576K, used 367616K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 106 young (108544K), 6 survivors (6144K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:38:05.883-0700: 798758.457: [GC pause (young)
Desired survivor size 7340032 bytes, new threshold 15 (max 15)
- age 1: 535816 bytes, 535816 total
- age 2: 2490064 bytes, 3025880 total
- age 3: 1060536 bytes, 4086416 total
- age 4: 1024088 bytes, 5110504 total
, 0.0365490 secs]
[Parallel Time: 35.5 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 798758457.2, Avg: 798758457.2, Max: 798758457.3, Diff: 0.0]
[Ext Root Scanning (ms): Min: 5.2, Avg: 6.4, Max: 7.6, Diff: 2.4, Sum: 12.8]
[Update RS (ms): Min: 5.2, Avg: 6.5, Max: 7.7, Diff: 2.4, Sum: 12.9]
[Processed Buffers: Min: 0, Avg: 12.0, Max: 24, Diff: 24, Sum: 24]
[Scan RS (ms): Min: 8.6, Avg: 8.7, Max: 8.8, Diff: 0.2, Sum: 17.4]
[Object Copy (ms): Min: 13.7, Avg: 13.8, Max: 13.9, Diff: 0.2, Sum: 27.7]
[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.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 35.4, Avg: 35.4, Max: 35.4, Diff: 0.0, Sum: 70.8]
[GC Worker End (ms): Min: 798758492.6, Avg: 798758492.6, Max: 798758492.6, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.5 ms]
[Eden: 100.0M(100.0M)->0.0B(178.0M) Survivors: 6144.0K->7168.0K Heap: 359.0M(1024.0M)->259.5M(1024.0M)]
Heap after GC invocations=4962 (full 0):
garbage-first heap total 1048576K, used 265728K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 7 young (7168K), 7 survivors (7168K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
[Times: user=0.08 sys=0.00, real=0.04 secs]
2014-08-21T16:38:05.920-0700: 798758.494: Total time for which application threads were stopped: 0.0375420 seconds
2014-08-21T16:38:26.099-0700: 798778.673: Total time for which application threads were stopped: 0.0010220 seconds
2014-08-21T16:38:47.342-0700: 798799.916: Total time for which application threads were stopped: 0.0036430 seconds
2014-08-21T16:39:47.317-0700: 798859.892: Total time for which application threads were stopped: 0.0008300 seconds
2014-08-21T16:39:56.099-0700: 798868.674: Total time for which application threads were stopped: 0.0006290 seconds
2014-08-21T16:40:47.760-0700: 798920.334: Total time for which application threads were stopped: 0.0006050 seconds
{Heap before GC invocations=4962 (full 0):
garbage-first heap total 1048576K, used 448000K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 185 young (189440K), 7 survivors (7168K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:41:06.971-0700: 798939.546: [GC pause (young)
Desired survivor size 12582912 bytes, new threshold 15 (max 15)
- age 1: 660960 bytes, 660960 total
- age 2: 447312 bytes, 1108272 total
- age 3: 2380256 bytes, 3488528 total
- age 4: 1043336 bytes, 4531864 total
- age 5: 1019096 bytes, 5550960 total
, 0.0459440 secs]
[Parallel Time: 43.9 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 798939545.8, Avg: 798939545.8, Max: 798939545.9, Diff: 0.1]
[Ext Root Scanning (ms): Min: 6.4, Avg: 6.4, Max: 6.4, Diff: 0.0, Sum: 12.8]
[Update RS (ms): Min: 7.9, Avg: 9.3, Max: 10.6, Diff: 2.7, Sum: 18.5]
[Processed Buffers: Min: 12, Avg: 14.0, Max: 16, Diff: 4, Sum: 28]
[Scan RS (ms): Min: 7.5, Avg: 8.8, Max: 10.2, Diff: 2.8, Sum: 17.7]
[Object Copy (ms): Min: 19.2, Avg: 19.3, Max: 19.3, Diff: 0.1, Sum: 38.5]
[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.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 43.7, Avg: 43.8, Max: 43.8, Diff: 0.1, Sum: 87.5]
[GC Worker End (ms): Min: 798939589.6, Avg: 798939589.6, Max: 798939589.6, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 1.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 178.0M(178.0M)->0.0B(193.0M) Survivors: 7168.0K->7168.0K Heap: 437.5M(1024.0M)->259.5M(1024.0M)]
Heap after GC invocations=4963 (full 0):
garbage-first heap total 1048576K, used 265728K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
region size 1024K, 7 young (7168K), 7 survivors (7168K)
compacting perm gen total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
the space 20480K, 82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
[Times: user=0.10 sys=0.00, real=0.05 secs]
2014-08-21T16:41:07.018-0700: 798939.592: Total time for which application threads were stopped: 0.0471700 seconds
2014-08-21T16:41:47.416-0700: 798979.990: Total time for which application threads were stopped: 0.0006110 seconds
2014-08-21T16:42:26.100-0700: 799018.674: Total time for which application threads were stopped: 0.0008380 seconds
2014-08-21T16:42:47.463-0700: 799040.037: Total time for which application threads were stopped: 0.0008070 seconds
2014-08-21T16:43:26.100-0700: 799078.675: Total time for which application threads were stopped: 0.0009130 seconds
2014-08-21T16:43:47.648-0700: 799100.222: Total time for which application threads were stopped: 0.0006330 seconds
2014-08-21T16:43:48.700-0700: 799101.274: Total time for which application threads were stopped: 0.0006050 seconds
2014-08-21T16:44:18.539-0700: 799131.113: Total time for which application threads were stopped: 0.0006640 seconds
解决方案
This is not related to garbage collection. According to the log the pause has happened outside GC cycle.
Total time for which application threads were stopped message is printed after every safepoint. Extremely long safepoint time can be typically seen due to OS freezes. This may happen because of intensive disk I/O, or when the system starts swapping, or when another high-priority process takes all CPU time. To find out the reason examine your OS performance counters.
这篇关于G1 gc日志不会显示长时间暂停的线索的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
查看全文
