jdk19 OpenJDK timeout with call to VirtualThread.notifyJvmtiUnmountBegin #16340

pshipton · 2022-11-18T18:30:39Z

There are other earlier occurrences of this failure in comments of #16259
Other tests where this has been seen (Windows, xlinux, zlinux):
java/lang/Thread/virtual/HoldsLock.java
java/lang/Thread/virtual/stress/GetStackTraceALot.java#id0

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/52
jdk_lang_0
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

Timeout.
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/52/openjdk_test_output.tar.gz

3XMTHREADINFO      "pool-1-thread-1" J9VMThread:0x0000000030539300, omrthread_t:0x000001002365C960, java/lang/Thread:0x00000000FFDA8BB8, state:R, prio=0
3XMJAVALTHREAD            (java/lang/Thread getId:0x24, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000000E0054EF0)
3XMTHREADINFO1            (native thread ID:0x765024D, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x000000a1)
3XMTHREADINFO2            (native stack address range from:0x0000010023670000, to:0x00000100236FE888, size:0x8E888)
3XMCPUTIME               CPU usage total: 0.001914000 secs, user: 0.001821000 secs, system: 0.000093000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/VirtualThread.notifyJvmtiUnmountBegin(Native Method)
4XESTACKTRACE                at java/lang/VirtualThread.yieldContinuation(VirtualThread.java:372)
4XESTACKTRACE                at java/lang/VirtualThread.park(VirtualThread.java:504)
4XESTACKTRACE                at java/lang/Access.parkVirtualThread(Access.java:494)
4XESTACKTRACE                at jdk/internal/misc/VirtualThreads.park(VirtualThreads.java:54)
4XESTACKTRACE                at java/util/concurrent/locks/LockSupport.park(LockSupport.java:369)
4XESTACKTRACE                at ParkWithFixedThreadPool$1.run(ParkWithFixedThreadPool.java:59)
4XESTACKTRACE                at java/lang/VirtualThread.run(VirtualThread.java:292)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation$$Lambda$88/0x000000002361fb58.run(Bytecode PC:8)
4XESTACKTRACE                at jdk/internal/vm/Continuation.execute(Continuation.java:171)

The text was updated successfully, but these errors were encountered:

dmitripivkine · 2022-11-18T19:10:20Z

FYI There is no evidence so far (GC does not block during Unmount) but potentially it might be regression from #16290. Would somebody from VM team triage it first please to be sure what scenario we have deal with?

pshipton · 2022-11-21T22:04:17Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_mac_Nightly/52/
jdk_lang_1
java/lang/Thread/virtual/stress/GetStackTraceALot.java#id0

Timeout, no diagnostics.

pshipton · 2022-11-22T16:02:35Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_windows_Nightly/55
jdk_lang_1
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

Timeout.
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_x86-64_windows_Nightly/55/openjdk_test_output.tar.gz

3XMTHREADINFO      "pool-1-thread-1" J9VMThread:0x0000005A7DD5E000, omrthread_t:0x0000005A68B51148, java/lang/Thread:0x00007FF769B13990, state:R, prio=0
3XMJAVALTHREAD            (java/lang/Thread getId:0x1C, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00007FF749C531A0)
3XMTHREADINFO1            (native thread ID:0x18E8, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x000000a1)
3XMCPUTIME               CPU usage total: 0.0 secs, user: 0.0 secs, system: 0.0 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/VirtualThread.notifyJvmtiUnmountBegin(Native Method)
4XESTACKTRACE                at java/lang/VirtualThread.yieldContinuation(VirtualThread.java:372)
4XESTACKTRACE                at java/lang/VirtualThread.park(VirtualThread.java:504)
4XESTACKTRACE                at java/lang/Access.parkVirtualThread(Access.java:494)
4XESTACKTRACE                at jdk/internal/misc/VirtualThreads.park(VirtualThreads.java:54)
4XESTACKTRACE                at java/util/concurrent/locks/LockSupport.park(LockSupport.java:369)
4XESTACKTRACE                at ParkWithFixedThreadPool$1.run(ParkWithFixedThreadPool.java:59)
4XESTACKTRACE                at java/lang/VirtualThread.run(VirtualThread.java:292)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation$$Lambda$91/0x000000007e0e3898.run(Bytecode PC:8)
4XESTACKTRACE                at jdk/internal/vm/Continuation.execute(Continuation.java:171)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               ZwWaitForSingleObject+0xa (0x00007FF9E6A0021A [ntdll+0x9021a])
4XENATIVESTACK               WaitForSingleObjectEx+0x98 (0x00007FF9E3AE1118 [KERNELBASE+0x1118])
4XENATIVESTACK               omrthread_get_category+0x3e58 (0x00007FF9D6EB7648 [j9thr29+0x7648])
4XENATIVESTACK               omrthread_monitor_wait+0x43 (0x00007FF9D6EB28C3 [j9thr29+0x28c3])
4XENATIVESTACK               JVM_VirtualThreadUnmountBegin+0x292 (0x00007FF9D5809B82 [jvm+0x19b82])
4XENATIVESTACK               ffi_call_go+0x3d1 (0x00007FF9D576FBB1 [j9vm29+0x19fbb1])
4XENATIVESTACK               ffi_call_go+0x20d (0x00007FF9D576F9ED [j9vm29+0x19f9ed])
4XENATIVESTACK               ffi_call_go+0x22 (0x00007FF9D576F802 [j9vm29+0x19f802])

babsingh · 2022-11-22T18:09:49Z

There are different reasons for the timeouts.

Issue

First one: I was able to reproduce the ParkWithFixedThreadPool timeout locally.

Thread 1: JVM_VirtualThreadMountEnd
           -> Acquires VM Access and liveVirtualThreadListMutex
           -> J9AllocateObject
           -> Multiple GC frames
           -> acquireExclusiveVMAccess

Thread 28: JVM_VirtualThreadMountEnd
           -> Acquires VM Access
           -> Blocked to enter liveVirtualThreadListMutex

This is a classic deadlock. Thread 1 wants exclusive VM access but it is unable to acquire exclusive VM access because Thread 28 also holds VM access. Thread 28 is waiting to acquire liveVirtualThreadListMutex and unable to proceed because Thread 1 holds liveVirtualThreadListMutex. This prevents both threads to proceed and leads to a deadlock.

@amicic @dmitripivkine @gacholio Is there a variant of mmFuncs->J9AllocateObject which does not need exclusive VM access? Other solution: we can create the root of liveVirtualThreadList at VM startup or some location where there is no such contention.

Core file, gdb and jdmpview output

https://ibm.box.com/shared/static/liii5foobatpj5dyym2ueigmi8zh63eg.zip

GBD output

======= Thread 1 (Thread 0x7f64c359a700 (LWP 4637)) ======= 
#0  0x00007f65312cead3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7f64ac12914c) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x7f652c006fb8, cond=0x7f64ac129120) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=0x7f64ac129120, mutex=0x7f652c006fb8) at pthread_cond_wait.c:655
#3  0x00007f653063f7f7 in monitor_wait_original (interruptible=0, nanos=0, millis=0, monitor=0x7f652c006f38, self=0x7f64ac128cb0) at /root/openj9-openjdk-jdk/omr/thread/common/omrthread.c:4686
#4  monitor_wait (interruptible=0, nanos=0, millis=0, monitor=0x7f652c006f38) at /root/openj9-openjdk-jdk/omr/thread/common/omrthread.c:4531
#5  omrthread_monitor_wait (monitor=0x7f652c006f38) at /root/openj9-openjdk-jdk/omr/thread/common/omrthread.c:4401
#6  0x00007f65308dbc24 in acquireExclusiveVMAccess (vmThread=0x722100) at /root/openj9-openjdk-jdk/openj9/runtime/vm/VMAccess.cpp:305
#7  0x00007f6529a9e4f9 in MM_EnvironmentBase::acquireExclusiveVMAccess (this=this@entry=0x7f64ac12aef8) at /root/openj9-openjdk-jdk/omr/gc/base/EnvironmentBase.cpp:350
#8  0x00007f6529a9e684 in MM_EnvironmentBase::acquireExclusiveVMAccessForGC (this=0x7f64ac12aef8, collector=0x7f652c08c200, failIfNotFirst=<optimized out>, flushCaches=<optimized out>)
    at /root/openj9-openjdk-jdk/omr/gc/base/EnvironmentBase.cpp:451
#9  0x00007f6529b6cdf8 in MM_MemorySubSpaceSemiSpace::allocationRequestFailed (this=0x7f652c097a80, env=0x7f64ac12aef8, allocateDescription=0x7f64c35970f8, allocationType=MM_MemorySubSpace::ALLOCATION_TYPE_TLH,
    objectAllocationInterface=0x7f64ac12dd80, baseSubSpace=<optimized out>, previousSubSpace=0x7f652c0976e0) at /root/openj9-openjdk-jdk/omr/gc/base/MemorySubSpaceSemiSpace.cpp:99
#10 0x00007f6529b52f18 in MM_MemorySubSpaceGeneric::allocateTLH (this=0x7f652c0976e0, env=0x7f64ac12aef8, allocDescription=0x7f64c35970f8, objectAllocationInterface=0x7f64ac12dd80, baseSubSpace=0x0,
    previousSubSpace=<optimized out>, shouldCollectOnFailure=true) at /root/openj9-openjdk-jdk/omr/gc/base/MemorySubSpaceGeneric.cpp:377
#11 0x00007f6529ac69d4 in MM_TLHAllocationSupport::refresh (this=this@entry=0x7f64ac12de30, env=0x7f64ac12aef8, allocDescription=allocDescription@entry=0x7f64c35970f8, shouldCollectOnFailure=<optimized out>)
    at /root/openj9-openjdk-jdk/omr/gc/base/TLHAllocationSupport.cpp:210
#12 0x00007f6529ac6bbe in MM_TLHAllocationSupport::allocateFromTLH (this=0x7f64ac12de30, env=<optimized out>, allocDescription=0x7f64c35970f8, shouldCollectOnFailure=<optimized out>)
    at /root/openj9-openjdk-jdk/omr/gc/base/TLHAllocationSupport.cpp:279
#13 0x00007f6529ac551a in MM_TLHAllocationInterface::allocateObject (this=0x7f64ac12dd80, env=0x7f64ac12aef8, allocDescription=0x7f64c35970f8, memorySpace=0x7f652c09d0d0, shouldCollectOnFailure=true)
    at /root/openj9-openjdk-jdk/omr/gc/base/TLHAllocationInterface.cpp:183
#14 0x00007f6529acb79b in MM_AllocateInitialization::allocateAndInitializeObject (omrVMThread=<optimized out>, this=0x7f64c35970e0) at /root/openj9-openjdk-jdk/omr/gc/base/AllocateInitialization.hpp:201
#15 OMR_GC_AllocateObject (omrVMThread=<optimized out>, allocator=allocator@entry=0x7f64c35970e0) at /root/openj9-openjdk-jdk/omr/gc/startup/omrgcalloc.cpp:39
#16 0x00007f65299d4ee6 in J9AllocateObject (vmThread=0x722100, clazz=0x95900, allocateFlags=<optimized out>) at /root/openj9-openjdk-jdk/openj9/runtime/gc_modron_startup/mgcalloc.cpp:416
#17 0x00007f6530e84f51 in JVM_VirtualThreadMountEnd (env=0x722100, thread=0x38d788, firstMount=<optimized out>) at /root/openj9-openjdk-jdk/openj9/runtime/j9vm/javanextvmi.cpp:335
#18 0x00007f6530a0891a in ffi_call_unix64 () at /root/openj9-openjdk-jdk/openj9/runtime/libffi/x86/unix64.S:105
#19 0x00007f6530a06bfc in ffi_call_int (cif=0x7f64c3597710, fn=0x7f65310b8700 <JVM_VirtualThreadMountEnd>, rvalue=<optimized out>, avalue=0x7f64c35977b0, closure=<optimized out>)
    at /root/openj9-openjdk-jdk/openj9/runtime/libffi/x86/ffi64.c:672
...

======= Thread 28 (Thread 0x7f64c361b700 (LWP 4636)) ======= 
Thread 28 (Thread 0x7f64c361b700 (LWP 4636)):
#0  0x00007f65312cead3 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7f64a800ef20) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x7f652c0732c8, cond=0x7f64a800eef8) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=0x7f64a800eef8, mutex=0x7f652c0732c8) at pthread_cond_wait.c:655
#3  0x00007f653063bb9f in monitor_enter_three_tier (self=0x7f64a800ea88, monitor=0x7f652c073248, isAbortable=0) at /root/openj9-openjdk-jdk/omr/thread/common/omrthread.c:4058
#4  0x00007f6530e848f1 in JVM_VirtualThreadMountEnd (env=0x71e500, thread=0x38a248, firstMount=<optimized out>) at /root/openj9-openjdk-jdk/openj9/runtime/j9vm/javanextvmi.cpp:312
#5  0x00007f6530a0891a in ffi_call_unix64 () at /root/openj9-openjdk-jdk/openj9/runtime/libffi/x86/unix64.S:105
#6  0x00007f6530a06bfc in ffi_call_int (cif=0x7f64c3618710, fn=0x7f65310b8700 <JVM_VirtualThreadMountEnd>, rvalue=<optimized out>, avalue=0x7f64c36187b0, closure=<optimized out>)
    at /root/openj9-openjdk-jdk/openj9/runtime/libffi/x86/ffi64.c:672
...

amicic · 2022-11-22T18:19:20Z

There is J9AllocateObjectNoGC that will return NULL, rather than trigger GC (hence not request exclusive VM access)

gacholio · 2022-11-22T18:35:16Z

This is not a real solution - if it returns NULL you'll have to abort the VM.

gacholio · 2022-11-22T18:38:11Z

Can you allocate the object without acquiring the mutex? After acquiring the mutex, if the object has already been allocated by another thread, just leave newly-allocated one to die. The standard check before mutex should make this infrequent, i.e. before acquiring the mutex, see if the head object is already allocated.

gacholio · 2022-11-22T18:40:36Z

Even better, why not just allocate the head at VM startup?

amicic · 2022-11-22T18:41:28Z

After having a look at the code, and understanding the nature of this alloc, seems like this allocate is only on first mount, so likely should be able to do it early at startup, what @babsingh was already suggesting.

babsingh · 2022-11-22T18:42:01Z

re #16340 (comment) and #16340 (comment): Both solutions should be feasible. I am leaning towards VM startup, which was also previously mentioned in #16340 (comment).

gacholio · 2022-11-22T19:00:33Z

Remember in general that VM access should be treated like a mutex. Acquiring exclusive may release and reacquire VM access, so holding any mutex going for exclusive (and by extension allocating an object) is invalid.

babsingh · 2022-11-22T19:11:48Z

Continuing #16340 (comment) ... There are different reasons for the timeouts.

The second timeout happens at VirtualThread.notifyJvmtiUnmountBegin. This timeout was reported in #16340 (comment) and #16340 (comment).

This timeout was also previously discussed in the following comments:

Symptoms:

The virtual thread is waiting to be notified on J9JavaVM->liveVirtualThreadListMutex;
VirtualThread.inspectorCount is 0xFFFFFFFFFFFFFFFF (= -1); and
VirtualThread.linkNext and VirtualThread.linkPrevious fields are NULL.

Two possible scenarios which can create the above symptoms:

Scenario 1: notifyJvmtiMountEnd was not invoked after notifyJvmtiMountBegin, and the thread was not appended to liveVirtualThreadList.
Scenario 2: notifyJvmtiUnmountBegin was invoked twice consecutively without a call to notifyJvmtiUnmountEnd.

@fengxue-IS Thoughts? In VirtualThread.park -> yieldContinuation, Continuation.yield will stop the thread, and notifyJvmtiMountEnd won't be invoked after notifyJvmtiUnmountBegin. Can two threads concurrently invoke VirtualThread.park and cause the above symptoms?

jdmpview output

VT_notifyJvmtiUnmountBegin_timeout.log

fengxue-IS · 2022-11-22T20:33:25Z

@babsingh

In VirtualThread.park -> yieldContinuation, Continuation.yield will stop the thread, and notifyJvmtiMountEnd won't be invoked after notifyJvmtiUnmountBegin.

Continuation.yield will pause the virtual thread execution and return to carrier thread stack which triggered the continuation mounting through cont.run and continue at https://github.com/ibmruntimes/openj9-openjdk-jdk19/blob/openj9/src/java.base/share/classes/java/lang/VirtualThread.java#L223

The two methods (afterTerminate/afterYield) will both call notifyJvmtiUnmountEnd

So Scenario 1 is not possible, since if notifyJvmtiMountEnd was not invoked after notifyJvmtiMountBegin, then the vthread must not be mounted and invoke notifyJvmtiUnmountEnd

Can two threads concurrently invoke VirtualThread.park and cause the above symptoms?

Maybe, I am not sure how exposed is VirtualThread.park() to other threads, will have to verify if this is possible.

gacholio · 2022-11-22T23:55:17Z

park() on normal Threads applies implicitly to the current thread. Is the behaviour different for vthreads?

babsingh · 2022-11-23T00:03:31Z

park() on normal Threads applies implicitly to the current thread. Is the behaviour different for vthreads?

I believe that it is the same. So, it won't be possible for two threads to concurrently invoke park() on the same virtual thread. But, sequentially invoking park() twice on the same virtual thread may be possible and have similar symptoms to the ones that are described in #16340 (comment).

Related code:

openj9/jcl/src/java.base/share/classes/java/lang/Access.java

Lines 586 to 600 in 55c52ff

    
           public void parkVirtualThread() { 
        
           	if (Thread.currentThread() instanceof BaseVirtualThread bvt) { 
        
           		bvt.park(); 
        
           	} else { 
        
           		throw new WrongThreadException(); 
        
           	} 
        
           } 
        
           public void parkVirtualThread(long nanos) { 
        
           	if (Thread.currentThread() instanceof BaseVirtualThread bvt) { 
        
           		bvt.parkNanos(nanos); 
        
           	} else { 
        
           		throw new WrongThreadException(); 
        
           	} 
        
           }

pshipton · 2022-11-23T13:30:35Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/55
jdk_lang_1
java/lang/Thread/virtual/HoldsLock.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/55/openjdk_test_output.tar.gz

3XMTHREADINFO      "Thread-4" J9VMThread:0x00000100232A2800, omrthread_t:0x000001002303EE68, java/lang/Thread:0x0A0000001FF916E0, state:R, prio=0
3XMJAVALTHREAD            (java/lang/Thread getId:0x25, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0A000000000708D0)
3XMTHREADINFO1            (native thread ID:0x50403C5, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x000000a1)
3XMTHREADINFO2            (native stack address range from:0x0000010023850000, to:0x00000100238D3888, size:0x83888)
3XMCPUTIME               CPU usage total: 0.002800000 secs, user: 0.002716000 secs, system: 0.000084000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/VirtualThread.notifyJvmtiUnmountBegin(Native Method)
4XESTACKTRACE                at java/lang/VirtualThread.run(VirtualThread.java:310)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:179)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation$$Lambda$91/0x0000000023210f18.run(Bytecode PC:8)
4XESTACKTRACE                at jdk/internal/vm/Continuation.execute(Continuation.java:171)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               _event_wait+0x350 (0x0900000000576BF4 [libpthreads.a+0x19bf4])
4XENATIVESTACK               _cond_wait_local+0x514 (0x0900000000585FB8 [libpthreads.a+0x28fb8])
4XENATIVESTACK               _cond_wait+0x34 (0x0900000000586598 [libpthreads.a+0x29598])
4XENATIVESTACK               pthread_cond_wait+0x1a8 (0x0900000000586FAC [libpthreads.a+0x29fac])
4XENATIVESTACK               IPRA.$monitor_wait_original+0xa10 (0x09000000043F5494 [libj9thr29.so+0xa494])
4XENATIVESTACK               omrthread_monitor_wait+0x44 (0x09000000043F4A28 [libj9thr29.so+0x9a28])
4XENATIVESTACK               JVM_VirtualThreadUnmountBegin+0x270 (0x0900000003F71B94 [libjvm.so+0x59b94])
4XENATIVESTACK               JVM_VirtualThreadUnmountBegin+0x5c (0x0900000003F08A00 [libjvm.so+0x1ca00])
4XENATIVESTACK               JVM_VirtualThreadUnmountBegin+0x5c (0x0900000003EDCA00 [libjvm.so+0x1ca00])
4XENATIVESTACK               (0x09000000040696BC [libj9vm29.so+0xe06bc])
4XENATIVESTACK               ffi_call+0x110 (0x0900000004068FF4 [libj9vm29.so+0xdfff4])

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_linux_Nightly/55
jdk_lang_1
java/lang/Thread/virtual/HoldsLock.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_x86-64_linux_Nightly/55/openjdk_test_output.tar.gz

3XMTHREADINFO      "Thread-4" J9VMThread:0x00007FA118242D00, omrthread_t:0x00007FA118021B48, java/lang/Thread:0x00007FA1C63D26A8, state:R, prio=0
3XMJAVALTHREAD            (java/lang/Thread getId:0x1D, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00007FA1A6672870)
3XMTHREADINFO1            (native thread ID:0x910, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x000000a1)
3XMTHREADINFO2            (native stack address range from:0x00007FA184B2E000, to:0x00007FA184BAF000, size:0x81000)
3XMCPUTIME               CPU usage total: 0.008274482 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/VirtualThread.notifyJvmtiUnmountBegin(Native Method)
4XESTACKTRACE                at java/lang/VirtualThread.run(Bytecode PC:106)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation.lambda$new$0(Bytecode PC:2)
4XESTACKTRACE                at java/lang/VirtualThread$VThreadContinuation$$Lambda$91/0x0000000018249ac8.run(Bytecode PC:8)
4XESTACKTRACE                at jdk/internal/vm/Continuation.execute(Bytecode PC:6)

pshipton · 2022-11-23T13:42:01Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_mac_Nightly/54
jdk_lang_0
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

No diagnostics.

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_windows_Nightly/56
jdk_lang_0
jdk_lang_1
java/lang/Thread/virtual/HoldsLock.java

No diagnostics.

pshipton · 2022-11-27T22:50:00Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_windows_Nightly/57
jdk_lang_1
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_x86-64_windows_Nightly/57/openjdk_test_output.tar.gz

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_mac_Nightly/60
jdk_lang_1
java/lang/Thread/virtual/stress/GetStackTraceALot.java#id0

No diagnostics

This change fixes the below deadlock. Thread 1 wants exclusive VM access but it is unable to acquire exclusive VM access because Thread 2 also holds VM access. Thread 2 is waiting to acquire liveVirtualThreadListMutex and unable to proceed because Thread 1 holds liveVirtualThreadListMutex. This prevents both threads to proceed and leads to a deadlock. Thread 1: JVM_VirtualThreadMountEnd -> Acquires VM Access and liveVirtualThreadListMutex -> J9AllocateObject -> Multiple GC frames -> acquireExclusiveVMAccess Thread 2: JVM_VirtualThreadMountEnd -> Acquires VM Access -> Blocked to enter liveVirtualThreadListMutex Related: eclipse-openj9#16340 Signed-off-by: Babneet Singh <sbabneet@ca.ibm.com>

pshipton · 2022-12-01T15:09:29Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/61/
jdk_lang_0
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_Nightly/61/openjdk_test_output.tar.gz

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_Nightly/60
jdk_lang_0
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_Nightly/60/openjdk_test_output.tar.gz

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_s390x_linux_Nightly/63
jdk_lang_1
java/lang/Thread/virtual/ParkWithFixedThreadPool.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_s390x_linux_Nightly/63/openjdk_test_output.tar.gz

This change fixes the below deadlock. Thread 1 wants exclusive VM access but it is unable to acquire exclusive VM access because Thread 2 also holds VM access. Thread 2 is waiting to acquire liveVirtualThreadListMutex and unable to proceed because Thread 1 holds liveVirtualThreadListMutex. This prevents both threads to proceed and leads to a deadlock. Thread 1: JVM_VirtualThreadMountEnd -> Acquires VM Access and liveVirtualThreadListMutex -> J9AllocateObject -> Multiple GC frames -> acquireExclusiveVMAccess Thread 2: JVM_VirtualThreadMountEnd -> Acquires VM Access -> Blocked to enter liveVirtualThreadListMutex Related: eclipse-openj9#16340 Signed-off-by: Babneet Singh <sbabneet@ca.ibm.com>

tajila · 2022-12-05T19:15:47Z

closing the issue as the fix is in

pshipton added comp:vm test failure jdk19 labels Nov 18, 2022

pshipton added this to the Java 19 milestone Nov 18, 2022

pshipton mentioned this issue Nov 18, 2022

jdk19 OpenJDK crash JVM_VirtualThreadUnmountBegin #16259

Closed

babsingh mentioned this issue Nov 22, 2022

JDK19 java/lang/Thread/virtual/stress/GetStackTraceALot.java#id0 - Segmentation error vmState=0x0002000f #16351

Closed

babsingh mentioned this issue Nov 29, 2022

Initialize J9JavaVM->liveVirtualThreadList at startup #16384

Closed

babsingh mentioned this issue Nov 30, 2022

Invoke J9AllocateObject without acquiring liveVirtualThreadListMutex #16389

Merged

tajila closed this as completed Dec 5, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

jdk19 OpenJDK timeout with call to VirtualThread.notifyJvmtiUnmountBegin #16340

jdk19 OpenJDK timeout with call to VirtualThread.notifyJvmtiUnmountBegin #16340

pshipton commented Nov 18, 2022 •

edited

Loading

dmitripivkine commented Nov 18, 2022 •

edited

Loading

pshipton commented Nov 21, 2022

pshipton commented Nov 22, 2022 •

edited

Loading

babsingh commented Nov 22, 2022 •

edited

Loading

amicic commented Nov 22, 2022

gacholio commented Nov 22, 2022

gacholio commented Nov 22, 2022

gacholio commented Nov 22, 2022

amicic commented Nov 22, 2022

babsingh commented Nov 22, 2022 •

edited

Loading

gacholio commented Nov 22, 2022

babsingh commented Nov 22, 2022 •

edited

Loading

fengxue-IS commented Nov 22, 2022

gacholio commented Nov 22, 2022

babsingh commented Nov 23, 2022 •

edited

Loading

pshipton commented Nov 23, 2022 •

edited

Loading

pshipton commented Nov 23, 2022 •

edited

Loading

pshipton commented Nov 27, 2022

pshipton commented Dec 1, 2022 •

edited

Loading

tajila commented Dec 5, 2022

jdk19 OpenJDK timeout with call to VirtualThread.notifyJvmtiUnmountBegin #16340

jdk19 OpenJDK timeout with call to VirtualThread.notifyJvmtiUnmountBegin #16340

Comments

pshipton commented Nov 18, 2022 • edited Loading

dmitripivkine commented Nov 18, 2022 • edited Loading

pshipton commented Nov 21, 2022

pshipton commented Nov 22, 2022 • edited Loading

babsingh commented Nov 22, 2022 • edited Loading

Issue

Core file, gdb and jdmpview output

GBD output

amicic commented Nov 22, 2022

gacholio commented Nov 22, 2022

gacholio commented Nov 22, 2022

gacholio commented Nov 22, 2022

amicic commented Nov 22, 2022

babsingh commented Nov 22, 2022 • edited Loading

gacholio commented Nov 22, 2022

babsingh commented Nov 22, 2022 • edited Loading

jdmpview output

fengxue-IS commented Nov 22, 2022

gacholio commented Nov 22, 2022

babsingh commented Nov 23, 2022 • edited Loading

pshipton commented Nov 23, 2022 • edited Loading

pshipton commented Nov 23, 2022 • edited Loading

pshipton commented Nov 27, 2022

pshipton commented Dec 1, 2022 • edited Loading

tajila commented Dec 5, 2022

pshipton commented Nov 18, 2022 •

edited

Loading

dmitripivkine commented Nov 18, 2022 •

edited

Loading

pshipton commented Nov 22, 2022 •

edited

Loading

babsingh commented Nov 22, 2022 •

edited

Loading

babsingh commented Nov 22, 2022 •

edited

Loading

babsingh commented Nov 22, 2022 •

edited

Loading

babsingh commented Nov 23, 2022 •

edited

Loading

pshipton commented Nov 23, 2022 •

edited

Loading

pshipton commented Nov 23, 2022 •

edited

Loading

pshipton commented Dec 1, 2022 •

edited

Loading