我的一个应用程序展示出奇怪的GC行为。该应用程序以正常间隔执行年轻代GC(小GC),暂停时间约为30-50毫秒,并且偶尔会执行混合GC,暂停时间为约100-150毫秒,在健康运行状态下这从未成为问题,直到jvm或我们启动Full GC。
在Full GC事件之后,我们看到连续的年轻代GC(小GC)暂停时间不断增加,并超过了200毫秒的MaxGCPauseMillis。时间花费在对象复制上。稍后,G1的人体工程学行为开始起作用,以减少Eden空间和复制时间,以满足200ms的目标,而在接下来的几个小时内,它缓慢恢复,但没有恢复到其原始状态。这似乎与GC设置或流入流量无关,因为系统在FullGC之后表现出相同的行为。
最初,我认为问题是由于NUMA策略引起的,因为显示此行为的主机是2插座系统,并且在FullGC事件之后观察到该主机执行了更多的远程内存引用,但现在我看到类似的行为适用于单插座系统。想知道是否由于内存碎片整理,使用LargePages可以解决此问题,但不确定。
如果有人看到类似的行为或知道主机上发生了什么其他情况,从社区获得任何见解都将非常有帮助。该主机具有128gb RAM,应用程序使用64gb堆,GC标志如下。
在Full GC事件之后,我们看到连续的年轻代GC(小GC)暂停时间不断增加,并超过了200毫秒的MaxGCPauseMillis。时间花费在对象复制上。稍后,G1的人体工程学行为开始起作用,以减少Eden空间和复制时间,以满足200ms的目标,而在接下来的几个小时内,它缓慢恢复,但没有恢复到其原始状态。这似乎与GC设置或流入流量无关,因为系统在FullGC之后表现出相同的行为。
最初,我认为问题是由于NUMA策略引起的,因为显示此行为的主机是2插座系统,并且在FullGC事件之后观察到该主机执行了更多的远程内存引用,但现在我看到类似的行为适用于单插座系统。想知道是否由于内存碎片整理,使用LargePages可以解决此问题,但不确定。
如果有人看到类似的行为或知道主机上发生了什么其他情况,从社区获得任何见解都将非常有帮助。该主机具有128gb RAM,应用程序使用64gb堆,GC标志如下。
-XX:GCLogFileSize=10485760 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=<file path> -XX:InitialHeapSize=67108864000 -XX:+ManagementServer -XX:MaxGCPauseMillis=200 -XX:MaxHeapSize=67108864000 -XX:NumberOfGCLogFiles=15 -XX:+PrintFlagsFinal -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:-UsePerfData -XX:+PrintAdaptiveSizePolicy
使用-XX:+PrintAdaptiveSizePolicy显示FullGC事件之前和之后的暂停时间的GC日志,没有看到太大的差异。
2018-01-17T09:56:25.494-0800: 60956.918: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 150874320 bytes, 150874320 total
- age 2: 5005336 bytes, 155879656 total
- age 3: 4381232 bytes, 160260888 total
- age 4: 1157480 bytes, 161418368 total
- age 5: 1194728 bytes, 162613096 total
- age 6: 1053664 bytes, 163666760 total
- age 7: 1050744 bytes, 164717504 total
- age 8: 628728 bytes, 165346232 total
- age 9: 802400 bytes, 166148632 total
- age 10: 850728 bytes, 166999360 total
- age 11: 661672 bytes, 167661032 total
- age 12: 778384 bytes, 168439416 total
- age 13: 713024 bytes, 169152440 total
- age 14: 754600 bytes, 169907040 total
- age 15: 765992 bytes, 170673032 total
60956.918: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 51732, predicted base time: 9.89 ms, remaining time: 190.11 ms, target pause time: 200.00 ms]
60956.918: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2382 regions, survivors: 18 regions, predicted young region time: 14.35 ms]
60956.918: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2382 regions, survivors: 18 regions, old: 0 regions, predicted pause time: 24.24 ms, target pause time: 200.00 ms]
, 0.0292727 secs]
[Parallel Time: 22.9 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 60956918.7, Avg: 60956919.0, Max: 60956919.3, Diff: 0.6]
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.4, Max: 0.7, Diff: 0.6, Sum: 9.8]
[Update RS (ms): Min: 4.5, Avg: 4.8, Max: 5.9, Diff: 1.4, Sum: 119.2]
[Processed Buffers: Min: 9, Avg: 15.6, Max: 34, Diff: 25, Sum: 391]
[Scan RS (ms): Min: 0.2, Avg: 0.5, Max: 0.7, Diff: 0.5, Sum: 12.9]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 15.7, Avg: 16.5, Max: 16.6, Diff: 1.0, Sum: 411.3]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Termination Attempts: Min: 1, Avg: 2.1, Max: 4, Diff: 3, Sum: 52]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 4.1]
[GC Worker Total (ms): Min: 21.9, Avg: 22.3, Max: 22.7, Diff: 0.8, Sum: 557.5]
[GC Worker End (ms): Min: 60956941.2, Avg: 60956941.3, Max: 60956941.5, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.7 ms]
[Other: 3.6 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: 2.3 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 288.0M->288.0M Heap: 44.3G(62.5G)->7272.3M(62.5G)]
[Times: user=0.59 sys=0.03, real=0.02 secs]
2018-01-17T09:56:27.978-0800: 60959.402: [Full GC (System.gc()) 8364M->1798M(62G), 5.0412807 secs]
[Eden: 1104.0M(37.2G)->0.0B(37.5G) Survivors: 288.0M->0.0B Heap: 8364.7M(62.5G)->1798.5M(62.5G)], [Metaspace: 25957K->25914K(28672K)]
[Times: user=7.21 sys=0.09, real=5.04 secs]
2018-01-17T09:57:35.135-0800: 61026.559: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 149090328 bytes, 149090328 total
- age 2: 6795360 bytes, 155885688 total
- age 3: 3953152 bytes, 159838840 total
- age 4: 813920 bytes, 160652760 total
- age 5: 1157328 bytes, 161810088 total
- age 6: 1193904 bytes, 163003992 total
- age 7: 689488 bytes, 163693480 total
- age 8: 1050744 bytes, 164744224 total
- age 9: 628608 bytes, 165372832 total
- age 10: 802368 bytes, 166175200 total
- age 11: 850416 bytes, 167025616 total
- age 12: 661360 bytes, 167686976 total
- age 13: 778072 bytes, 168465048 total
- age 14: 712800 bytes, 169177848 total
- age 15: 754600 bytes, 169932448 total
61026.559: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 21934, predicted base time: 7.23 ms, remaining time: 192.77 ms, target pause time: 200.00 ms]
61026.559: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2400 regions, survivors: 0 regions, predicted young region time: 13.29 ms]
61026.559: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2400 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 20.52 ms, target pause time: 200.00 ms]
, 0.0276684 secs]
[Parallel Time: 21.1 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61026559.6, Avg: 61026559.9, Max: 61026560.1, Diff: 0.4]
[Ext Root Scanning (ms): Min: 0.3, Avg: 0.5, Max: 0.9, Diff: 0.6, Sum: 12.9]
[Update RS (ms): Min: 1.7, Avg: 1.9, Max: 2.2, Diff: 0.5, Sum: 47.6]
[Processed Buffers: Min: 4, Avg: 11.9, Max: 42, Diff: 38, Sum: 297]
[Scan RS (ms): Min: 0.2, Avg: 0.5, Max: 0.7, Diff: 0.5, Sum: 12.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 17.4, Avg: 17.6, Max: 17.6, Diff: 0.2, Sum: 439.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Termination Attempts: Min: 2, Avg: 4.1, Max: 7, Diff: 5, Sum: 102]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 3.6]
[GC Worker Total (ms): Min: 20.3, Avg: 20.6, Max: 21.0, Diff: 0.6, Sum: 515.6]
[GC Worker End (ms): Min: 61026580.4, Avg: 61026580.5, Max: 61026580.6, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 2.7 ms]
[Other: 3.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.3 ms]
[Eden: 37.5G(37.5G)->0.0B(37.2G) Survivors: 0.0B->304.0M Heap: 39.3G(62.5G)->2099.4M(62.5G)]
[Times: user=0.56 sys=0.01, real=0.02 secs]
2018-01-17T09:58:19.569-0800: 61070.994: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 171868664 bytes, 171868664 total
61070.994: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 18959, predicted base time: 6.96 ms, remaining time: 193.04 ms, target pause time: 200.00 ms]
61070.994: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2381 regions, survivors: 19 regions, predicted young region time: 27.61 ms]
61070.994: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2381 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 34.57 ms, target pause time: 200.00 ms]
, 0.0282614 secs]
[Parallel Time: 21.7 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61070993.9, Avg: 61070994.1, Max: 61070994.4, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.8, Diff: 0.6, Sum: 11.0]
[Update RS (ms): Min: 1.5, Avg: 1.7, Max: 2.2, Diff: 0.7, Sum: 41.6]
[Processed Buffers: Min: 2, Avg: 10.9, Max: 45, Diff: 43, Sum: 273]
[Scan RS (ms): Min: 0.2, Avg: 0.6, Max: 0.7, Diff: 0.6, Sum: 14.9]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 18.3, Avg: 18.4, Max: 18.5, Diff: 0.3, Sum: 460.4]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 25]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 3.8]
[GC Worker Total (ms): Min: 20.9, Avg: 21.3, Max: 21.6, Diff: 0.6, Sum: 531.9]
[GC Worker End (ms): Min: 61071015.3, Avg: 61071015.4, Max: 61071015.5, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.7 ms]
[Other: 3.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.4 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.3 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->336.0M Heap: 39.3G(62.5G)->2125.0M(62.5G)]
[Times: user=0.65 sys=0.00, real=0.03 secs]
2018-01-17T09:59:06.219-0800: 61117.643: [GC pause (GCLocker Initiated GC) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 169100408 bytes, 169100408 total
- age 2: 22415336 bytes, 191515744 total
61117.643: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 21531, predicted base time: 7.14 ms, remaining time: 192.86 ms, target pause time: 200.00 ms]
61117.643: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2380 regions, survivors: 21 regions, predicted young region time: 17.20 ms]
61117.643: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2380 regions, survivors: 21 regions, old: 0 regions, predicted pause time: 24.34 ms, target pause time: 200.00 ms]
, 0.0303978 secs]
[Parallel Time: 24.1 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61117643.5, Avg: 61117643.8, Max: 61117644.0, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.5, Max: 0.7, Diff: 0.5, Sum: 11.3]
[Update RS (ms): Min: 1.6, Avg: 1.8, Max: 2.3, Diff: 0.8, Sum: 44.6]
[Processed Buffers: Min: 3, Avg: 11.6, Max: 26, Diff: 23, Sum: 291]
[Scan RS (ms): Min: 0.2, Avg: 0.6, Max: 0.7, Diff: 0.5, Sum: 14.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 20.4, Avg: 20.6, Max: 20.7, Diff: 0.2, Sum: 514.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 25]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.5]
[GC Worker Total (ms): Min: 23.2, Avg: 23.5, Max: 23.9, Diff: 0.6, Sum: 588.3]
[GC Worker End (ms): Min: 61117667.2, Avg: 61117667.3, Max: 61117667.5, Diff: 0.2]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.7 ms]
[Other: 3.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.2 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 336.0M->304.0M Heap: 39.3G(62.5G)->2100.7M(62.5G)]
[Times: user=0.64 sys=0.01, real=0.03 secs]
2018-01-17T09:59:52.967-0800: 61164.391: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 164897824 bytes, 164897824 total
- age 2: 5482152 bytes, 170379976 total
- age 3: 19623112 bytes, 190003088 total
61164.391: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 20596, predicted base time: 6.99 ms, remaining time: 193.01 ms, target pause time: 200.00 ms]
61164.391: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2381 regions, survivors: 19 regions, predicted young region time: 18.71 ms]
61164.391: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2381 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 25.70 ms, target pause time: 200.00 ms]
, 0.0310130 secs]
[Parallel Time: 24.4 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61164391.2, Avg: 61164391.5, Max: 61164391.7, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.8, Diff: 0.6, Sum: 10.4]
[Update RS (ms): Min: 1.6, Avg: 1.8, Max: 2.3, Diff: 0.7, Sum: 45.2]
[Processed Buffers: Min: 3, Avg: 11.3, Max: 31, Diff: 28, Sum: 283]
[Scan RS (ms): Min: 0.2, Avg: 0.6, Max: 0.7, Diff: 0.5, Sum: 14.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 20.9, Avg: 21.0, Max: 21.1, Diff: 0.2, Sum: 524.7]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 25]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 3.7]
[GC Worker Total (ms): Min: 23.7, Avg: 24.0, Max: 24.3, Diff: 0.7, Sum: 598.8]
[GC Worker End (ms): Min: 61164415.3, Avg: 61164415.4, Max: 61164415.6, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.7 ms]
[Other: 3.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.5 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->304.0M Heap: 39.3G(62.5G)->2100.9M(62.5G)]
[Times: user=0.70 sys=0.00, real=0.03 secs]
2018-01-17T10:00:39.866-0800: 61211.290: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 168482032 bytes, 168482032 total
- age 2: 4749088 bytes, 173231120 total
- age 3: 3178336 bytes, 176409456 total
- age 4: 19619976 bytes, 196029432 total
61211.290: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 22074, predicted base time: 7.07 ms, remaining time: 192.93 ms, target pause time: 200.00 ms]
61211.290: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2381 regions, survivors: 19 regions, predicted young region time: 19.28 ms]
61211.290: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2381 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 26.36 ms, target pause time: 200.00 ms]
, 0.0361588 secs]
[Parallel Time: 29.7 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61211290.3, Avg: 61211290.5, Max: 61211290.7, Diff: 0.4]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.6, Diff: 0.4, Sum: 10.9]
[Update RS (ms): Min: 1.8, Avg: 1.9, Max: 2.4, Diff: 0.6, Sum: 47.6]
[Processed Buffers: Min: 5, Avg: 12.4, Max: 32, Diff: 27, Sum: 309]
[Scan RS (ms): Min: 0.2, Avg: 0.6, Max: 0.7, Diff: 0.5, Sum: 14.9]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 26.0, Avg: 26.1, Max: 26.2, Diff: 0.2, Sum: 652.8]
[Termination (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.6]
[Termination Attempts: Min: 40, Avg: 52.2, Max: 65, Diff: 25, Sum: 1305]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.4]
[GC Worker Total (ms): Min: 29.1, Avg: 29.3, Max: 29.6, Diff: 0.6, Sum: 733.3]
[GC Worker End (ms): Min: 61211319.7, Avg: 61211319.8, Max: 61211319.9, Diff: 0.2]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.8 ms]
[Other: 3.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.2 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->304.0M Heap: 39.3G(62.5G)->2093.9M(62.5G)]
[Times: user=0.78 sys=0.01, real=0.03 secs]
2018-01-17T10:01:24.926-0800: 61256.351: [GC pause (GCLocker Initiated GC) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 164765392 bytes, 164765392 total
- age 2: 3962056 bytes, 168727448 total
- age 3: 3375800 bytes, 172103248 total
- age 4: 3152672 bytes, 175255920 total
- age 5: 19567808 bytes, 194823728 total
61256.351: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 26856, predicted base time: 7.46 ms, remaining time: 192.54 ms, target pause time: 200.00 ms]
61256.351: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2382 regions, survivors: 19 regions, predicted young region time: 22.07 ms]
61256.351: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2382 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 29.53 ms, target pause time: 200.00 ms]
, 0.0525081 secs]
[Parallel Time: 46.1 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61256351.0, Avg: 61256351.3, Max: 61256351.5, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.7, Diff: 0.5, Sum: 10.6]
[Update RS (ms): Min: 2.0, Avg: 2.2, Max: 2.5, Diff: 0.5, Sum: 55.8]
[Processed Buffers: Min: 3, Avg: 11.6, Max: 39, Diff: 36, Sum: 290]
[Scan RS (ms): Min: 0.2, Avg: 0.5, Max: 0.7, Diff: 0.4, Sum: 13.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 41.5, Avg: 41.6, Max: 41.8, Diff: 0.3, Sum: 1041.1]
[Termination (ms): Min: 0.6, Avg: 0.7, Max: 0.8, Diff: 0.2, Sum: 16.8]
[Termination Attempts: Min: 234, Avg: 259.0, Max: 289, Diff: 55, Sum: 6474]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.6]
[GC Worker Total (ms): Min: 45.4, Avg: 45.7, Max: 46.0, Diff: 0.6, Sum: 1141.5]
[GC Worker End (ms): Min: 61256396.8, Avg: 61256396.9, Max: 61256397.1, Diff: 0.2]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.7 ms]
[Other: 3.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.3 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->304.0M Heap: 39.3G(62.5G)->2093.9M(62.5G)]
[Times: user=1.23 sys=0.00, real=0.05 secs]
2018-01-17T10:02:12.464-0800: 61303.888: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 169945088 bytes, 169945088 total
- age 2: 4935304 bytes, 174880392 total
- age 3: 2952560 bytes, 177832952 total
- age 4: 3375096 bytes, 181208048 total
- age 5: 3152384 bytes, 184360432 total
- age 6: 19545992 bytes, 203906424 total
61303.888: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 25648, predicted base time: 7.29 ms, remaining time: 192.71 ms, target pause time: 200.00 ms]
61303.888: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2381 regions, survivors: 19 regions, predicted young region time: 30.07 ms]
61303.888: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2381 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 37.36 ms, target pause time: 200.00 ms]
, 0.0604556 secs]
[Parallel Time: 53.9 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61303888.2, Avg: 61303888.4, Max: 61303888.6, Diff: 0.4]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.7, Diff: 0.4, Sum: 10.8]
[Update RS (ms): Min: 2.0, Avg: 2.2, Max: 2.8, Diff: 0.8, Sum: 55.0]
[Processed Buffers: Min: 5, Avg: 12.0, Max: 49, Diff: 44, Sum: 301]
[Scan RS (ms): Min: 0.2, Avg: 0.6, Max: 0.8, Diff: 0.6, Sum: 15.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 49.1, Avg: 49.3, Max: 49.5, Diff: 0.4, Sum: 1232.0]
[Termination (ms): Min: 0.6, Avg: 0.8, Max: 1.0, Diff: 0.3, Sum: 19.1]
[Termination Attempts: Min: 292, Avg: 317.8, Max: 351, Diff: 59, Sum: 7946]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 3.8]
[GC Worker Total (ms): Min: 53.2, Avg: 53.5, Max: 53.8, Diff: 0.6, Sum: 1336.5]
[GC Worker End (ms): Min: 61303941.7, Avg: 61303941.9, Max: 61303942.0, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.8 ms]
[Other: 3.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.2 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->304.0M Heap: 39.2G(62.5G)->2094.1M(62.5G)]
[Times: user=1.38 sys=0.01, real=0.07 secs]
2018-01-17T10:02:59.224-0800: 61350.648: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 165515088 bytes, 165515088 total
- age 2: 5810696 bytes, 171325784 total
- age 3: 3680000 bytes, 175005784 total
- age 4: 2952376 bytes, 177958160 total
- age 5: 3374960 bytes, 181333120 total
- age 6: 3152352 bytes, 184485472 total
- age 7: 19542960 bytes, 204028432 total
61350.648: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 26349, predicted base time: 7.38 ms, remaining time: 192.62 ms, target pause time: 200.00 ms]
61350.648: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2381 regions, survivors: 19 regions, predicted young region time: 37.34 ms]
61350.648: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2381 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 44.72 ms, target pause time: 200.00 ms]
, 0.0681355 secs]
[Parallel Time: 61.7 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61350648.3, Avg: 61350648.6, Max: 61350648.8, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.4, Max: 0.6, Diff: 0.5, Sum: 8.9]
[Update RS (ms): Min: 2.2, Avg: 2.3, Max: 2.8, Diff: 0.6, Sum: 58.1]
[Processed Buffers: Min: 4, Avg: 12.3, Max: 27, Diff: 23, Sum: 308]
[Scan RS (ms): Min: 0.2, Avg: 0.5, Max: 0.7, Diff: 0.5, Sum: 13.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 56.6, Avg: 56.8, Max: 57.0, Diff: 0.4, Sum: 1421.1]
[Termination (ms): Min: 0.8, Avg: 1.0, Max: 1.2, Diff: 0.4, Sum: 24.2]
[Termination Attempts: Min: 333, Avg: 397.2, Max: 450, Diff: 117, Sum: 9931]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.6]
[GC Worker Total (ms): Min: 60.9, Avg: 61.2, Max: 61.5, Diff: 0.6, Sum: 1529.2]
[GC Worker End (ms): Min: 61350709.6, Avg: 61350709.7, Max: 61350709.8, Diff: 0.2]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.8 ms]
[Other: 3.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.2 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->304.0M Heap: 39.2G(62.5G)->2102.0M(62.5G)]
[Times: user=1.59 sys=0.00, real=0.07 secs]
2018-01-17T10:03:44.854-0800: 61396.278: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2516582400 bytes, new threshold 15 (max 15)
- age 1: 164753576 bytes, 164753576 total
- age 2: 4971568 bytes, 169725144 total
- age 3: 5802160 bytes, 175527304 total
- age 4: 3678784 bytes, 179206088 total
- age 5: 2952376 bytes, 182158464 total
- age 6: 3374960 bytes, 185533424 total
- age 7: 3152352 bytes, 188685776 total
- age 8: 19525304 bytes, 208211080 total
61396.278: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 27515, predicted base time: 7.50 ms, remaining time: 192.50 ms, target pause time: 200.00 ms]
61396.278: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2381 regions, survivors: 19 regions, predicted young region time: 44.05 ms]
61396.278: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2381 regions, survivors: 19 regions, old: 0 regions, predicted pause time: 51.55 ms, target pause time: 200.00 ms]
, 0.0757171 secs]
[Parallel Time: 69.3 ms, GC Workers: 25]
[GC Worker Start (ms): Min: 61396278.1, Avg: 61396278.3, Max: 61396278.6, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.7, Diff: 0.5, Sum: 10.4]
[Update RS (ms): Min: 2.3, Avg: 2.4, Max: 2.8, Diff: 0.5, Sum: 61.2]
[Processed Buffers: Min: 5, Avg: 12.2, Max: 29, Diff: 24, Sum: 305]
[Scan RS (ms): Min: 0.3, Avg: 0.5, Max: 0.7, Diff: 0.4, Sum: 13.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 63.7, Avg: 64.1, Max: 64.3, Diff: 0.6, Sum: 1601.9]
[Termination (ms): Min: 1.1, Avg: 1.2, Max: 1.5, Diff: 0.5, Sum: 30.1]
[Termination Attempts: Min: 453, Avg: 502.3, Max: 540, Diff: 87, Sum: 12557]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 3.5]
[GC Worker Total (ms): Min: 68.6, Avg: 68.8, Max: 69.2, Diff: 0.7, Sum: 1720.8]
[GC Worker End (ms): Min: 61396347.1, Avg: 61396347.2, Max: 61396347.3, Diff: 0.2]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.8 ms]
[Other: 3.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 2.3 ms]
[Eden: 37.2G(37.2G)->0.0B(37.2G) Survivors: 304.0M->288.0M Heap: 39.3G(62.5G)->2086.3M(62.5G)]
[Times: user=1.79 sys=0.00, real=0.08 secs]
-XX:+PrintAdaptiveSizePolicy
会更好地了解情况。 - yegodm