TestG1ParallelPhases.java fails with phase NonYoungFreeCSet not found (2)

The following test continues to fail in the JDK14 CI:

jdk/jfr/event/gc/collection/TestG1ParallelPhases.java

Follow-up after the logging changes in JDK-8232951: the test still fails.

There looks to be a (wrong) small time window where a whitebox initiated concurrent cycle request may abort the space reclamation phase right after a Young (Prepare Mixed) gc.
Which means that there is never a Mixed GC that sends the correct message.

Not sure whether this is a test or GC bug (either whitebox being able to interrupt the space reclamation phase started with the prepare mixed gc, or the space reclamation phase not yet officially started after the prepare mixed gc).

Log output:

----------System.out:(307/31276)----------
[0.017s][info][gc,heap] Heap region size: 1M
[0.017s][debug][gc,heap] Minimum heap 20971520 Initial heap 20971520 Maximum heap 20971520
[0.024s][info ][gc,heap,coops] Heap address: 0x00000000fec00000, size: 20 MB, Compressed Oops mode: 32-bit
[0.024s][debug][gc ] ConcGCThreads: 3 offset 29
[0.024s][debug][gc ] ParallelGCThreads: 13
[0.025s][debug][gc ] Initialize mark stack with 4096 chunks, maximum 16384
[0.031s][debug][gc,ergo,heap ] Expand the heap. requested expansion amount: 20971520B expansion amount: 20971520B
[0.032s][debug][gc,ergo,refine] Initial Refinement Zones: green: 3328, yellow: 9984, red: 16640, min yellow size: 6656
[0.033s][info ][gc ] Using G1
[0.380s][info ][gc ] Periodic GC disabled
[2.406s][debug][gc,heap ] GC(0) Heap before GC invocations=0 (full 0): garbage-first heap total 20480K, used 9216K [0x00000000fec00000, 0x0000000100000000)
[2.406s][debug][gc,heap ] GC(0) region size 1024K, 9 young (9216K), 0 survivors (0K)
[2.406s][debug][gc,heap ] GC(0) Metaspace used 2693K, capacity 4798K, committed 4864K, reserved 1056768K
[2.406s][debug][gc,heap ] GC(0) class space used 285K, capacity 459K, committed 512K, reserved 1048576K
[2.406s][info ][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2.407s][debug][gc,ergo ] GC(0) Running G1 Merge Heap Roots using 4 workers for 9 regions
[2.463s][debug][gc,ergo ] GC(0) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 9 regions.
[2.467s][debug][gc,ergo ] GC(0) Running G1 Free Collection Set using 1 workers for collection set length 9
[2.473s][debug][gc,ergo,refine] GC(0) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: -nan(ind)ms HCC time: 0.01ms
[2.473s][debug][gc,ergo,refine] GC(0) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[2.473s][info ][gc,heap ] GC(0) Eden regions: 9->0(7)
[2.473s][info ][gc,heap ] GC(0) Survivor regions: 0->0(2)
[2.473s][info ][gc,heap ] GC(0) Old regions: 0->3
[2.473s][info ][gc,heap ] GC(0) Archive regions: 0->0
[2.473s][info ][gc,heap ] GC(0) Humongous regions: 0->0
[2.474s][debug][gc,heap ] GC(0) Heap after GC invocations=1 (full 0): garbage-first heap total 20480K, used 2370K [0x00000000fec00000, 0x0000000100000000)
[2.474s][debug][gc,heap ] GC(0) region size 1024K, 0 young (0K), 0 survivors (0K)
[2.474s][debug][gc,heap ] GC(0) Metaspace used 2693K, capacity 4798K, committed 4864K, reserved 1056768K
[2.474s][debug][gc,heap ] GC(0) class space used 285K, capacity 459K, committed 512K, reserved 1048576K
[2.474s][info ][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 9M->2M(20M) 67.766ms
[3.368s][debug][gc,heap ] GC(1) Heap before GC invocations=1 (full 0): garbage-first heap total 20480K, used 9538K [0x00000000fec00000, 0x0000000100000000)
[3.368s][debug][gc,heap ] GC(1) region size 1024K, 7 young (7168K), 0 survivors (0K)
[3.368s][debug][gc,heap ] GC(1) Metaspace used 3730K, capacity 4849K, committed 5120K, reserved 1056768K
[3.368s][debug][gc,heap ] GC(1) class space used 379K, capacity 475K, committed 512K, reserved 1048576K
[3.368s][info ][gc,start ] GC(1) Pause Young (Normal) (G1 Evacuation Pause)
[3.369s][debug][gc,ergo ] GC(1) Running G1 Merge Heap Roots using 4 workers for 7 regions
[3.388s][debug][gc,ergo ] GC(1) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 10 regions.
[3.390s][debug][gc,ergo ] GC(1) Running G1 Free Collection Set using 1 workers for collection set length 7
[3.392s][debug][gc,ergo,refine] GC(1) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 2.81ms HCC time: 0.01ms
[3.392s][debug][gc,ergo,refine] GC(1) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[3.392s][info ][gc,heap ] GC(1) Eden regions: 7->0(8)
[3.392s][info ][gc,heap ] GC(1) Survivor regions: 0->0(1)
[3.392s][info ][gc,heap ] GC(1) Old regions: 3->3
[3.392s][info ][gc,heap ] GC(1) Archive regions: 0->0
[3.392s][info ][gc,heap ] GC(1) Humongous regions: 0->0
[3.392s][debug][gc,heap ] GC(1) Heap after GC invocations=2 (full 0): garbage-first heap total 20480K, used 2817K [0x00000000fec00000, 0x0000000100000000)
[3.393s][debug][gc,heap ] GC(1) region size 1024K, 0 young (0K), 0 survivors (0K)
[3.393s][debug][gc,heap ] GC(1) Metaspace used 3730K, capacity 4849K, committed 5120K, reserved 1056768K
[3.393s][debug][gc,heap ] GC(1) class space used 379K, capacity 475K, committed 512K, reserved 1048576K
[3.393s][info ][gc ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 9M->2M(20M) 24.399ms
[3.810s][debug][gc,ergo,ihop ] Request concurrent cycle initiation (occupancy higher than threshold) occupancy: 9437184B allocation request: 1000016B threshold: 9437184B (45.00) source: concurrent humongous allocation
[3.816s][debug][gc,ergo ] Request concurrent cycle initiation (requested by GC cause). GC cause: G1 Humongous Allocation
[3.817s][debug][gc,heap ] GC(2) Heap before GC invocations=2 (full 0): garbage-first heap total 20480K, used 11009K [0x00000000fec00000, 0x0000000100000000)
[3.817s][debug][gc,heap ] GC(2) region size 1024K, 3 young (3072K), 0 survivors (0K)
[3.817s][debug][gc,heap ] GC(2) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.817s][debug][gc,heap ] GC(2) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.817s][debug][gc,ergo ] GC(2) Initiate concurrent cycle (concurrent cycle initiation requested)
[3.817s][info ][gc,start ] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[3.817s][debug][gc,ergo ] GC(2) Running G1 Merge Heap Roots using 4 workers for 3 regions
[3.838s][debug][gc,ergo ] GC(2) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 6 regions.
[3.851s][debug][gc,ergo ] GC(2) Running G1 Free Collection Set using 1 workers for collection set length 3
[3.852s][debug][gc,ergo,refine] GC(2) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 1.93ms HCC time: 0.01ms
[3.852s][debug][gc,ergo,refine] GC(2) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[3.852s][info ][gc,heap ] GC(2) Eden regions: 3->0(4)
[3.852s][info ][gc,heap ] GC(2) Survivor regions: 0->0(1)
[3.852s][info ][gc,heap ] GC(2) Old regions: 3->4
[3.852s][info ][gc,heap ] GC(2) Archive regions: 0->0
[3.852s][info ][gc,heap ] GC(2) Humongous regions: 6->6
[3.852s][debug][gc,heap ] GC(2) Heap after GC invocations=3 (full 0): garbage-first heap total 20480K, used 10195K [0x00000000fec00000, 0x0000000100000000)
[3.852s][debug][gc,heap ] GC(2) region size 1024K, 0 young (0K), 0 survivors (0K)
[3.852s][debug][gc,heap ] GC(2) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.852s][debug][gc,heap ] GC(2) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.852s][info ][gc ] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation) 11M->9M(20M) 35.399ms
[3.852s][info ][gc ] GC(3) Concurrent Cycle
[3.852s][debug][gc,ergo ] GC(3) Running G1 Root Region Scan using 2 workers for 2 work units.
[3.869s][debug][gc,heap ] GC(4) Heap before GC invocations=3 (full 0): garbage-first heap total 20480K, used 19411K [0x00000000fec00000, 0x0000000100000000)
[3.869s][debug][gc,heap ] GC(4) region size 1024K, 1 young (1024K), 0 survivors (0K)
[3.869s][debug][gc,heap ] GC(4) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.869s][debug][gc,heap ] GC(4) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.869s][info ][gc,start ] GC(4) Pause Young (Normal) (G1 Humongous Allocation)
[3.869s][debug][gc,ergo ] GC(4) Running G1 Merge Heap Roots using 4 workers for 1 regions
[3.876s][debug][gc,ergo ] GC(4) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 3 regions.
[3.878s][debug][gc,ergo ] GC(4) Running G1 Free Collection Set using 1 workers for collection set length 1
[3.878s][debug][gc,ergo,refine] GC(4) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 4.92ms HCC time: 0.01ms
[3.878s][debug][gc,ergo,refine] GC(4) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[3.878s][info ][gc,heap ] GC(4) Eden regions: 1->0(1)
[3.878s][info ][gc,heap ] GC(4) Survivor regions: 0->0(0)
[3.878s][info ][gc,heap ] GC(4) Old regions: 4->4
[3.879s][info ][gc,heap ] GC(4) Archive regions: 0->0
[3.879s][info ][gc,heap ] GC(4) Humongous regions: 15->15
[3.879s][debug][gc,heap ] GC(4) Heap after GC invocations=4 (full 0): garbage-first heap total 20480K, used 19456K [0x00000000fec00000, 0x0000000100000000)
[3.879s][debug][gc,heap ] GC(4) region size 1024K, 0 young (0K), 0 survivors (0K)
[3.879s][debug][gc,heap ] GC(4) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.879s][debug][gc,heap ] GC(4) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.879s][info ][gc ] GC(4) Pause Young (Normal) (G1 Humongous Allocation) 19M->19M(20M) 9.897ms
[3.880s][debug][gc,heap ] GC(5) Heap before GC invocations=4 (full 0): garbage-first heap total 20480K, used 20480K [0x00000000fec00000, 0x0000000100000000)
[3.880s][debug][gc,heap ] GC(5) region size 1024K, 0 young (0K), 0 survivors (0K)
[3.880s][debug][gc,heap ] GC(5) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.881s][debug][gc,heap ] GC(5) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.881s][info ][gc,start ] GC(5) Pause Young (Normal) (G1 Evacuation Pause)
[3.881s][debug][gc,ergo ] GC(5) Running G1 Merge Heap Roots using 4 workers for 0 regions
[3.882s][debug][gc,ergo ] GC(5) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 2 regions.
[3.884s][debug][gc,ergo ] GC(5) Running G1 Free Collection Set using 1 workers for collection set length 0
[3.884s][debug][gc,ergo,refine] GC(5) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 0.10ms HCC time: 0.01ms
[3.884s][debug][gc,ergo,refine] GC(5) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[3.884s][info ][gc,heap ] GC(5) Eden regions: 0->0(1)
[3.884s][info ][gc,heap ] GC(5) Survivor regions: 0->0(0)
[3.884s][info ][gc,heap ] GC(5) Old regions: 4->4
[3.884s][info ][gc,heap ] GC(5) Archive regions: 0->0
[3.884s][info ][gc,heap ] GC(5) Humongous regions: 16->16
[3.885s][debug][gc,heap ] GC(5) Heap after GC invocations=5 (full 0): garbage-first heap total 20480K, used 20480K [0x00000000fec00000, 0x0000000100000000)
[3.885s][debug][gc,heap ] GC(5) region size 1024K, 0 young (0K), 0 survivors (0K)
[3.885s][debug][gc,heap ] GC(5) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.885s][debug][gc,heap ] GC(5) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.885s][info ][gc ] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 20M->20M(20M) 4.107ms
[3.885s][debug][gc,ergo,heap ] Attempt heap expansion (allocation request failed). Allocation request: 18576B
[3.885s][debug][gc,ergo,heap ] Expand the heap. requested expansion amount: 1048576B expansion amount: 1048576B
[3.885s][debug][gc,ergo,heap ] Did not expand the heap (heap already fully expanded)
[3.887s][info ][gc,start ] GC(6) Pause Full (G1 Evacuation Pause)
[3.887s][debug][gc,heap ] GC(6) Heap before GC invocations=5 (full 0): garbage-first heap total 20480K, used 20480K [0x00000000fec00000, 0x0000000100000000)
[3.887s][debug][gc,heap ] GC(6) region size 1024K, 0 young (0K), 0 survivors (0K)
[3.887s][debug][gc,heap ] GC(6) Metaspace used 3801K, capacity 4867K, committed 5120K, reserved 1056768K
[3.887s][debug][gc,heap ] GC(6) class space used 388K, capacity 481K, committed 512K, reserved 1048576K
[3.887s][debug][gc,start ] GC(6) Clear Next Bitmap
[3.887s][debug][gc,ergo ] GC(6) Running G1 Clear Bitmap with 1 workers for 1 work units.
[3.887s][debug][gc ] GC(6) Clear Next Bitmap 0.379ms
[4.008s][info ][gc,heap ] GC(6) Eden regions: 0->0(7)
[4.008s][info ][gc,heap ] GC(6) Survivor regions: 0->0(0)
[4.008s][info ][gc,heap ] GC(6) Old regions: 4->3
[4.008s][info ][gc,heap ] GC(6) Archive regions: 0->0
[4.008s][info ][gc,heap ] GC(6) Humongous regions: 16->0
[4.008s][debug][gc,heap ] GC(6) Heap after GC invocations=6 (full 1): garbage-first heap total 20480K, used 2401K [0x00000000fec00000, 0x0000000100000000)
[4.008s][debug][gc,heap ] GC(6) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.008s][debug][gc,heap ] GC(6) Metaspace used 3795K, capacity 4858K, committed 5120K, reserved 1056768K
[4.008s][debug][gc,heap ] GC(6) class space used 386K, capacity 478K, committed 512K, reserved 1048576K
[4.008s][info ][gc ] GC(6) Pause Full (G1 Evacuation Pause) 20M->2M(20M) 121.288ms
[4.014s][info ][gc ] GC(3) Concurrent Cycle 161.880ms
[4.020s][debug][gc,ergo,ihop ] Request concurrent cycle initiation (occupancy higher than threshold) occupancy: 9437184B allocation request: 1000016B threshold: 9437184B (45.00) source: concurrent humongous allocation
[4.021s][debug][gc,ergo ] Request concurrent cycle initiation (requested by GC cause). GC cause: G1 Humongous Allocation
[4.021s][debug][gc,heap ] GC(7) Heap before GC invocations=6 (full 1): garbage-first heap total 20480K, used 8545K [0x00000000fec00000, 0x0000000100000000)
[4.021s][debug][gc,heap ] GC(7) region size 1024K, 1 young (1024K), 0 survivors (0K)
[4.021s][debug][gc,heap ] GC(7) Metaspace used 3796K, capacity 4858K, committed 5120K, reserved 1056768K
[4.021s][debug][gc,heap ] GC(7) class space used 386K, capacity 478K, committed 512K, reserved 1048576K
[4.021s][debug][gc,ergo ] GC(7) Initiate concurrent cycle (concurrent cycle initiation requested)
[4.021s][info ][gc,start ] GC(7) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[4.021s][debug][gc,ergo ] GC(7) Running G1 Merge Heap Roots using 4 workers for 1 regions
[4.025s][debug][gc,ergo ] GC(7) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 3 regions.
[4.033s][debug][gc,ergo ] GC(7) Running G1 Free Collection Set using 1 workers for collection set length 1
[4.034s][debug][gc,ergo,refine] GC(7) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 0.11ms HCC time: 0.01ms
[4.034s][debug][gc,ergo,refine] GC(7) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[4.034s][info ][gc,heap ] GC(7) Eden regions: 1->0(5)
[4.034s][info ][gc,heap ] GC(7) Survivor regions: 0->0(1)
[4.034s][info ][gc,heap ] GC(7) Old regions: 3->4
[4.034s][info ][gc,heap ] GC(7) Archive regions: 0->0
[4.034s][info ][gc,heap ] GC(7) Humongous regions: 6->6
[4.034s][debug][gc,heap ] GC(7) Heap after GC invocations=7 (full 1): garbage-first heap total 20480K, used 8548K [0x00000000fec00000, 0x0000000100000000)
[4.034s][debug][gc,heap ] GC(7) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.034s][debug][gc,heap ] GC(7) Metaspace used 3796K, capacity 4858K, committed 5120K, reserved 1056768K
[4.034s][debug][gc,heap ] GC(7) class space used 386K, capacity 478K, committed 512K, reserved 1048576K
[4.034s][info ][gc ] GC(7) Pause Young (Concurrent Start) (G1 Humongous Allocation) 8M->8M(20M) 13.225ms
[4.039s][info ][gc ] GC(8) Concurrent Cycle
[4.039s][debug][gc,ergo ] GC(8) Running G1 Root Region Scan using 1 workers for 1 work units.
[4.063s][info ][gc,start ] GC(8) Pause Remark
[4.090s][debug][gc,ergo ] GC(8) Running G1 Update RemSet Tracking Before Rebuild using 1 workers for 20 regions in heap
[4.090s][info ][gc ] GC(8) Pause Remark 15M->15M(20M) 27.832ms
[4.128s][info ][gc,start ] GC(8) Pause Cleanup
[4.129s][debug][gc,ergo ] GC(8) request mixed gcs (candidate old regions available). candidate old regions: 2 reclaimable: 692280 (3.30) threshold: 0
[4.129s][info ][gc ] GC(8) Pause Cleanup 17M->17M(20M) 0.372ms
[4.140s][debug][gc,ergo ] GC(8) Running G1 Clear Bitmap with 1 workers for 1 work units.
[4.141s][info ][gc ] GC(8) Concurrent Cycle 101.949ms
[4.210s][debug][gc,heap ] GC(9) Heap before GC invocations=8 (full 1): garbage-first heap total 20480K, used 16740K [0x00000000fec00000, 0x0000000100000000)
[4.210s][debug][gc,heap ] GC(9) region size 1024K, 3 young (3072K), 0 survivors (0K)
[4.210s][debug][gc,heap ] GC(9) Metaspace used 3925K, capacity 4915K, committed 5120K, reserved 1056768K
[4.210s][debug][gc,heap ] GC(9) class space used 402K, capacity 499K, committed 512K, reserved 1048576K
[4.210s][info ][gc,start ] GC(9) Pause Young (Prepare Mixed) (WhiteBox Initiated Young GC)
[4.211s][debug][gc,ergo ] GC(9) Running G1 Merge Heap Roots using 4 workers for 3 regions
[4.213s][debug][gc,ergo,heap ] GC(9) Attempt heap expansion (region allocation request failed). Allocation request: 20016B
[4.213s][debug][gc,ergo,heap ] GC(9) Expand the heap. requested expansion amount: 20016B expansion amount: 1048576B
[4.213s][debug][gc,ergo,heap ] GC(9) Did not expand the heap (heap already fully expanded)
[4.213s][debug][gc,ergo ] GC(9) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 7 regions.
[4.216s][debug][gc,ergo ] GC(9) Running G1 Free Collection Set using 1 workers for collection set length 3
[4.216s][debug][gc,ergo,refine] GC(9) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 0.36ms HCC time: 0.01ms
[4.216s][debug][gc,ergo,refine] GC(9) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[4.216s][info ][gc ] GC(9) To-space exhausted
[4.216s][info ][gc,heap ] GC(9) Eden regions: 3->0(1)
[4.216s][info ][gc,heap ] GC(9) Survivor regions: 0->0(0)
[4.216s][info ][gc,heap ] GC(9) Old regions: 4->6
[4.216s][info ][gc,heap ] GC(9) Archive regions: 0->0
[4.216s][info ][gc,heap ] GC(9) Humongous regions: 13->13
[4.217s][debug][gc,heap ] GC(9) Heap after GC invocations=9 (full 1): garbage-first heap total 20480K, used 18785K [0x00000000fec00000, 0x0000000100000000)
[4.217s][debug][gc,heap ] GC(9) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.217s][debug][gc,heap ] GC(9) Metaspace used 3925K, capacity 4915K, committed 5120K, reserved 1056768K
[4.217s][debug][gc,heap ] GC(9) class space used 402K, capacity 499K, committed 512K, reserved 1048576K
[4.217s][info ][gc ] GC(9) Pause Young (Prepare Mixed) (WhiteBox Initiated Young GC) 17M->18M(20M) 6.421ms
[4.223s][debug][gc,ergo ] Request concurrent cycle initiation (requested by GC cause). GC cause: WhiteBox Initiated Concurrent Mark
[4.224s][debug][gc,heap ] GC(10) Heap before GC invocations=9 (full 1): garbage-first heap total 20480K, used 18785K [0x00000000fec00000, 0x0000000100000000)
[4.224s][debug][gc,heap ] GC(10) region size 1024K, 1 young (1024K), 0 survivors (0K)
[4.224s][debug][gc,heap ] GC(10) Metaspace used 3940K, capacity 4917K, committed 5120K, reserved 1056768K
[4.224s][debug][gc,heap ] GC(10) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.224s][debug][gc,ergo ] GC(10) Initiate concurrent cycle (user requested concurrent cycle)
[4.224s][info ][gc,start ] GC(10) Pause Young (Concurrent Start) (WhiteBox Initiated Concurrent Mark)
[4.224s][debug][gc,ergo ] GC(10) Running G1 Merge Heap Roots using 4 workers for 1 regions
[4.225s][debug][gc,ergo,heap ] GC(10) Attempt heap expansion (region allocation request failed). Allocation request: 2064B
[4.225s][debug][gc,ergo,heap ] GC(10) Expand the heap. requested expansion amount: 2064B expansion amount: 1048576B
[4.225s][debug][gc,ergo,heap ] GC(10) Did not expand the heap (heap already fully expanded)
[4.226s][debug][gc,ergo ] GC(10) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 5 regions.
[4.228s][debug][gc,ergo ] GC(10) Running G1 Free Collection Set using 1 workers for collection set length 1
[4.229s][debug][gc,ergo,refine] GC(10) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 0.33ms HCC time: 0.01ms
[4.229s][debug][gc,ergo,refine] GC(10) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[4.229s][info ][gc ] GC(10) To-space exhausted
[4.229s][info ][gc,heap ] GC(10) Eden regions: 1->0(1)
[4.229s][info ][gc,heap ] GC(10) Survivor regions: 0->0(0)
[4.229s][info ][gc,heap ] GC(10) Old regions: 6->7
[4.229s][info ][gc,heap ] GC(10) Archive regions: 0->0
[4.229s][info ][gc,heap ] GC(10) Humongous regions: 13->13
[4.229s][debug][gc,heap ] GC(10) Heap after GC invocations=10 (full 1): garbage-first heap total 20480K, used 18804K [0x00000000fec00000, 0x0000000100000000)
[4.229s][debug][gc,heap ] GC(10) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.229s][debug][gc,heap ] GC(10) Metaspace used 3940K, capacity 4917K, committed 5120K, reserved 1056768K
[4.229s][debug][gc,heap ] GC(10) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.229s][info ][gc ] GC(10) Pause Young (Concurrent Start) (WhiteBox Initiated Concurrent Mark) 18M->18M(20M) 5.453ms
[4.230s][info ][gc ] GC(11) Concurrent Cycle
[4.241s][debug][gc,heap ] GC(12) Heap before GC invocations=10 (full 1): garbage-first heap total 20480K, used 18804K [0x00000000fec00000, 0x0000000100000000)
[4.241s][debug][gc,heap ] GC(12) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.241s][debug][gc,heap ] GC(12) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.241s][debug][gc,heap ] GC(12) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.241s][info ][gc,start ] GC(12) Pause Young (Normal) (G1 Evacuation Pause)
[4.242s][debug][gc,ergo ] GC(12) Running G1 Merge Heap Roots using 4 workers for 0 regions
[4.244s][debug][gc,ergo ] GC(12) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 5 regions.
[4.245s][debug][gc,ergo ] GC(12) Running G1 Free Collection Set using 1 workers for collection set length 0
[4.246s][debug][gc,ergo,refine] GC(12) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 0.46ms HCC time: 0.01ms
[4.246s][debug][gc,ergo,refine] GC(12) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[4.246s][info ][gc,heap ] GC(12) Eden regions: 0->0(1)
[4.246s][info ][gc,heap ] GC(12) Survivor regions: 0->0(0)
[4.246s][info ][gc,heap ] GC(12) Old regions: 7->7
[4.246s][info ][gc,heap ] GC(12) Archive regions: 0->0
[4.246s][info ][gc,heap ] GC(12) Humongous regions: 13->13
[4.246s][debug][gc,heap ] GC(12) Heap after GC invocations=11 (full 1): garbage-first heap total 20480K, used 18804K [0x00000000fec00000, 0x0000000100000000)
[4.246s][debug][gc,heap ] GC(12) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.246s][debug][gc,heap ] GC(12) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.246s][debug][gc,heap ] GC(12) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.246s][info ][gc ] GC(12) Pause Young (Normal) (G1 Evacuation Pause) 18M->18M(20M) 5.062ms
[4.246s][debug][gc,ergo,heap ] Attempt heap expansion (allocation request failed). Allocation request: 2648B
[4.246s][debug][gc,ergo,heap ] Expand the heap. requested expansion amount: 1048576B expansion amount: 1048576B
[4.247s][debug][gc,ergo,heap ] Did not expand the heap (heap already fully expanded)
[4.248s][info ][gc,start ] GC(13) Pause Full (G1 Evacuation Pause)
[4.248s][debug][gc,heap ] GC(13) Heap before GC invocations=11 (full 1): garbage-first heap total 20480K, used 18804K [0x00000000fec00000, 0x0000000100000000)
[4.248s][debug][gc,heap ] GC(13) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.248s][debug][gc,heap ] GC(13) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.248s][debug][gc,heap ] GC(13) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.249s][debug][gc,start ] GC(13) Clear Next Bitmap
[4.249s][debug][gc,ergo ] GC(13) Running G1 Clear Bitmap with 1 workers for 1 work units.
[4.249s][debug][gc ] GC(13) Clear Next Bitmap 0.300ms
[4.364s][info ][gc,heap ] GC(13) Eden regions: 0->0(8)
[4.364s][info ][gc,heap ] GC(13) Survivor regions: 0->0(0)
[4.364s][info ][gc,heap ] GC(13) Old regions: 7->4
[4.364s][info ][gc,heap ] GC(13) Archive regions: 0->0
[4.364s][info ][gc,heap ] GC(13) Humongous regions: 13->0
[4.364s][debug][gc,heap ] GC(13) Heap after GC invocations=12 (full 2): garbage-first heap total 20480K, used 3433K [0x00000000fec00000, 0x0000000100000000)
[4.364s][debug][gc,heap ] GC(13) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.364s][debug][gc,heap ] GC(13) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.364s][debug][gc,heap ] GC(13) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.364s][info ][gc ] GC(13) Pause Full (G1 Evacuation Pause) 18M->3M(20M) 115.662ms
[4.366s][info ][gc ] GC(11) Concurrent Cycle 136.255ms
[4.377s][debug][gc,heap ] GC(14) Heap before GC invocations=12 (full 2): garbage-first heap total 20480K, used 3433K [0x00000000fec00000, 0x0000000100000000)
[4.377s][debug][gc,heap ] GC(14) region size 1024K, 1 young (1024K), 0 survivors (0K)
[4.377s][debug][gc,heap ] GC(14) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.377s][debug][gc,heap ] GC(14) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.378s][info ][gc,start ] GC(14) Pause Young (Normal) (WhiteBox Initiated Young GC)
[4.378s][debug][gc,ergo ] GC(14) Running G1 Merge Heap Roots using 4 workers for 1 regions
[4.379s][debug][gc,ergo ] GC(14) Running G1 Clear Card Table Task using 1 workers for 1 units of work for 3 regions.
[4.380s][debug][gc,ergo ] GC(14) Running G1 Free Collection Set using 1 workers for collection set length 1
[4.381s][debug][gc,ergo,refine] GC(14) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: 0.11ms HCC time: 0.01ms
[4.381s][debug][gc,ergo,refine] GC(14) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[4.381s][info ][gc,heap ] GC(14) Eden regions: 1->0(9)
[4.381s][info ][gc,heap ] GC(14) Survivor regions: 0->0(1)
[4.381s][info ][gc,heap ] GC(14) Old regions: 4->4
[4.381s][info ][gc,heap ] GC(14) Archive regions: 0->0
[4.381s][info ][gc,heap ] GC(14) Humongous regions: 0->0
[4.381s][debug][gc,heap ] GC(14) Heap after GC invocations=13 (full 2): garbage-first heap total 20480K, used 3433K [0x00000000fec00000, 0x0000000100000000)
[4.381s][debug][gc,heap ] GC(14) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.381s][debug][gc,heap ] GC(14) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.381s][debug][gc,heap ] GC(14) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.381s][info ][gc ] GC(14) Pause Young (Normal) (WhiteBox Initiated Young GC) 3M->3M(20M) 3.779ms
[4.382s][debug][gc,heap ] GC(15) Heap before GC invocations=13 (full 2): garbage-first heap total 20480K, used 3433K [0x00000000fec00000, 0x0000000100000000)
[4.382s][debug][gc,heap ] GC(15) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.382s][debug][gc,heap ] GC(15) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.382s][debug][gc,heap ] GC(15) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.382s][info ][gc,start ] GC(15) Pause Young (Normal) (WhiteBox Initiated Young GC)
[4.382s][debug][gc,ergo ] GC(15) Running G1 Merge Heap Roots using 4 workers for 0 regions
[4.385s][debug][gc,ergo ] GC(15) Running G1 Free Collection Set using 1 workers for collection set length 0
[4.385s][debug][gc,ergo,refine] GC(15) Concurrent refinement times: Logged Cards Scan time goal: 19.99ms Logged Cards Scan time: -nan(ind)ms HCC time: 0.01ms
[4.385s][debug][gc,ergo,refine] GC(15) Updated Refinement Zones: green: 3328, yellow: 9984, red: 16640
[4.385s][info ][gc,heap ] GC(15) Eden regions: 0->0(9)
[4.385s][info ][gc,heap ] GC(15) Survivor regions: 0->0(2)
[4.385s][info ][gc,heap ] GC(15) Old regions: 4->4
[4.385s][info ][gc,heap ] GC(15) Archive regions: 0->0
[4.385s][info ][gc,heap ] GC(15) Humongous regions: 0->0
[4.385s][debug][gc,heap ] GC(15) Heap after GC invocations=14 (full 2): garbage-first heap total 20480K, used 3433K [0x00000000fec00000, 0x0000000100000000)
[4.385s][debug][gc,heap ] GC(15) region size 1024K, 0 young (0K), 0 survivors (0K)
[4.385s][debug][gc,heap ] GC(15) Metaspace used 3943K, capacity 4917K, committed 5120K, reserved 1056768K
[4.385s][debug][gc,heap ] GC(15) class space used 402K, capacity 501K, committed 512K, reserved 1048576K
[4.386s][info ][gc ] GC(15) Pause Young (Normal) (WhiteBox Initiated Young GC) 3M->3M(20M) 3.746ms
[5.804s][info ][gc,heap,exit ] Heap
[5.804s][info ][gc,heap,exit ] garbage-first heap total 20480K, used 7529K [0x00000000fec00000, 0x0000000100000000)
[5.804s][info ][gc,heap,exit ] region size 1024K, 5 young (5120K), 0 survivors (0K)
[5.804s][info ][gc,heap,exit ] Metaspace used 4942K, capacity 5181K, committed 5248K, reserved 1056768K
[5.804s][info ][gc,heap,exit ] class space used 511K, capacity 594K, committed 640K, reserved 1048576K