The following test failed in the JDK25 CI:
gc/z/TestUncommit.java
Here's a snippet from the log file:
#section:main
----------messages:(7/436)----------
command: main -XX:+UseZGC -Xlog:gc*,gc+heap=debug,gc+stats=off -Xms128M -Xmx512M -XX:ZUncommitDelay=5 gc.z.TestUncommit
reason: User specified action: run main/othervm -XX:+UseZGC -Xlog:gc*,gc+heap=debug,gc+stats=off -Xms128M -Xmx512M -XX:ZUncommitDelay=5 gc.z.TestUncommit
started: Fri Jul 04 09:27:02 GMT 2025
Mode: othervm [/othervm specified]
Process id: 65665
finished: Fri Jul 04 09:27:43 GMT 2025
elapsed time (seconds): 40.521
----------configuration:(0/0)----------
----------System.out:(324/29822)----------
[0.017s][debug][gc,heap] Minimum heap 134217728 Initial heap 134217728 Maximum heap 536870912
[0.017s][info ][gc,init] Initializing The Z Garbage Collector
[0.017s][info ][gc,init] Version: 25-ea+30-LTS-3418 (fastdebug)
[0.017s][info ][gc,init] NUMA Support: Disabled
[0.017s][info ][gc,init] CPUs: 8 total, 8 available
[0.017s][info ][gc,init] Memory: 16384M
[0.017s][info ][gc,init] Large Page Support: Disabled
[0.017s][info ][gc,init] Address Space Size: unlimited
[0.017s][info ][gc,init] Reserved Space Type: Contiguous/Unrestricted/Complete
[0.017s][info ][gc,init] Reserved Space Size: 8G
[0.017s][info ][gc,init] Min Capacity: 128M
[0.017s][info ][gc,init] Initial Capacity: 128M
[0.017s][info ][gc,init] Max Capacity: 512M
[0.017s][info ][gc,init] Soft Max Capacity: 512M
[0.017s][info ][gc,init] Page Size Medium: Range [2M, 16M]
[0.017s][info ][gc,init] Pre-touch: Disabled
[0.018s][info ][gc,init] Uncommit: Enabled
[0.018s][info ][gc,init] Uncommit Delay: 5s
[0.018s][info ][gc,init] GC Workers for Old Generation: 2 (dynamic)
[0.018s][info ][gc,init] GC Workers for Young Generation: 2 (dynamic)
[0.018s][info ][gc,init] GC Workers Max: 2 (dynamic)
[0.018s][info ][gc,init] Runtime Workers: 5
[0.018s][info ][gc ] Using The Z Garbage Collector
[0.035s][info ][gc,metaspace] CDS archive(s) mapped at: [0x0000000700000000-0x0000000700e74000-0x0000000700e74000), size 15155200, SharedBaseAddress: 0x0000000700000000, ArchiveRelocationMode: 1.
[0.035s][info ][gc,metaspace] Compressed class space mapped at: 0x0000000701000000-0x0000000741000000, reserved size: 1073741824
[0.035s][info ][gc,metaspace] UseCompressedClassPointers 1, UseCompactObjectHeaders 0
[0.035s][info ][gc,metaspace] Narrow klass pointer bits 32, Max shift 3
[0.035s][info ][gc,metaspace] Narrow klass base: 0x0000000700000000, Narrow klass shift: 0
[0.035s][info ][gc,metaspace] Encoding Range: [0x0000000700000000 - 0x0000000800000000), (4294967296 bytes)
[0.035s][info ][gc,metaspace] Klass Range: [0x0000000700004000 - 0x0000000741000000), (1090502656 bytes)
[0.035s][info ][gc,metaspace] Klass ID Range: [16384 - 1090519033) (1090502649)
[0.035s][info ][gc,metaspace] Protection zone: [0x0000000700000000 - 0x0000000700004000), (16384 bytes)
[0.060s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[5.200s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 0ms
[5.200s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[5.200s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[10.348s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[10.348s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[3.383s] (MainThread) Iteration 0
[15.453s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[15.453s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[7.050s] (MainThread) Allocating
[15.484s][info ][gc ] GC(0) Major Collection (Warmup)
[15.484s][info ][gc,task ] GC(0) Using 2 Workers for Young Generation
[15.484s][info ][gc,task ] GC(0) Using 1 Workers for Old Generation
[15.484s][debug][gc,heap ] GC(0) Y: Heap Before GC invocations=0 (full 0):
[15.484s][debug][gc,heap ] GC(0) Y: ZHeap used 54M, capacity 128M, max capacity 512M
[15.484s][debug][gc,heap ] GC(0) Y: Cache 74M (1)
[15.484s][debug][gc,heap ] GC(0) Y: size classes 64M (1)
[15.484s][info ][gc,phases ] GC(0) Y: Young Generation
[15.486s][info ][gc,phases ] GC(0) Y: Pause Mark Start (Major) 0.270ms
[7.211s] (MainThread) Reclaiming
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Mark 1028.605ms
[16.515s][info ][gc,phases ] GC(0) Y: Pause Mark End 0.009ms
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Mark Free 0.001ms
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Reset Relocation Set 0.000ms
[16.515s][info ][gc,reloc ] GC(0) Y: Using tenuring threshold: 1 (Computed)
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Select Relocation Set 0.130ms
[16.516s][info ][gc,phases ] GC(0) Y: Pause Relocate Start 0.006ms
[16.516s][info ][gc,phases ] GC(0) Y: Concurrent Relocate 0.104ms
[16.516s][debug][gc,heap ] GC(0) Y: Heap After GC invocations=1 (full 1):
[16.516s][debug][gc,heap ] GC(0) Y: ZHeap used 224M, capacity 224M, max capacity 512M
[16.516s][debug][gc,heap ] GC(0) Y: Cache 0M (0)
[16.516s][info ][gc,alloc ] GC(0) Y: Mark Start Mark End Relocate Start Relocate End
[16.516s][info ][gc,alloc ] GC(0) Y: Allocation Stalls: 0 0 0 0
[16.516s][info ][gc,load ] GC(0) Y: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[16.516s][info ][gc,mmu ] GC(0) Y: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[16.516s][info ][gc,marking ] GC(0) Y: Mark: 2 stripe(s), 9 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[16.516s][info ][gc,nmethod ] GC(0) Y: NMethods: 7112 registered, 0 unregistered
[16.516s][info ][gc,metaspace] GC(0) Y: Metaspace: 3M used, 3M committed, 1088M reserved
[16.516s][info ][gc,reloc ] GC(0) Y: Candidates Selected In-Place Size Empty Relocated
[16.516s][info ][gc,reloc ] GC(0) Y: Small Pages: 27 0 0 54M 0M 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Medium Pages: 0 0 0 0M 0M 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Large Pages: 0 0 0 0M 0M 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Forwarding Usage: 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Age Table:
[16.516s][info ][gc,reloc ] GC(0) Y: Live Garbage Small Medium Large
[16.516s][info ][gc,reloc ] GC(0) Y: Eden 50M (10%) 3M (1%) 27 / 0 0 / 0 0 / 0
[16.516s][info ][gc,heap ] GC(0) Y: Min Capacity: 128M(25%)
[16.516s][info ][gc,heap ] GC(0) Y: Max Capacity: 512M(100%)
[16.516s][info ][gc,heap ] GC(0) Y: Soft Max Capacity: 512M(100%)
[16.516s][info ][gc,heap ] GC(0) Y: Heap Statistics:
[16.516s][info ][gc,heap ] GC(0) Y: Mark Start Mark End Relocate Start Relocate End High Low
[16.516s][info ][gc,heap ] GC(0) Y: Capacity: 128M (25%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 128M (25%)
[16.516s][info ][gc,heap ] GC(0) Y: Free: 458M (89%) 288M (56%) 288M (56%) 288M (56%) 458M (89%) 288M (56%)
[16.516s][info ][gc,heap ] GC(0) Y: Used: 54M (11%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 54M (11%)
[16.516s][info ][gc,heap ] GC(0) Y: Young Generation Statistics:
[16.516s][info ][gc,heap ] GC(0) Y: Mark Start Mark End Relocate Start Relocate End
[16.516s][info ][gc,heap ] GC(0) Y: Used: 54M (11%) 224M (44%) 224M (44%) 224M (44%)
[16.516s][info ][gc,heap ] GC(0) Y: Live: - 50M (10%) 50M (10%) 50M (10%)
[16.516s][info ][gc,heap ] GC(0) Y: Garbage: - 3M (1%) 3M (1%) 3M (1%)
[16.516s][info ][gc,heap ] GC(0) Y: Allocated: - 170M (33%) 170M (33%) 170M (33%)
[16.516s][info ][gc,heap ] GC(0) Y: Reclaimed: - - 0M (0%) 0M (0%)
[16.516s][info ][gc,heap ] GC(0) Y: Promoted: - - 0M (0%) 0M (0%)
[16.516s][info ][gc,heap ] GC(0) Y: Compacted: - - - 0M (0%)
[16.516s][info ][gc,phases ] GC(0) Y: Young Generation 54M(11%)->224M(44%) 1.031s
[16.516s][debug][gc,heap ] GC(0) O: Heap Before GC invocations=1 (full 1):
[16.516s][debug][gc,heap ] GC(0) O: ZHeap used 224M, capacity 224M, max capacity 512M
[16.516s][debug][gc,heap ] GC(0) O: Cache 0M (0)
[16.516s][info ][gc,phases ] GC(0) O: Old Generation
[16.516s][info ][gc,phases ] GC(0) O: Concurrent Mark 0.162ms
[16.516s][info ][gc,phases ] GC(0) O: Pause Mark End 0.057ms
[16.516s][info ][gc,phases ] GC(0) O: Concurrent Mark Free 0.000ms
[20.452s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 95ms
[20.452s][debug][gc,heap ] Uncommitter (0) Timeout: 95ms
[20.559s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[20.559s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[20.774s][info ][gc,phases ] GC(0) O: Concurrent Process Non-Strong 4257.458ms
[20.774s][info ][gc,phases ] GC(0) O: Concurrent Reset Relocation Set 0.000ms
[20.779s][info ][gc,phases ] GC(0) O: Concurrent Select Relocation Set 0.329ms
[20.779s][info ][gc,task ] GC(0) O: Using 2 Workers for Old Generation
[20.791s][info ][gc,task ] GC(0) O: Using 1 Workers for Old Generation
[20.791s][info ][gc,phases ] GC(0) O: Concurrent Remap Roots 12.545ms
[20.792s][info ][gc,phases ] GC(0) O: Pause Relocate Start 0.054ms
[20.792s][info ][gc,phases ] GC(0) O: Concurrent Relocate 0.051ms
[20.792s][debug][gc,heap ] GC(0) O: Heap After GC invocations=1 (full 1):
[20.792s][debug][gc,heap ] GC(0) O: ZHeap used 224M, capacity 224M, max capacity 512M
[20.792s][debug][gc,heap ] GC(0) O: Cache 0M (0)
[20.792s][info ][gc,alloc ] GC(0) O: Mark Start Mark End Relocate Start Relocate End
[20.792s][info ][gc,alloc ] GC(0) O: Allocation Stalls: 0 0 0 0
[20.792s][info ][gc,load ] GC(0) O: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.792s][info ][gc,mmu ] GC(0) O: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.792s][info ][gc,marking ] GC(0) O: Mark: 1 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.792s][info ][gc,nmethod ] GC(0) O: NMethods: 3252 registered, 3860 unregistered
[20.792s][info ][gc,metaspace] GC(0) O: Metaspace: 3M used, 3M committed, 1088M reserved
[20.792s][info ][gc,ref ] GC(0) O: Encountered Discovered Enqueued
[20.792s][info ][gc,ref ] GC(0) O: Soft References: 90 0 0
[20.792s][info ][gc,ref ] GC(0) O: Weak References: 121 0 0
[20.792s][info ][gc,ref ] GC(0) O: Final References: 0 0 0
[20.792s][info ][gc,ref ] GC(0) O: Phantom References: 5 0 0
[20.792s][info ][gc,heap ] GC(0) O: Min Capacity: 128M(25%)
[20.792s][info ][gc,heap ] GC(0) O: Max Capacity: 512M(100%)
[20.792s][info ][gc,heap ] GC(0) O: Soft Max Capacity: 512M(100%)
[20.792s][info ][gc,heap ] GC(0) O: Heap Statistics:
[20.792s][info ][gc,heap ] GC(0) O: Mark Start Mark End Relocate Start Relocate End High Low
[20.792s][info ][gc,heap ] GC(0) O: Capacity: 128M (25%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 128M (25%)
[20.792s][info ][gc,heap ] GC(0) O: Free: 458M (89%) 288M (56%) 288M (56%) 288M (56%) 458M (89%) 288M (56%)
[20.792s][info ][gc,heap ] GC(0) O: Used: 54M (11%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 54M (11%)
[20.792s][info ][gc,heap ] GC(0) O: Old Generation Statistics:
[20.792s][info ][gc,heap ] GC(0) O: Mark Start Mark End Relocate Start Relocate End
[20.792s][info ][gc,heap ] GC(0) O: Used: 0M (0%) 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Live: - 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Garbage: - 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Allocated: - 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Reclaimed: - - 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Compacted: - - - 0M (0%)
[20.792s][info ][gc,phases ] GC(0) O: Old Generation 224M(44%)->224M(44%) 4.276s
[20.792s][info ][gc ] GC(0) Major Collection (Warmup) 54M(11%)->224M(44%) 5.308s
[20.792s][info ][gc ] GC(1) Major Collection (System.gc())
[20.792s][info ][gc,task ] GC(1) Using 2 Workers for Young Generation
[20.792s][info ][gc,task ] GC(1) Using 2 Workers for Old Generation
[20.792s][debug][gc,heap ] GC(1) Y: Heap Before GC invocations=1 (full 1):
[20.792s][debug][gc,heap ] GC(1) Y: ZHeap used 224M, capacity 224M, max capacity 512M
[20.792s][debug][gc,heap ] GC(1) Y: Cache 0M (0)
[20.792s][info ][gc,phases ] GC(1) Y: Young Generation (Promote All)
[20.792s][info ][gc,phases ] GC(1) Y: Pause Mark Start 0.016ms
[20.801s][info ][gc,phases ] GC(1) Y: Concurrent Mark 8.420ms
[20.801s][info ][gc,phases ] GC(1) Y: Pause Mark End 0.006ms
[20.801s][info ][gc,phases ] GC(1) Y: Concurrent Mark Free 0.002ms
[20.801s][info ][gc,phases ] GC(1) Y: Concurrent Reset Relocation Set 0.000ms
[20.801s][info ][gc,reloc ] GC(1) Y: Using tenuring threshold: 0 (Promote All)
[20.805s][info ][gc,phases ] GC(1) Y: Concurrent Select Relocation Set 3.885ms
[20.805s][info ][gc,phases ] GC(1) Y: Pause Relocate Start 0.014ms
[20.812s][info ][gc,phases ] GC(1) Y: Concurrent Relocate 7.426ms
[20.812s][debug][gc,heap ] GC(1) Y: Heap After GC invocations=2 (full 1):
[20.812s][debug][gc,heap ] GC(1) Y: ZHeap used 4M, capacity 224M, max capacity 512M
[20.812s][debug][gc,heap ] GC(1) Y: Cache 220M (2)
[20.812s][debug][gc,heap ] GC(1) Y: size classes 4M (1), 128M (1)
[20.812s][info ][gc,alloc ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.812s][info ][gc,alloc ] GC(1) Y: Allocation Stalls: 0 0 0 0
[20.812s][info ][gc,load ] GC(1) Y: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.812s][info ][gc,mmu ] GC(1) Y: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.812s][info ][gc,marking ] GC(1) Y: Mark: 2 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.812s][info ][gc,nmethod ] GC(1) Y: NMethods: 3252 registered, 3860 unregistered
[20.812s][info ][gc,metaspace] GC(1) Y: Metaspace: 3M used, 3M committed, 1088M reserved
[20.812s][info ][gc,reloc ] GC(1) Y: Candidates Selected In-Place Size Empty Relocated
[20.812s][info ][gc,reloc ] GC(1) Y: Small Pages: 104 1 0 208M 204M 1M
[20.812s][info ][gc,reloc ] GC(1) Y: Medium Pages: 1 0 0 16M 16M 0M
[20.812s][info ][gc,reloc ] GC(1) Y: Large Pages: 0 0 0 0M 0M 0M
[20.812s][info ][gc,reloc ] GC(1) Y: Forwarding Usage: 0M
[20.812s][info ][gc,reloc ] GC(1) Y: Age Table:
[20.813s][info ][gc,reloc ] GC(1) Y: Live Garbage Small Medium Large
[20.813s][info ][gc,reloc ] GC(1) Y: Eden - 170M (33%) 77 / 0 1 / 0 0 / 0
[20.813s][info ][gc,reloc ] GC(1) Y: Survivor 1 1M (0%) 52M (10%) 27 / 1 0 / 0 0 / 0
[20.813s][info ][gc,heap ] GC(1) Y: Min Capacity: 128M(25%)
[20.813s][info ][gc,heap ] GC(1) Y: Max Capacity: 512M(100%)
[20.813s][info ][gc,heap ] GC(1) Y: Soft Max Capacity: 512M(100%)
[20.813s][info ][gc,heap ] GC(1) Y: Heap Statistics:
[20.813s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End High Low
[20.813s][info ][gc,heap ] GC(1) Y: Capacity: 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%)
[20.813s][info ][gc,heap ] GC(1) Y: Free: 288M (56%) 288M (56%) 508M (99%) 508M (99%) 508M (99%) 288M (56%)
[20.813s][info ][gc,heap ] GC(1) Y: Used: 224M (44%) 224M (44%) 4M (1%) 4M (1%) 224M (44%) 4M (1%)
[20.813s][info ][gc,heap ] GC(1) Y: Young Generation Statistics:
[20.813s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.813s][info ][gc,heap ] GC(1) Y: Used: 224M (44%) 224M (44%) 4M (1%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Live: - 1M (0%) 1M (0%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Garbage: - 222M (43%) 2M (0%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Allocated: - 0M (0%) 0M (0%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Reclaimed: - - 220M (43%) 222M (43%)
[20.813s][info ][gc,heap ] GC(1) Y: Promoted: - - 0M (0%) 1M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Compacted: - - - 0M (0%)
[20.813s][info ][gc,phases ] GC(1) Y: Young Generation (Promote All) 224M(44%)->4M(1%) 0.020s
[20.813s][debug][gc,heap ] GC(1) Y: Heap Before GC invocations=2 (full 1):
[20.813s][debug][gc,heap ] GC(1) Y: ZHeap used 4M, capacity 224M, max capacity 512M
[20.813s][debug][gc,heap ] GC(1) Y: Cache 220M (2)
[20.813s][debug][gc,heap ] GC(1) Y: size classes 4M (1), 128M (1)
[20.813s][info ][gc,phases ] GC(1) Y: Young Generation (Collect Roots)
[20.813s][info ][gc,phases ] GC(1) Y: Pause Mark Start (Major) 0.012ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Mark 5.096ms
[20.818s][info ][gc,phases ] GC(1) Y: Pause Mark End 0.005ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Mark Free 0.001ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Reset Relocation Set 0.001ms
[20.818s][info ][gc,reloc ] GC(1) Y: Using tenuring threshold: 0 (Computed)
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Select Relocation Set 0.064ms
[20.818s][info ][gc,phases ] GC(1) Y: Pause Relocate Start 0.016ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Relocate 0.031ms
[20.818s][debug][gc,heap ] GC(1) Y: Heap After GC invocations=3 (full 2):
[20.818s][debug][gc,heap ] GC(1) Y: ZHeap used 4M, capacity 224M, max capacity 512M
[20.818s][debug][gc,heap ] GC(1) Y: Cache 220M (2)
[20.818s][debug][gc,heap ] GC(1) Y: size classes 4M (1), 128M (1)
[20.818s][info ][gc,alloc ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.818s][info ][gc,alloc ] GC(1) Y: Allocation Stalls: 0 0 0 0
[20.818s][info ][gc,load ] GC(1) Y: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.818s][info ][gc,mmu ] GC(1) Y: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.818s][info ][gc,marking ] GC(1) Y: Mark: 2 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.818s][info ][gc,nmethod ] GC(1) Y: NMethods: 3252 registered, 3860 unregistered
[20.818s][info ][gc,metaspace] GC(1) Y: Metaspace: 3M used, 3M committed, 1088M reserved
[20.818s][info ][gc,heap ] GC(1) Y: Min Capacity: 128M(25%)
[20.818s][info ][gc,heap ] GC(1) Y: Max Capacity: 512M(100%)
[20.818s][info ][gc,heap ] GC(1) Y: Soft Max Capacity: 512M(100%)
[20.818s][info ][gc,heap ] GC(1) Y: Heap Statistics:
[20.818s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End High Low
[20.818s][info ][gc,heap ] GC(1) Y: Capacity: 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%)
[20.818s][info ][gc,heap ] GC(1) Y: Free: 508M (99%) 508M (99%) 508M (99%) 508M (99%) 508M (99%) 508M (99%)
[20.818s][info ][gc,heap ] GC(1) Y: Used: 4M (1%) 4M (1%) 4M (1%) 4M (1%) 4M (1%) 4M (1%)
[20.818s][info ][gc,heap ] GC(1) Y: Young Generation Statistics:
[20.818s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.818s][info ][gc,heap ] GC(1) Y: Used: 0M (0%) 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Live: - 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Garbage: - 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Allocated: - 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Reclaimed: - - 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Promoted: - - 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Compacted: - - - 0M (0%)
[20.818s][info ][gc,phases ] GC(1) Y: Young Generation (Collect Roots) 4M(1%)->4M(1%) 0.006s
[20.818s][debug][gc,heap ] GC(1) O: Heap Before GC invocations=3 (full 2):
[20.818s][debug][gc,heap ] GC(1) O: ZHeap used 4M, capacity 224M, max capacity 512M
[20.818s][debug][gc,heap ] GC(1) O: Cache 220M (2)
[20.818s][debug][gc,heap ] GC(1) O: size classes 4M (1), 128M (1)
[20.818s][info ][gc,phases ] GC(1) O: Old Generation
[20.823s][info ][gc,phases ] GC(1) O: Concurrent Mark 4.943ms
[20.824s][info ][gc,phases ] GC(1) O: Pause Mark End 0.058ms
[20.824s][info ][gc,phases ] GC(1) O: Concurrent Mark Free 0.003ms
[20.838s][info ][gc,phases ] GC(1) O: Concurrent Process Non-Strong 14.293ms
[20.838s][info ][gc,phases ] GC(1) O: Concurrent Reset Relocation Set 0.000ms
[20.839s][info ][gc,phases ] GC(1) O: Concurrent Select Relocation Set 0.190ms
[20.839s][info ][gc,task ] GC(1) O: Using 2 Workers for Old Generation
[20.843s][info ][gc,task ] GC(1) O: Using 2 Workers for Old Generation
[20.843s][info ][gc,phases ] GC(1) O: Concurrent Remap Roots 4.278ms
[20.843s][info ][gc,phases ] GC(1) O: Pause Relocate Start 0.017ms
[20.848s][info ][gc,phases ] GC(1) O: Concurrent Relocate 4.722ms
[20.848s][debug][gc,heap ] GC(1) O: Heap After GC invocations=3 (full 2):
[20.848s][debug][gc,heap ] GC(1) O: ZHeap used 6M, capacity 224M, max capacity 512M
[20.848s][debug][gc,heap ] GC(1) O: Cache 218M (2)
[20.848s][debug][gc,heap ] GC(1) O: size classes 4M (1), 128M (1)
[20.848s][info ][gc,alloc ] GC(1) O: Mark Start Mark End Relocate Start Relocate End
[20.848s][info ][gc,alloc ] GC(1) O: Allocation Stalls: 0 0 0 0
[20.848s][info ][gc,load ] GC(1) O: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.848s][info ][gc,mmu ] GC(1) O: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.848s][info ][gc,marking ] GC(1) O: Mark: 2 stripe(s), 2 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.848s][info ][gc,nmethod ] GC(1) O: NMethods: 3245 registered, 0 unregistered
[20.848s][info ][gc,metaspace] GC(1) O: Metaspace: 3M used, 3M committed, 1088M reserved
[20.848s][info ][gc,ref ] GC(1) O: Encountered Discovered Enqueued
[20.848s][info ][gc,ref ] GC(1) O: Soft References: 90 0 0
[20.848s][info ][gc,ref ] GC(1) O: Weak References: 121 22 11
[20.848s][info ][gc,ref ] GC(1) O: Final References: 0 0 0
[20.848s][info ][gc,ref ] GC(1) O: Phantom References: 5 3 0
[20.848s][info ][gc,reloc ] GC(1) O: Candidates Selected In-Place Size Empty Relocated
[20.848s][info ][gc,reloc ] GC(1) O: Small Pages: 2 1 0 4M 0M 1M
[20.848s][info ][gc,reloc ] GC(1) O: Medium Pages: 0 0 0 0M 0M 0M
[20.848s][info ][gc,reloc ] GC(1) O: Large Pages: 0 0 0 0M 0M 0M
[20.848s][info ][gc,reloc ] GC(1) O: Forwarding Usage: 0M
[20.848s][info ][gc,heap ] GC(1) O: Min Capacity: 128M(25%)
[20.848s][info ][gc,heap ] GC(1) O: Max Capacity: 512M(100%)
[20.848s][info ][gc,heap ] GC(1) O: Soft Max Capacity: 512M(100%)
[20.848s][info ][gc,heap ] GC(1) O: Heap Statistics:
[20.848s][info ][gc,heap ] GC(1) O: Mark Start Mark End Relocate Start Relocate End High Low
[20.848s][info ][gc,heap ] GC(1) O: Capacity: 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%)
[20.848s][info ][gc,heap ] GC(1) O: Free: 508M (99%) 508M (99%) 508M (99%) 506M (99%) 508M (99%) 502M (98%)
[20.848s][info ][gc,heap ] GC(1) O: Used: 4M (1%) 4M (1%) 4M (1%) 6M (1%) 10M (2%) 4M (1%)
[20.848s][info ][gc,heap ] GC(1) O: Old Generation Statistics:
[20.848s][info ][gc,heap ] GC(1) O: Mark Start Mark End Relocate Start Relocate End
[20.848s][info ][gc,heap ] GC(1) O: Used: 4M (1%) 4M (1%) 4M (1%) 6M (1%)
[20.848s][info ][gc,heap ] GC(1) O: Live: - 1M (0%) 1M (0%) 1M (0%)
[20.848s][info ][gc,heap ] GC(1) O: Garbage: - 2M (0%) 2M (0%) 0M (0%)
[20.848s][info ][gc,heap ] GC(1) O: Allocated: - 0M (0%) 0M (0%) 4M (1%)
[20.848s][info ][gc,heap ] GC(1) O: Reclaimed: - - 0M (0%) 2M (0%)
[20.848s][info ][gc,heap ] GC(1) O: Compacted: - - - 1M (0%)
[20.848s][info ][gc,phases ] GC(1) O: Old Generation 4M(1%)->6M(1%) 0.030s
[20.848s][info ][gc ] GC(1) Major Collection (System.gc()) 224M(44%)->6M(1%) 0.056s
[12.491s] (MainThread) Waiting for uncommit to start
[25.599s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[25.599s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[22.818s] (MainThread) Uncommit started
[22.825s] (MainThread) Waiting for uncommit to complete
[35.743s][info ][gc,heap ] Uncommitter (0) Uncommitted: 96M(19%) in 46.329ms
[35.743s][debug][gc,heap ] Uncommitter (0) Finish Next Cycle Timeout: 0ms
[35.743s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[35.743s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[27.963s] (MainThread) Uncommit completed
[27.963s] (MainThread) Uncommit Delay: 5000
[28.505s] (MainThread) Object Size: 4096
[28.505s] (MainThread) Alloc Size: 209715200
[29.016s] (MainThread) Before Alloc: 134217728
[29.017s] (MainThread) After Alloc: 234881024
[29.017s] (MainThread) After Uncommit: 134217728
[29.017s] (MainThread) Actual Uncommit Delay: 15774
[40.479s][info ][gc,exit ] Stopping ZGC
[40.479s][info ][gc,exit ] Heap
[40.479s][info ][gc,exit ] ZHeap used 8M, capacity 128M, max capacity 512M
[40.479s][info ][gc,exit ] Cache 120M (2)
[40.479s][info ][gc,exit ] size classes 2M (1), 64M (1)
[40.479s][info ][gc,exit ] Metaspace used 3521K, committed 3648K, reserved 1114112K
[40.479s][info ][gc,exit ] class space used 59K, committed 128K, reserved 1048576K
----------System.err:(12/647)----------
java.lang.Exception: Uncommitted too slow
at gc.z.TestUncommit.test(TestUncommit.java:112)
at gc.z.TestUncommit.main(TestUncommit.java:129)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:565)
at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
at java.base/java.lang.Thread.run(Thread.java:1474)
JavaTest Message: Test threw exception: java.lang.Exception: Uncommitted too slow
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.Exception: Uncommitted too slow
----------rerun:(49/6775)*----------
gc/z/TestUncommit.java
Here's a snippet from the log file:
#section:main
----------messages:(7/436)----------
command: main -XX:+UseZGC -Xlog:gc*,gc+heap=debug,gc+stats=off -Xms128M -Xmx512M -XX:ZUncommitDelay=5 gc.z.TestUncommit
reason: User specified action: run main/othervm -XX:+UseZGC -Xlog:gc*,gc+heap=debug,gc+stats=off -Xms128M -Xmx512M -XX:ZUncommitDelay=5 gc.z.TestUncommit
started: Fri Jul 04 09:27:02 GMT 2025
Mode: othervm [/othervm specified]
Process id: 65665
finished: Fri Jul 04 09:27:43 GMT 2025
elapsed time (seconds): 40.521
----------configuration:(0/0)----------
----------System.out:(324/29822)----------
[0.017s][debug][gc,heap] Minimum heap 134217728 Initial heap 134217728 Maximum heap 536870912
[0.017s][info ][gc,init] Initializing The Z Garbage Collector
[0.017s][info ][gc,init] Version: 25-ea+30-LTS-3418 (fastdebug)
[0.017s][info ][gc,init] NUMA Support: Disabled
[0.017s][info ][gc,init] CPUs: 8 total, 8 available
[0.017s][info ][gc,init] Memory: 16384M
[0.017s][info ][gc,init] Large Page Support: Disabled
[0.017s][info ][gc,init] Address Space Size: unlimited
[0.017s][info ][gc,init] Reserved Space Type: Contiguous/Unrestricted/Complete
[0.017s][info ][gc,init] Reserved Space Size: 8G
[0.017s][info ][gc,init] Min Capacity: 128M
[0.017s][info ][gc,init] Initial Capacity: 128M
[0.017s][info ][gc,init] Max Capacity: 512M
[0.017s][info ][gc,init] Soft Max Capacity: 512M
[0.017s][info ][gc,init] Page Size Medium: Range [2M, 16M]
[0.017s][info ][gc,init] Pre-touch: Disabled
[0.018s][info ][gc,init] Uncommit: Enabled
[0.018s][info ][gc,init] Uncommit Delay: 5s
[0.018s][info ][gc,init] GC Workers for Old Generation: 2 (dynamic)
[0.018s][info ][gc,init] GC Workers for Young Generation: 2 (dynamic)
[0.018s][info ][gc,init] GC Workers Max: 2 (dynamic)
[0.018s][info ][gc,init] Runtime Workers: 5
[0.018s][info ][gc ] Using The Z Garbage Collector
[0.035s][info ][gc,metaspace] CDS archive(s) mapped at: [0x0000000700000000-0x0000000700e74000-0x0000000700e74000), size 15155200, SharedBaseAddress: 0x0000000700000000, ArchiveRelocationMode: 1.
[0.035s][info ][gc,metaspace] Compressed class space mapped at: 0x0000000701000000-0x0000000741000000, reserved size: 1073741824
[0.035s][info ][gc,metaspace] UseCompressedClassPointers 1, UseCompactObjectHeaders 0
[0.035s][info ][gc,metaspace] Narrow klass pointer bits 32, Max shift 3
[0.035s][info ][gc,metaspace] Narrow klass base: 0x0000000700000000, Narrow klass shift: 0
[0.035s][info ][gc,metaspace] Encoding Range: [0x0000000700000000 - 0x0000000800000000), (4294967296 bytes)
[0.035s][info ][gc,metaspace] Klass Range: [0x0000000700004000 - 0x0000000741000000), (1090502656 bytes)
[0.035s][info ][gc,metaspace] Klass ID Range: [16384 - 1090519033) (1090502649)
[0.035s][info ][gc,metaspace] Protection zone: [0x0000000700000000 - 0x0000000700004000), (16384 bytes)
[0.060s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[5.200s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 0ms
[5.200s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[5.200s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[10.348s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[10.348s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[3.383s] (MainThread) Iteration 0
[15.453s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[15.453s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[7.050s] (MainThread) Allocating
[15.484s][info ][gc ] GC(0) Major Collection (Warmup)
[15.484s][info ][gc,task ] GC(0) Using 2 Workers for Young Generation
[15.484s][info ][gc,task ] GC(0) Using 1 Workers for Old Generation
[15.484s][debug][gc,heap ] GC(0) Y: Heap Before GC invocations=0 (full 0):
[15.484s][debug][gc,heap ] GC(0) Y: ZHeap used 54M, capacity 128M, max capacity 512M
[15.484s][debug][gc,heap ] GC(0) Y: Cache 74M (1)
[15.484s][debug][gc,heap ] GC(0) Y: size classes 64M (1)
[15.484s][info ][gc,phases ] GC(0) Y: Young Generation
[15.486s][info ][gc,phases ] GC(0) Y: Pause Mark Start (Major) 0.270ms
[7.211s] (MainThread) Reclaiming
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Mark 1028.605ms
[16.515s][info ][gc,phases ] GC(0) Y: Pause Mark End 0.009ms
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Mark Free 0.001ms
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Reset Relocation Set 0.000ms
[16.515s][info ][gc,reloc ] GC(0) Y: Using tenuring threshold: 1 (Computed)
[16.515s][info ][gc,phases ] GC(0) Y: Concurrent Select Relocation Set 0.130ms
[16.516s][info ][gc,phases ] GC(0) Y: Pause Relocate Start 0.006ms
[16.516s][info ][gc,phases ] GC(0) Y: Concurrent Relocate 0.104ms
[16.516s][debug][gc,heap ] GC(0) Y: Heap After GC invocations=1 (full 1):
[16.516s][debug][gc,heap ] GC(0) Y: ZHeap used 224M, capacity 224M, max capacity 512M
[16.516s][debug][gc,heap ] GC(0) Y: Cache 0M (0)
[16.516s][info ][gc,alloc ] GC(0) Y: Mark Start Mark End Relocate Start Relocate End
[16.516s][info ][gc,alloc ] GC(0) Y: Allocation Stalls: 0 0 0 0
[16.516s][info ][gc,load ] GC(0) Y: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[16.516s][info ][gc,mmu ] GC(0) Y: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[16.516s][info ][gc,marking ] GC(0) Y: Mark: 2 stripe(s), 9 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[16.516s][info ][gc,nmethod ] GC(0) Y: NMethods: 7112 registered, 0 unregistered
[16.516s][info ][gc,metaspace] GC(0) Y: Metaspace: 3M used, 3M committed, 1088M reserved
[16.516s][info ][gc,reloc ] GC(0) Y: Candidates Selected In-Place Size Empty Relocated
[16.516s][info ][gc,reloc ] GC(0) Y: Small Pages: 27 0 0 54M 0M 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Medium Pages: 0 0 0 0M 0M 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Large Pages: 0 0 0 0M 0M 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Forwarding Usage: 0M
[16.516s][info ][gc,reloc ] GC(0) Y: Age Table:
[16.516s][info ][gc,reloc ] GC(0) Y: Live Garbage Small Medium Large
[16.516s][info ][gc,reloc ] GC(0) Y: Eden 50M (10%) 3M (1%) 27 / 0 0 / 0 0 / 0
[16.516s][info ][gc,heap ] GC(0) Y: Min Capacity: 128M(25%)
[16.516s][info ][gc,heap ] GC(0) Y: Max Capacity: 512M(100%)
[16.516s][info ][gc,heap ] GC(0) Y: Soft Max Capacity: 512M(100%)
[16.516s][info ][gc,heap ] GC(0) Y: Heap Statistics:
[16.516s][info ][gc,heap ] GC(0) Y: Mark Start Mark End Relocate Start Relocate End High Low
[16.516s][info ][gc,heap ] GC(0) Y: Capacity: 128M (25%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 128M (25%)
[16.516s][info ][gc,heap ] GC(0) Y: Free: 458M (89%) 288M (56%) 288M (56%) 288M (56%) 458M (89%) 288M (56%)
[16.516s][info ][gc,heap ] GC(0) Y: Used: 54M (11%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 54M (11%)
[16.516s][info ][gc,heap ] GC(0) Y: Young Generation Statistics:
[16.516s][info ][gc,heap ] GC(0) Y: Mark Start Mark End Relocate Start Relocate End
[16.516s][info ][gc,heap ] GC(0) Y: Used: 54M (11%) 224M (44%) 224M (44%) 224M (44%)
[16.516s][info ][gc,heap ] GC(0) Y: Live: - 50M (10%) 50M (10%) 50M (10%)
[16.516s][info ][gc,heap ] GC(0) Y: Garbage: - 3M (1%) 3M (1%) 3M (1%)
[16.516s][info ][gc,heap ] GC(0) Y: Allocated: - 170M (33%) 170M (33%) 170M (33%)
[16.516s][info ][gc,heap ] GC(0) Y: Reclaimed: - - 0M (0%) 0M (0%)
[16.516s][info ][gc,heap ] GC(0) Y: Promoted: - - 0M (0%) 0M (0%)
[16.516s][info ][gc,heap ] GC(0) Y: Compacted: - - - 0M (0%)
[16.516s][info ][gc,phases ] GC(0) Y: Young Generation 54M(11%)->224M(44%) 1.031s
[16.516s][debug][gc,heap ] GC(0) O: Heap Before GC invocations=1 (full 1):
[16.516s][debug][gc,heap ] GC(0) O: ZHeap used 224M, capacity 224M, max capacity 512M
[16.516s][debug][gc,heap ] GC(0) O: Cache 0M (0)
[16.516s][info ][gc,phases ] GC(0) O: Old Generation
[16.516s][info ][gc,phases ] GC(0) O: Concurrent Mark 0.162ms
[16.516s][info ][gc,phases ] GC(0) O: Pause Mark End 0.057ms
[16.516s][info ][gc,phases ] GC(0) O: Concurrent Mark Free 0.000ms
[20.452s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 95ms
[20.452s][debug][gc,heap ] Uncommitter (0) Timeout: 95ms
[20.559s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[20.559s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[20.774s][info ][gc,phases ] GC(0) O: Concurrent Process Non-Strong 4257.458ms
[20.774s][info ][gc,phases ] GC(0) O: Concurrent Reset Relocation Set 0.000ms
[20.779s][info ][gc,phases ] GC(0) O: Concurrent Select Relocation Set 0.329ms
[20.779s][info ][gc,task ] GC(0) O: Using 2 Workers for Old Generation
[20.791s][info ][gc,task ] GC(0) O: Using 1 Workers for Old Generation
[20.791s][info ][gc,phases ] GC(0) O: Concurrent Remap Roots 12.545ms
[20.792s][info ][gc,phases ] GC(0) O: Pause Relocate Start 0.054ms
[20.792s][info ][gc,phases ] GC(0) O: Concurrent Relocate 0.051ms
[20.792s][debug][gc,heap ] GC(0) O: Heap After GC invocations=1 (full 1):
[20.792s][debug][gc,heap ] GC(0) O: ZHeap used 224M, capacity 224M, max capacity 512M
[20.792s][debug][gc,heap ] GC(0) O: Cache 0M (0)
[20.792s][info ][gc,alloc ] GC(0) O: Mark Start Mark End Relocate Start Relocate End
[20.792s][info ][gc,alloc ] GC(0) O: Allocation Stalls: 0 0 0 0
[20.792s][info ][gc,load ] GC(0) O: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.792s][info ][gc,mmu ] GC(0) O: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.792s][info ][gc,marking ] GC(0) O: Mark: 1 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.792s][info ][gc,nmethod ] GC(0) O: NMethods: 3252 registered, 3860 unregistered
[20.792s][info ][gc,metaspace] GC(0) O: Metaspace: 3M used, 3M committed, 1088M reserved
[20.792s][info ][gc,ref ] GC(0) O: Encountered Discovered Enqueued
[20.792s][info ][gc,ref ] GC(0) O: Soft References: 90 0 0
[20.792s][info ][gc,ref ] GC(0) O: Weak References: 121 0 0
[20.792s][info ][gc,ref ] GC(0) O: Final References: 0 0 0
[20.792s][info ][gc,ref ] GC(0) O: Phantom References: 5 0 0
[20.792s][info ][gc,heap ] GC(0) O: Min Capacity: 128M(25%)
[20.792s][info ][gc,heap ] GC(0) O: Max Capacity: 512M(100%)
[20.792s][info ][gc,heap ] GC(0) O: Soft Max Capacity: 512M(100%)
[20.792s][info ][gc,heap ] GC(0) O: Heap Statistics:
[20.792s][info ][gc,heap ] GC(0) O: Mark Start Mark End Relocate Start Relocate End High Low
[20.792s][info ][gc,heap ] GC(0) O: Capacity: 128M (25%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 128M (25%)
[20.792s][info ][gc,heap ] GC(0) O: Free: 458M (89%) 288M (56%) 288M (56%) 288M (56%) 458M (89%) 288M (56%)
[20.792s][info ][gc,heap ] GC(0) O: Used: 54M (11%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 54M (11%)
[20.792s][info ][gc,heap ] GC(0) O: Old Generation Statistics:
[20.792s][info ][gc,heap ] GC(0) O: Mark Start Mark End Relocate Start Relocate End
[20.792s][info ][gc,heap ] GC(0) O: Used: 0M (0%) 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Live: - 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Garbage: - 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Allocated: - 0M (0%) 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Reclaimed: - - 0M (0%) 0M (0%)
[20.792s][info ][gc,heap ] GC(0) O: Compacted: - - - 0M (0%)
[20.792s][info ][gc,phases ] GC(0) O: Old Generation 224M(44%)->224M(44%) 4.276s
[20.792s][info ][gc ] GC(0) Major Collection (Warmup) 54M(11%)->224M(44%) 5.308s
[20.792s][info ][gc ] GC(1) Major Collection (System.gc())
[20.792s][info ][gc,task ] GC(1) Using 2 Workers for Young Generation
[20.792s][info ][gc,task ] GC(1) Using 2 Workers for Old Generation
[20.792s][debug][gc,heap ] GC(1) Y: Heap Before GC invocations=1 (full 1):
[20.792s][debug][gc,heap ] GC(1) Y: ZHeap used 224M, capacity 224M, max capacity 512M
[20.792s][debug][gc,heap ] GC(1) Y: Cache 0M (0)
[20.792s][info ][gc,phases ] GC(1) Y: Young Generation (Promote All)
[20.792s][info ][gc,phases ] GC(1) Y: Pause Mark Start 0.016ms
[20.801s][info ][gc,phases ] GC(1) Y: Concurrent Mark 8.420ms
[20.801s][info ][gc,phases ] GC(1) Y: Pause Mark End 0.006ms
[20.801s][info ][gc,phases ] GC(1) Y: Concurrent Mark Free 0.002ms
[20.801s][info ][gc,phases ] GC(1) Y: Concurrent Reset Relocation Set 0.000ms
[20.801s][info ][gc,reloc ] GC(1) Y: Using tenuring threshold: 0 (Promote All)
[20.805s][info ][gc,phases ] GC(1) Y: Concurrent Select Relocation Set 3.885ms
[20.805s][info ][gc,phases ] GC(1) Y: Pause Relocate Start 0.014ms
[20.812s][info ][gc,phases ] GC(1) Y: Concurrent Relocate 7.426ms
[20.812s][debug][gc,heap ] GC(1) Y: Heap After GC invocations=2 (full 1):
[20.812s][debug][gc,heap ] GC(1) Y: ZHeap used 4M, capacity 224M, max capacity 512M
[20.812s][debug][gc,heap ] GC(1) Y: Cache 220M (2)
[20.812s][debug][gc,heap ] GC(1) Y: size classes 4M (1), 128M (1)
[20.812s][info ][gc,alloc ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.812s][info ][gc,alloc ] GC(1) Y: Allocation Stalls: 0 0 0 0
[20.812s][info ][gc,load ] GC(1) Y: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.812s][info ][gc,mmu ] GC(1) Y: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.812s][info ][gc,marking ] GC(1) Y: Mark: 2 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.812s][info ][gc,nmethod ] GC(1) Y: NMethods: 3252 registered, 3860 unregistered
[20.812s][info ][gc,metaspace] GC(1) Y: Metaspace: 3M used, 3M committed, 1088M reserved
[20.812s][info ][gc,reloc ] GC(1) Y: Candidates Selected In-Place Size Empty Relocated
[20.812s][info ][gc,reloc ] GC(1) Y: Small Pages: 104 1 0 208M 204M 1M
[20.812s][info ][gc,reloc ] GC(1) Y: Medium Pages: 1 0 0 16M 16M 0M
[20.812s][info ][gc,reloc ] GC(1) Y: Large Pages: 0 0 0 0M 0M 0M
[20.812s][info ][gc,reloc ] GC(1) Y: Forwarding Usage: 0M
[20.812s][info ][gc,reloc ] GC(1) Y: Age Table:
[20.813s][info ][gc,reloc ] GC(1) Y: Live Garbage Small Medium Large
[20.813s][info ][gc,reloc ] GC(1) Y: Eden - 170M (33%) 77 / 0 1 / 0 0 / 0
[20.813s][info ][gc,reloc ] GC(1) Y: Survivor 1 1M (0%) 52M (10%) 27 / 1 0 / 0 0 / 0
[20.813s][info ][gc,heap ] GC(1) Y: Min Capacity: 128M(25%)
[20.813s][info ][gc,heap ] GC(1) Y: Max Capacity: 512M(100%)
[20.813s][info ][gc,heap ] GC(1) Y: Soft Max Capacity: 512M(100%)
[20.813s][info ][gc,heap ] GC(1) Y: Heap Statistics:
[20.813s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End High Low
[20.813s][info ][gc,heap ] GC(1) Y: Capacity: 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%)
[20.813s][info ][gc,heap ] GC(1) Y: Free: 288M (56%) 288M (56%) 508M (99%) 508M (99%) 508M (99%) 288M (56%)
[20.813s][info ][gc,heap ] GC(1) Y: Used: 224M (44%) 224M (44%) 4M (1%) 4M (1%) 224M (44%) 4M (1%)
[20.813s][info ][gc,heap ] GC(1) Y: Young Generation Statistics:
[20.813s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.813s][info ][gc,heap ] GC(1) Y: Used: 224M (44%) 224M (44%) 4M (1%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Live: - 1M (0%) 1M (0%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Garbage: - 222M (43%) 2M (0%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Allocated: - 0M (0%) 0M (0%) 0M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Reclaimed: - - 220M (43%) 222M (43%)
[20.813s][info ][gc,heap ] GC(1) Y: Promoted: - - 0M (0%) 1M (0%)
[20.813s][info ][gc,heap ] GC(1) Y: Compacted: - - - 0M (0%)
[20.813s][info ][gc,phases ] GC(1) Y: Young Generation (Promote All) 224M(44%)->4M(1%) 0.020s
[20.813s][debug][gc,heap ] GC(1) Y: Heap Before GC invocations=2 (full 1):
[20.813s][debug][gc,heap ] GC(1) Y: ZHeap used 4M, capacity 224M, max capacity 512M
[20.813s][debug][gc,heap ] GC(1) Y: Cache 220M (2)
[20.813s][debug][gc,heap ] GC(1) Y: size classes 4M (1), 128M (1)
[20.813s][info ][gc,phases ] GC(1) Y: Young Generation (Collect Roots)
[20.813s][info ][gc,phases ] GC(1) Y: Pause Mark Start (Major) 0.012ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Mark 5.096ms
[20.818s][info ][gc,phases ] GC(1) Y: Pause Mark End 0.005ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Mark Free 0.001ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Reset Relocation Set 0.001ms
[20.818s][info ][gc,reloc ] GC(1) Y: Using tenuring threshold: 0 (Computed)
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Select Relocation Set 0.064ms
[20.818s][info ][gc,phases ] GC(1) Y: Pause Relocate Start 0.016ms
[20.818s][info ][gc,phases ] GC(1) Y: Concurrent Relocate 0.031ms
[20.818s][debug][gc,heap ] GC(1) Y: Heap After GC invocations=3 (full 2):
[20.818s][debug][gc,heap ] GC(1) Y: ZHeap used 4M, capacity 224M, max capacity 512M
[20.818s][debug][gc,heap ] GC(1) Y: Cache 220M (2)
[20.818s][debug][gc,heap ] GC(1) Y: size classes 4M (1), 128M (1)
[20.818s][info ][gc,alloc ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.818s][info ][gc,alloc ] GC(1) Y: Allocation Stalls: 0 0 0 0
[20.818s][info ][gc,load ] GC(1) Y: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.818s][info ][gc,mmu ] GC(1) Y: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.818s][info ][gc,marking ] GC(1) Y: Mark: 2 stripe(s), 1 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.818s][info ][gc,nmethod ] GC(1) Y: NMethods: 3252 registered, 3860 unregistered
[20.818s][info ][gc,metaspace] GC(1) Y: Metaspace: 3M used, 3M committed, 1088M reserved
[20.818s][info ][gc,heap ] GC(1) Y: Min Capacity: 128M(25%)
[20.818s][info ][gc,heap ] GC(1) Y: Max Capacity: 512M(100%)
[20.818s][info ][gc,heap ] GC(1) Y: Soft Max Capacity: 512M(100%)
[20.818s][info ][gc,heap ] GC(1) Y: Heap Statistics:
[20.818s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End High Low
[20.818s][info ][gc,heap ] GC(1) Y: Capacity: 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%)
[20.818s][info ][gc,heap ] GC(1) Y: Free: 508M (99%) 508M (99%) 508M (99%) 508M (99%) 508M (99%) 508M (99%)
[20.818s][info ][gc,heap ] GC(1) Y: Used: 4M (1%) 4M (1%) 4M (1%) 4M (1%) 4M (1%) 4M (1%)
[20.818s][info ][gc,heap ] GC(1) Y: Young Generation Statistics:
[20.818s][info ][gc,heap ] GC(1) Y: Mark Start Mark End Relocate Start Relocate End
[20.818s][info ][gc,heap ] GC(1) Y: Used: 0M (0%) 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Live: - 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Garbage: - 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Allocated: - 0M (0%) 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Reclaimed: - - 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Promoted: - - 0M (0%) 0M (0%)
[20.818s][info ][gc,heap ] GC(1) Y: Compacted: - - - 0M (0%)
[20.818s][info ][gc,phases ] GC(1) Y: Young Generation (Collect Roots) 4M(1%)->4M(1%) 0.006s
[20.818s][debug][gc,heap ] GC(1) O: Heap Before GC invocations=3 (full 2):
[20.818s][debug][gc,heap ] GC(1) O: ZHeap used 4M, capacity 224M, max capacity 512M
[20.818s][debug][gc,heap ] GC(1) O: Cache 220M (2)
[20.818s][debug][gc,heap ] GC(1) O: size classes 4M (1), 128M (1)
[20.818s][info ][gc,phases ] GC(1) O: Old Generation
[20.823s][info ][gc,phases ] GC(1) O: Concurrent Mark 4.943ms
[20.824s][info ][gc,phases ] GC(1) O: Pause Mark End 0.058ms
[20.824s][info ][gc,phases ] GC(1) O: Concurrent Mark Free 0.003ms
[20.838s][info ][gc,phases ] GC(1) O: Concurrent Process Non-Strong 14.293ms
[20.838s][info ][gc,phases ] GC(1) O: Concurrent Reset Relocation Set 0.000ms
[20.839s][info ][gc,phases ] GC(1) O: Concurrent Select Relocation Set 0.190ms
[20.839s][info ][gc,task ] GC(1) O: Using 2 Workers for Old Generation
[20.843s][info ][gc,task ] GC(1) O: Using 2 Workers for Old Generation
[20.843s][info ][gc,phases ] GC(1) O: Concurrent Remap Roots 4.278ms
[20.843s][info ][gc,phases ] GC(1) O: Pause Relocate Start 0.017ms
[20.848s][info ][gc,phases ] GC(1) O: Concurrent Relocate 4.722ms
[20.848s][debug][gc,heap ] GC(1) O: Heap After GC invocations=3 (full 2):
[20.848s][debug][gc,heap ] GC(1) O: ZHeap used 6M, capacity 224M, max capacity 512M
[20.848s][debug][gc,heap ] GC(1) O: Cache 218M (2)
[20.848s][debug][gc,heap ] GC(1) O: size classes 4M (1), 128M (1)
[20.848s][info ][gc,alloc ] GC(1) O: Mark Start Mark End Relocate Start Relocate End
[20.848s][info ][gc,alloc ] GC(1) O: Allocation Stalls: 0 0 0 0
[20.848s][info ][gc,load ] GC(1) O: Load: 5.80 (73%) / 6.39 (80%) / 7.63 (95%)
[20.848s][info ][gc,mmu ] GC(1) O: MMU: 2ms/86.5%, 5ms/94.6%, 10ms/97.3%, 20ms/98.7%, 50ms/99.5%, 100ms/99.7%
[20.848s][info ][gc,marking ] GC(1) O: Mark: 2 stripe(s), 2 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[20.848s][info ][gc,nmethod ] GC(1) O: NMethods: 3245 registered, 0 unregistered
[20.848s][info ][gc,metaspace] GC(1) O: Metaspace: 3M used, 3M committed, 1088M reserved
[20.848s][info ][gc,ref ] GC(1) O: Encountered Discovered Enqueued
[20.848s][info ][gc,ref ] GC(1) O: Soft References: 90 0 0
[20.848s][info ][gc,ref ] GC(1) O: Weak References: 121 22 11
[20.848s][info ][gc,ref ] GC(1) O: Final References: 0 0 0
[20.848s][info ][gc,ref ] GC(1) O: Phantom References: 5 3 0
[20.848s][info ][gc,reloc ] GC(1) O: Candidates Selected In-Place Size Empty Relocated
[20.848s][info ][gc,reloc ] GC(1) O: Small Pages: 2 1 0 4M 0M 1M
[20.848s][info ][gc,reloc ] GC(1) O: Medium Pages: 0 0 0 0M 0M 0M
[20.848s][info ][gc,reloc ] GC(1) O: Large Pages: 0 0 0 0M 0M 0M
[20.848s][info ][gc,reloc ] GC(1) O: Forwarding Usage: 0M
[20.848s][info ][gc,heap ] GC(1) O: Min Capacity: 128M(25%)
[20.848s][info ][gc,heap ] GC(1) O: Max Capacity: 512M(100%)
[20.848s][info ][gc,heap ] GC(1) O: Soft Max Capacity: 512M(100%)
[20.848s][info ][gc,heap ] GC(1) O: Heap Statistics:
[20.848s][info ][gc,heap ] GC(1) O: Mark Start Mark End Relocate Start Relocate End High Low
[20.848s][info ][gc,heap ] GC(1) O: Capacity: 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%) 224M (44%)
[20.848s][info ][gc,heap ] GC(1) O: Free: 508M (99%) 508M (99%) 508M (99%) 506M (99%) 508M (99%) 502M (98%)
[20.848s][info ][gc,heap ] GC(1) O: Used: 4M (1%) 4M (1%) 4M (1%) 6M (1%) 10M (2%) 4M (1%)
[20.848s][info ][gc,heap ] GC(1) O: Old Generation Statistics:
[20.848s][info ][gc,heap ] GC(1) O: Mark Start Mark End Relocate Start Relocate End
[20.848s][info ][gc,heap ] GC(1) O: Used: 4M (1%) 4M (1%) 4M (1%) 6M (1%)
[20.848s][info ][gc,heap ] GC(1) O: Live: - 1M (0%) 1M (0%) 1M (0%)
[20.848s][info ][gc,heap ] GC(1) O: Garbage: - 2M (0%) 2M (0%) 0M (0%)
[20.848s][info ][gc,heap ] GC(1) O: Allocated: - 0M (0%) 0M (0%) 4M (1%)
[20.848s][info ][gc,heap ] GC(1) O: Reclaimed: - - 0M (0%) 2M (0%)
[20.848s][info ][gc,heap ] GC(1) O: Compacted: - - - 1M (0%)
[20.848s][info ][gc,phases ] GC(1) O: Old Generation 4M(1%)->6M(1%) 0.030s
[20.848s][info ][gc ] GC(1) Major Collection (System.gc()) 224M(44%)->6M(1%) 0.056s
[12.491s] (MainThread) Waiting for uncommit to start
[25.599s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[25.599s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[22.818s] (MainThread) Uncommit started
[22.825s] (MainThread) Waiting for uncommit to complete
[35.743s][info ][gc,heap ] Uncommitter (0) Uncommitted: 96M(19%) in 46.329ms
[35.743s][debug][gc,heap ] Uncommitter (0) Finish Next Cycle Timeout: 0ms
[35.743s][debug][gc,heap ] Uncommitter (0) Cancel Next Cycle Timeout: 5000ms
[35.743s][debug][gc,heap ] Uncommitter (0) Timeout: 5000ms
[27.963s] (MainThread) Uncommit completed
[27.963s] (MainThread) Uncommit Delay: 5000
[28.505s] (MainThread) Object Size: 4096
[28.505s] (MainThread) Alloc Size: 209715200
[29.016s] (MainThread) Before Alloc: 134217728
[29.017s] (MainThread) After Alloc: 234881024
[29.017s] (MainThread) After Uncommit: 134217728
[29.017s] (MainThread) Actual Uncommit Delay: 15774
[40.479s][info ][gc,exit ] Stopping ZGC
[40.479s][info ][gc,exit ] Heap
[40.479s][info ][gc,exit ] ZHeap used 8M, capacity 128M, max capacity 512M
[40.479s][info ][gc,exit ] Cache 120M (2)
[40.479s][info ][gc,exit ] size classes 2M (1), 64M (1)
[40.479s][info ][gc,exit ] Metaspace used 3521K, committed 3648K, reserved 1114112K
[40.479s][info ][gc,exit ] class space used 59K, committed 128K, reserved 1048576K
----------System.err:(12/647)----------
java.lang.Exception: Uncommitted too slow
at gc.z.TestUncommit.test(TestUncommit.java:112)
at gc.z.TestUncommit.main(TestUncommit.java:129)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:565)
at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
at java.base/java.lang.Thread.run(Thread.java:1474)
JavaTest Message: Test threw exception: java.lang.Exception: Uncommitted too slow
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.Exception: Uncommitted too slow
----------rerun:(49/6775)*----------