JDK-4796505 : HotSpot hangs during dispatch of JVMPI_EVENT_GC_START
  • Type: Bug
  • Component: vm-legacy
  • Sub-Component: jvmpi
  • Affected Version: 1.3.1_07
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: generic
  • CPU: generic
  • Submitted: 2002-12-19
  • Updated: 2003-01-15
  • Resolved: 2003-01-15
Related Reports
Duplicate :  
JDK-4489387 - -Xrunhprof crashed jvm or got program run to hang
Description
I'll preface this by saying that while I have seen what I believe
is this bug with our product with 1.3.1 through 1.4.1, the test case
provided hangs for me much more reliably with 1.3.1. I have seen
the problem on Solaris and Linux; haven't really looked at Windows.
I've also only looked at C1, so I don't know if it happens with C2.

The problem appears to be that the JVM is holding some resources
during the dispatch of a GC_START event when doing a GC in the young
generations. The behaviour is that the JVMPI client attempts to get
a lock, and hangs. Usually, but not always, another thread is also
in the client, and may be holding the lock. But if so, it is also
blocked in a call back to the JVM.

This never happens if the OBJECT_ALLOC event is enabled and HotSpot
only allocates out of and GCs the old generation. That's why we are
only noticing it now; we used to always get that event, and now we
do not in some modes.

The test case provided enables CLASS_LOAD and CLASS_LOAD_HOOK as
well as GC_START and GC_FINISH. It does some work (churning rand()
on each event, as well as getting/setting thread local storage and
getting a lock around the work. It may be necessary to vary the
workload by providing an integer to the client; the higher the number
the more work it does at each event.

When run against SwingSet2, with the defaults, it hangs usually
at the splash screen or early on in populating the toolbar of the
main window. Solaris I had to vary the workload, but it hung in
the same place.

When hung, you have to kill -9 it.

The stack traces provided are of the thread dispatching the GC
in all cases. They are of the test program for 1.3.1_04 on Linux,
1.3.1_06 on Solaris, and of our product with 1.4.1_01 on Linux.

test prog, 1.3.1_04, Linux RH 6.2:

#0  0x403ff157 in __sched_yield () from /lib/libc.so.6
#1  0x4019c1fd in os::yield ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#2  0x4019668c in ObjectMonitor::raw_enter ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#3  0x401859a3 in jvmpi::raw_monitor_enter ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#4  0x43631b94 in ?? ()
#5  0x401805d2 in jvmpi::post_gc_start_event ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#6  0x4018bb87 in MarkSweep::invoke_at_safepoint ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#7  0x401ab515 in Scavenge::invoke_at_safepoint ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#8  0x401d9fd1 in VM_Scavenge::doit ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#9  0x401d9a2d in VM_Operation::evaluate ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#10 0x401d8caf in VMThread::evaluate_operation ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#11 0x401d8fa1 in VMThread::loop ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#12 0x401d8c0d in VMThread::run ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#13 0x4019a3d3 in _start ()
   from /workspace/johnmac/java/sun1.3.1_04/jre/lib/i386/client/libjvm.so
#14 0x40026b85 in pthread_start_thread (arg=0xbf7ffe40) at manager.c:241

test prog, 1.3.1_06 Solaris 2.8:

#0  0xff29c054 in _lwp_sema_wait () from /usr/lib/libc.so.1
#1  0xff359afc in _park () from /usr/lib/libthread.so.1
#2  0xff3597c4 in _swtch () from /usr/lib/libthread.so.1
#3  0xff3582a4 in cond_wait () from /usr/lib/libthread.so.1
#4  0xfe57fec4 in long Monitor::wait(long,long) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#5  0xfe5ebee8 in void VMThread::execute(VM_Operation*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#6  0xfe623f68 in void Scavenge::invoke(int,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#7  0xfe623d90 in oopDesc**Scavenge::invoke_and_allocate(int,long,Thread*)
    ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#8  0xfe703dc0 in 
oopDesc**Universe::allocate_array(KlassHandle,int,int,long,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#9  0xfe56847c in typeArrayOopDesc*typeArrayKlass::allocate(int,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#10 0xfe62c890 in void Runtime1::new_type_array(JavaThread*,BasicType,long)
    ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#11 0xfb000138 in ?? ()
#12 0xfb011c38 in ?? ()
#13 0xfb00fe1c in ?? ()
#14 0x7a190 in _end ()
#15 0x7a14c in _end ()
#16 0x7a14c in _end ()
#17 0xfe7cb45c in StubRoutines::_code1 ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#18 0xfe581a5c in void 
JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#19 0xfe5816ec in void 
JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#20 0xfe621efc in 
oopDesc*Reflection::invoke(instanceKlassHandle,methodHandle,Handle,long,objArray
Handle,BasicType,objArrayHandle,long,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#21 0xfe623408 in 
oopDesc*Reflection::invoke_constructor(oopDesc*,objArrayHandle,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#22 0xfe622f18 in JVM_NewInstanceFromConstructor ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#23 0xfe44d27c in Java_java_lang_reflect_Constructor_newInstance ()
   from /workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/libjava.so
#24 0x7cfe8 in _end ()
#25 0x7a190 in _end ()
#26 0x7a14c in _end ()
#27 0x7a14c in _end ()
#28 0xfe7cb45c in StubRoutines::_code1 ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#29 0xfe581a5c in void 
JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#30 0xfe5906f4 in void 
JavaCalls::call_virtual(JavaValue*,KlassHandle,symbolHandle,symbolHandle,JavaCal
lArguments*,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#31 0xfe590584 in void 
JavaCalls::call_virtual(JavaValue*,Handle,KlassHandle,symbolHandle,symbolHandle,
Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#32 0xfe59050c in void thread_entry(JavaThread*,Thread*) ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#33 0xfe590318 in void JavaThread::run() ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so
#34 0xfe58013c in _start ()
   from 
/workspace/jdk/solaris/1.3.1/j2sdk1_3_1_03/jre/lib/sparc/client/libjvm.so

Our product, 1.4.1_01, Linux

#0  0x40056deb in __sigsuspend (set=0xbf7ff720)
    at ../sysdeps/unix/sysv/linux/sigsuspend.c:48
#1  0x40028c82 in __pthread_wait_for_restart_signal (self=0xbf7ffe40)
    at pthread.c:785
#2  0x4002a2c2 in __pthread_lock (lock=0x8121f90, self=0xbf7ffe40)
    at spinlock.c:68
#3  0x400277ba in __pthread_mutex_lock (mutex=0x8121f80) at mutex.c:84
#4  0x403cb3be in os::Linux::safe_mutex_lock ()
   from /workspace/johnmac/java/sun1.4.1-b21-fcs/jre/lib/i386/client/libjvm.so
#5  0x403c3b53 in ObjectMonitor::raw_enter ()
   from /workspace/johnmac/java/sun1.4.1-b21-fcs/jre/lib/i386/client/libjvm.so
#6  0x403a7bab in jvmpi::raw_monitor_enter ()
   from /workspace/johnmac/java/sun1.4.1-b21-fcs/jre/lib/i386/client/libjvm.so
#7  0x4c27b0eb in jvmpiAgentRawMonitorEnter ()
   from /workroom/johnmac/JProbe/linux_ia32/Arkham-b2-rc1/bin/libjprobeagent.so
#8  0x4c2752de in AG_Lock ()
   from /workroom/johnmac/JProbe/linux_ia32/Arkham-b2-rc1/bin/libjprobeagent.so
#9  0x4c2781b1 in setupJBCIClass ()
   from /workroom/johnmac/JProbe/linux_ia32/Arkham-b2-rc1/bin/libjprobeagent.so
#10 0x403a08d2 in jvmpi::post_gc_start_event ()
   from /workspace/johnmac/java/sun1.4.1-b21-fcs/jre/lib/i386/client/libjvm.so
#11 0x403078f5 in GenCollectedHeap::gc_prologue ()
   from /workspace/johnmac/java/sun1.4.1-b21-fcs/jre/lib/i386/client/libjvm.so
#12 0x40306e9b in GenCollectedHeap::do_collection ()
   from /workspace/johnmac/java/sun1.4.1-b21-fcs/jre/lib/i386/client/libjvm.so
#13 0x402e3efa in TwoGenerationCollectorPolicy::satisfy_fail
----------------------

raghunath.verabelli  12/19/02

I could reproduce this problem using the attached sample program on Solaris with 1.3.1_06/1.3.1_07 release.  Please note that it is not consistent. The hang is timing depdendent with other factors like memory size, speed, etc affecting it. Plus the  GC has to happen at just the wrong time.  It usually hangs before or just after drawing the splashscreen (while loading demos), but not always.

gcc -I$JAVA_HOME/include -I$JAVA_HOME/include/solaris -fpic -shared -o 
libsimple.so simple.c

To run, make sure libsimple.so is in your LD_LIBRARY_PATH and use:

java -Xrunsimple:50000 -jar $JAVA_HOME/demo/jfc/SwingSet2/SwingSet2.jar

The "50000" is the "workload" mentioned in the problem report. The higher 
the number, the longer the client spends handling each event.

I could not reproduce it on 1.4.1 using the sample test case. Customer says that he can consistently reproduce with 1.4.x with the current development release of their product (JProbe) both on Solaris and LinuX.
Comments
EVALUATION ###@###.### 2003-01-07 I reproduced the "hang" using JDK1.3.1-FCS (B24) on my dual-450MHZ Ultra 80 running Solaris 8. Since I didn't have a built workspace that old, I had to do old fashioned spelunking through a core file. I have attached my analysis as threads.log.17402. For JDK1.3.1, this isn't really a hang. The VMThread is stuck in a very tight loop due to some incorrect code in ObjectMonitor::raw_enter(). Mandy fixed this bug for Merlin-Beta3 using the following bug ID: 4489387 2/4 -Xrunhprof crashed jvm or got program run to hang I believe the above resolves the JDK1.3.1 bug sighting. Sitraka reports that this is a problem up through JDK1.4.1. Raghunath indicates that he could not reproduce it with JDK1.4.1. More analysis is needed. ###@###.### 2003-01-15 Raghu has confirmed with Sitraka that this bug cannot be reproduced with releases newer than JDK1.3.1 (neither JDK1.4 or JDK1.4.1). I'm closing this bug as a duplicate of 4489387.
11-06-2004
PUBLIC COMMENTS .
10-06-2004