700M的堆young gc时用了70秒
环境:
java version “1.8.0_45”
Java HotSpot™ 64-Bit Server VM (build 25.45-b02, mixed mode)
Linux version 3.10.0-862.mt20190308.130.el7.x86_64 (root@gh-hulk-k8s-ep01) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-11) (GCC) ) #1 SMP Fri Mar 8 06:37:16 UTC 2019
CentOS release 6.8 (Final)
GC日志
[Times: user=0.04 sys=0.01, real=0.35 secs]
2019-12-12T16:58:56.080+0800: 624216.197: Total time for which application threads were stopped: 0.4716215 seconds, Stopping threads took: 0.0001637 seconds
{Heap before GC invocations=3861 (full 0):
garbage-first heap total 6291456K, used 699144K [0x0000000640000000, 0x0000000640403000, 0x00000007c0000000)
region size 4096K, 76 young (311296K), 3 survivors (12288K)
Metaspace used 147487K, capacity 151988K, committed 152192K, reserved 1183744K
class space used 16748K, capacity 17703K, committed 17792K, reserved 1048576K
2019-12-12T16:59:12.061+0800: 624232.177: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 20971520 bytes, new threshold 15 (max 15)
- age 1: 1886968 bytes, 1886968 total
- age 2: 239392 bytes, 2126360 total
- age 3: 102464 bytes, 2228824 total
- age 4: 276920 bytes, 2505744 total
- age 5: 22824 bytes, 2528568 total
- age 6: 319288 bytes, 2847856 total
- age 7: 340312 bytes, 3188168 total
- age 8: 322072 bytes, 3510240 total
- age 9: 501176 bytes, 4011416 total
- age 10: 451264 bytes, 4462680 total
- age 11: 701304 bytes, 5163984 total
- age 12: 497560 bytes, 5661544 total
- age 13: 494368 bytes, 6155912 total
- age 14: 404664 bytes, 6560576 total
- age 15: 348944 bytes, 6909520 total
624232.712: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3220, predicted base time: 314.99 ms, remaining time: 0.00 ms, target pause time:200.00 ms]
624232.712: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 73 regions, survivors: 3 regions, predicted young region time: 18.77 ms]
624232.712: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 73 regions, survivors: 3 regions, old: 0 regions, predicted pause time: 333.76 ms, target pause time: 200.00 ms], 74.9579940 secs]
[Parallel Time: 72933.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 624233673.7, Avg: 624233673.8, Max: 624233673.8, Diff: 0.1]
[Ext Root Scanning (ms): Min: 5611.4, Avg: 6759.2, Max: 7143.2, Diff: 1531.8, Sum: 27037.0]
[Update RS (ms): Min: 13300.8, Avg: 14061.3, Max: 15541.4, Diff: 2240.5, Sum: 56245.3]
[Processed Buffers: Min: 2, Avg: 44.2, Max: 93, Diff: 91, Sum: 177]
[Scan RS (ms): Min: 36455.3, Avg: 36455.3, Max: 36455.3, Diff: 0.0, Sum: 145821.3]
[Code Root Scanning (ms): Min: 8663.3, Avg: 8663.3, Max: 8663.4, Diff: 0.0, Sum: 34653.4]
[Object Copy (ms): Min: 4075.5, Avg: 4458.7, Max: 5606.3, Diff: 1530.8, Sum: 17834.6]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Other (ms): Min: 1049.4, Avg: 2530.2, Max: 3290.9, Diff: 2241.4, Sum: 10120.6]
[GC Worker Total (ms): Min: 72928.0, Avg: 72928.0, Max: 72928.1, Diff: 0.2, Sum: 291712.1]
[GC Worker End (ms): Min: 624306601.8, Avg: 624306601.8, Max: 624306601.8, Diff: 0.1]
[Code Root Fixup: 0.4 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 2023.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 25.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 292.0M(292.0M)->0.0B(288.0M) Survivors: 12.0M->16.0M Heap: 682.8M(6144.0M)->393.3M(6144.0M)]
Heap after GC invocations=3862 (full 0):
garbage-first heap total 6291456K, used 402775K [0x0000000640000000, 0x0000000640403000, 0x00000007c0000000)
region size 4096K, 4 young (16384K), 4 survivors (16384K)
Metaspace used 147487K, capacity 151988K, committed 152192K, reserved 1183744K
class space used 16748K, capacity 17703K, committed 17792K, reserved 1048576K
}
[Times: user=0.05 sys=0.03, real=75.00 secs]
2019-12-12T17:00:26.513+0800: 624306.629: Total time for which application threads were stopped: 76.8287768 seconds, Stopping threads took: 0.9801482 seconds
2019-12-12T17:00:28.950+0800: 624309.066: Total time for which application threads were stopped: 1.4367328 seconds, Stopping threads took: 1.4328138 seconds
2019-12-12T17:00:29.470+0800: 624309.586: Total time for which application threads were stopped: 0.4734412 seconds, Stopping threads took: 0.4705677 seconds
{Heap before GC invocations=3862 (full 0):
garbage-first heap total 6291456K, used 697687K [0x0000000640000000, 0x0000000640403000, 0x00000007c0000000)
region size 4096K, 76 young (311296K), 4 survivors (16384K)
Metaspace used 147489K, capacity 151988K, committed 152192K, reserved 1183744K
class space used 16748K, capacity 17703K, committed 17792K, reserved 1048576K
2019-12-12T17:00:29.575+0800: 624309.692: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 20971520 bytes, new threshold 15 (max 15) - age 1: 2243136 bytes, 2243136 total
- age 2: 250616 bytes, 2493752 total
- age 3: 170696 bytes, 2664448 total
- age 4: 93728 bytes, 2758176 total
- age 5: 272336 bytes, 3030512 total
- age 6: 22288 bytes, 3052800 total
- age 7: 246392 bytes, 3299192 total
- age 8: 338904 bytes, 3638096 total
- age 9: 321736 bytes, 3959832 total
- age 10: 500352 bytes, 4460184 total
- age 11: 450928 bytes, 4911112 total
- age 12: 701304 bytes, 5612416 total
- age 13: 497560 bytes, 6109976 total
- age 14: 494328 bytes, 6604304 total
- age 15: 404664 bytes, 7008968 total
624309.692: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 7877, predicted base time: 26338.13 ms, remaining time: 0.00 ms, target pause time: 200.00 ms]
624309.692: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 72 regions, survivors: 4 regions, predicted young region time: 2333.72 ms]
624309.692: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 72 regions, survivors: 4 regions, old: 0 regions, predicted pause time: 28671.85 ms, target pause time: 200.00 ms]
624309.708: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 11.91 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.
00 %)]
, 0.0162867 secs]
[Parallel Time: 14.3 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 624309692.3, Avg: 624309692.3, Max: 624309692.3, Diff: 0.0]
[Ext Root Scanning (ms): Min: 4.0, Avg: 4.2, Max: 4.4, Diff: 0.3, Sum: 16.8]
[Update RS (ms): Min: 2.0, Avg: 2.1, Max: 2.2, Diff: 0.2, Sum: 8.5]
[Processed Buffers: Min: 22, Avg: 73.0, Max: 112, Diff: 90, Sum: 292]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 7.8, Avg: 7.9, Max: 8.1, Diff: 0.3, Sum: 31.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.0]
[GC Worker Total (ms): Min: 14.3, Avg: 14.3, Max: 14.3, Diff: 0.0, Sum: 57.2]
[GC Worker End (ms): Min: 624309706.6, Avg: 624309706.6, Max: 624309706.6, Diff: 0.0]
[Code Root Fixup: 0.4 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 1.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 288.0M(288.0M)->0.0B(280.0M) Survivors: 16.0M->24.0M Heap: 681.3M(6144.0M)->402.1M(6144.0M)]
Heap after GC invocations=3863 (full 0):
garbage-first heap total 6291456K, used 411706K [0x0000000640000000, 0x0000000640403000, 0x00000007c0000000)
region size 4096K, 6 young (24576K), 6 survivors (24576K)
Metaspace used 147489K, capacity 151988K, committed 152192K, reserved 1183744K
class space used 16748K, capacity 17703K, committed 17792K, reserved 1048576K
}
[Times: user=0.05 sys=0.01, real=0.02 secs]