openj9
openj9 copied to clipboard
Published
20 hours ago •
eclipse-openj9
eclipse-openj9
serviceability_jvmti_j9_0 serviceability/jvmti/ObjectMonitorUsage/ObjectMonitorUsage.java timed out
Failure link
From internal Test_openjdk24_j9_extended.openjdk_ppc64le_linux_testList_2 (sles15le-svl-rt3-1)
openjdk version "24.0.1-beta" 2025-04-15
IBM Semeru Runtime Open Edition 24.0.1+9-202505150003 (build 24.0.1-beta+9-202505150003)
Eclipse OpenJ9 VM 24.0.1+9-202505150003 (build master-9a36a00f72, JRE 24 Linux ppc64le-64-Bit Compressed References 20250515_60 (JIT enabled, AOT enabled)
OpenJ9 - 9a36a00f72
OMR - b9fa405a4
JCL - b819e31a4 based on jdk-24.0.1+9)
Rerun in Grinder - Change TARGET to run only the failed test targets
Optional info
Failure output (captured from console output)
[2025-05-15T01:23:03.393Z] variation: Mode150
[2025-05-15T01:23:03.393Z] JVM_OPTIONS: -XX:+UseCompressedOops -Xverbosegclog
[2025-05-15T01:41:01.440Z] TEST: serviceability/jvmti/ObjectMonitorUsage/ObjectMonitorUsage.java
[2025-05-15T01:41:01.443Z] TEST RESULT: Error. Program `/home/jenkins/workspace/Test_openjdk24_j9_extended.openjdk_ppc64le_linux_testList_2/jdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 964546ms).
[2025-05-15T01:41:01.443Z] --------------------------------------------------
[2025-05-15T01:41:01.443Z] Test results: passed: 162; error: 1
[2025-05-15T01:41:13.098Z] serviceability_jvmti_j9_0_FAILED
50x internal Grinder - 9 timed out
17 assertion failure j9shr.1552 * ** ASSERTION FAILED ** at openj9/runtime/shared_common/SCImplementedAPI.cpp:479: ((currentThread)->publicFlags & J9_PUBLIC_FLAGS_VM_ACCESS)
- https://github.com/eclipse-openj9/openj9/issues/21824
Looked at core.20250515.085412.835.0001.dmp & javacore.20250515.085414.835.0002.txt
3XMTHREADINFO "MainThread" J9VMThread:0x00000000002B6800, omrthread_t:0x00007FFF882655C8, java/lang/Thread:0x00000000E00C0218, state:P, rawStateValue:0x80, prio=5
3XMJAVALTHREAD (java/lang/Thread getId:0x18, isDaemon:false)
3XMJAVALTHRCCL jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000000E0056E10)
3XMTHREADINFO1 (native thread ID:0x37E, native priority:0x5, native policy:UNKNOWN, vmstate:P, vm thread flags:0x00020081)
3XMTHREADINFO2 (native stack address range from:0x00007FFF6BF80000, to:0x00007FFF6C000000, size:0x80000)
3XMCPUTIME CPU usage total: 0.156638786 secs, current category="Application"
3XMTHREADBLOCK Parked on: java/util/concurrent/CountDownLatch$Sync@0x00000000FFDC1A90 Owned by: <unknown>
3XMHEAPALLOC Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3 Java callstack:
4XESTACKTRACE at jdk/internal/misc/Unsafe.park(Native Method)
4XESTACKTRACE at java/util/concurrent/locks/LockSupport.park(LockSupport.java:223)
4XESTACKTRACE at java/util/concurrent/locks/AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:789)
4XESTACKTRACE at java/util/concurrent/locks/AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1138)
4XESTACKTRACE at java/util/concurrent/CountDownLatch.await(CountDownLatch.java:230)
4XESTACKTRACE at java/lang/VirtualThread.joinNanos(VirtualThread.java:1006)
4XESTACKTRACE at java/lang/Thread.join(Thread.java:1878)
4XESTACKTRACE at java/lang/Thread.join(Thread.java:1971)
4XESTACKTRACE at ObjectMonitorUsage.joinThreads(ObjectMonitorUsage.java:111)
4XESTACKTRACE at ObjectMonitorUsage.test1(ObjectMonitorUsage.java:199)
4XESTACKTRACE at ObjectMonitorUsage.test(ObjectMonitorUsage.java:321)
4XESTACKTRACE at ObjectMonitorUsage.main(ObjectMonitorUsage.java:331)
4XESTACKTRACE at java/lang/invoke/LambdaForm$DMH/0x000000000400d130.invokeStatic(LambdaForm$DMH)
4XESTACKTRACE at java/lang/invoke/LambdaForm$MH/0x0000000004013420.invoke(LambdaForm$MH)
4XESTACKTRACE at java/lang/invoke/LambdaForm$MH/0x0000000004013940.invokeExact_MT(LambdaForm$MH)
4XESTACKTRACE at jdk/internal/reflect/DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:155)
4XESTACKTRACE at jdk/internal/reflect/DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
4XESTACKTRACE at java/lang/reflect/Method.invoke(Method.java:571)
4XESTACKTRACE at com/sun/javatest/regtest/agent/MainWrapper$MainTask.run(MainWrapper.java:138)
4XESTACKTRACE at java/lang/Thread.runWith(Thread.java:1471)
4XESTACKTRACE at java/lang/Thread.run(Thread.java:1458)
MainThread is a virtual thread awaiting for termination at https://github.com/ibmruntimes/openj9-openjdk-jdk24/blob/b1ac779dfbfebf988be3c8b3a24aafaa23c33c62/src/java.base/share/classes/java/lang/VirtualThread.java#L1006
which was parked at https://github.com/ibmruntimes/openj9-openjdk-jdk24/blob/b1ac779dfbfebf988be3c8b3a24aafaa23c33c62/src/java.base/share/classes/java/util/concurrent/locks/LockSupport.java#L223 but never received a permit for returning.
> !stack 0x002b6800
<2b6800> !j9method 0x00000000000C66B0 jdk/internal/misc/Unsafe.park(ZJ)V
<2b6800> !j9method 0x0000000000100848 java/util/concurrent/locks/LockSupport.park(Ljava/lang/Object;)V
<2b6800> !j9method 0x00000000001AE870 java/util/concurrent/locks/AbstractQueuedSynchronizer.acquire(Ljava/util/concurrent/locks/AbstractQueuedSynchronizer$Node;IZZZJ)I
<2b6800> !j9method 0x00000000001AEA30 java/util/concurrent/locks/AbstractQueuedSynchronizer.acquireSharedInterruptibly(I)V
<2b6800> !j9method 0x00000000002ED568 java/util/concurrent/CountDownLatch.await()V
<2b6800> !j9method 0x0000000000107390 java/lang/VirtualThread.joinNanos(J)Z
<2b6800> !j9method 0x00000000000EAE08 java/lang/Thread.join(J)V
<2b6800> !j9method 0x00000000000EAE48 java/lang/Thread.join()V
<2b6800> !j9method 0x00000000002A6BD8 ObjectMonitorUsage.joinThreads([Ljava/lang/Thread;)V
<2b6800> !j9method 0x00000000002A6C58 ObjectMonitorUsage.test1(Z)V
<2b6800> !j9method 0x00000000002A6CB8 ObjectMonitorUsage.test(Z)V
<2b6800> !j9method 0x00000000002A6CD8 ObjectMonitorUsage.main([Ljava/lang/String;)V
<2b6800> !j9method 0x00000000002B52A8 java/lang/invoke/LambdaForm$DMH/0x000000000400d130.invokeStatic(Ljava/lang/Object;Ljava/lang/Object;)V
<2b6800> !j9method 0x00000000002C6CB8 java/lang/invoke/LambdaForm$MH/0x0000000004013420.invoke(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;
<2b6800> !j9method 0x00000000002C71B8 java/lang/invoke/LambdaForm$MH/0x0000000004013940.invokeExact_MT(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;
<2b6800> !j9method 0x0000000000255298 jdk/internal/reflect/DirectMethodHandleAccessor.invokeImpl(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;
<2b6800> !j9method 0x0000000000255258 jdk/internal/reflect/DirectMethodHandleAccessor.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;
<2b6800> !j9method 0x00000000000E2050 java/lang/reflect/Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;
<2b6800> !j9method 0x00000000002A64E8 com/sun/javatest/regtest/agent/MainWrapper$MainTask.run()V
<2b6800> !j9method 0x00000000000EAB88 java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V
<2b6800> !j9method 0x00000000000EAB68 java/lang/Thread.run()V
<2b6800> JNI call-in frame
<2b6800> Native method frame
**<2b6800> Bytecode frame: bp = 0x00000000002BC9B0, sp = 0x00000000002BC9A0, pc = 0x00007FFF350C410E, cp = 0x00000000000EB510, arg0EA = 0x00000000002BC9B8, flags = 0x0000000000000000
<2b6800> Method: java/lang/Thread.join()V !j9method 0x00000000000EAE48
<2b6800> Bytecode index = 2
<2b6800> Using debug local mapper
<2b6800> Locals starting at 0x00000000002BC9B8 for 0x0000000000000001 slots
<2b6800> O-Slot: a0[0x00000000002BC9B8] = 0x00000000FFEEA430
> !j9object 0x00000000FFEEA430
!J9Object 0x00000000FFEEA430 {
struct J9Class* clazz = !j9class 0x107C00 // java/lang/VirtualThread
Object flags = 0x00000012;
I lockword = 0x00000008 (offset = 0) (java/lang/Object) <hidden>
J eetop = 0x0000000000000000 (offset = 4) (java/lang/Thread)
J tid = 0x000000000000003C (offset = 12) (java/lang/Thread)
Ljava/lang/String; name = !fj9object 0xffeec148 (offset = 44) (java/lang/Thread)
Z interrupted = 0x00000000 (offset = 96) (java/lang/Thread)
Ljava/lang/ClassLoader; contextClassLoader = !fj9object 0xe0056e10 (offset = 48) (java/lang/Thread)
Ljava/lang/Thread$FieldHolder; holder = !fj9object 0x0 (offset = 52) (java/lang/Thread)
Ljava/lang/ThreadLocal$ThreadLocalMap; threadLocals = !fj9object 0x0 (offset = 56) (java/lang/Thread)
Ljava/lang/ThreadLocal$ThreadLocalMap; inheritableThreadLocals = !fj9object 0x0 (offset = 60) (java/lang/Thread)
Ljava/lang/Object; scopedValueBindings = !fj9object 0xe00027c8 (offset = 64) (java/lang/Thread)
Ljava/lang/Object; interruptLock = !fj9object 0xffeec160 (offset = 68) (java/lang/Thread)
Ljava/lang/Object; parkBlocker = !fj9object 0x0 (offset = 72) (java/lang/Thread)
Lsun/nio/ch/Interruptible; nioBlocker = !fj9object 0x0 (offset = 76) (java/lang/Thread)
Ljdk/internal/vm/Continuation; cont = !fj9object 0x0 (offset = 80) (java/lang/Thread)
Ljava/lang/Thread$UncaughtExceptionHandler; uncaughtExceptionHandler = !fj9object 0x0 (offset = 84) (java/lang/Thread)
J threadLocalRandomSeed = 0x0000000000000000 (offset = 20) (java/lang/Thread)
I threadLocalRandomProbe = 0x00000000 (offset = 100) (java/lang/Thread)
I threadLocalRandomSecondarySeed = 0x00000000 (offset = 104) (java/lang/Thread)
Ljdk/internal/vm/ThreadContainer; container = !fj9object 0xffee1f58 (offset = 88) (java/lang/Thread)
Ljdk/internal/vm/StackableScope; headStackableScopes = !fj9object 0x0 (offset = 92) (java/lang/Thread)
Z started = 0x00000000 (offset = 108) (java/lang/Thread)
J tls = 0x0000000000000000 (offset = 36) (java/lang/Thread) <hidden>
J internalSuspendState = 0x0000000000000000 (offset = 28) (java/lang/Thread) <hidden>
Ljava/util/concurrent/Executor; scheduler = !fj9object 0xffee0798 (offset = 132) (java/lang/VirtualThread)
Ljdk/internal/vm/Continuation; cont = !fj9object 0xffeea9e8 (offset = 136) (java/lang/VirtualThread)
Ljava/lang/Runnable; runContinuation = !fj9object 0xffeeaa20 (offset = 140) (java/lang/VirtualThread)
I state = 0x00000002 (offset = 112) (java/lang/VirtualThread)
Z parkPermit = 0x00000000 (offset = 160) (java/lang/VirtualThread)
Z blockPermit = 0x00000000 (offset = 164) (java/lang/VirtualThread)
Z onWaitingList = 0x00000000 (offset = 168) (java/lang/VirtualThread)
Ljava/lang/VirtualThread; next = !fj9object 0x0 (offset = 144) (java/lang/VirtualThread)
Z notified = 0x00000000 (offset = 172) (java/lang/VirtualThread)
B timedWaitSeqNo = 0x00000000 (offset = 176) (java/lang/VirtualThread)
J timeout = 0x0000000000000000 (offset = 116) (java/lang/VirtualThread)
Ljava/util/concurrent/Future; timeoutTask = !fj9object 0x0 (offset = 148) (java/lang/VirtualThread)
Ljava/lang/Thread; carrierThread = !fj9object 0xffeea8f8 (offset = 152) (java/lang/VirtualThread)
Ljava/util/concurrent/CountDownLatch; termination = !fj9object 0xffeea420 (offset = 156) (java/lang/VirtualThread)
J inspectorCount = 0x0000000000000000 (offset = 124) (java/lang/VirtualThread) <hidden>
}
J eetop = 0x0000000000000000 (offset = 4) (java/lang/Thread) indicates that this VirtualThread already terminated.
I lockword = 0x00000008 (offset = 0) (java/lang/Object) <hidden> seems a invalid state like https://github.com/eclipse-openj9/openj9/issues/21639#issuecomment-2852811671
@babsingh does this appear a dup of https://github.com/eclipse-openj9/openj9/issues/21826?
After analyzing the four virtual threads below, this does not appear to be a duplicate of https://github.com/eclipse-openj9/openj9/issues/21826.
- All virtual thread stacks are JIT-compiled, including the
ObjectMonitorUsage$EnteringTask.run()Vmethod, where thesynchronizedblock resides. - VT0 is mounted to a carrier thread and is about to enter the object monitor in
ObjectMonitorUsage$EnteringTask.run()V. In contrast, VT1, VT2, and VT3 are currently unmounted and waiting to acquire the same object monitor. - This appears to be a JIT-related issue (fyi @hzongaro).
- @JasonFengJ9 Do you have access to the native stack for
0x002dd900(ForkJoinPool-1-worker-6)? It could help identify why VT0 is stuck when trying to acquire the monitor. - As a diagnostic step, @JasonFengJ9 does the issue still occur when running with
-Xintor with-Xjit:exclude={*ObjectMonitorUsage$EnteringTask.run*}? Note: Verify the syntax for the-Xjitoption before using. - @fengxue-IS Would you happen to know why
J9ObjectMonitor->platformThreadWaitCountandJ9Thread->ownerare showing invalid values in the failing scenario?
> !vthreads
!continuationstack 0x00007ffee4003470 !j9vmcontinuation 0x00007ffee4003470 !j9object 0x00000000FFEEA9E8 (Continuation) !j9object 0x00000000FFEEA430 (VThread) - EnteringVT0
!continuationstack 0x00007ffee4005a80 !j9vmcontinuation 0x00007ffee4005a80 !j9object 0x00000000FFEEDBB0 (Continuation) !j9object 0x00000000FFEEC170 (VThread) - EnteringVT1
!continuationstack 0x00007ffee4006e00 !j9vmcontinuation 0x00007ffee4006e00 !j9object 0x00000000FFEEDC20 (Continuation) !j9object 0x00000000FFEEC230 (VThread) - EnteringVT2
!continuationstack 0x00007ffee4008180 !j9vmcontinuation 0x00007ffee4008180 !j9object 0x00000000FFEEDC90 (Continuation) !j9object 0x00000000FFEEC2F0 (VThread) - EnteringVT3
> All four virtual threads have the below stack.
<7ffee4005a80> known but unhandled frame type com.ibm.j9ddr.vm29.pointer.U8Pointer @ 0x00000005
FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT FAULT
<7ffee4005a80> !j9method 0x00000000002A7B00 ObjectMonitorUsage$EnteringTask.run()V
<7ffee4005a80> !j9method 0x00000000000EAB88 java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V
<7ffee4005a80> !j9method 0x0000000000107130 java/lang/VirtualThread.run(Ljava/lang/Runnable;)V
<7ffee4005a80> !j9method 0x00000000003031E8 java/lang/VirtualThread$VThreadContinuation$1.run()V
<7ffee4005a80> !j9method 0x0000000000118270 jdk/internal/vm/Continuation.enter(Ljdk/internal/vm/Continuation;)V
<7ffee4005a80> JNI call-in frame
<7ffee4005a80> Native method frame
> !j9object 0x00000000FFEEDBB0 (Continuation)
!J9Object 0x00000000FFEEDBB0 {
struct J9Class* clazz = !j9class 0x302C00 // java/lang/VirtualThread$VThreadContinuation
Object flags = 0x00000010;
I lockword = 0x00000008 (offset = 0) (java/lang/Object) <hidden>
J vmRef = 0x00007FFEE4005A80 (offset = 4) (jdk/internal/vm/Continuation)
Ljava/lang/Thread; vthread = !fj9object 0xffeec170 (offset = 20) (jdk/internal/vm/Continuation)
Ljava/lang/Object; blocker = !fj9object 0xe0048ef0 (offset = 24) (jdk/internal/vm/Continuation) <--- blocked object
[Ljava/lang/Object; scopedValueCache = !fj9object 0x0 (offset = 28) (jdk/internal/vm/Continuation)
Ljdk/internal/vm/ContinuationScope; scope = !fj9object 0xffee0788 (offset = 32) (jdk/internal/vm/Continuation)
Ljava/lang/Runnable; runnable = !fj9object 0xffeeef90 (offset = 36) (jdk/internal/vm/Continuation)
Ljdk/internal/vm/Continuation; parent = !fj9object 0x0 (offset = 40) (jdk/internal/vm/Continuation)
J state = 0x0000000000000001 (offset = 12) (jdk/internal/vm/Continuation)
Z isAccessible = 0x00000001 (offset = 44) (jdk/internal/vm/Continuation)
I continuationLink = 0xFFEEDC20 (offset = 48) (jdk/internal/vm/Continuation) <hidden>
}
> !fj9object 0xe0048ef0
!J9Object 0x00000000E0048EF0 {
struct J9Class* clazz = !j9class 0xB2400 // java/lang/Object
Object flags = 0x00000002;
I lockword = 0x000933C9 (offset = 0) (java/lang/Object) <hidden> <--- Inflated object monitor
}
> !j9objectmonitor 0x00000000000933C8
J9ObjectMonitor at 0x933c8 {
Fields for J9ObjectMonitor:
0x0: struct J9ThreadMonitor* monitor = !j9threadmonitor 0x00007FFF14006D08
0x8: UDATA proDeflationCount = 0x000000000000001A (26)
0x10: UDATA antiDeflationCount = 0x000000000000000C (12)
0x18: j9objectmonitor_t alternateLockword = !j9x 0x933e0
0x20: U32 hash = 0x61B458C6 (1639209158)
0x24: volatile U32 virtualThreadWaitCount = 0x00000003 (3)
0x28: volatile U32 platformThreadWaitCount = 0x6BC53858 (1808087128) <--- Looks corrupt
0x30: struct J9VMContinuation* ownerContinuation = !j9vmcontinuation 0x0000000000000000
0x38: struct J9VMContinuation* waitingContinuations = !j9vmcontinuation 0x0000000000000000
0x40: struct J9ObjectMonitor* next = !j9objectmonitor 0x0000000000000000
}
> !j9threadmonitor 0x00007FFF14006D08
J9ThreadMonitor at 0x7fff14006d08 {
Fields for J9ThreadMonitor:
0x0: U64 count = 0x0000000000000001 (1)
0x8: volatile struct J9Thread* owner = !j9thread 0x00007FFEE400DDA8 <--- J9Thread doesn't exist
0x10: struct J9Thread* waiting = !j9thread 0x0000000000000000
0x18: U64 flags = 0x0000000000070000 (458752)
0x20: U64 userData = 0x00000000E0048EF0 (3758395120)
0x28: struct J9ThreadMonitorTracing* tracing = !j9threadmonitortracing 0x00007FFF100015E0
0x30: U8* name = !j9x 0x0000000000000000
0x38: U64 pinCount = 0x0000000000000000 (0)
0x40: U64 spinlockState = 0x0000000000000001 (1)
0x48: U64 spinCount1 = 0x0000000000000100 (256)
0x50: U64 spinCount2 = 0x0000000000000020 (32)
0x58: U64 spinCount3 = 0x000000000000002D (45)
0x60: struct J9Thread* blocking = !j9thread 0x0000000000000000
0x68: U64 sampleCounter = 0x00000000000003C2 (962)
0x70: const struct J9ThreadCustomSpinOptions* customSpinOptions = !j9threadcustomspinoptions 0x0000000000000000
0x78: volatile U64 spinThreads = 0x0000000000000000 (0)
0x80: pthread_mutex_t mutex = !pthread_mutex_t 0x00007FFF14006D88
0xa8: struct J9Thread* notifyAllWaiting = !j9thread 0x0000000000000000
}
> !j9object 0x00000000FFEEA430 <--- VT0
!J9Object 0x00000000FFEEA430 {
...
Ljava/lang/Thread; carrierThread = !fj9object 0xffeea8f8 (offset = 152) (java/lang/VirtualThread) <--- VT0's carrier thread
}
> !fj9object 0xffeea8f8
!J9Object 0x00000000FFEEA8F8 {
...
J eetop = 0x00000000002DD900 (offset = 4) (java/lang/Thread) <--- !stack 0x002dd900 !j9vmthread 0x002dd900 !j9thread 0x7ffee400dda8 tid 0x3b0 (944) // (ForkJoinPool-1-worker-6)
}
does the issue still occur when running with -Xint or with -Xjit:exclude={ObjectMonitorUsage$EnteringTask.run}? This appears to be a JIT-related issue
50x -Xint grinder - failed with
- https://github.com/eclipse-openj9/openj9/issues/21916
50x -Xjit:exclude={ObjectMonitorUsage$EnteringTask.run} grinder - only one known failure https://github.com/eclipse-openj9/openj9/issues/21695 Yes, this appears to be a JIT-related issue.
Do you have access to the native stack for 0x002dd900 (ForkJoinPool-1-worker-6)?
@babsingh which core file/link is this?
which core file/link is this?
core.20250515.085412.835.0001.dmp ... it's the same one used in https://github.com/eclipse-openj9/openj9/issues/21890#issuecomment-2887669894.
@fengxue-IS Would you happen to know why J9ObjectMonitor->platformThreadWaitCount and J9Thread->owner are showing invalid values in the failing scenario?
The platformThreadWaitCount isn't updated using barrier/CAS so it could have overwritten between threads, but the given value (0x6BC53858) doesn't seem to be possible just from that. more like an random value. The owner field is only updated by the detach/attach helper in ContinuationHelpers.cpp and omr code which have not been changed.
I feel the 0x933c8 address maybe incorrect in this case.
Run disabled tests 50x serviceability_jvmti_j9 in linux-ppc64le grinder, serviceability/jvmti/ObjectMonitorUsage/ObjectMonitorUsage.java failed with timeout (this issue) and a few
- https://github.com/eclipse-openj9/openj9/issues/21824
Note this test was excluded only for linux-ppc64le, and no failures were observed in nightly runs.
Run serviceability/jvmti/ObjectMonitorUsage/ObjectMonitorUsage.java in a local machine and reproduced a hang, some observations from the core generated via gdb:
From jdmpview
> !threads
!stack 0x000bf100 !j9vmthread 0x000bf100 !j9thread 0x7fffb401deb0 tid 0x34c3 (13507) // (main)
...
!stack 0x00309400 !j9vmthread 0x00309400 !j9thread 0x7ffecc016258 tid 0x350e (13582) // (VirtualThread-unblocker)
!stack 0x00306e00 !j9vmthread 0x00306e00 !j9thread 0x7fffb42dc968 tid 0x350f (13583) // (ForkJoinPool-1-worker-1)
!stack 0x0030df00 !j9vmthread 0x0030df00 !j9thread 0x7ffeb40094e0 tid 0x3510 (13584) // (ForkJoinPool-1-worker-3)
!stack 0x002ca500 !j9vmthread 0x002ca500 !j9thread 0x7ffeb4009a58 tid 0x3511 (13585) // (ForkJoinPool-1-worker-2)
!stack 0x00310500 !j9vmthread 0x00310500 !j9thread 0x7ffe98007680 tid 0x3512 (13586) // (ForkJoinPool-1-worker-4)
!stack 0x00312a00 !j9vmthread 0x00312a00 !j9thread 0x7ffe98007bf8 tid 0x3513 (13587) // (ForkJoinPool-1-worker-5)
!stack 0x0030b900 !j9vmthread 0x0030b900 !j9thread 0x7ffe9800d9a0 tid 0x3514 (13588) // (ForkJoinPool-1-worker-6)
!stack 0x00315000 !j9vmthread 0x00315000 !j9thread 0x7ffe9800df18 tid 0x3515 (13589) // (ForkJoinPool-1-worker-8)
!stack 0x00354c00 !j9vmthread 0x00354c00 !j9thread 0x7ffe98012ca0 tid 0x3516 (13590) // (ForkJoinPool-1-worker-7)
> !stack 0x000bf100
<bf100> !j9method 0x00000000000EE030 jdk/internal/misc/Unsafe.park(ZJ)V
<bf100> !j9method 0x0000000000128148 java/util/concurrent/locks/LockSupport.park(Ljava/lang/Object;)V
<bf100> !j9method 0x00000000001D4A40 java/util/concurrent/locks/AbstractQueuedSynchronizer.acquire(Ljava/util/concurrent/locks/AbstractQueuedSynchronizer$Node;IZZZJ)I
<bf100> !j9method 0x00000000001D4C00 java/util/concurrent/locks/AbstractQueuedSynchronizer.acquireSharedInterruptibly(I)V
<bf100> !j9method 0x000000000031E5E8 java/util/concurrent/CountDownLatch.await()V
<bf100> !j9method 0x000000000012EF90 java/lang/VirtualThread.joinNanos(J)Z
<bf100> !j9method 0x0000000000112788 java/lang/Thread.join(J)V
<bf100> !j9method 0x00000000001127C8 java/lang/Thread.join()V
<bf100> !j9method 0x00000000002D3898 ObjectMonitorUsage.joinThreads([Ljava/lang/Thread;)V
<bf100> !j9method 0x00000000002D3938 ObjectMonitorUsage.test2(Z)V
<bf100> !j9method 0x00000000002D3978 ObjectMonitorUsage.test(Z)V
<bf100> !j9method 0x00000000002D3998 ObjectMonitorUsage.main([Ljava/lang/String;)V
> !stack 0x00309400
<309400> !j9method 0x000000000012F410 java/lang/VirtualThread.takeVirtualThreadListToUnblock()Ljava/lang/VirtualThread;
<309400> !j9method 0x000000000012F3F0 java/lang/VirtualThread.unblockVirtualThreads()V
<309400> !j9method 0x0000000000334150 java/lang/VirtualThread$$Lambda/0x0000000000000000.run()V
<309400> !j9method 0x0000000000112508 java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V
<309400> !j9method 0x00000000001124E8 java/lang/Thread.run()V
<309400> !j9method 0x00000000001E5A80 jdk/internal/misc/InnocuousThread.run()V
> !stack 0x0030df00
<30df00> !j9method 0x00000000002D4800 ObjectMonitorUsage$EnteringTask.run()V
<30df00> !j9method 0x0000000000112508 java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V
<30df00> !j9method 0x000000000012ED30 java/lang/VirtualThread.run(Ljava/lang/Runnable;)V
<30df00> !j9method 0x0000000000334D28 java/lang/VirtualThread$VThreadContinuation$1.run()V
<30df00> !j9method 0x0000000000140070 jdk/internal/vm/Continuation.enter(Ljdk/internal/vm/Continuation;)V
Other worker threads have similar stacktrace
> !stack 0x00354c00
<354c00> !j9method 0x00000000000EE030 jdk/internal/misc/Unsafe.park(ZJ)V
<354c00> !j9method 0x00000000003174B8 java/util/concurrent/ForkJoinPool.awaitWork(Ljava/util/concurrent/ForkJoinPool$WorkQueue;I)I
<354c00> !j9method 0x0000000000317498 java/util/concurrent/ForkJoinPool.deactivate(Ljava/util/concurrent/ForkJoinPool$WorkQueue;I)I
<354c00> !j9method 0x0000000000317478 java/util/concurrent/ForkJoinPool.runWorker(Ljava/util/concurrent/ForkJoinPool$WorkQueue;)V
<354c00> !j9method 0x0000000000318ED0 java/util/concurrent/ForkJoinWorkerThread.run()V
> !vthreads
!continuationstack 0x0000000000000000 !j9vmcontinuation 0x0000000000000000 !j9object 0x00000000FFE220E8 (Continuation) !j9object 0x0000000000000000 (VThread) - <N/A>
From gdb
(gdb) thread 2
[Switching to thread 2 (Thread 0x7fffb8e1f120 (LWP 13507))]
#0 0x00007fffb8ace9b4 in __futex_abstimed_wait_cancelable64 () from /lib64/libc.so.6
(gdb) bt
#0 0x00007fffb8ace9b4 in __futex_abstimed_wait_cancelable64 () from /lib64/libc.so.6
#1 0x00007fffb8ad3818 in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libc.so.6
#2 0x00007fffb899aed0 in omrthread_park (millis=0, nanos=0) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/thread/common/omrthread.c:3312
#3 0x00007fffb3ca3c8c in timeCompensationHelper (vmThread=0xbf100, threadHelperType=<optimized out>, monitor=0x0, millis=0, nanos=0)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/threadhelp.cpp:464
#4 0x00007fffb3ca4eb8 in threadParkImpl (vmThread=0xbf100, timeoutIsEpochRelative=<optimized out>, timeout=0) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/threadpark.cpp:104
#5 0x00007fffb36c30d8 in Java_sun_misc_Unsafe_park (env=0xbf100, receiver=<optimized out>, isAbsolute=<optimized out>, time=0)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/jcl/common/sun_misc_Unsafe.cpp:354
#6 0x00007fffb3e491b8 in ffi_call_LINUX64 () at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/libffi/powerpc/linux64.S:178
#7 0x00007fffb3e48e84 in ffi_call_int (cif=0x7fffb8e1d158, fn=<optimized out>, rvalue=<optimized out>, avalue=<optimized out>, closure=<optimized out>)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/libffi/powerpc/ffi.c:105
#8 0x00007fffb3d54088 in VM_DebugBytecodeInterpreterCompressed::cJNICallout (isStatic=<optimized out>, function=0x7fffb36c3070 <Java_sun_misc_Unsafe_park(JNIEnv*, jobject, jboolean, jlong)>, returnStorage=0xbf220, returnType=<synthetic pointer>,
javaArgs=<optimized out>, receiverAddress=<optimized out>, _pc=<synthetic pointer>: <optimized out>, _sp=<synthetic pointer>: <optimized out>, this=0x7fffb8e1d280)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/BytecodeInterpreter.hpp:2786
(gdb) thread 54
[Switching to thread 54 (Thread 0x7fff9541f120 (LWP 13584))]
#0 0x00007fff95d0f068 in ?? ()
(gdb) bt
#0 0x00007fff95d0f068 in ?? ()
#1 0x00007fff95d0f074 in ?? ()
#2 0x00007fffb3c18b50 in runJavaThread (currentThread=0xffe80e88) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/callin.cpp:682
#3 0x00007fffb3cbf508 in javaProtectedThreadProc (portLibrary=0xffe06900, entryarg=0x30df00) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/vmthread.cpp:2153
#4 0x00007fffb84196d4 in omrsig_protect (portLibrary=0xffe06900, fn=0x7fffb3cbf440 <javaProtectedThreadProc(J9PortLibrary*, void*)>, fn_arg=0x30df00, handler=0x7fffb3c43c50 <structuredSignalHandler>, handler_arg=0xffe80fb0, flags=<optimized out>,
result=0x7fff9541c3e8) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/port/unix/omrsignal.c:425
#5 0x00007fffb3cba9a0 in javaThreadProc (entryarg=0x7fffb402aee0) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/vmthread.cpp:414
#6 0x00007fffb899cc00 in thread_wrapper (arg=0x7ffeb40094e0) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/thread/common/omrthread.c:1724
#7 0x00007fffb8ad43cc in start_thread () from /lib64/libc.so.6
(gdb) thread 52
[Switching to thread 52 (Thread 0x7fff9538f120 (LWP 13582))]
#0 0x00007fffb899c0e0 in omrthread_monitor_exit (monitor=0x7fffb40befd8) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/thread/common/omrthread.c:4266
warning: 4266 /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/thread/common/omrthread.c: No such file or directory
(gdb) bt
#0 0x00007fffb899c0e0 in omrthread_monitor_exit (monitor=0x7fffb40befd8) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/thread/common/omrthread.c:4266
#1 0x00007fffb3ce2e64 in takeVirtualThreadListToUnblock (currentThread=0x309400) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/ContinuationHelpers.cpp:1276
#2 0x00007fffb8d49d7c in JVM_TakeVirtualThreadListToUnblock (env=<optimized out>, ignored=<optimized out>) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/j9vm/javanextvmi.cpp:677
#3 0x00007fffb8e2ddd0 in JVM_TakeVirtualThreadListToUnblock (env=<optimized out>, ignored=<optimized out>)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/build/linux-ppc64le-server-release/vm/runtime/redirector/generated.c:8664
#4 0x00007fffb3e491b8 in ffi_call_LINUX64 () at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/libffi/powerpc/linux64.S:178
#5 0x00007fffb3e48e84 in ffi_call_int (cif=0x7fff9538b118, fn=<optimized out>, rvalue=<optimized out>, avalue=<optimized out>, closure=<optimized out>)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/libffi/powerpc/ffi.c:105
#6 0x00007fffb3d54088 in VM_DebugBytecodeInterpreterCompressed::cJNICallout (isStatic=<optimized out>, function=0x7fffb8e2dda0 <JVM_TakeVirtualThreadListToUnblock>, returnStorage=0x309520, returnType=<synthetic pointer>, javaArgs=<optimized out>,
receiverAddress=<optimized out>, _pc=<synthetic pointer>: <optimized out>, _sp=<synthetic pointer>: <optimized out>, this=0x7fff9538b240)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/BytecodeInterpreter.hpp:2786
Other work threads have similar stacktrace:
(gdb) thread 53
[Switching to thread 53 (Thread 0x7fff9553f120 (LWP 13583))]
#0 0x00007fffb8ace9b4 in __futex_abstimed_wait_cancelable64 () from /lib64/libc.so.6
(gdb) bt
#0 0x00007fffb8ace9b4 in __futex_abstimed_wait_cancelable64 () from /lib64/libc.so.6
#1 0x00007fffb8ad3818 in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libc.so.6
#2 0x00007fffb899aed0 in omrthread_park (millis=0, nanos=0) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/omr/thread/common/omrthread.c:3312
#3 0x00007fffb3ca3c8c in timeCompensationHelper (vmThread=0x306e00, threadHelperType=<optimized out>, monitor=0x0, millis=0, nanos=0)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/threadhelp.cpp:464
#4 0x00007fffb3ca4eb8 in threadParkImpl (vmThread=0x306e00, timeoutIsEpochRelative=<optimized out>, timeout=0) at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/threadpark.cpp:104
#5 0x00007fffb36c30d8 in Java_sun_misc_Unsafe_park (env=0x306e00, receiver=<optimized out>, isAbsolute=<optimized out>, time=0)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/jcl/common/sun_misc_Unsafe.cpp:354
#6 0x00007fffb3e491b8 in ffi_call_LINUX64 () at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/libffi/powerpc/linux64.S:178
#7 0x00007fffb3e48e84 in ffi_call_int (cif=0x7fff9553b118, fn=<optimized out>, rvalue=<optimized out>, avalue=<optimized out>, closure=<optimized out>)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/libffi/powerpc/ffi.c:105
#8 0x00007fffb3d54088 in VM_DebugBytecodeInterpreterCompressed::cJNICallout (isStatic=<optimized out>, function=0x7fffb36c3070 <Java_sun_misc_Unsafe_park(JNIEnv*, jobject, jboolean, jlong)>, returnStorage=0x306f20, returnType=<synthetic pointer>,
javaArgs=<optimized out>, receiverAddress=<optimized out>, _pc=<synthetic pointer>: <optimized out>, _sp=<synthetic pointer>: <optimized out>, this=0x7fff9553b240)
at /home/jenkins/workspace/build-scripts/jobs/jdk24/jdk24-linux-ppc64le-openj9/workspace/build/src/openj9/runtime/vm/BytecodeInterpreter.hpp:2786
It seems VirtualThread.joinNanos() stuck waiting for the virtual thread exit.
VirtualThread.joinNanos() is simply waiting for the virtual threads (either wThreads or eThreads) to complete. Based on the diagnostic information above, all virtual threads appear to be unmounted. @JasonFengJ9, can you inspect what the virtual threads are doing using !vthreads? Please take a look at the !continuationstack, !j9vmcontinuation, Continuation, and VThread objects. We need to determine why the virtual threads are not completing.
> !vthreads
!continuationstack 0x00007ffee4003470 !j9vmcontinuation 0x00007ffee4003470 !j9object 0x00000000FFEEA9E8 (Continuation) !j9object 0x00000000FFEEA430 (VThread) - EnteringVT0
...
/* Scenario #2:
* - owning: 1
* - entering: N
* - re-entering: 0
* - to be notified: N
*/
static void test2(boolean isVirtual) throws Error {
String vtag = vtag(isVirtual);
log("\n### test2: started " + vtag);
setTestedMonitor(lockCheck);
Thread[] wThreads = startWaitingThreads(isVirtual);
Thread[] eThreads = null;
synchronized (lockCheck) {
// Virtual threads are not supported by the GetObjectMonitorUsage.
// Correct the expected values for the virtual thread case.
int expEnteringCount = isVirtual ? 0 : NUMBER_OF_ENTERING_THREADS;
int expWaitingCount = isVirtual ? 0 : NUMBER_OF_WAITING_THREADS;
eThreads = startEnteringThreads(isVirtual);
// The numbers below describe the testing scenario, not the expected results.
// The expected numbers are different for virtual threads because
// they are not supported by JVMTI GetObjectMonitorUsage.
// entry count: 1
// count of threads waiting to enter: NUMBER_OF_ENTERING_THREADS
// count of threads waiting to re-enter: 0
// count of threads waiting to be notified: NUMBER_OF_WAITING_THREADS
check(lockCheck, expOwnerThread(), expEntryCount(),
expEnteringCount,
expWaitingCount);
lockCheck.notifyAll();
}
joinThreads(wThreads); <--- Wait either over here
joinThreads(eThreads); <--- or waits over here
setTestedMonitor(null);
log("### test2: finished " + vtag);
}
can you inspect what the virtual threads are doing using !vthreads? Please take a look at the !continuationstack, !j9vmcontinuation, Continuation, and VThread objects.
Will update after the fyre machine is back online (didn't download the core file).
Not much info from !vthreads
> !vthreads
!continuationstack 0x0000000000000000 !j9vmcontinuation 0x0000000000000000 !j9object 0x00000000FFE220E8 (Continuation) !j9object 0x0000000000000000 (VThread) - <N/A>
> !j9object 0x00000000FFE220E8
!J9Object 0x00000000FFE220E8 {
struct J9Class* clazz = !j9class 0x334A00 // java/lang/VirtualThread$VThreadContinuation
Object flags = 0x00000010;
I lockword = 0x00000008 (offset = 0) (java/lang/Object) <hidden>
J vmRef = 0x0000000000000000 (offset = 4) (jdk/internal/vm/Continuation)
Ljava/lang/Thread; vthread = !fj9object 0x0 (offset = 20) (jdk/internal/vm/Continuation)
Ljava/lang/Object; blocker = !fj9object 0x0 (offset = 24) (jdk/internal/vm/Continuation)
[Ljava/lang/Object; scopedValueCache = !fj9object 0x0 (offset = 28) (jdk/internal/vm/Continuation)
Ljdk/internal/vm/ContinuationScope; scope = !fj9object 0xffe01908 (offset = 32) (jdk/internal/vm/Continuation)
Ljava/lang/Runnable; runnable = !fj9object 0xffe22120 (offset = 36) (jdk/internal/vm/Continuation)
Ljdk/internal/vm/Continuation; parent = !fj9object 0x0 (offset = 40) (jdk/internal/vm/Continuation)
J state = 0x0000000000000023 (offset = 12) (jdk/internal/vm/Continuation)
Z isAccessible = 0x00000001 (offset = 44) (jdk/internal/vm/Continuation)
I continuationLink = 0x00000000 (offset = 48) (jdk/internal/vm/Continuation) <hidden>
!continuationstack 0x0000000000000000, !j9vmcontinuation 0x0000000000000000, and !j9object 0x0000000000000000 (VThread) all point to 0x0.
@babsingh here is the link to the core file (no password) - https://ibm.box.com/s/gzrxioqtknhdyb19ozptllyqdb0vkg3l
@JasonFengJ9 !vthreads doesn't list all virtual threads; likely because the GC hasn’t flushed the thread-local cache or updated the virtual thread list yet.
I did find one virtual thread mounted on ForkJoinPool-1-worker-3 (a carrier thread). No other carrier threads currently have virtual threads mounted.
The annotated jdmpview output is below. In short, the top method frame of the virtual thread is JIT-compiled: ObjectMonitorUsage$EnteringTask.run, which includes monitorenter and monitorexit bytecodes. The exception handler path is being taken for monitorexit. In the system core file, the virtual thread is at bytecode 16 astore2, which stores the exception object; executing this bytecode shouldn't lead to a hang.
@hzongaro Could the JIT team take a look? This might be similar to other failures involving invalid eetop/currentThread values.
> !threads <--- See all the threads with an associated J9VMThread
...
> !stack 0x0030df00 <--- Only ONE carrier thread (ForkJoinPool-1-worker-3) has a virtual thread mounted
<30df00> !j9method 0x00000000002D4800 ObjectMonitorUsage$EnteringTask.run()V <--- TOP frame is JIT compiled
<30df00> !j9method 0x0000000000112508 java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V
<30df00> !j9method 0x000000000012ED30 java/lang/VirtualThread.run(Ljava/lang/Runnable;)V
<30df00> !j9method 0x0000000000334D28 java/lang/VirtualThread$VThreadContinuation$1.run()V
<30df00> !j9method 0x0000000000140070 jdk/internal/vm/Continuation.enter(Ljdk/internal/vm/Continuation;)V
<30df00> JNI call-in frame
<30df00> Native method frame
> !j9vmthread 0x0030df00 | grep -i threadobject <--- Virtual thread is correctly mounted
0xa8: struct J9Object* threadObject = !j9object 0x00000000FFE80EE8 // java/lang/VirtualThread
0xb08: struct J9Object* carrierThreadObject = !j9object 0x00000000FFE8DE78 // jdk/internal/misc/CarrierThread
> !stack 0x00306e00 <--- All OTHER carrier threads (ForkJoinPool-1-worker-*) are just waiting for work (don't have a mounted virtual thread)
<306e00> !j9method 0x00000000000EE030 jdk/internal/misc/Unsafe.park(ZJ)V
<306e00> !j9method 0x00000000003174B8 java/util/concurrent/ForkJoinPool.awaitWork(Ljava/util/concurrent/ForkJoinPool$WorkQueue;I)I
<306e00> !j9method 0x0000000000317498 java/util/concurrent/ForkJoinPool.deactivate(Ljava/util/concurrent/ForkJoinPool$WorkQueue;I)I
<306e00> !j9method 0x0000000000317478 java/util/concurrent/ForkJoinPool.runWorker(Ljava/util/concurrent/ForkJoinPool$WorkQueue;)V
<306e00> !j9method 0x0000000000318ED0 java/util/concurrent/ForkJoinWorkerThread.run()V
<306e00> JNI call-in frame
<306e00> Native method frame
> !j9object 0x00000000FFE80EE8 <--- NO ISSUES OBSERVED
!J9Object 0x00000000FFE80EE8 {
struct J9Class* clazz = !j9class 0x12F800 // java/lang/VirtualThread
Object flags = 0x00000008;
I lockword = 0x00000008 (offset = 0) (java/lang/Object) <hidden>
J eetop = 0x0000000000000000 (offset = 4) (java/lang/Thread)
J tid = 0x0000000000000060 (offset = 12) (java/lang/Thread)
Ljava/lang/String; name = !fj9object 0xffe80ed0 (offset = 44) (java/lang/Thread)
Z interrupted = 0x00000000 (offset = 96) (java/lang/Thread)
Ljava/lang/ClassLoader; contextClassLoader = !fj9object 0xffe031a8 (offset = 48) (java/lang/Thread)
Ljava/lang/Thread$FieldHolder; holder = !fj9object 0x0 (offset = 52) (java/lang/Thread)
Ljava/lang/ThreadLocal$ThreadLocalMap; threadLocals = !fj9object 0x0 (offset = 56) (java/lang/Thread)
Ljava/lang/ThreadLocal$ThreadLocalMap; inheritableThreadLocals = !fj9object 0x0 (offset = 60) (java/lang/Thread)
Ljava/lang/Object; scopedValueBindings = !fj9object 0x851627c8 (offset = 64) (java/lang/Thread)
Ljava/lang/Object; interruptLock = !fj9object 0xffe80fa0 (offset = 68) (java/lang/Thread)
Ljava/lang/Object; parkBlocker = !fj9object 0x0 (offset = 72) (java/lang/Thread)
Lsun/nio/ch/Interruptible; nioBlocker = !fj9object 0x0 (offset = 76) (java/lang/Thread)
Ljdk/internal/vm/Continuation; cont = !fj9object 0x0 (offset = 80) (java/lang/Thread)
Ljava/lang/Thread$UncaughtExceptionHandler; uncaughtExceptionHandler = !fj9object 0x0 (offset = 84) (java/lang/Thread)
J threadLocalRandomSeed = 0x0000000000000000 (offset = 20) (java/lang/Thread)
I threadLocalRandomProbe = 0x00000000 (offset = 100) (java/lang/Thread)
I threadLocalRandomSecondarySeed = 0x00000000 (offset = 104) (java/lang/Thread)
Ljdk/internal/vm/ThreadContainer; container = !fj9object 0xffe08a98 (offset = 88) (java/lang/Thread)
Ljdk/internal/vm/StackableScope; headStackableScopes = !fj9object 0x0 (offset = 92) (java/lang/Thread)
Z started = 0x00000000 (offset = 108) (java/lang/Thread)
J tls = 0x0000000000000000 (offset = 36) (java/lang/Thread) <hidden>
J internalSuspendState = 0x0000000000000000 (offset = 28) (java/lang/Thread) <hidden>
Ljava/util/concurrent/Executor; scheduler = !fj9object 0xffe0ce30 (offset = 132) (java/lang/VirtualThread)
Ljdk/internal/vm/Continuation; cont = !fj9object 0xffe80fb0 (offset = 136) (java/lang/VirtualThread)
Ljava/lang/Runnable; runContinuation = !fj9object 0xffe80ff8 (offset = 140) (java/lang/VirtualThread)
I state = 0x00000002 (offset = 112) (java/lang/VirtualThread)
Z parkPermit = 0x00000000 (offset = 160) (java/lang/VirtualThread)
Z blockPermit = 0x00000000 (offset = 164) (java/lang/VirtualThread)
Z onWaitingList = 0x00000000 (offset = 168) (java/lang/VirtualThread)
Ljava/lang/VirtualThread; next = !fj9object 0x0 (offset = 144) (java/lang/VirtualThread)
Z notified = 0x00000000 (offset = 172) (java/lang/VirtualThread)
B timedWaitSeqNo = 0x00000000 (offset = 176) (java/lang/VirtualThread)
J timeout = 0x0000000000000000 (offset = 116) (java/lang/VirtualThread)
Ljava/util/concurrent/Future; timeoutTask = !fj9object 0x0 (offset = 148) (java/lang/VirtualThread)
Ljava/lang/Thread; carrierThread = !fj9object 0xffe8de78 (offset = 152) (java/lang/VirtualThread)
Ljava/util/concurrent/CountDownLatch; termination = !fj9object 0x0 (offset = 156) (java/lang/VirtualThread)
J inspectorCount = 0x0000000000000000 (offset = 124) (java/lang/VirtualThread) <hidden>
}
> !fj9object 0xffe80fb0 <--- NO ISSUES OBSERVED
!J9Object 0x00000000FFE80FB0 {
struct J9Class* clazz = !j9class 0x334A00 // java/lang/VirtualThread$VThreadContinuation
Object flags = 0x00000000;
I lockword = 0x00000008 (offset = 0) (java/lang/Object) <hidden>
J vmRef = 0x00007FFEAC008C90 (offset = 4) (jdk/internal/vm/Continuation)
Ljava/lang/Thread; vthread = !fj9object 0xffe80ee8 (offset = 20) (jdk/internal/vm/Continuation)
Ljava/lang/Object; blocker = !fj9object 0x0 (offset = 24) (jdk/internal/vm/Continuation)
[Ljava/lang/Object; scopedValueCache = !fj9object 0x0 (offset = 28) (jdk/internal/vm/Continuation)
Ljdk/internal/vm/ContinuationScope; scope = !fj9object 0xffe01908 (offset = 32) (jdk/internal/vm/Continuation)
Ljava/lang/Runnable; runnable = !fj9object 0xffe80fe8 (offset = 36) (jdk/internal/vm/Continuation)
Ljdk/internal/vm/Continuation; parent = !fj9object 0x0 (offset = 40) (jdk/internal/vm/Continuation)
J state = 0x000000000030DF01 (offset = 12) (jdk/internal/vm/Continuation)
Z isAccessible = 0x00000000 (offset = 44) (jdk/internal/vm/Continuation)
I continuationLink = 0xFFE80DF0 (offset = 48) (jdk/internal/vm/Continuation) <hidden>
}
> !j9vmcontinuation 0x00007FFEAC008C90 <--- NO ISSUES OBSERVED
J9VMContinuation at 0x7ffeac008c90 {
Fields for J9VMContinuation:
0x0: UDATA* arg0EA = !j9x 0x0000000000340AB0
0x8: UDATA* bytecodes = !j9x 0x0000000000000000
0x10: UDATA* sp = !j9x 0x0000000000340A88
0x18: U8* pc = !j9x 0x0000000000000003
0x20: struct J9Method* literals = !j9method 0x0000000000000000
0x28: UDATA* stackOverflowMark = !j9x 0x00000000003406F0
0x30: UDATA* stackOverflowMark2 = !j9x 0x00000000003406F0
0x38: struct J9JavaStack* stackObject = !j9javastack 0x000000000033F6E8
0x40: struct J9JITDecompilationInfo* decompilationStack = !j9jitdecompilationinfo 0x0000000000000000
0x48: UDATA* j2iFrame = !j9x 0x0000000000000000
0x50: struct J9JITGPRSpillArea jitGPRs = !j9jitgprspillarea 0x00007FFEAC008CE0
0x160: struct J9I2JState i2jState = !j9i2jstate 0x00007FFEAC008DF0
0x180: struct J9VMEntryLocalStorage* oldEntryLocalStorage = !j9vmentrylocalstorage 0x0000000000000000
0x188: UDATA dropFlags = 0x0000000000000000 (0)
0x190: UDATA returnState = 0x0000000000000004 (4)
0x198: IDATA waitingMonitorEnterCount = 0x0000000000000000 (0)
0x1a0: UDATA ownedMonitorCount = 0x0000000000000000 (0)
0x1a8: struct J9Pool* monitorEnterRecordPool = !j9pool 0x00007FFEB4004A20
0x1b0: struct J9MonitorEnterRecord* monitorEnterRecords = !j9monitorenterrecord 0x0000000000000000
0x1b8: struct J9MonitorEnterRecord* jniMonitorEnterRecords = !j9monitorenterrecord 0x0000000000000000
0x1c0: struct J9Object* vthread = !j9object 0x00000000FFE80EE8 // java/lang/VirtualThread
0x1c8: struct J9VMContinuation* nextWaitingContinuation = !j9vmcontinuation 0x0000000000000000
0x1d0: struct J9ObjectMonitor* objectWaitMonitor = !j9objectmonitor 0x0000000000000000
0x1d8: struct J9ObjectMonitor* enteredMonitors = !j9objectmonitor 0x0000000000000000
0x1e0: UDATA runtimeFlags = 0x0000000000000000 (0)
0x1e8: I64 startTicks = 0x0000000000000000 (0)
0x1f0: struct J9VMThread* previousOwner = !j9vmthread 0x0000000000000000
}
> !stackslots 0x0030df00 <--- TOP FRAME IS JIT COMPILED
<30df00> *** BEGIN STACK WALK, flags = 01400001 walkThread = 3,202,816 ***
<30df00> START_AT_JIT_FRAME
<30df00> ITERATE_O_SLOTS
<30df00> RECORD_BYTECODE_PC_OFFSET
<30df00> Initial values: walkSP = 0x000000000034E870, PC = 0x00007FFF95D0F068, literals = 0x0000000000000000, A0 = 0x000000000034E868, j2iFrame = 0x0000000000000000, decomp = 0x0000000000000000
<30df00> JIT frame: bp = 0x000000000034E8D8, pc = 0x00007FFF95D0F068, unwindSP = 0x000000000034E870, cp = 0x00000000002D4510, arg0EA = 0x000000000034E8E0, jitInfo = 0x00007FFF774FEBF8
<30df00> Method: ObjectMonitorUsage$EnteringTask.run()V !j9method 0x00000000002D4800
<30df00> Bytecode index = 16, inlineDepth = 0, PC offset = 0xFFFFFFFFFFFFCD6C
<30df00> stackMap=0x00007FFF774FED70, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFE0)
<30df00> Described JIT args starting at 0x000000000034E8E0 for U16(0x0001) slots
<30df00> O-Slot: : a0[0x000000000034E8E0] = 0x00000000FFE80E88
<30df00> Described JIT temps starting at 0x000000000034E8B8 for IDATA(0x0000000000000004) slots
<30df00> O-Slot: : t3[0x000000000034E8B8] = 0x00000000FFE938B0
<30df00> O-Slot: : t2[0x000000000034E8C0] = 0x0000000000000000
<30df00> O-Slot: : t1[0x000000000034E8C8] = 0x00000000FFE004A8
<30df00> O-Slot: : t0[0x000000000034E8D0] = 0x00000000FFE004A8
<30df00> JIT-RegisterMap = UDATA(0x0000000000000000)
<30df00> JIT-Frame-RegisterMap[0x000000000034E888] = UDATA(0x00000000FFE8F9C0) (jit_r26)
<30df00> JIT-Frame-RegisterMap[0x000000000034E890] = UDATA(0x0000000000000000) (jit_r27)
<30df00> JIT-Frame-RegisterMap[0x000000000034E898] = UDATA(0x0000000000000001) (jit_r28)
<30df00> JIT-Frame-RegisterMap[0x000000000034E8A0] = UDATA(0x0000000000000000) (jit_r29)
<30df00> JIT-Frame-RegisterMap[0x000000000034E8A8] = UDATA(0x0000000000000001) (jit_r30)
<30df00> JIT-Frame-RegisterMap[0x000000000034E8B0] = UDATA(0x0000000000000001) (jit_r31)
<30df00> I2J values: PC = 0x00007FFF5D2C38A7, A0 = 0x000000000034E910, walkSP = 0x000000000034E8E8, literals = 0x0000000000112508, JIT PC = 0x00007FFFB32CE898, pcAddress = 0x00007FFF9541BF68, decomp = 0x0000000000000000
<30df00> Bytecode frame: bp = 0x000000000034E8F8, sp = 0x000000000034E8E8, pc = 0x00007FFF5D2C38A7, cp = 0x0000000000112E90, arg0EA = 0x000000000034E910, flags = 0x0000000000000000
<30df00> Method: java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V !j9method 0x0000000000112508
<30df00> Bytecode index = 7
<30df00> Using debug local mapper
<30df00> Locals starting at 0x000000000034E910 for 0x0000000000000003 slots
<30df00> O-Slot: a0[0x000000000034E910] = 0x00000000FFE80EE8
<30df00> O-Slot: a1[0x000000000034E908] = 0x00000000851627C8
<30df00> O-Slot: a2[0x000000000034E900] = 0x00000000FFE80E88
...
// <30df00> Bytecode index = 16, inlineDepth = 0, PC offset = 0xFFFFFFFFFFFFCD6C
0 aload0
1 iconst1
2 putfield 3 ObjectMonitorUsage$EnteringTask.ready Z
5 getstatic 5 ObjectMonitorUsage.lockCheck Ljava/lang/Object;
8 dup
9 astore1
10 monitorenter <--- acquire monitor on lockCheck
11 aload1
12 monitorexit <--- normal release of monitor
13 goto 21 <--- Skip exception handler
16 astore2 <--- Store the exception object
17 aload1
18 monitorexit <--- Release lock (exception case)
19 aload2
20 athrow <--- Rethrow the exception
21 return0
@hzongaro Could the JIT team take a look? This might be similar to other failures involving invalid eetop/currentThread values.
FYI @hzongaro
I tried running this workload locally on a ppcle Linux machine and observed hangs even under -Xint.
Machine: pjavaubun02.rtp.raleigh.ibm.com
Java build is a JDK24 with recent source code:
openjdk version "24.0.1-internal" 2025-04-15
OpenJDK Runtime Environment (build 24.0.1-internal-adhoc.root.openj9-openjdk-jdk24)
Eclipse OpenJ9 VM (build master-d5a2273bb0, JRE 24 Linux ppc64le-64-Bit Compressed References 20250617_000000 (JIT enabled, AOT disabled)
OpenJ9 - d5a2273bb0
OMR - 6873ddb55
JCL - 7adb8bad278 based on jdk-24.0.1+9)
Test command:
java -Xint -Xshareclasses:none -Xnoaot -Djdk.virtualThreadScheduler.parallelism=10 -agentpath:/team/jimmyk/Defects/21890-virtualThreads/testimage/jdk-24.0.1plus9-test-image/hotspot/jtreg/native/libObjectMonitorUsage.so ObjectMonitorUsage
Example failure outputs:
### test0: started virtual
>>> [12]
>>> owner: none (0x0)
>>> entry_count: 0
>>> waiter_count: 0
>>> notify_waiter_count: 0
***HANGS***
### test1: started virtual
>>> [13]
>>> owner: main (0x0x1ecfc0)
>>> entry_count: 1
>>> waiter_count: 0
>>> notify_waiter_count: 0
>>> [14]
>>> owner: main (0x0x1ecfc0)
>>> entry_count: 1
>>> waiter_count: 0
>>> notify_waiter_count: 0
***HANGS***
Failure rate is 17/500 runs (~1/29).
I also tried running the test with Hotspot it always passed (1000/1000).
@JasonFengJ9 Can you confirm if you can reproduce the problem with -Xint on your setup? Earlier grinders might have gotten lucky with not hitting the hang while under -Xint. If not, is there anything about my setup that seems to be different than yours?
The hang is seen with following command line:
java -Xint -Xshareclasses:none -Xnoaot -Djdk.virtualThreadScheduler.parallelism=10 -agentpath:/home/jenkins/issue21890/jdk24-0619-openj9/test-images/hotspot/jtreg/native/libObjectMonitorUsage.so -cp /home/jenkins/issue21890/jdk24-0618 ObjectMonitorUsage
Without -Xnoaot, the test passes in multiple 500x runs.
java -Xint -Xshareclasses:none -Djdk.virtualThreadScheduler.parallelism=10 -agentpath:/home/jenkins/issue21890/jdk24-0619-openj9/test-images/hotspot/jtreg/native/libObjectMonitorUsage.so -cp /home/jenkins/issue21890/jdk24-0618 ObjectMonitorUsage
Captured a core when the hang occurred, jdmpview shows JIT threads, @IBMJimmyk is this expected? in addition, any thoughts about how -Xnoaot could cause a hang?
> !threads
!stack 0x000bf100 !j9vmthread 0x000bf100 !j9thread 0x7fffa401dee0 tid 0x4dfd (19965) // (main)
!stack 0x000c1700 !j9vmthread 0x000c1700 !j9thread 0x7fffa4189a30 tid 0x4dff (19967) // (JIT Compilation Thread-000 Suspended)
!stack 0x000c3c00 !j9vmthread 0x000c3c00 !j9thread 0x7fffa4189fa8 tid 0x4e00 (19968) // (JIT Compilation Thread-001)
!stack 0x000c6200 !j9vmthread 0x000c6200 !j9thread 0x7fffa418af60 tid 0x4e01 (19969) // (JIT Compilation Thread-002 Suspended)
!stack 0x000c8800 !j9vmthread 0x000c8800 !j9thread 0x7fffa418b4d8 tid 0x4e02 (19970) // (JIT Compilation Thread-003 Suspended)
!stack 0x000cad00 !j9vmthread 0x000cad00 !j9thread 0x7fffa418c490 tid 0x4e03 (19971) // (JIT Compilation Thread-004 Suspended)
!stack 0x000cd300 !j9vmthread 0x000cd300 !j9thread 0x7fffa418ca08 tid 0x4e04 (19972) // (JIT Compilation Thread-005 Suspended)
!stack 0x000cf900 !j9vmthread 0x000cf900 !j9thread 0x7fffa418d9c0 tid 0x4e05 (19973) // (JIT Compilation Thread-006 Suspended)
!stack 0x000d1f00 !j9vmthread 0x000d1f00 !j9thread 0x7fffa418df38 tid 0x4e06 (19974) // (JIT Diagnostic Compilation Thread-007 Suspended)
!stack 0x000d4400 !j9vmthread 0x000d4400 !j9thread 0x7fffa419c2b0 tid 0x4e07 (19975) // (JVMTI event reporting thread)
!stack 0x000d6a00 !j9vmthread 0x000d6a00 !j9thread 0x7fffa419c828 tid 0x4e08 (19976) // (JIT-SamplerThread)
!stack 0x000d9000 !j9vmthread 0x000d9000 !j9thread 0x7fffa419d730 tid 0x4e09 (19977) // (IProfiler)
It turns out that -Xnoaot unexpectedly causes the JIT to be loaded even if -Xint is set. So this might still be a JIT issue after all. I will continue to take a look.
The problem does seem to be related to a compiled method.
I am currently using this JVM (different from above):
openjdk version "24.0.1-internal" 2025-04-15
OpenJDK Runtime Environment (build 24.0.1-internal-adhoc.jenkins.BuildJDK24ppc64lelinuxPersonal)
Eclipse OpenJ9 VM (build master-f26458259ca, JRE 24 Linux ppc64le-64-Bit Compressed References 20250618_100 (JIT enabled, AOT disabled)
OpenJ9 - f26458259ca
OMR - 41204d22161
JCL - 7adb8bad278 based on jdk-24.0.1+9)
I am able to reliably (100% or close to it) reproduce the hang with the following command:
java -Xjit:"disableInlineMonEnt,disableInlineMonExit,lastoptindex=0,optlevel=noopt,count=0,disableasynccompilation,limit={*ObjectMonitorUsage*EnteringTask.run*},tracefull,log=trace/virtual.log" -Xshareclasses:none -Xnoaot -Xdump:none -Djdk.virtualThreadScheduler.parallelism=10 -agentpath:/team/jimmyk/Defects/21890-virtualThreads/testimage/jdk-24.0.1plus9-test-image/hotspot/jtreg/native/libObjectMonitorUsage.so ObjectMonitorUsage
This causes only one method to be compiled: ObjectMonitorUsage$EnteringTask.run()V.
Test no longer fails if that method is also excluded.
The Xjit options turns off all optimizations. monent and monexit are performed via calls to the VM rather than with inlined assembly.
With everything turned off, the method is now under 100 instructions in size so I can reasonably check the whole thing.
I am currently looking through the assembly to see if I can catch the problem.
0x00007fffc2e900d0: ld r3,1880(r16) //* two instruction sequence to load static object lockCheck into r31
0x00007fffc2e900d4: ld r31,0(r3) //*
0x00007fffc2e900d8: std r31,48(r14) // lockCheck recorded to stack at 48(r14)
0x00007fffc2e900dc: tdeqi r31,0 // null check on lockCheck in r31
0x00007fffc2e900e0: ori r3,r15,0 // copy VMThread to r3
0x00007fffc2e900e4: ori r4,r31,0 // copy lockCheck to r4
0x00007fffc2e900e8: ld r12,920(r16)
0x00007fffc2e900ec: bl 0x7fffc308f100 // call jitMonitorEntry
0x00007fffc2e900f0: std r31,40(r14)
0x00007fffc2e900f4: ld r4,48(r14) // load lockCheck into r4 from 48(r14)
0x00007fffc2e900f8: tdeqi r4,0 // null check lockCheck
0x00007fffc2e900fc: ori r3,r15,0 // copy VMThread to r3
0x00007fffc2e90100: ld r12,936(r16)
0x00007fffc2e90104: bl 0x7fffc308f140 // call jitMonitorExit
0x00007fffc2e90108: b 0x7fffc2e9010c // jump to return sequence
There's not really a whole lot of code here and it doesn't do very much.
jitMonitorEntry eventually reaches objectMonitorEnterNonBlocking.
jitMonitorExit eventually reaches objectMonitorExit.
It might be the something goes wrong in the transition.
I'm now using a slightly different command. traceILGen and disableOSR were added as options. count=10 is now used instead of count=0. The test was modified to run test1 multiple times in a row to be compatible with the higher count. test0, test2, test3 are no longer run to focus on the test1 hang. NUMBER_OF_ENTERING_THREADS is set to 2 to further simply things.
java -Xjit:"traceILGen,disableOSR,disableInlineMonEnt,disableInlineMonExit,lastoptindex=0,optlevel=noopt,count=10,disableasynccompilation,limit={*ObjectMonitorUsage*EnteringTask.run*},tracefull,log=trace/virtual.log" -Xshareclasses:none -Xnoaot -Xdump:none -Xnocompressedrefs -Djdk.virtualThreadScheduler.parallelism=10 -agentpath:/team/jimmyk/Defects/21890-virtualThreads/testimage/jdk-24.0.1plus9-test-image/hotspot/jtreg/native/libObjectMonitorUsage.so ObjectMonitorUsage
The trees at the very start of the tracefile look like this:
<trees
title="Pre IlGenOpt Trees"
method="ObjectMonitorUsage$EnteringTask.run()V"
hotness="no-opt">
Pre IlGenOpt Trees: for ObjectMonitorUsage$EnteringTask.run()V
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
n11n BBStart <block_2> [ 0x74b003004a50] bci=[-1,0,368] rc=0 vc=0 vn=- li=- udi=- nc=0
n17n istorei ObjectMonitorUsage$EnteringTask.ready Z[#401 volatile Shadow +24] [flags 0x6601 0x0 ] [ 0x74b003004c30] bci=[-1,2,368] rc=0 vc=0 vn=- li=- udi=- nc=2
n13n aload <'this' parm LObjectMonitorUsage$EnteringTask;>[#400 Parm] [flags 0x40000107 0x0 ] (X!=0 ) [ 0x74b003004af0] bci=[-1,0,368] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x4
n16n iand [ 0x74b003004be0] bci=[-1,2,368] rc=1 vc=0 vn=- li=- udi=- nc=2
n14n iconst 1 (X!=0 X>=0 ) [ 0x74b003004b40] bci=[-1,1,368] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x104
n15n iconst 1 (X!=0 X>=0 ) [ 0x74b003004b90] bci=[-1,2,368] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x104
n19n astore <auto slot 1>[#403 Auto] [flags 0x7 0x0 ] [ 0x74b003004cd0] bci=[-1,9,369] rc=0 vc=0 vn=- li=- udi=- nc=1
n18n aload ObjectMonitorUsage.lockCheck Ljava/lang/Object;[#402 Static] [flags 0x307 0x0 ] [ 0x74b003004c80] bci=[-1,5,369] rc=3 vc=0 vn=- li=- udi=- nc=0
n21n NULLCHK on n18n [#32] [ 0x74b003004d70] bci=[-1,10,369] rc=0 vc=0 vn=- li=- udi=- nc=1
n20n monent jitMonitorEntry[#116 helper Method] [flags 0x400 0x0 ] [ 0x74b003004d20] bci=[-1,10,369] rc=1 vc=0 vn=- li=- udi=- nc=1
n18n ==>aload
n22n astore <temp slot 4 holds monitoredObject>[#404 Auto] [flags 0x8000007 0x0 ] [ 0x74b003004dc0] bci=[-1,10,369] rc=0 vc=0 vn=- li=- udi=- nc=1
n18n ==>aload
n12n BBEnd </block_2> ===== [ 0x74b003004aa0] bci=[-1,10,369] rc=0 vc=0 vn=- li=- udi=- nc=0
n3n BBStart <block_3> [ 0x74b0030047d0] bci=[-1,11,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n24n monexitfence [ 0x74b003004e60] bci=[-1,12,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n26n NULLCHK on n23n [#32] [ 0x74b003004f00] bci=[-1,12,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n25n monexit jitMonitorExit[#118 helper Method] [flags 0x400 0x0 ] [ 0x74b003004eb0] bci=[-1,12,370] rc=1 vc=0 vn=- li=- udi=- nc=1
n23n aload <auto slot 1>[#403 Auto] [flags 0x7 0x0 ] [ 0x74b003004e10] bci=[-1,11,370] rc=1 vc=0 vn=- li=- udi=- nc=0
n4n BBEnd </block_3> ===== [ 0x74b003004820] bci=[-1,12,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n5n BBStart <block_4> [ 0x74b003004870] bci=[-1,13,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n27n goto --> block_5 BBStart at n1n [ 0x74b003004f50] bci=[-1,13,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n6n BBEnd </block_4> ===== [ 0x74b0030048c0] bci=[-1,13,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n1n BBStart <block_5> [ 0x74b003004730] bci=[-1,21,371] rc=0 vc=0 vn=- li=- udi=- nc=0
n28n return [ 0x74b003004fa0] bci=[-1,21,371] rc=0 vc=0 vn=- li=- udi=- nc=0
n2n BBEnd </block_5> ===== [ 0x74b003004780] bci=[-1,21,371] rc=0 vc=0 vn=- li=- udi=- nc=0
n7n BBStart <block_6> (catches ...) [ 0x74b003004910] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n31n astore <pending push temp 0>[#405 Auto] [flags 0x7 0x800 ] [ 0x74b003005090] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n29n aload ExceptionMeta[#319 MethodMeta +64] [flags 0x207 0x0 ] [ 0x74b003004ff0] bci=[-1,16,370] rc=2 vc=0 vn=- li=- udi=- nc=0
n30n asynccheck jitCheckAsyncMessages[#23 helper Method] [flags 0x400 0x0 ] [ 0x74b003005040] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n32n astore <temp slot 5>[#406 Auto] [flags 0x7 0x0 ] [ 0x74b0030050e0] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n29n ==>aload
n34n astore ExceptionMeta[#319 MethodMeta +64] [flags 0x207 0x0 ] [ 0x74b003005180] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n33n aconst NULL (X==0 ) [ 0x74b003005130] bci=[-1,16,370] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x2
n36n astore <auto slot 2>[#407 Auto] [flags 0x7 0x0 ] [ 0x74b003005220] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n35n aload <temp slot 5>[#406 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x74b0030051d0] bci=[-1,16,370] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x4
n38n monexitfence [ 0x74b0030052c0] bci=[-1,18,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n40n NULLCHK on n37n [#32] [ 0x74b003005360] bci=[-1,18,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n39n monexit jitMonitorExit[#118 helper Method] [flags 0x400 0x0 ] [ 0x74b003005310] bci=[-1,18,370] rc=1 vc=0 vn=- li=- udi=- nc=1
n37n aload <auto slot 1>[#403 Auto] [flags 0x7 0x0 ] [ 0x74b003005270] bci=[-1,17,370] rc=1 vc=0 vn=- li=- udi=- nc=0
n8n BBEnd </block_6> ===== [ 0x74b003004960] bci=[-1,18,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n9n BBStart <block_7> [ 0x74b0030049b0] bci=[-1,19,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n43n NULLCHK on n41n [#32] [ 0x74b003005450] bci=[-1,20,370] rc=0 vc=0 vn=- li=- udi=- nc=1
n42n athrow jitThrowException[#24 helper Method] [flags 0x400 0x0 ] [ 0x74b003005400] bci=[-1,20,370] rc=1 vc=0 vn=- li=- udi=- nc=1
n41n aload <auto slot 2>[#407 Auto] [flags 0x7 0x0 ] [ 0x74b0030053b0] bci=[-1,19,370] rc=1 vc=0 vn=- li=- udi=- nc=0
n10n BBEnd </block_7> ===== [ 0x74b003004a00] bci=[-1,20,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n44n BBStart <block_8> (freq 3) (catches ...) (cold) [ 0x74b0030054a0] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n58n monexitfence [ 0x74b0030801e0] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n57n BBEnd </block_8> (cold) ===== [ 0x74b003080190] bci=[-1,18,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n59n BBStart <block_9> (freq 3) (cold) [ 0x74b003080230] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n61n asynccheck jitCheckAsyncMessages[#23 helper Method] [flags 0x400 0x0 ] [ 0x74b0030802d0] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n62n goto --> block_9 BBStart at n59n [ 0x74b003080320] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
n60n BBEnd </block_9> (cold) [ 0x74b003080280] bci=[-1,16,370] rc=0 vc=0 vn=- li=- udi=- nc=0
Note block_9 at the bottom. This is an infinite loop and it's where the hang occurs. The loop is an asynccheck then loops back on itself forever.
Even with traceILGen the tracefile does not say where the trees in block 9 come from.
please look back to the bytecode ... of course don't expect asyncCheck in bytecode, it is added by ILgen for a loop. so, you should expect a goto bytecode to near above.
The bytecodes looks like this:
0, JBaload0
1, JBiconst1
2, JBputfield 3
5, JBgetstatic 5
8, JBdup
9, JBastore1
10, JBmonitorenter
11, JBaload1
12, JBmonitorexit
13, JBgoto 8, 21,
16, JBastore2
17, JBaload1
18, JBmonitorexit
19, JBaload2
20, JBathrow
21, JBreturn0
There is a goto at 13.
that goto bytecode is jumping to the return ... how come the endless loop is beyond me. intuitively some ILgen bug to me, but is the same IL gen-ed for a good run (no VT, let's say)? if yes, how can it come out of the block9 loop to end the run? something to look further here
It still happens even on Semeru JDK21 with no virtual threads:
Java code:
static class EnteringTask implements Runnable {
public void run() {
synchronized (lockCheck) {
}
}
}
Bytecodes:
0, JBgetstatic 3
3, JBdup
4, JBastore1
5, JBmonitorenter
6, JBaload1
7, JBmonitorexit
8, JBgoto 8, 16,
11, JBastore2
12, JBaload1
13, JBmonitorexit
14, JBaload2
15, JBathrow
16, JBreturn0
Trees:
n11n BBStart <block_2> [ 0x73c1e41649c0] bci=[-1,0,91] rc=0 vc=0 vn=- li=- udi=- nc=0
n14n ResolveCHK [#320] [ 0x73c1e4164ab0] bci=[-1,0,91] rc=0 vc=0 vn=- li=- udi=- nc=1
n13n aload ObjectMonitorUsage.lockCheck Ljava/lang/Object;[#399 unresolved notAccessed volatile Static] [flags 0x2307 0x0 ] [ 0x73c1e4164a60] bci=[-1,0,91] rc=4 vc=0 vn=- li=-
udi=- nc=0
n15n astore <auto slot 1>[#400 Auto] [flags 0x7 0x0 ] [ 0x73c1e4164b00] bci=[-1,4,91] rc=0 vc=0 vn=- li=- udi=- nc=1
n13n ==>aload
n17n NULLCHK on n13n [#32] [ 0x73c1e4164ba0] bci=[-1,5,91] rc=0 vc=0 vn=- li=- udi=- nc=1
n16n monent jitMonitorEntry[#115 helper Method] [flags 0x400 0x0 ] [ 0x73c1e4164b50] bci=[-1,5,91] rc=1 vc=0 vn=- li=- udi=- nc=1
n13n ==>aload
n18n astore <temp slot 4 holds monitoredObject>[#401 Auto] [flags 0x8000007 0x0 ] [ 0x73c1e4164bf0] bci=[-1,5,91] rc=0 vc=0 vn=- li=- udi=- nc=1
n13n ==>aload
n12n BBEnd </block_2> ===== [ 0x73c1e4164a10] bci=[-1,5,91] rc=0 vc=0 vn=- li=- udi=- nc=0
n3n BBStart <block_3> [ 0x73c1e4164740] bci=[-1,6,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n20n monexitfence [ 0x73c1e4164c90] bci=[-1,7,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n22n NULLCHK on n19n [#32] [ 0x73c1e4164d30] bci=[-1,7,92] rc=0 vc=0 vn=- li=- udi=- nc=1
n21n monexit jitMonitorExit[#117 helper Method] [flags 0x400 0x0 ] [ 0x73c1e4164ce0] bci=[-1,7,92] rc=1 vc=0 vn=- li=- udi=- nc=1
n19n aload <auto slot 1>[#400 Auto] [flags 0x7 0x0 ] [ 0x73c1e4164c40] bci=[-1,6,92] rc=1 vc=0 vn=- li=- udi=- nc=0
n4n BBEnd </block_3> ===== [ 0x73c1e4164790] bci=[-1,7,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n5n BBStart <block_4> [ 0x73c1e41647e0] bci=[-1,8,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n23n goto --> block_5 BBStart at n1n [ 0x73c1e4164d80] bci=[-1,8,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n6n BBEnd </block_4> ===== [ 0x73c1e4164830] bci=[-1,8,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n1n BBStart <block_5> [ 0x73c1e41646a0] bci=[-1,16,93] rc=0 vc=0 vn=- li=- udi=- nc=0
n24n return [ 0x73c1e4164dd0] bci=[-1,16,93] rc=0 vc=0 vn=- li=- udi=- nc=0
n2n BBEnd </block_5> ===== [ 0x73c1e41646f0] bci=[-1,16,93] rc=0 vc=0 vn=- li=- udi=- nc=0
n7n BBStart <block_6> (catches ...) [ 0x73c1e4164880] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n26n astore <temp slot 5>[#402 Auto] [flags 0x7 0x0 ] [ 0x73c1e4164e70] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=1
n25n aload ExceptionMeta[#318 MethodMeta +64] [flags 0x207 0x0 ] [ 0x73c1e4164e20] bci=[-1,11,92] rc=1 vc=0 vn=- li=- udi=- nc=0
n28n astore ExceptionMeta[#318 MethodMeta +64] [flags 0x207 0x0 ] [ 0x73c1e4164f10] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=1
n27n aconst NULL (X==0 ) [ 0x73c1e4164ec0] bci=[-1,11,92] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x2
n30n astore <auto slot 2>[#403 Auto] [flags 0x7 0x0 ] [ 0x73c1e4164fb0] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=1
n29n aload <temp slot 5>[#402 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x73c1e4164f60] bci=[-1,11,92] rc=1 vc=0 vn=- li=- udi=- nc=0 flg=0x4
n32n monexitfence [ 0x73c1e4165050] bci=[-1,13,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n34n NULLCHK on n31n [#32] [ 0x73c1e41650f0] bci=[-1,13,92] rc=0 vc=0 vn=- li=- udi=- nc=1
n33n monexit jitMonitorExit[#117 helper Method] [flags 0x400 0x0 ] [ 0x73c1e41650a0] bci=[-1,13,92] rc=1 vc=0 vn=- li=- udi=- nc=1
n31n aload <auto slot 1>[#400 Auto] [flags 0x7 0x0 ] [ 0x73c1e4165000] bci=[-1,12,92] rc=1 vc=0 vn=- li=- udi=- nc=0
n8n BBEnd </block_6> ===== [ 0x73c1e41648d0] bci=[-1,13,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n9n BBStart <block_7> [ 0x73c1e4164920] bci=[-1,14,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n37n NULLCHK on n35n [#32] [ 0x73c1e41651e0] bci=[-1,15,92] rc=0 vc=0 vn=- li=- udi=- nc=1
n36n athrow jitThrowException[#24 helper Method] [flags 0x400 0x0 ] [ 0x73c1e4165190] bci=[-1,15,92] rc=1 vc=0 vn=- li=- udi=- nc=1
n35n aload <auto slot 2>[#403 Auto] [flags 0x7 0x0 ] [ 0x73c1e4165140] bci=[-1,14,92] rc=1 vc=0 vn=- li=- udi=- nc=0
n10n BBEnd </block_7> ===== [ 0x73c1e4164970] bci=[-1,15,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n38n BBStart <block_8> (freq 3) (catches ...) (cold) [ 0x73c1e4165230] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n50n monexitfence [ 0x73c1e41655f0] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n49n BBEnd </block_8> (cold) ===== [ 0x73c1e41655a0] bci=[-1,13,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n51n BBStart <block_9> (freq 3) (cold) [ 0x73c1e4165640] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n53n asynccheck jitCheckAsyncMessages[#23 helper Method] [flags 0x400 0x0 ] [ 0x73c1e41e0050] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n54n goto --> block_9 BBStart at n51n [ 0x73c1e41e00a0] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
n52n BBEnd </block_9> (cold) [ 0x73c1e41e0000] bci=[-1,11,92] rc=0 vc=0 vn=- li=- udi=- nc=0
I doesn't take the exception path when I run it so block 9 doesn't run. Although, I'm not sure why the original virtual threads test is taking the exception path either.
I forgot to mention this before but the unmodified test case can be found here:
https://github.com/ibmruntimes/openj9-openjdk-jdk24/blob/7adb8bad278d7cfcd77aa44bdb00919437c16a35/test/hotspot/jtreg/serviceability/jvmti/ObjectMonitorUsage/ObjectMonitorUsage.java
I'm currently using a modified version that only runs the virtual thread version of test1 and runs it multiple times in a row. It can be found here:
https://github.ibm.com/jimmyk/workspace/blob/30ef35a05b1d191c13d7f68b47455ec1755eef18/testCode/ObjectMonitorUsage/ObjectMonitorUsage.java
are you able to confirm: when the "hang" happened, at least one VT was mounted and was busy looping in block#9? since that is the only method JIT-ed and block#9 is part of a catcher (i.e. you can come here only by VM/runtime exception handling code jumping to the appropriate catcher somehow). had better ask @tajila and @fengxue-IS diagnose this further from VM/runtime perspective.
Yes. I was able to verify via gdb that a thread was looping in block 9 during a hang.
I tried adding -Xdump:java:events=throw to a run and I now get this before the hang:
### test1: started virtual
>>> [2]
>>> owner: main (0x0x7a67145a9fb0)
>>> entry_count: 1
>>> waiter_count: 0
>>> notify_waiter_count: 0
>>> [3]
>>> owner: main (0x0x7a67145a9fb0)
>>> entry_count: 1
>>> waiter_count: 0
>>> notify_waiter_count: 0
JVMDUMP039I Processing dump event "throw", detail "java/lang/IllegalMonitorStateException" at 2025/06/24 13:12:12 - please wait.
JVMDUMP032I JVM requested Java dump using '/team/jimmyk/Defects/21890-virtualThreads/workspace/javacore.20250624.131212.856433.0006.txt' in response to an event
JVMDUMP010I Java dump written to /team/jimmyk/Defects/21890-virtualThreads/workspace/javacore.20250624.131212.856433.0006.txt
JVMDUMP013I Processed dump event "throw", detail "java/lang/IllegalMonitorStateException".
JVMDUMP039I Processing dump event "throw", detail "java/lang/IllegalMonitorStateException" at 2025/06/24 13:12:12 - please wait.
JVMDUMP032I JVM requested Java dump using '/team/jimmyk/Defects/21890-virtualThreads/workspace/javacore.20250624.131212.856433.0007.txt' in response to an event
JVMDUMP010I Java dump written to /team/jimmyk/Defects/21890-virtualThreads/workspace/javacore.20250624.131212.856433.0007.txt
JVMDUMP013I Processed dump event "throw", detail "java/lang/IllegalMonitorStateException".
****HANGS****
This test isn't supposed to generate an IllegalMonitorStateException so that's a problem. I double checked with an -Xint run and I don't see any IllegalMonitorStateException. For this failing run, disableInlineMonEnt,disableInlineMonExit Xjit options are set which means JIT code does not attempt to modify monitor state and calls the VM.