JDK-8212152 : runtime/Thread/SuspendAtExit.java hangs intermittently on Solaris-X64
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 12
  • Priority: P4
  • Status: Resolved
  • Resolution: Duplicate
  • OS: solaris_11
  • CPU: x86_64
  • Submitted: 2018-10-13
  • Updated: 2020-05-15
  • Resolved: 2018-11-08
Related Reports
Duplicate :  
JDK-8212933 - Thread-SMR: requesting a VM operation whilst holding a ThreadsListHandle can cause deadlocks
Description
The following test failed due to an infinite loop on Solaris-X64
in the slowdebug config using jdk12+14 bits:

runtime/Thread/SuspendAtExit.java

Here's the tail of the log file when I killed the test:

[16489.777s][debug][thread,smr] tid=8: ThreadsSMRSupport::release_stable_list notified regular hazard ptr
[16489.777s][debug][thread,smr] tid=8: ThreadsSMRSupport::release_stable_list notified regular hazard ptr
/work/shared/bug_hunt/thread_SMR_stress/jdk12_exp/do_one_AtExit_test.sh: line 18: 14140: Killed
+ status=265
+ [ 265 '!=' 0 ]
+ echo 'Test SuspendAtExit.java FAILed with status=265'
Test SuspendAtExit.java FAILed with status=265
+ exit 265

Here's a breakdown of the lines in the log file:

$ cat SuspendAtExit.d.00/do_one_AtExit_test.log.SuspendAtExit.245.log_lines.count
   1 [debug][thread,smr] tid=13: Threads::add: new ThreadsList=0x0000000000b92440
   1 [debug][thread,smr] tid=13: ThreadsSMRSupport::free_list: threads=0x0000000000a06fb0 is freed.
   1 [debug][thread,smr] tid=15: Threads::add: new ThreadsList=0x0000000000cb9470
   1 [debug][thread,smr] tid=15: Threads::add: new ThreadsList=0x0000000000cbcf70
   1 [debug][thread,smr] tid=15: Threads::add: new ThreadsList=0x0000000000cd0f90
   1 [debug][thread,smr] tid=15: Threads::remove: new ThreadsList=0x00000000012e63b0
   1 [debug][thread,smr] tid=15: ThreadsSMRSupport::free_list: threads=0x0000000000b92440 is freed.
   1 [debug][thread,smr] tid=15: ThreadsSMRSupport::free_list: threads=0x0000000000cb9470 is freed.
   1 [debug][thread,smr] tid=15: ThreadsSMRSupport::free_list: threads=0x0000000000cd0f90 is freed.
   1 [debug][thread,smr] tid=15: ThreadsSMRSupport::free_list: threads=0x00000000013054b0 is freed.
   1 [debug][thread,smr] tid=15: ThreadsSMRSupport::smr_delete: thread=0x0000000000b90800 is not deleted.
   1 [debug][thread,smr] tid=16: Threads::remove: new ThreadsList=0x00000000013054b0
   1 [debug][thread,smr] tid=16: ThreadsSMRSupport::free_list: threads=0x00000000012e63b0 is freed.
   1 [debug][thread,smr] tid=16: ThreadsSMRSupport::smr_delete: thread=0x0000000000caf800 is not deleted.
   1 [debug][thread,smr] tid=17: Threads::remove: new ThreadsList=0x00000000012e63b0
   1 [debug][thread,smr] tid=17: ThreadsSMRSupport::free_list: threads=0x00000000013054b0 is freed.
   1 [debug][thread,smr] tid=17: ThreadsSMRSupport::smr_delete: thread=0x0000000000cb9800 is not deleted.
   1 [debug][thread,smr] tid=18: Threads::remove: new ThreadsList=0x00000000013054b0
   1 [debug][thread,smr] tid=18: ThreadsSMRSupport::free_list: threads=0x00000000012e63b0 is freed.
   1 [debug][thread,smr] tid=18: ThreadsSMRSupport::smr_delete: thread=0x0000000000cbb000 is not deleted.
 211 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x0000000000f665c0
  90 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012c6200
 157 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012c9e40
  45 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012dea90
  27 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012dee10
  27 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012e3fb0
  58 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012e63b0
   1 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012e8090
  70 [debug][thread,smr] tid=2: SafeThreadsListPtr::acquire_stable_list: add nested list pointer to ThreadsList=0x00000000012f4180
 211 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x0000000000f665c0
  90 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012c6200
 157 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012c9e40
  45 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012dea90
  27 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012dee10
  27 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012e3fb0
  58 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012e63b0
  70 [debug][thread,smr] tid=2: SafeThreadsListPtr::release_stable_list: delete nested list pointer to ThreadsList=0x00000000012f4180
   2 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x000000000095cbc0
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x000000000099f330
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000009e9f90
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000009eca00
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000009ef940
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x0000000000a06fb0
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x0000000000e548a0
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x0000000000f12620
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x0000000000f665c0
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x0000000000f9a740
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012c4b30
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012c6200
   2 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012c9e40
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012d1270
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012d5c10
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012dea90
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012dec80
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012e2f30
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012e5e00
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012e8090
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012f3bc0
   1 [debug][thread,smr] tid=2: Threads::add: new ThreadsList=0x00000000012f4180
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x000000000041cd20 is freed.
   2 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x000000000095cbc0 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x000000000099f330 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000009e9f90 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000009eca00 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000009ef940 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x0000000000cbcf70 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x0000000000e548a0 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x0000000000f12620 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x0000000000f69620 is freed.
   2 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x0000000000f9a740 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012c6200 is freed.
   4 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012c9e40 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012dfcd0 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012e3fb0 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012e63b0 is freed.
   1 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012f2700 is freed.
   2 [debug][thread,smr] tid=2: ThreadsSMRSupport::free_list: threads=0x00000000012f4180 is freed.
   1 [debug][thread,smr] tid=22: Threads::remove: new ThreadsList=0x0000000000f69620
   1 [debug][thread,smr] tid=22: ThreadsSMRSupport::free_list: threads=0x0000000000f665c0 is freed.
   1 [debug][thread,smr] tid=22: ThreadsSMRSupport::smr_delete: thread=0x0000000000f64800 is deleted.
   1 [debug][thread,smr] tid=23: Threads::remove: new ThreadsList=0x00000000012c6200
   1 [debug][thread,smr] tid=23: ThreadsSMRSupport::free_list: threads=0x0000000000f9a740 is freed.
   1 [debug][thread,smr] tid=23: ThreadsSMRSupport::smr_delete: thread=0x00000000012c5000 is deleted.
   1 [debug][thread,smr] tid=24: Threads::remove: new ThreadsList=0x0000000000f9a740
   1 [debug][thread,smr] tid=24: ThreadsSMRSupport::smr_delete: thread=0x00000000012c8800 is deleted.
   1 [debug][thread,smr] tid=25: Threads::remove: new ThreadsList=0x0000000000f9a740
   1 [debug][thread,smr] tid=25: ThreadsSMRSupport::free_list: threads=0x00000000012c9e40 is freed.
   1 [debug][thread,smr] tid=26: Threads::remove: new ThreadsList=0x00000000012c9e40
   1 [debug][thread,smr] tid=26: ThreadsSMRSupport::free_list: threads=0x00000000012c4b30 is freed.
   1 [debug][thread,smr] tid=26: ThreadsSMRSupport::smr_delete: thread=0x00000000012c8800 is deleted.
   1 [debug][thread,smr] tid=27: Threads::remove: new ThreadsList=0x00000000012c9e40
   1 [debug][thread,smr] tid=27: ThreadsSMRSupport::free_list: threads=0x00000000012d1270 is freed.
   1 [debug][thread,smr] tid=27: ThreadsSMRSupport::smr_delete: thread=0x00000000012d8000 is deleted.
   1 [debug][thread,smr] tid=28: Threads::remove: new ThreadsList=0x00000000012c9e40
   1 [debug][thread,smr] tid=28: ThreadsSMRSupport::free_list: threads=0x00000000012d5c10 is freed.
   1 [debug][thread,smr] tid=28: ThreadsSMRSupport::smr_delete: thread=0x00000000012d0000 is deleted.
   1 [debug][thread,smr] tid=29: Threads::remove: new ThreadsList=0x00000000012dee10
   1 [debug][thread,smr] tid=29: ThreadsSMRSupport::free_list: threads=0x00000000012dec80 is freed.
   1 [debug][thread,smr] tid=29: ThreadsSMRSupport::smr_delete: thread=0x00000000012d8000 is deleted.
   1 [debug][thread,smr] tid=30: Threads::remove: new ThreadsList=0x00000000012dfcd0
   1 [debug][thread,smr] tid=30: ThreadsSMRSupport::free_list: threads=0x00000000012dee10 is freed.
   1 [debug][thread,smr] tid=31: Threads::remove: new ThreadsList=0x00000000012f2700
   1 [debug][thread,smr] tid=31: ThreadsSMRSupport::free_list: threads=0x00000000012dea90 is freed.
   1 [debug][thread,smr] tid=31: ThreadsSMRSupport::smr_delete: thread=0x00000000012dd800 is deleted.
   1 [debug][thread,smr] tid=32: Threads::remove: new ThreadsList=0x00000000012f4180
   1 [debug][thread,smr] tid=32: ThreadsSMRSupport::free_list: threads=0x00000000012e2f30 is freed.
   1 [debug][thread,smr] tid=32: ThreadsSMRSupport::smr_delete: thread=0x00000000012f3000 is deleted.
   1 [debug][thread,smr] tid=33: Threads::remove: new ThreadsList=0x00000000012e3fb0
   1 [debug][thread,smr] tid=33: ThreadsSMRSupport::free_list: threads=0x00000000012f3bc0 is freed.
   1 [debug][thread,smr] tid=33: ThreadsSMRSupport::smr_delete: thread=0x00000000012e1800 is deleted.
   1 [debug][thread,smr] tid=34: Threads::remove: new ThreadsList=0x00000000012e63b0
   1 [debug][thread,smr] tid=34: ThreadsSMRSupport::free_list: threads=0x00000000012e5e00 is freed.
   1 [debug][thread,smr] tid=34: ThreadsSMRSupport::smr_delete: thread=0x00000000012e3000 is deleted.
   1 [debug][thread,smr] tid=35: Threads::remove: new ThreadsList=0x00000000012e63b0
   1 [debug][thread,smr] tid=35: ThreadsSMRSupport::free_list: threads=0x00000000012e8090 is not freed.
   1 [debug][thread,smr] tid=35: ThreadsSMRSupport::smr_delete: thread=0x00000000012e4800 is not deleted.
337142383 [debug][thread,smr] tid=8: ThreadsSMRSupport::release_stable_list notified regular hazard ptr

That last line is a killer :-)
Comments
Here are the interesting threads for this infinite loop: The VMThread is looping in VM_HandshakeAllThreads::doit(): THREAD t@8 t@8(l@8) stopped in ___lwp_cond_wait at 0xffff80ffbf51e82a 0xffff80ffbf51e82a: ___lwp_cond_wait+0x000a: jae ___lwp_cond_wait+0x18 [ 0xffff80ffbf51e838, .+0xe ] current thread: t@8 [1] ___lwp_cond_wait(0x97e150, 0x97e138, 0x0, 0x0, 0xffff80ffbf4efed8, 0x97e100), at 0xffff80ffbf51e82a [2] _lwp_cond_wait(), at 0xffff80ffbf4efeec =>[3] os::Solaris::cond_wait(cv = 0x97e150, mx = 0x97e138), line 216 in "os_solaris.hpp" [4] os::PlatformEvent::park(this = 0x97e100), line 4985 in "os_solaris.cpp" [5] ParkCommon(ev = 0x97e100, timo = 0), line 399 in "mutex.cpp" [6] Monitor::ILock(this = 0x43d910, Self = 0x97d000), line 461 in "mutex.cpp" [7] Monitor::lock_without_safepoint_check(this = 0x43d910, Self = 0x97d000), line 932 in "mutex.cpp" [8] Monitor::lock_without_safepoint_check(this = 0x43d910), line 938 in "mutex.cpp" [9] MutexLockerEx::MutexLockerEx(this = 0xffff80ffb87fe778, mutex = 0x43d910, no_safepoint_check = true), line 226 in "mutexLocker.hpp" [10] VM_HandshakeAllThreads::doit(this = 0xffff80ff9c7fe7c8), line 213 in "handshake.cpp" [11] VM_Operation::evaluate(this = 0xffff80ff9c7fe7c8), line 67 in "vm_operations.cpp" [12] VMThread::evaluate_operation(this = 0x97d000, op = 0xffff80ff9c7fe7c8), line 370 in "vmThread.cpp" [13] VMThread::loop(this = 0x97d000), line 552 in "vmThread.cpp" [14] VMThread::run(this = 0x97d000), line 267 in "vmThread.cpp" [15] thread_native_entry(thread_addr = 0x97d000), line 778 in "os_solaris.cpp" [16] _thrp_setup(), at 0xffff80ffbf515221 [17] _lwp_start(), at 0xffff80ffbf5154c0 Current function is os::Solaris::cond_wait 216 static int cond_wait(cond_t *cv, mutex_t *mx) { return _cond_wait(cv, mx); } The main thread is calling java.lang.Thread.suspend() THREAD t@2 t@2(l@2) stopped in ___lwp_cond_wait at 0xffff80ffbf51e82a 0xffff80ffbf51e82a: ___lwp_cond_wait+0x000a: jae ___lwp_cond_wait+0x18 [ 0xffff80ffbf51e838, .+0xe ] current thread: t@2 [1] ___lwp_cond_wait(0x441b50, 0x441b38, 0x0, 0x0, 0xffff80ffbf4efed8, 0x441b00), at 0xffff80ffbf51e82a [2] _lwp_cond_wait(), at 0xffff80ffbf4efeec =>[3] os::Solaris::cond_wait(cv = 0x441b50, mx = 0x441b38), line 216 in "os_solaris.hpp" [4] os::PlatformEvent::park(this = 0x441b00), line 4985 in "os_solaris.cpp" [5] ParkCommon(ev = 0x441b00, timo = 0), line 399 in "mutex.cpp" [6] Monitor::IWait(this = 0x43dbb0, Self = 0x440000, timo = 0), line 768 in "mutex.cpp" [7] Monitor::wait(this = 0x43dbb0, no_safepoint_check = false, timeout = 0, as_suspend_equivalent = false), line 1106 in "mutex.cpp" [8] VMThread::execute(op = 0xffff80ffbf17e5e8), line 657 in "vmThread.cpp" [9] JavaThread::java_suspend(this = 0x1300800), line 2320 in "thread.cpp" [10] JVM_SuspendThread(env = 0x440388, jthread = 0xffff80ffbf17e7f8), line 3009 in "jvm.cpp" [11] 0xffff80ffa0c1ab8c(), at 0xffff80ffa0c1ab8c [12] 0xffff80ffa0c09fe7(), at 0xffff80ffa0c09fe7 [13] 0xffff80ffa0c09fe7(), at 0xffff80ffa0c09fe7 [14] 0xffff80ffa0c00a2f(), at 0xffff80ffa0c00a2f [15] JavaCalls::call_helper(result = 0xffff80ffbf17ee50, method = CLASS, args = 0xffff80ffbf17ebb0, __the_thread__ = 0x440000), line 451 in "javaCalls.cpp" [16] os::os_exception_wrapper(f = 0xffff80ec49bb0830 = &JavaCalls::call_helper(JavaValue*,const methodHandle&,JavaCallArguments*,Thread*), value = 0xffff80ffbf17ee50, method = CLASS, args = 0xffff80ffbf17ebb0, thread = 0x440000), line 3610 in "os_solaris.cpp" [17] JavaCalls::call(result = 0xffff80ffbf17ee50, method = CLASS, args = 0xffff80ffbf17ebb0, __the_thread__ = 0x440000), line 341 in "javaCalls.cpp" [18] jni_invoke_static(env = 0x440388, result = 0xffff80ffbf17ee50, receiver = (nil), call_type = JNI_STATIC, method_id = 0xf33d80, args = 0xffff80ffbf17ee00, __the_thread__ = 0x440000), line 1123 in "jni.cpp" [19] jni_CallStaticVoidMethod(env = 0x440388, cls = 0x442088, methodID = 0xf33d80, ...), line 1990 in "jni.cpp" [20] JavaMain(_args = 0xffff80ffbfffe530), line 549 in "java.c" [21] _thrp_setup(), at 0xffff80ffbf515221 [22] _lwp_start(), at 0xffff80ffbf5154c0 Current function is PosixSemaphore::wait 64 ret = sem_wait(&_semaphore); This worker thread is trying to exit (there are five of these): THREAD t@15 t@15(l@15) stopped in ___lwp_cond_wait at 0xffff80ffbf51e82a 0xffff80ffbf51e82a: ___lwp_cond_wait+0x000a: jae ___lwp_cond_wait+0x18 [ 0xffff80ffbf51e838, .+0xe ] current thread: t@15 [1] ___lwp_cond_wait(0xb91e50, 0xb91e38, 0x0, 0x0, 0xffff80ffbf4efed8, 0xb91e00), at 0xffff80ffbf51e82a [2] _lwp_cond_wait(), at 0xffff80ffbf4efeec =>[3] os::Solaris::cond_wait(cv = 0xb91e50, mx = 0xb91e38), line 216 in "os_solaris.hpp" [4] os::PlatformEvent::park(this = 0xb91e00), line 4985 in "os_solaris.cpp" [5] ParkCommon(ev = 0xb91e00, timo = 0), line 399 in "mutex.cpp" [6] Monitor::ILock(this = 0x43d910, Self = 0xb90800), line 461 in "mutex.cpp" [7] Monitor::lock_without_safepoint_check(this = 0x43d910, Self = 0xb90800), line 932 in "mutex.cpp" [8] Monitor::lock_without_safepoint_check(this = 0x43d910), line 938 in "mutex.cpp" [9] MutexLockerEx::MutexLockerEx(this = 0xffff80ff8c5feca0, mutex = 0x43d910, no_safepoint_check = true), line 226 in "mutexLocker.hpp" [10] ThreadsSMRSupport::smr_delete(thread = 0xb90800), line 940 in "threadSMR.cpp" [11] JavaThread::smr_delete(this = 0xb90800), line 209 in "thread.cpp" [12] JavaThread::thread_main_inner(this = 0xb90800), line 1800 in "thread.cpp" [13] JavaThread::run(this = 0xb90800), line 1774 in "thread.cpp" [14] thread_native_entry(thread_addr = 0xb90800), line 778 in "os_solaris.cpp" [15] _thrp_setup(), at 0xffff80ffbf515221 [16] _lwp_start(), at 0xffff80ffbf5154c0 Current function is os::Solaris::cond_wait 216 static int cond_wait(cond_t *cv, mutex_t *mx) { return _cond_wait(cv, mx); } This particular combination of threads matches the following recently filed bug: JDK-8212933 Thread-SMR: requesting a VM operation whilst holding a ThreadsListHandle can cause deadlocks
26-10-2018
No instances in jdk-12+16 testing.
25-10-2018
No instances in jdk-12+15 testing.
15-10-2018