The following test failed in the JDK18 CI:
gc/z/TestGarbageCollectorMXBean.java
Here's a snippet from the log file:
#section:main
----------messages:(5/347)----------
command: main -XX:+UseZGC -Xms512M -Xmx512M -Xlog:gc TestGarbageCollectorMXBean 512 512
reason: User specified action: run main/othervm -XX:+UseZGC -Xms512M -Xmx512M -Xlog:gc TestGarbageCollectorMXBean 512 512
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.management
elapsed time (seconds): 260.457
----------configuration:(3/46)----------
Boot Layer
add modules: java.management
----------System.out:(137/6258)----------
[0.048s][info][gc] Using The Z Garbage Collector
[34.661s][info][gc] GC(0) Garbage Collection (System.gc()) 4M(1%)->6M(1%)
[9.460s] (MainThread) Starting GC 0
[45.784s][info][gc] GC(1) Garbage Collection (System.gc()) 6M(1%)->8M(2%)
[12.837s] (MainThread) Starting GC 1
[52.037s][info][gc] GC(2) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[19.088s] (MainThread) Starting GC 2
[53.529s][info][gc] GC(3) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[20.579s] (MainThread) Starting GC 3
[53.653s][info][gc] GC(4) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[20.704s] (MainThread) Starting GC 4
[53.716s][info][gc] GC(5) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[20.766s] (MainThread) Waiting...
[21.780s] (MainThread) Waiting...
[22.788s] (MainThread) Waiting...
[23.796s] (MainThread) Waiting...
[24.839s] (MainThread) Waiting...
[25.840s] (MainThread) Waiting...
[26.842s] (MainThread) Waiting...
[27.845s] (MainThread) Waiting...
[28.858s] (MainThread) Waiting...
[29.871s] (MainThread) Waiting...
[31.017s] (MainThread) Waiting...
[36.854s] (MainThread) Waiting...
[37.862s] (MainThread) Waiting...
[38.877s] (MainThread) Waiting...
[39.890s] (MainThread) Waiting...
[40.894s] (MainThread) Waiting...
[41.901s] (MainThread) Waiting...
[42.906s] (MainThread) Waiting...
[43.913s] (MainThread) Waiting...
[44.918s] (MainThread) Waiting...
[45.930s] (MainThread) Waiting...
[51.237s] (MainThread) Waiting...
[57.039s] (MainThread) Waiting...
[58.048s] (MainThread) Waiting...
[59.063s] (MainThread) Waiting...
[63.230s] (MainThread) Waiting...
[64.665s] (MainThread) Waiting...
[65.715s] (MainThread) Waiting...
[71.377s] (MainThread) Waiting...
[77.227s] (MainThread) Waiting...
[78.238s] (MainThread) Waiting...
[79.246s] (MainThread) Waiting...
[80.261s] (MainThread) Waiting...
[86.726s] (MainThread) Waiting...
[87.737s] (MainThread) Waiting...
[88.742s] (MainThread) Waiting...
[91.622s] (MainThread) Waiting...
[97.504s] (MainThread) Waiting...
[98.507s] (MainThread) Waiting...
[99.511s] (MainThread) Waiting...
[104.737s] (MainThread) Waiting...
[105.739s] (MainThread) Waiting...
[106.740s] (MainThread) Waiting...
[107.746s] (MainThread) Waiting...
[108.753s] (MainThread) Waiting...
[109.760s] (MainThread) Waiting...
[110.776s] (MainThread) Waiting...
[111.782s] (MainThread) Waiting...
[112.785s] (MainThread) Waiting...
[113.794s] (MainThread) Waiting...
[114.799s] (MainThread) Waiting...
[115.803s] (MainThread) Waiting...
[116.810s] (MainThread) Waiting...
[117.817s] (MainThread) Waiting...
[118.824s] (MainThread) Waiting...
[119.832s] (MainThread) Waiting...
[120.836s] (MainThread) Waiting...
[121.841s] (MainThread) Waiting...
[122.844s] (MainThread) Waiting...
[123.854s] (MainThread) Waiting...
[129.833s] (MainThread) Waiting...
[137.021s] (MainThread) Waiting...
[138.037s] (MainThread) Waiting...
[139.050s] (MainThread) Waiting...
[140.057s] (MainThread) Waiting...
[141.062s] (MainThread) Waiting...
[142.070s] (MainThread) Waiting...
[143.072s] (MainThread) Waiting...
[144.078s] (MainThread) Waiting...
[145.083s] (MainThread) Waiting...
[150.193s] (MainThread) Waiting...
[151.208s] (MainThread) Waiting...
[157.365s] (MainThread) Waiting...
[158.377s] (MainThread) Waiting...
[159.377s] (MainThread) Waiting...
[165.695s] (MainThread) Waiting...
[167.298s] (Notification Thread) ZGC Pauses (com.sun.management.gc.notification)
[172.820s] (MainThread) Waiting...
[173.832s] (MainThread) Waiting...
[174.838s] (MainThread) Waiting...
[175.842s] (MainThread) Waiting...
[176.846s] (MainThread) Waiting...
[177.669s] (Notification Thread) Id: 4
[177.669s] (Notification Thread) Action: end of GC pause
[177.669s] (Notification Thread) Cause: System.gc()
[177.670s] (Notification Thread) StartTime: 45565
[177.670s] (Notification Thread) EndTime: 45565
[177.670s] (Notification Thread) Duration: 0
[177.849s] (MainThread) Waiting...
[178.854s] (MainThread) Waiting...
[179.858s] (MainThread) Waiting...
[180.866s] (MainThread) Waiting...
[181.872s] (MainThread) Waiting...
[182.886s] (MainThread) Waiting...
[188.281s] (Notification Thread) MemoryUsageBeforeGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[188.282s] (Notification Thread) MemoryUsageAfterGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[188.282s] (Notification Thread)
[189.446s] (MainThread) Waiting...
[195.206s] (MainThread) Waiting...
[196.210s] (MainThread) Waiting...
[197.214s] (MainThread) minCycles: 5
[197.215s] (MainThread) minPauses: 15
[197.215s] (MainThread) actualCycles: 0
[197.215s] (MainThread) actualPauses: 1
[197.215s] (MainThread) actualErrors: 0
[211.096s] (Notification Thread) ZGC Pauses (com.sun.management.gc.notification)
[211.136s] (Notification Thread) Id: 5
[211.137s] (Notification Thread) Action: end of GC pause
[211.137s] (Notification Thread) Cause: System.gc()
[211.137s] (Notification Thread) StartTime: 45615
[211.137s] (Notification Thread) EndTime: 45615
[211.137s] (Notification Thread) Duration: 0
[211.137s] (Notification Thread) MemoryUsageBeforeGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[211.137s] (Notification Thread) MemoryUsageAfterGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[211.137s] (Notification Thread)
[217.707s] (Notification Thread) ZGC Pauses (com.sun.management.gc.notification)
[217.726s] (Notification Thread) Id: 6
[217.727s] (Notification Thread) Action: end of GC pause
[217.727s] (Notification Thread) Cause: System.gc()
[217.727s] (Notification Thread) StartTime: 45646
[217.727s] (Notification Thread) EndTime: 45646
[217.727s] (Notification Thread) Duration: 0
[217.911s] (Notification Thread) MemoryUsageBeforeGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[217.912s] (Notification Thread) MemoryUsageAfterGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[217.912s] (Notification Thread)
----------System.err:(13/812)----------
java.lang.Exception: Unexpected cycles
at TestGarbageCollectorMXBean.main(TestGarbageCollectorMXBean.java:205)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
at java.base/java.lang.Thread.run(Thread.java:833)
JavaTest Message: Test threw exception: java.lang.Exception: Unexpected cycles
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.Exception: Unexpected cycles
----------rerun:(54/5496)*----------
gc/z/TestGarbageCollectorMXBean.java
Here's a snippet from the log file:
#section:main
----------messages:(5/347)----------
command: main -XX:+UseZGC -Xms512M -Xmx512M -Xlog:gc TestGarbageCollectorMXBean 512 512
reason: User specified action: run main/othervm -XX:+UseZGC -Xms512M -Xmx512M -Xlog:gc TestGarbageCollectorMXBean 512 512
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.management
elapsed time (seconds): 260.457
----------configuration:(3/46)----------
Boot Layer
add modules: java.management
----------System.out:(137/6258)----------
[0.048s][info][gc] Using The Z Garbage Collector
[34.661s][info][gc] GC(0) Garbage Collection (System.gc()) 4M(1%)->6M(1%)
[9.460s] (MainThread) Starting GC 0
[45.784s][info][gc] GC(1) Garbage Collection (System.gc()) 6M(1%)->8M(2%)
[12.837s] (MainThread) Starting GC 1
[52.037s][info][gc] GC(2) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[19.088s] (MainThread) Starting GC 2
[53.529s][info][gc] GC(3) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[20.579s] (MainThread) Starting GC 3
[53.653s][info][gc] GC(4) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[20.704s] (MainThread) Starting GC 4
[53.716s][info][gc] GC(5) Garbage Collection (System.gc()) 8M(2%)->6M(1%)
[20.766s] (MainThread) Waiting...
[21.780s] (MainThread) Waiting...
[22.788s] (MainThread) Waiting...
[23.796s] (MainThread) Waiting...
[24.839s] (MainThread) Waiting...
[25.840s] (MainThread) Waiting...
[26.842s] (MainThread) Waiting...
[27.845s] (MainThread) Waiting...
[28.858s] (MainThread) Waiting...
[29.871s] (MainThread) Waiting...
[31.017s] (MainThread) Waiting...
[36.854s] (MainThread) Waiting...
[37.862s] (MainThread) Waiting...
[38.877s] (MainThread) Waiting...
[39.890s] (MainThread) Waiting...
[40.894s] (MainThread) Waiting...
[41.901s] (MainThread) Waiting...
[42.906s] (MainThread) Waiting...
[43.913s] (MainThread) Waiting...
[44.918s] (MainThread) Waiting...
[45.930s] (MainThread) Waiting...
[51.237s] (MainThread) Waiting...
[57.039s] (MainThread) Waiting...
[58.048s] (MainThread) Waiting...
[59.063s] (MainThread) Waiting...
[63.230s] (MainThread) Waiting...
[64.665s] (MainThread) Waiting...
[65.715s] (MainThread) Waiting...
[71.377s] (MainThread) Waiting...
[77.227s] (MainThread) Waiting...
[78.238s] (MainThread) Waiting...
[79.246s] (MainThread) Waiting...
[80.261s] (MainThread) Waiting...
[86.726s] (MainThread) Waiting...
[87.737s] (MainThread) Waiting...
[88.742s] (MainThread) Waiting...
[91.622s] (MainThread) Waiting...
[97.504s] (MainThread) Waiting...
[98.507s] (MainThread) Waiting...
[99.511s] (MainThread) Waiting...
[104.737s] (MainThread) Waiting...
[105.739s] (MainThread) Waiting...
[106.740s] (MainThread) Waiting...
[107.746s] (MainThread) Waiting...
[108.753s] (MainThread) Waiting...
[109.760s] (MainThread) Waiting...
[110.776s] (MainThread) Waiting...
[111.782s] (MainThread) Waiting...
[112.785s] (MainThread) Waiting...
[113.794s] (MainThread) Waiting...
[114.799s] (MainThread) Waiting...
[115.803s] (MainThread) Waiting...
[116.810s] (MainThread) Waiting...
[117.817s] (MainThread) Waiting...
[118.824s] (MainThread) Waiting...
[119.832s] (MainThread) Waiting...
[120.836s] (MainThread) Waiting...
[121.841s] (MainThread) Waiting...
[122.844s] (MainThread) Waiting...
[123.854s] (MainThread) Waiting...
[129.833s] (MainThread) Waiting...
[137.021s] (MainThread) Waiting...
[138.037s] (MainThread) Waiting...
[139.050s] (MainThread) Waiting...
[140.057s] (MainThread) Waiting...
[141.062s] (MainThread) Waiting...
[142.070s] (MainThread) Waiting...
[143.072s] (MainThread) Waiting...
[144.078s] (MainThread) Waiting...
[145.083s] (MainThread) Waiting...
[150.193s] (MainThread) Waiting...
[151.208s] (MainThread) Waiting...
[157.365s] (MainThread) Waiting...
[158.377s] (MainThread) Waiting...
[159.377s] (MainThread) Waiting...
[165.695s] (MainThread) Waiting...
[167.298s] (Notification Thread) ZGC Pauses (com.sun.management.gc.notification)
[172.820s] (MainThread) Waiting...
[173.832s] (MainThread) Waiting...
[174.838s] (MainThread) Waiting...
[175.842s] (MainThread) Waiting...
[176.846s] (MainThread) Waiting...
[177.669s] (Notification Thread) Id: 4
[177.669s] (Notification Thread) Action: end of GC pause
[177.669s] (Notification Thread) Cause: System.gc()
[177.670s] (Notification Thread) StartTime: 45565
[177.670s] (Notification Thread) EndTime: 45565
[177.670s] (Notification Thread) Duration: 0
[177.849s] (MainThread) Waiting...
[178.854s] (MainThread) Waiting...
[179.858s] (MainThread) Waiting...
[180.866s] (MainThread) Waiting...
[181.872s] (MainThread) Waiting...
[182.886s] (MainThread) Waiting...
[188.281s] (Notification Thread) MemoryUsageBeforeGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[188.282s] (Notification Thread) MemoryUsageAfterGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[188.282s] (Notification Thread)
[189.446s] (MainThread) Waiting...
[195.206s] (MainThread) Waiting...
[196.210s] (MainThread) Waiting...
[197.214s] (MainThread) minCycles: 5
[197.215s] (MainThread) minPauses: 15
[197.215s] (MainThread) actualCycles: 0
[197.215s] (MainThread) actualPauses: 1
[197.215s] (MainThread) actualErrors: 0
[211.096s] (Notification Thread) ZGC Pauses (com.sun.management.gc.notification)
[211.136s] (Notification Thread) Id: 5
[211.137s] (Notification Thread) Action: end of GC pause
[211.137s] (Notification Thread) Cause: System.gc()
[211.137s] (Notification Thread) StartTime: 45615
[211.137s] (Notification Thread) EndTime: 45615
[211.137s] (Notification Thread) Duration: 0
[211.137s] (Notification Thread) MemoryUsageBeforeGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[211.137s] (Notification Thread) MemoryUsageAfterGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[211.137s] (Notification Thread)
[217.707s] (Notification Thread) ZGC Pauses (com.sun.management.gc.notification)
[217.726s] (Notification Thread) Id: 6
[217.727s] (Notification Thread) Action: end of GC pause
[217.727s] (Notification Thread) Cause: System.gc()
[217.727s] (Notification Thread) StartTime: 45646
[217.727s] (Notification Thread) EndTime: 45646
[217.727s] (Notification Thread) Duration: 0
[217.911s] (Notification Thread) MemoryUsageBeforeGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[217.912s] (Notification Thread) MemoryUsageAfterGC: init = 0(0K) used = 0(0K) committed = 0(0K) max = 0(0K)
[217.912s] (Notification Thread)
----------System.err:(13/812)----------
java.lang.Exception: Unexpected cycles
at TestGarbageCollectorMXBean.main(TestGarbageCollectorMXBean.java:205)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
at java.base/java.lang.Thread.run(Thread.java:833)
JavaTest Message: Test threw exception: java.lang.Exception: Unexpected cycles
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.Exception: Unexpected cycles
----------rerun:(54/5496)*----------
- relates to
-
JDK-8244291 Test: gc/z/TestGarbageCollectorMXBean.java failed: "unexpected cycles"
-
- Resolved
-