Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8361897

gc/z/TestUncommit.java fails with Uncommitted too slow

XMLWordPrintable

    • gc
    • b10
    • aarch64
    • os_x

        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)*----------

              aboldtch Axel Boldt-Christmas
              dcubed Daniel Daugherty
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Created:
                Updated:
                Resolved: