Bug ID: JDK-6908302 VM Crash during profiling of java/util/concurrent/BlockingQueue/CancelledProducerConsumerLoops.java

Type: Bug
Component: hotspot
Sub-Component: jvmti
Affected Version: hs17

Priority: P4
Status: Closed
Resolution: Not an Issue
OS: generic
CPU: x86

Submitted: 2009-12-08
Updated: 2023-12-13
Resolved: 2013-09-03

Other
tbdResolved

During run java/util/concurrent/BlockingQueue/CancelledProducerConsumerLoops.java
test under NetBeans 6.7 with profiler the profiled VM crashes.

The full test name is:
UTIL_REGRESSION/test/java/util/concurrent/BlockingQueue/CancelledProducerConsumerLoops.java


The log is in the attachement.
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (/BUILD_AREA/jdk7/hotspot/src/share/vm/runtime/synchronizer.cpp:3220), pid=8943, tid=20
#  Error: assert(Self->_Stalled == 0,"invariant")
#
# JRE version: 7.0-b77
# Java VM: Java HotSpot(TM) Server VM (17.0-b05-fastdebug mixed mode solaris-x86 )
# If you would like to submit a bug report, please visit:
#   http://java.sun.com/webapps/bugreport/crash.jsp
#

This seems to be a bug in the NetBeans profiler as the event callback function is not re-entrant. There is no reference to the profiling agent code to take a look and decide what exactly is wrong there. I'm closing this report as "Not an Issue". But it is possible this issue needs to be redirected to the NetBeans team. David and Dan, thank you for the analysis!
03-09-2013
PUBLIC COMMENTS It may be that some simple adjustments to the objectMonitor code, to reset the per-thread state before posting JVMTI events, can resolve these issues. For example: In ObjectMonitor::Enter move Self->_Stalled = intptr_t(this) ; // line 350 to after if (JvmtiExport::should_post_monitor_contended_enter()) { JvmtiExport::post_monitor_contended_enter(jt, this); } In ObjectMonitor::Wait where we have: // post monitor waited event. Note that this is past-tense, we are done waiting. if (JvmtiExport::should_post_monitor_waited()) { JvmtiExport::post_monitor_waited(jt, this, ret == OS_TIMEOUT); } OrderAccess::fence() ; assert (Self->_Stalled != 0, "invariant") ; Self->_Stalled = 0 ; Move the reset of _Stalled to before the posting of the event. Note however that while this will stop the asserts from triggering we have not verified that such recursive entry into the synchronization code is actually safe. We would need to verify this for the case where the second monitor is different to the first, and where it is the same. Though the second case is most definitely a bug in the Agent code as it could lead to infinite recursion.
30-11-2011
PUBLIC COMMENTS The "Events" section of the JVM/TI spec has some relevant words: http://java.sun.com/javase/6/docs/platform/jvmti/jvmti.html#EventSection The following general guideline seems relevant: * Event callback functions must be re-entrant. The JVM TI implementation does not queue events. If an agent needs to process events one at a time, it can use a raw monitor inside the event callback functions to serialize event processing. In this particular case, the agent's MonitorContendedEnter event handler is making a JNI call that requires that a Java level monitor be entered. Since the event handler is being called on behalf of a thread that is already contending for a Java level monitor, I would argue that this event callback function is not re-entrant. In other words, the thread is already blocked on entering one Java level monitor so it seems like a bad agent design for it to try and enter another Java level monitor. This style of event handler design is just asking for a deadlock. For now, this note is just a "comment note" and not an "evaluation note" because I still haven't seen what the agent is actually trying to do. I'm just making guesses based on the stack trace.
03-03-2010
PUBLIC COMMENTS Sorry I didn't make the call sequence clearer in the description. Yes the issue is that while in the process of acquiring a monitor we fire the contended_monitor_enter event which causes the agent to execute Java code which then tries to acquire another monitor. The monitor code uses per-thread state and is not designed to be reentrant. I can't see where JVMTI defines what actions an agent is allowed, or not allowed, to do. I would have expected that only JVMTI functions could be called, but I see blogs and tech-notes that mention using any JNI function too. That seems unreasonable to me as it would require every part of the VM that contains a JVMTI event-hook to be reentrant.
02-03-2010
PUBLIC COMMENTS Buried in the stack trace from the previous entry is: V [libjvm.so+0xaf1466];; jni_CallStaticVoidMethod+0x32a C [libprofilerinterface.so+0x3e2e] monitor_contended_enter_hook+0x52Warning: /usr/netbeans/profiler3/lib/deployed/jdk16/solaris-i386/libprofilerinterface.so does not exist V [libjvm.so+0xdf7b08];; __1cLJvmtiExportbCpost_monitor_contended_enter6FpnKJavaThread_pnNObjectMonitor__v_+0x192c V [libjvm.so+0x1578bcb];; __1cNObjectMonitorFenter6MpnGThread__v_+0x573 This snippet shows that the VM detected an attempt to enter a contended monitor and started to post a MonitorContendedEnter event. The post_monitor_contended_enter() function called the agent's handler: monitor_contended_enter_hook(). It is the code in the agent's handler that caused the reentrant Java monitor enter. I'm assuming here that the assertion that failed does mean that a reentrant Java monitor was attempted. This does not look like a JVM/TI bug to me. This looks like an error in the agent. However, it is hard to be sure without a closer look at the agent's code.
01-03-2010
PUBLIC COMMENTS The log shows a reentrant call into the monitor entry code by the JVMTI agent used by the profiler: ;; Using jvm: /java/re/jdk/7/promoted/all/b77/binaries/solaris-i586/fastdebug/jre/lib/i386/server/libjvm.so # # A fatal error has been detected by the Java Runtime Environment: # # Internal Error (/BUILD_AREA/jdk7/hotspot/src/share/vm/runtime/synchronizer.cpp:3220), pid=8943, tid=20 # Error: assert(Self->_Stalled == 0,"invariant") # # JRE version: 7.0-b77 # Java VM: Java HotSpot(TM) Server VM (17.0-b05-fastdebug mixed mode solaris-x86 ) # If you would like to submit a bug report, please visit: # http://java.sun.com/webapps/bugreport/crash.jsp # --------------- T H R E A D --------------- Current thread (0x08475c00): JavaThread "pool-1-thread-2" [_thread_in_vm, id=20, stack(0xb3c55000,0xb3ca5000)] Stack: [0xb3c55000,0xb3ca5000], sp=0xb3ca34c0, free space=139b3ca5000k Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) V [libjvm.so+0x16d867e];; __1cHVMErrorGreport6MpnMoutputStream__v_+0x5be V [libjvm.so+0x16d965a];; __1cHVMErrorOreport_and_die6M_v_+0x586 V [libjvm.so+0x7ba249];; __1cYreport_assertion_failure6Fpkci1_v_+0x61 V [libjvm.so+0x157926a];; __1cNObjectMonitorFenter6MpnGThread__v_+0xc12 V [libjvm.so+0x15720d2];; __1cSObjectSynchronizerKslow_enter6FnGHandle_pnJBasicLock_pnGThread__v_+0x272 V [libjvm.so+0x1571ac1];; __1cSObjectSynchronizerKfast_enter6FnGHandle_pnJBasicLock_bpnGThread__v_+0x10d V [libjvm.so+0x156f05b];; __1cMObjectLocker2t6MnGHandle_pnGThread_b_v_+0x6f V [libjvm.so+0x7a13bb];; __1cTconstantPoolOopDescOstring_at_impl6FnSconstantPoolHandle_ipnGThread__nDoop__+0x17f V [libjvm.so+0x7a118c];; __1cTconstantPoolOopDescbDresolve_string_constants_impl6FnSconstantPoolHandle_pnGThread__v_+0x418 V [libjvm.so+0x6ecb8c];; __1cTconstantPoolOopDescYresolve_string_constants6MpnGThread__v_+0x198 V [libjvm.so+0x6e3e33];; __1cNCompileBrokerOcompile_method6FnMmethodHandle_i1ipkcpnGThread__pnHnmethod__+0xbdfV [libjvm.so+0x6c8d09];; __1cQSimpleCompPolicyXmethod_invocation_event6MnMmethodHandle_pnGThread__v_+0x1e1 V [libjvm.so+0xa60e6e];; __1cSInterpreterRuntimebGfrequency_counter_overflow_inner6FpnKJavaThread_pC_pnHnmethod__+0x1556 V [libjvm.so+0xa5f647];; __1cSInterpreterRuntimebAfrequency_counter_overflow6FpnKJavaThread_pC_pnHnmethod__+0x23 j org.netbeans.lib.profiler.server.ProfilerServer.getProfilingSessionStatus()Lorg/netbeans/lib/profiler/global/ProfilingSessionStatus;+0 j org.netbeans.lib.profiler.server.ProfilerRuntime.monitorEntry(Ljava/lang/Thread;Ljava/lang/Object;)V+14 v ~StubRoutines::call_stub V [libjvm.so+0xa784af];; __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x80b V [libjvm.so+0x12dea87];; __1cCosUos_exception_wrapper6FpFpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v2468_v_+0x17 V [libjvm.so+0xa77c74];; __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_+0x44 V [libjvm.so+0xad3cc1];; __1cRjni_invoke_static6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_+0x245 V [libjvm.so+0xaf1466];; jni_CallStaticVoidMethod+0x32a C [libprofilerinterface.so+0x3e2e] monitor_contended_enter_hook+0x52Warning: /usr/netbeans/profiler3/lib/deployed/jdk16/solaris-i386/libprofilerinterface.so does not exist V [libjvm.so+0xdf7b08];; __1cLJvmtiExportbCpost_monitor_contended_enter6FpnKJavaThread_pnNObjectMonitor__v_+0x192c V [libjvm.so+0x1578bcb];; __1cNObjectMonitorFenter6MpnGThread__v_+0x573 V [libjvm.so+0x15720d2];; __1cSObjectSynchronizerKslow_enter6FnGHandle_pnJBasicLock_pnGThread__v_+0x272 V [libjvm.so+0x1571ac1];; __1cSObjectSynchronizerKfast_enter6FnGHandle_pnJBasicLock_bpnGThread__v_+0x10d V [libjvm.so+0x14591bd];; __1cNSharedRuntimebAcomplete_monitor_locking_C6FpnHoopDesc_pnJBasicLock_pnKJavaThread__v_+0x3d5 Java frames: (J=compiled Java code, j=interpreted, Vv=VM code) j org.netbeans.lib.profiler.server.ProfilerServer.getProfilingSessionStatus()Lorg/netbeans/lib/profiler/global/ProfilingSessionStatus;+0 j org.netbeans.lib.profiler.server.ProfilerRuntime.monitorEntry(Ljava/lang/Thread;Ljava/lang/Object;)V+14 v ~StubRoutines::call_stub v ~RuntimeStub::_complete_monitor_locking_Java J org.netbeans.lib.profiler.server.ProfilerRuntimeObjAlloc.traceObjAlloc(Ljava/lang/Object;C)V J CancelledProducerConsumerLoops$Producer.call()Ljava/lang/Integer; j CancelledProducerConsumerLoops$Producer.call()Ljava/lang/Object;+1 j java.util.concurrent.FutureTask$Sync.innerRun()V+29 j java.util.concurrent.FutureTask.run()V+4 j java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V+46 j java.util.concurrent.ThreadPoolExecutor$Worker.run()V+5 j java.lang.Thread.run()V+11 v ~StubRoutines::call_stub I don't know if this is supposed to be legal according to the JVMTI rules, but the VM is certainly not designed to handle this kind of reentrancy.
01-03-2010