One of my application shows weird GC behavior. Application does young gc (minor GC) at regular intervals with pause time of ~30-50 ms and occasionally does mixed gc with ~100-150 ms this is never problem in healthy running state until jvm or we initiate Full GC.
After a Full GC event, we see that consecutive young gen gc (minor gc) pause time keeps increasing, and goes above MaxGCPauseMillis of 200 ms. The time is spent doing object copy. Later on G1's ergo behavior kicks in to reduce eden space and copy time to meet the goal of 200 ms and over couple of hours it slowly recovers but not to it's original behavior. This doesn't seem like problem with GC settings or incoming traffic, as system exhibits the same behavior after FullGC.
Initially, I thought the problem was due to NUMA policy as the host that showed this behavior was 2-socket system, and also observed that host was doing lot more remote memory references after FullGC event, but now I am seeing the similar behavior for 1-socket system. Wondering if it is due to memory defrag and using LargePages would solve this, but not sure about it.
It would be really helpful to get any insights from community, if anyone has seen similar behavior or knows what else might be going on with the host. The host has 128gb RAM and application uses 64gb heap, GC flags are below.
-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
GC logs showing pause time before FullGC event and after including -XX:+PrintAdaptiveSizePolicy, don't see much difference.
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]
