JDK-8249890 : CheckLoopStripMining.java "fatal error: Safepoint sync time longer than 1200ms detected when executing SafepointALot."
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 16
  • Priority: P4
  • Status: Closed
  • Resolution: Cannot Reproduce
  • OS: windows
  • CPU: x86_64
  • Submitted: 2020-07-22
  • Updated: 2020-11-20
  • Resolved: 2020-11-20
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 16
16Resolved
Related Reports
Relates :  
Relates :  
Description
The following test failed in the JDK16 CI:

compiler/loopstripmining/CheckLoopStripMining.java

Here's a snippet from the log file:

----------System.err:(48/3050)*----------
 stdout: [CompileCommand: compileonly compiler/loopstripmining/CheckLoopStripMining$Test1.test_loop
[3.913s][warning][safepoint] 
[3.914s][warning][safepoint] # SafepointSynchronize::begin: Timeout detected:
[3.914s][warning][safepoint] # SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
[3.914s][warning][safepoint] # SafepointSynchronize::begin: Threads which did not reach the safepoint:
[3.914s][warning][safepoint] # "main" #1 prio=5 os_prio=0 cpu=2484.38ms elapsed=3.90s tid=0x000002477b374f30 nid=0x1908 runnable  [0x0000000000000000]
[3.914s][warning][safepoint]    java.lang.Thread.State: RUNNABLE
[3.914s][warning][safepoint] Thread: 0x000002477b374f30  [0x1908] State: _running _at_poll_safepoint 0
[3.914s][warning][safepoint]    JavaThread state: _thread_in_Java
[3.914s][warning][safepoint] 
[3.914s][warning][safepoint] # SafepointSynchronize::begin: (End of list)
# To suppress the following error report, specify this argument
# after -XX: or in .hotspotrc:  SuppressErrorAt=t:/workspace/open/src/hotspot/share/runtime/safepoint.cpp:856
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (t:/workspace/open/src/hotspot/share/runtime/safepoint.cpp:856), pid=9448, tid=6548
#  fatal error: Safepoint sync time longer than 1200ms detected when executing SafepointALot.
#
# JRE version: Java(TM) SE Runtime Environment (16.0+7) (fastdebug build 16-ea+7-243)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 16-ea+7-243, compiled mode, sharing, compressed oops, g1 gc, windows-amd64)
# Core dump will be written. Default location: T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_not_fast_compiler\\scratch\\3\\hs_err_pid9448.mdmp
#
# An error report file with more information is saved as:
# T:\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_hotspot_not_fast_compiler\\scratch\\3\\hs_err_pid9448.log
#
# If you would like to submit a bug report, please visit:
#   https://bugreport.java.com/bugreport/crash.jsp
#
];
 stderr: [Java HotSpot(TM) 64-Bit Server VM warning: Temporarily processing option UseBiasedLocking; support is scheduled for removal in 16.0
]
 exitValue = 1

java.lang.RuntimeException: Expected to get exit value of [0]

	at jdk.test.lib.process.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:457)
	at compiler.loopstripmining.CheckLoopStripMining.main(CheckLoopStripMining.java:56)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
	at java.base/java.lang.Thread.run(Thread.java:832)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]


Here's the crashing thread's stack:

---------------  T H R E A D  ---------------

Current thread (0x000002471a1040e0):  VMThread "VM Thread" [stack: 0x00000065dec00000,0x00000065ded00000] [id=6548], _nested_threads_hazard_ptr_cnt=1

Stack: [0x00000065dec00000,0x00000065ded00000]
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [jvm.dll+0xa50e31]  os::platform_print_native_stack+0xf1  (os_windows_x86.cpp:368)
V  [jvm.dll+0xc6b6f6]  VMError::report+0xf86  (vmError.cpp:732)
V  [jvm.dll+0xc6cf5e]  VMError::report_and_die+0x7ee  (vmError.cpp:1548)
V  [jvm.dll+0xc6d614]  VMError::report_and_die+0x64  (vmError.cpp:1341)
V  [jvm.dll+0x43a04d]  report_fatal+0x9d  (debug.cpp:284)
V  [jvm.dll+0xaf925f]  SafepointSynchronize::print_safepoint_timeout+0x22f  (safepoint.cpp:855)
V  [jvm.dll+0xaf963a]  SafepointSynchronize::synchronize_threads+0x22a  (safepoint.cpp:253)
V  [jvm.dll+0xaf6c83]  SafepointSynchronize::begin+0x3b3  (safepoint.cpp:380)
V  [jvm.dll+0xc7405e]  VMThread::loop+0x22e  (vmThread.cpp:450)
V  [jvm.dll+0xc7460a]  VMThread::run+0xda  (vmThread.cpp:255)
V  [jvm.dll+0xbffaf4]  Thread::call_run+0x1b4  (thread.cpp:398)
V  [jvm.dll+0xa4f3ee]  thread_native_entry+0x10e  (os_windows.cpp:463)
C  [ucrtbase.dll+0x1fb80]
C  [KERNEL32.DLL+0x84d4]
C  [ntdll.dll+0x6e871]

VM_Operation (0x00007ffb50674208): SafepointALot, mode: safepoint

Here's the command line:

Command Line: -XX:MaxRAMPercentage=6 -Djava.io.tmpdir=t:/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_not_fast_compiler/tmp -XX:+CreateCoredumpOnCrash -ea -esa -XX:CompileThreshold=100 -XX:+UnlockExperimentalVMOptions -XX:-TieredCompilation -XX:+UnlockDiagnosticVMOptions -XX:-UseBiasedLocking -XX:+SafepointTimeout -XX:+SafepointALot -XX:+AbortVMOnSafepointTimeout -XX:SafepointTimeoutDelay=1200 -XX:GuaranteedSafepointInterval=1200 -XX:-TieredCompilation -XX:+UseCountedLoopSafepoints -XX:LoopStripMiningIter=1000 -XX:LoopUnrollLimit=0 -XX:CompileCommand=compileonly,compiler.loopstripmining.CheckLoopStripMining$Test1::test_loop -Xcomp compiler.loopstripmining.CheckLoopStripMining$Test1


Comments
This only happened once in June and never showed up again. Might have been due to a slow machine. Closing this as "Cannot Reproduce" for now.
20-11-2020

Roland, could you please have a look?
01-09-2020

Hard to evaluate. 1200ms seems a long time between safepoints, but if this was a heavily loaded machine ...
23-07-2020