Details
Description
The following test failed in the JDK22 CI:
runtime/Safepoint/TestAbortVMOnSafepointTimeout.java
Here's a snippet from the log file:
#section:driver
----------messages:(7/260)----------
command: driver TestAbortVMOnSafepointTimeout
reason: User specified action: run driver TestAbortVMOnSafepointTimeout
started: Tue Sep 05 23:27:38 UTC 2023
Mode: agentvm
Agent id: 45
finished: Tue Sep 05 23:27:41 UTC 2023
elapsed time (seconds): 3.969
----------configuration:(16/1689)*----------
<snip>
----------System.out:(8/3627)*----------
Command line: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\windows-x64-debug.jdk\\jdk-22\\fastdebug\\bin\\java.exe -cp C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\runtime\\Safepoint\\TestAbortVMOnSafepointTimeout.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\src.full\\open\\test\\hotspot\\jtreg\\runtime\\Safepoint;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\testlibrary;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jtreg.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\junit-platform-console-standalone-1.9.2.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\testng-7.3.0.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jcommander-1.82.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\guice-5.1.0.jar -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+SafepointTimeout -XX:+SafepointALot -XX:+AbortVMOnSafepointTimeout -XX:SafepointTimeoutDelay=50 -XX:GuaranteedSafepointInterval=1 -XX:-CreateCoredumpOnCrash -Xms64m TestAbortVMOnSafepointTimeout$Test 999 ]
[2023-09-05T23:27:38.062973700Z] Gathering output for process 9824
[2023-09-05T23:27:38.916360Z] Waiting for completion for process 9824
[2023-09-05T23:27:38.932021200Z] Waiting for completion finished for process 9824
Command line: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\windows-x64-debug.jdk\\jdk-22\\fastdebug\\bin\\java.exe -cp C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\runtime\\Safepoint\\TestAbortVMOnSafepointTimeout.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\src.full\\open\\test\\hotspot\\jtreg\\runtime\\Safepoint;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\testlibrary;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jtreg.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\junit-platform-console-standalone-1.9.2.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\testng-7.3.0.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jcommander-1.82.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\guice-5.1.0.jar -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+SafepointTimeout -XX:+SafepointALot -XX:+AbortVMOnSafepointTimeout -XX:AbortVMOnSafepointTimeoutDelay=2500 -XX:SafepointTimeoutDelay=50 -XX:GuaranteedSafepointInterval=1 -XX:-CreateCoredumpOnCrash -Xms64m TestAbortVMOnSafepointTimeout$TestWithDelay ]
[2023-09-05T23:27:38.932021200Z] Gathering output for process 47860
[2023-09-05T23:27:41.724038600Z] Waiting for completion for process 47860
[2023-09-05T23:27:41.739681500Z] Waiting for completion finished for process 47860
----------System.err:(55/3512)*----------
stdout: [[0.530s][warning][safepoint]
[0.531s][warning][safepoint] # SafepointSynchronize::begin: Timeout detected:
[0.531s][warning][safepoint] # SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
[0.531s][warning][safepoint] # SafepointSynchronize::begin: Threads which did not reach the safepoint:
[0.531s][warning][safepoint] # "main" #1 [53624] prio=5 os_prio=0 cpu=187.50ms elapsed=0.49s tid=0x000001f5c77c2980 nid=53624 runnable [0x00000001ab5fd000]
[0.531s][warning][safepoint] java.lang.Thread.State: RUNNABLE
[0.531s][warning][safepoint] Thread: 0x000001f5c77c2980 [0xd178] State: _running _at_poll_safepoint 0
[0.531s][warning][safepoint] JavaThread state: _thread_in_vm
[0.531s][warning][safepoint]
[0.531s][warning][safepoint] # SafepointSynchronize::begin: (End of list)
[0.743s][warning][safepoint] # SafepointSynchronize: Finished after 281 ms
[1.013s][warning][safepoint]
[1.013s][warning][safepoint] # SafepointSynchronize::begin: Timeout detected:
[1.013s][warning][safepoint] # SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
[1.013s][warning][safepoint] # SafepointSynchronize::begin: Threads which did not reach the safepoint:
[1.013s][warning][safepoint] # "main" #1 [53624] prio=5 os_prio=0 cpu=250.00ms elapsed=0.97s tid=0x000001f5c77c2980 nid=53624 runnable [0x00000001ab5ff000]
[1.013s][warning][safepoint] java.lang.Thread.State: RUNNABLE
[1.013s][warning][safepoint] Thread: 0x000001f5c77c2980 [0xd178] State: _running _at_poll_safepoint 0
[1.013s][warning][safepoint] JavaThread state: _thread_in_vm
[1.013s][warning][safepoint]
[1.013s][warning][safepoint] # SafepointSynchronize::begin: (End of list)
#
# A fatal error has been detected by the Java Runtime Environment:
#
# Internal Error (c:\\sb\\prod\\1693954293\\workspace\\open\\src\\hotspot\\share\\runtime\\safepoint.cpp:823), pid=47860, tid=60696
# fatal error: Safepoint sync time longer than 50.000000 ms detected when executing SafepointALot.
#
# JRE version: Java(TM) SE Runtime Environment (22.0+14) (fastdebug build 22-ea+14-1021)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 22-ea+14-1021, mixed mode, sharing, tiered, compressed oops, compressed class ptrs, g1 gc, windows-amd64)
# CreateCoredumpOnCrash turned off, no core file dumped
#
Unsupported internal testing APIs have been used.
# An error report file with more information is saved as:
# C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\scratch\\4\\hs_err_pid47860.log
#
# If you would like to submit a bug report, please visit:
# https://bugreport.java.com/bugreport/crash.jsp
#
];
stderr: []
exitValue = 1
java.lang.RuntimeException: 'THE FOLLOWING STALL SHOULD BE CAPTURED' missing from stdout/stderr
at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:221)
at TestAbortVMOnSafepointTimeout.testGracePeriodAppliedBeforeVmAbort(TestAbortVMOnSafepointTimeout.java:80)
at TestAbortVMOnSafepointTimeout.main(TestAbortVMOnSafepointTimeout.java:102)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
at java.base/java.lang.Thread.run(Thread.java:1570)
JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test
result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'THE FOLLOWING STALL SHOULD BE CAPTURED' missing from stdout/stderr
The failing error mesg was added by the following fix:
JDK-8305507 Add support for grace period before AbortVMOnSafepointTimeout triggers
so it looks likeJDK-8305507 has caused a regression so I'm starting
this bug off as a P2. The fix forJDK-8305507 was integrated in
jdk-22+14-1015 and this first sighting happened in jdk-22+14-1021-tier1.
runtime/Safepoint/TestAbortVMOnSafepointTimeout.java
Here's a snippet from the log file:
#section:driver
----------messages:(7/260)----------
command: driver TestAbortVMOnSafepointTimeout
reason: User specified action: run driver TestAbortVMOnSafepointTimeout
started: Tue Sep 05 23:27:38 UTC 2023
Mode: agentvm
Agent id: 45
finished: Tue Sep 05 23:27:41 UTC 2023
elapsed time (seconds): 3.969
----------configuration:(16/1689)*----------
<snip>
----------System.out:(8/3627)*----------
Command line: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\windows-x64-debug.jdk\\jdk-22\\fastdebug\\bin\\java.exe -cp C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\runtime\\Safepoint\\TestAbortVMOnSafepointTimeout.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\src.full\\open\\test\\hotspot\\jtreg\\runtime\\Safepoint;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\testlibrary;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jtreg.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\junit-platform-console-standalone-1.9.2.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\testng-7.3.0.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jcommander-1.82.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\guice-5.1.0.jar -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+SafepointTimeout -XX:+SafepointALot -XX:+AbortVMOnSafepointTimeout -XX:SafepointTimeoutDelay=50 -XX:GuaranteedSafepointInterval=1 -XX:-CreateCoredumpOnCrash -Xms64m TestAbortVMOnSafepointTimeout$Test 999 ]
[2023-09-05T23:27:38.062973700Z] Gathering output for process 9824
[2023-09-05T23:27:38.916360Z] Waiting for completion for process 9824
[2023-09-05T23:27:38.932021200Z] Waiting for completion finished for process 9824
Command line: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\windows-x64-debug.jdk\\jdk-22\\fastdebug\\bin\\java.exe -cp C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\runtime\\Safepoint\\TestAbortVMOnSafepointTimeout.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-22+14-1021\\src.full\\open\\test\\hotspot\\jtreg\\runtime\\Safepoint;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\testlibrary;C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\1\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jtreg.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\junit-platform-console-standalone-1.9.2.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\testng-7.3.0.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\jcommander-1.82.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.3.1\\1\\bundles\\jtreg-7.3.1+1.zip\\jtreg\\lib\\guice-5.1.0.jar -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:+SafepointTimeout -XX:+SafepointALot -XX:+AbortVMOnSafepointTimeout -XX:AbortVMOnSafepointTimeoutDelay=2500 -XX:SafepointTimeoutDelay=50 -XX:GuaranteedSafepointInterval=1 -XX:-CreateCoredumpOnCrash -Xms64m TestAbortVMOnSafepointTimeout$TestWithDelay ]
[2023-09-05T23:27:38.932021200Z] Gathering output for process 47860
[2023-09-05T23:27:41.724038600Z] Waiting for completion for process 47860
[2023-09-05T23:27:41.739681500Z] Waiting for completion finished for process 47860
----------System.err:(55/3512)*----------
stdout: [[0.530s][warning][safepoint]
[0.531s][warning][safepoint] # SafepointSynchronize::begin: Timeout detected:
[0.531s][warning][safepoint] # SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
[0.531s][warning][safepoint] # SafepointSynchronize::begin: Threads which did not reach the safepoint:
[0.531s][warning][safepoint] # "main" #1 [53624] prio=5 os_prio=0 cpu=187.50ms elapsed=0.49s tid=0x000001f5c77c2980 nid=53624 runnable [0x00000001ab5fd000]
[0.531s][warning][safepoint] java.lang.Thread.State: RUNNABLE
[0.531s][warning][safepoint] Thread: 0x000001f5c77c2980 [0xd178] State: _running _at_poll_safepoint 0
[0.531s][warning][safepoint] JavaThread state: _thread_in_vm
[0.531s][warning][safepoint]
[0.531s][warning][safepoint] # SafepointSynchronize::begin: (End of list)
[0.743s][warning][safepoint] # SafepointSynchronize: Finished after 281 ms
[1.013s][warning][safepoint]
[1.013s][warning][safepoint] # SafepointSynchronize::begin: Timeout detected:
[1.013s][warning][safepoint] # SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
[1.013s][warning][safepoint] # SafepointSynchronize::begin: Threads which did not reach the safepoint:
[1.013s][warning][safepoint] # "main" #1 [53624] prio=5 os_prio=0 cpu=250.00ms elapsed=0.97s tid=0x000001f5c77c2980 nid=53624 runnable [0x00000001ab5ff000]
[1.013s][warning][safepoint] java.lang.Thread.State: RUNNABLE
[1.013s][warning][safepoint] Thread: 0x000001f5c77c2980 [0xd178] State: _running _at_poll_safepoint 0
[1.013s][warning][safepoint] JavaThread state: _thread_in_vm
[1.013s][warning][safepoint]
[1.013s][warning][safepoint] # SafepointSynchronize::begin: (End of list)
#
# A fatal error has been detected by the Java Runtime Environment:
#
# Internal Error (c:\\sb\\prod\\1693954293\\workspace\\open\\src\\hotspot\\share\\runtime\\safepoint.cpp:823), pid=47860, tid=60696
# fatal error: Safepoint sync time longer than 50.000000 ms detected when executing SafepointALot.
#
# JRE version: Java(TM) SE Runtime Environment (22.0+14) (fastdebug build 22-ea+14-1021)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 22-ea+14-1021, mixed mode, sharing, tiered, compressed oops, compressed class ptrs, g1 gc, windows-amd64)
# CreateCoredumpOnCrash turned off, no core file dumped
#
Unsupported internal testing APIs have been used.
# An error report file with more information is saved as:
# C:\\sb\\prod\\1693955935\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\scratch\\4\\hs_err_pid47860.log
#
# If you would like to submit a bug report, please visit:
# https://bugreport.java.com/bugreport/crash.jsp
#
];
stderr: []
exitValue = 1
java.lang.RuntimeException: 'THE FOLLOWING STALL SHOULD BE CAPTURED' missing from stdout/stderr
at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:221)
at TestAbortVMOnSafepointTimeout.testGracePeriodAppliedBeforeVmAbort(TestAbortVMOnSafepointTimeout.java:80)
at TestAbortVMOnSafepointTimeout.main(TestAbortVMOnSafepointTimeout.java:102)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
at java.base/java.lang.Thread.run(Thread.java:1570)
JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test
result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'THE FOLLOWING STALL SHOULD BE CAPTURED' missing from stdout/stderr
The failing error mesg was added by the following fix:
so it looks like
this bug off as a P2. The fix for
jdk-22+14-1015 and this first sighting happened in jdk-22+14-1021-tier1.
Attachments
Issue Links
- relates to
-
JDK-8305507 Add support for grace period before AbortVMOnSafepointTimeout triggers
-
- Resolved
-