问题描述:
YongGC 消耗时间过长
环境说明
CENTOS 6.5
启动参数
server -Xmx6G -Xms6G -Xss256k
2022-07-13T08:41:05.431+0800: 120718.482: [GC pause (G1 Evacuation Pause) (young), 0.0169975 secs]
[Parallel Time: 10.2 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 120718483.5, Avg: 120718483.6, Max: 120718483.7, Diff: 0.2]
[Ext Root Scanning (ms): Min: 2.4, Avg: 2.6, Max: 3.1, Diff: 0.7, Sum: 21.1]
[Update RS (ms): Min: 4.2, Avg: 4.4, Max: 4.5, Diff: 0.3, Sum: 35.0]
[Processed Buffers: Min: 101, Avg: 132.6, Max: 164, Diff: 63, Sum: 1061]
[Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 2.3, Avg: 2.4, Max: 2.5, Diff: 0.2, Sum: 19.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 3.6, Max: 6, Diff: 5, Sum: 29]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
[GC Worker Total (ms): Min: 9.7, Avg: 9.9, Max: 10.0, Diff: 0.2, Sum: 79.1]
[GC Worker End (ms): Min: 120718493.4, Avg: 120718493.5, Max: 120718493.6, Diff: 0.2]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 6.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.8 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.5 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.8 ms]
[Eden: 3450.0M(3450.0M)->0.0B(3446.0M) Survivors: 14.0M->16.0M Heap: 5511.5M(6144.0M)->2063.3M(6144.0M)]
[Times: user=0.09 sys=0.00, real=0.02 secs]
2022-07-13T08:41:23.257+0800: 120736.308: [GC pause (G1 Evacuation Pause) (young), 0.0779682 secs]
[Parallel Time: 55.3 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 120736315.3, Avg: 120736315.4, Max: 120736315.6, Diff: 0.3]
[Ext Root Scanning (ms): Min: 15.4, Avg: 16.6, Max: 18.1, Diff: 2.7, Sum: 133.2]
[Update RS (ms): Min: 5.8, Avg: 8.0, Max: 13.6, Diff: 7.7, Sum: 63.9]
[Processed Buffers: Min: 2, Avg: 131.6, Max: 179, Diff: 177, Sum: 1053]
[Scan RS (ms): Min: 0.3, Avg: 0.5, Max: 0.6, Diff: 0.3, Sum: 3.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 22.8, Avg: 29.5, Max: 31.0, Diff: 8.2, Sum: 235.7]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.0]
[GC Worker Total (ms): Min: 54.6, Avg: 54.7, Max: 54.9, Diff: 0.4, Sum: 437.6]
[GC Worker End (ms): Min: 120736370.1, Avg: 120736370.1, Max: 120736370.2, Diff: 0.1]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 5.0 ms]
[Other: 17.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.4 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 8.0 ms]
[Eden: 3446.0M(3446.0M)->0.0B(3454.0M) Survivors: 16.0M->12.0M Heap: 5509.3M(6144.0M)->2060.1M(6144.0M)]
[Times: user=0.37 sys=0.00, real=0.08 secs]
2022-07-13T08:41:38.995+0800: 120752.047: [GC pause (G1 Evacuation Pause) (young), 6.3129019 secs]
[Parallel Time: 6283.7 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 120752049.6, Avg: 120752053.4, Max: 120752059.9, Diff: 10.4]
[Ext Root Scanning (ms): Min: 5.1, Avg: 13.7, Max: 21.7, Diff: 16.6, Sum: 109.7]
[Update RS (ms): Min: 0.0, Avg: 44.4, Max: 146.1, Diff: 146.1, Sum: 355.4]
[Processed Buffers: Min: 0, Avg: 133.0, Max: 292, Diff: 292, Sum: 1064]
[Scan RS (ms): Min: 0.2, Avg: 0.8, Max: 4.8, Diff: 4.6, Sum: 6.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[Object Copy (ms): Min: 5925.8, Avg: 6116.3, Max: 6238.4, Diff: 312.7, Sum: 48930.8]
[Termination (ms): Min: 0.0, Avg: 103.8, Max: 192.1, Diff: 192.1, Sum: 830.5]
[Termination Attempts: Min: 1, Avg: 2.2, Max: 8, Diff: 7, Sum: 18]
[GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 4.1, Diff: 4.1, Sum: 4.4]
[GC Worker Total (ms): Min: 6273.2, Avg: 6279.7, Max: 6283.5, Diff: 10.3, Sum: 50237.3]
[GC Worker End (ms): Min: 120758333.1, Avg: 120758333.1, Max: 120758333.1, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 28.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 12.4 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.7 ms]
[Eden: 3454.0M(3454.0M)->0.0B(404.0M) Survivors: 12.0M->346.0M Heap: 5514.1M(6144.0M)->2393.2M(6144.0M)]
[Times: user=1.19 sys=0.44, real=6.31 secs]
2022-07-13T08:41:45.457+0800: 120758.508: [GC pause (G1 Evacuation Pause) (young), 9.0956509 secs]
[Parallel Time: 9091.4 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 120758509.4, Avg: 120758509.5, Max: 120758510.0, Diff: 0.6]
[Ext Root Scanning (ms): Min: 3.1, Avg: 5.8, Max: 14.4, Diff: 11.2, Sum: 46.3]
[Update RS (ms): Min: 4.4, Avg: 10.0, Max: 28.4, Diff: 24.1, Sum: 79.7]
[Processed Buffers: Min: 5, Avg: 50.5, Max: 75, Diff: 70, Sum: 404]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 9034.3, Avg: 9063.3, Max: 9074.1, Diff: 39.8, Sum: 72506.1]
[Termination (ms): Min: 0.0, Avg: 10.8, Max: 13.8, Diff: 13.8, Sum: 86.1]
[Termination Attempts: Min: 1, Avg: 26.6, Max: 53, Diff: 52, Sum: 213]
[GC Worker Other (ms): Min: 0.0, Avg: 1.1, Max: 8.6, Diff: 8.6, Sum: 8.8]
[GC Worker Total (ms): Min: 9090.4, Avg: 9090.9, Max: 9091.1, Diff: 0.7, Sum: 72727.4]
[GC Worker End (ms): Min: 120767600.4, Avg: 120767600.5, Max: 120767600.5, Diff: 0.0]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.6 ms]
[Other: 3.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.4 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.5 ms]
[Eden: 404.0M(404.0M)->0.0B(212.0M) Survivors: 346.0M->94.0M Heap: 2797.2M(6144.0M)->2532.6M(6144.0M)]
[Times: user=0.53 sys=0.51, real=9.10 secs]
2022-07-13T08:41:54.618+0800: 120767.669: [GC pause (G1 Evacuation Pause) (young), 0.5383254 secs]
[Parallel Time: 527.7 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 120767669.9, Avg: 120767670.5, Max: 120767670.9, Diff: 1.1]
[Ext Root Scanning (ms): Min: 0.4, Avg: 9.0, Max: 19.3, Diff: 18.9, Sum: 72.0]
[Update RS (ms): Min: 246.1, Avg: 251.6, Max: 255.1, Diff: 9.0, Sum: 2013.0]
[Processed Buffers: Min: 24, Avg: 44.1, Max: 97, Diff: 73, Sum: 353]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 211.5, Avg: 232.8, Max: 271.3, Diff: 59.8, Sum: 1862.3]
[Termination (ms): Min: 0.0, Avg: 33.3, Max: 49.3, Diff: 49.3, Sum: 266.2]
[Termination Attempts: Min: 1, Avg: 1.4, Max: 3, Diff: 2, Sum: 11]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 0.7]
[GC Worker Total (ms): Min: 526.4, Avg: 526.8, Max: 527.4, Diff: 1.0, Sum: 4214.3]
[GC Worker End (ms): Min: 120768197.3, Avg: 120768197.3, Max: 120768197.3, Diff: 0.1]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 10.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 7.8 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 212.0M(212.0M)->0.0B(266.0M) Survivors: 94.0M->40.0M Heap: 2744.6M(6144.0M)->2686.0M(6144.0M)]
[Times: user=0.53 sys=0.05, real=0.54 secs]
2022-07-13T08:41:55.241+0800: 120768.292: [GC pause (G1 Evacuation Pause) (young), 0.1784613 secs]
[Parallel Time: 174.6 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 120768292.9, Avg: 120768293.3, Max: 120768293.9, Diff: 1.0]
[Ext Root Scanning (ms): Min: 3.5, Avg: 8.0, Max: 17.3, Diff: 13.8, Sum: 64.1]
[Update RS (ms): Min: 102.1, Avg: 110.0, Max: 114.7, Diff: 12.5, Sum: 879.8]
[Processed Buffers: Min: 8, Avg: 43.2, Max: 84, Diff: 76, Sum: 346]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 49.7, Avg: 55.7, Max: 59.6, Diff: 9.9, Sum: 445.4]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7]
[Termination Attempts: Min: 1, Avg: 16.4, Max: 24, Diff: 23, Sum: 131]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 173.2, Avg: 173.8, Max: 174.2, Diff: 1.0, Sum: 1390.4]
[GC Worker End (ms): Min: 120768467.1, Avg: 120768467.1, Max: 120768467.1, Diff: 0.0]
[Code Root Fixup: 0.3 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 3.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.5 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 266.0M(266.0M)->0.0B(266.0M) Survivors: 40.0M->40.0M Heap: 2952.0M(6144.0M)->2852.0M(6144.0M)]
[Times: user=0.29 sys=0.01, real=0.18 secs]
这是 前后几次YongGC 其中中间两次，一次耗时6秒，一次耗时9秒。
大量时间花费在Objects Copy，经过比对发现了Yong Eden好像出现了动态调整，从5G降到了3G不到，不知道是什么机制触发了这个调整
之前有固定Yong区大小，结果触发了FullGC , 取消Xmn 后没有出现FullGC了，但是会偶线这种长时间的YongGc
【赏金领取规则及入口】
麻烦大家关注【Heapdump性能社区】公众号，及时接收信息！