Runtime crashes when attached to JNI-based profiler #22337
Description
Java -version output
Eclipse OpenJ9 VM 21.0.7.0 (build openj9-0.51.0, JRE 21 Linux amd64-64-Bit Compressed References 20250415_458 (JIT enabled, AOT enabled)
OpenJ9 - 31cf553
OMR - 9bcff94a2
JCL - 26c2dc3d801 based on jdk-21.0.7+6)
Summary of problem
Want to use async-profiler for lock contention profiling of processes running on openj9 runtime. All attempts to do this result in the same crash within the runtime
Console output of process at segfault:
18:50:23.122 0x1e7f00 j9vm.225 * ** ASSERTION FAILED ** at /home/jenkins/workspace/build-scripts/jobs/jdk21u/jdk21u-linux-x64-openj9/workspace/build/src/openj9/runtime/vm/VMAccess.cpp:133: (!(vmThread->inNative))
Stack trace of the two overstepping threads:
#0 0x00007fc607e8bedc in __pthread_kill_implementation () from /lib64/libc.so.6
#1 0x00007fc607e3eb46 in raise () from /lib64/libc.so.6
#2 0x00007fc607e28833 in abort () from /lib64/libc.so.6
#3 0x00007fc607e2875b in __assert_fail_base.cold () from /lib64/libc.so.6
#4 0x00007fc607e37886 in __assert_fail () from /lib64/libc.so.6
#5 0x00007fc6061a407e in MM_JNICriticalRegion::releaseAccess(J9VMThread*, unsigned long*) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#6 0x00007fc6061144d2 in MM_EnvironmentBase::acquireExclusiveVMAccessForGC(MM_Collector*, bool) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#7 0x00007fc6061e53ed in MM_MemorySubSpaceSemiSpace::allocationRequestFailed(MM_EnvironmentBase*, MM_AllocateDescription*, MM_MemorySubSpace::AllocationType, MM_ObjectAllocationInterface*, MM_MemorySubSpace*, MM_MemorySubSpace*) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#8 0x00007fc6061c9e48 in MM_MemorySubSpaceGeneric::allocateTLH(MM_EnvironmentBase*, MM_AllocateDescription*, MM_ObjectAllocationInterface*, MM_MemorySubSpace*, MM_MemorySubSpace*, bool) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#9 0x00007fc60613ecbf in MM_TLHAllocationSupport::refresh(MM_EnvironmentBase*, MM_AllocateDescription*, bool) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#10 0x00007fc60613eebe in MM_TLHAllocationSupport::allocateFromTLH(MM_EnvironmentBase*, MM_AllocateDescription*, bool) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#11 0x00007fc60613d5bb in MM_TLHAllocationInterface::allocateObject(MM_EnvironmentBase*, MM_AllocateDescription*, MM_MemorySpace*, bool) [clone .localalias] () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#12 0x00007fc606143ae3 in OMR_GC_AllocateObject(OMR_VMThread*, MM_AllocateInitialization*) () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#13 0x00007fc6060517ee in J9AllocateObject () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9gc29.so
#14 0x00007fc606e15bb6 in old_slow_jitNewObject () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9jit29.so
#15 0x00007fc606e2a881 in jitNewObject () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9jit29.so
#16 0x0000000000013f00 in ?? ()
#17 0x00007fc5f5945ab0 in ?? ()
#18 0x00000000e0041a70 in ?? ()
#19 0x0000000000000000 in ?? ()
and
#0 0x00007fc6071c7578 in jvmtiGetCurrentThread () from /usr/lib/jvm/ibm-semeru-open-21-jdk/lib/default/libj9jvmti29.so
#1 0x00007fc5f53f4f11 in _jvmtiEnv::GetCurrentThread (thread_ptr=0x7fc5f58c4890, this=0x7fc60009e318) at /usr/lib/jvm/ibm-semeru-open-21-jdk/include/jvmti.h:1198
#2 LockTracer::getParkBlocker (env=0x1e4200, jvmti=0x7fc60009e318) at src/lockTracer.cpp:234
#3 LockTracer::UnsafeParkHook (env=0x1e4200, instance=0x0, isAbsolute=<optimized out>, time=3758329432) at src/lockTracer.cpp:205
#4 0x00007fc58aa9d714 in ?? () #5 0x00000000001e4200 in ?? () #6 0x00000000001e4200 in ?? () #7 0x00000000001e4200 in ?? () #8 0x00007fc5f58c4ab0 in ?? () #9 0x0000000000000001 in ?? () #10 0x00000000e00423f0 in ?? () #11 0x0000000000000000 in ?? ()
The assert looks like:
void MM_JNICriticalRegion::releaseAccess(J9VMThread* vmThread, UDATA* accessMask) { #if defined(J9VM_INTERP_ATOMIC_FREE_JNI) // Current thread must have entered the VM before acquiring exclusive Assert_MM_false(vmThread->inNative);
and the async-profiler injected code does invoke InternalExitFromJNI(J9VMThread *currentThread) which looks like:
void internalExitVMToJNI(J9VMThread *currentThread) { VM_AtomicSupport::writeBarrier(); currentThread->inNative = TRUE;
So my guess is that there are two pairs of functions that modify currentThread->InNative: internalEnterVMFromJNI(...)/internalExitVMToJNI(...) and MM_JNICriticalRegion::reacquireAccess(...)/MM_JNICriticalRegion::releaseAccess(...). The calls of these functions are chronologically overlapped/interleaved such that the inNative flag is set to an unexpected state for MM_JNICriticalRegion::releaseAccess
Diagnostic files
I do have system core dumps, but the files are quite large
Reproduction Steps
- Ensure that active java runtime is 'IBM Semeru Runtime Open Edition 21.0.7.0 (build 21.0.7+6-LTS)'
- Install async-profiler per https://github.com/async-profiler/async-profiler
- In a shell, run the attached java program (e.g,.
java RaceToLock)
RaceToLock.java.txt - (for viewing the stacktraces) In a separate shell, run gdb attached to the 'RaceToLock" process (e.g., 'gdb attach ')
- after attach, make sure to continue the process execution after initial interrupt
- In a separate shell, run asprof lock contention profiling (e.g.,
./build/bin/asprof -d 30 -e lock -i 10ms <pid>) - Process should crash