MC deadlock

[alesj]

We should do something about this deadlock.
Dunno really how to reproduce it :-), but it happens quite often.

java.exe session:0 threads:10 parent:3780 4052
Full thread dump Java HotSpot(TM) Client VM (1.5.0_11-b03 mixed mode, sharing):

"StackTrace Remote Thread" prio=6 tid=0x00a67468 nid=0x6c8 runnable [0x00000000..0x0346fb70]

"B" prio=6 tid=0x02eeba68 nid=0xed8 waiting for monitor entry [0x033be000..0x033bfb68]
 at org.jboss.classloader.spi.base.BaseClassLoader.unlock(BaseClassLoader.java:713)
 - waiting to lock <0x22a5b438> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at org.jboss.classloader.spi.base.BaseClassLoader.unlock(BaseClassLoader.java:595)
 at org.jboss.classloader.spi.base.ClassLoaderManager.nextTask(ClassLoaderManager.java:286)
 at org.jboss.classloader.spi.base.ClassLoaderManager.process(ClassLoaderManager.java:145)
 at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:193)
 at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:752)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClassFromDomain(BaseClassLoader.java:483)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:158)
 - locked <0x22a60ac0> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
 at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
 - locked <0x22a60ac0> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at java.lang.ClassLoader.defineClass1(Native Method)
 at java.lang.ClassLoader.defineClass(ClassLoader.java:620)
 at org.jboss.classloader.spi.base.BaseClassLoader.access$200(BaseClassLoader.java:58)
 at org.jboss.classloader.spi.base.BaseClassLoader$1.run(BaseClassLoader.java:279)
 at org.jboss.classloader.spi.base.BaseClassLoader$1.run(BaseClassLoader.java:246)
 at java.security.AccessController.doPrivileged(Native Method)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClassLocally(BaseClassLoader.java:244)
 - locked <0x22a60ac0> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClassLocally(BaseClassLoader.java:217)
 at org.jboss.classloader.spi.base.BaseDelegateLoader.loadClass(BaseDelegateLoader.java:75)
 at org.jboss.classloader.spi.filter.FilteredDelegateLoader.loadClass(FilteredDelegateLoader.java:90)
 at org.jboss.classloader.spi.base.ClassLoadingTask$ThreadTask.run(ClassLoadingTask.java:449)
 at org.jboss.classloader.spi.base.ClassLoaderManager.nextTask(ClassLoaderManager.java:251)
 at org.jboss.classloader.spi.base.ClassLoaderManager.process(ClassLoaderManager.java:145)
 at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:193)
 at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:752)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClassFromDomain(BaseClassLoader.java:483)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:158)
 - locked <0x22a60ac0> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
 at org.jboss.test.classloader.AbstractClassLoaderTest.assertLoadClass(AbstractClassLoaderTest.java:176)
 at org.jboss.test.classloader.AbstractClassLoaderTest.assertLoadClass(AbstractClassLoaderTest.java:158)
 at org.jboss.test.classloader.AbstractClassLoaderTest.assertLoadClass(AbstractClassLoaderTest.java:143)
 at org.jboss.test.classloader.delegate.test.DelegateUnitTestCase.access$100(DelegateUnitTestCase.java:54)
 at org.jboss.test.classloader.delegate.test.DelegateUnitTestCase$2.run(DelegateUnitTestCase.java:299)

"A" prio=6 tid=0x02ef2d28 nid=0x980 in Object.wait() [0x0337e000..0x0337fbe8]
 at java.lang.Object.wait(Native Method)
 - waiting on <0x22a7aac8> (a java.util.Collections$SynchronizedList)
 at java.lang.Object.wait(Object.java:474)
 at org.jboss.classloader.spi.base.ClassLoaderManager.nextTask(ClassLoaderManager.java:204)
 - locked <0x22a7aac8> (a java.util.Collections$SynchronizedList)
 at org.jboss.classloader.spi.base.ClassLoaderManager.process(ClassLoaderManager.java:145)
 at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:193)
 at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:752)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClassFromDomain(BaseClassLoader.java:483)
 at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:158)
 - locked <0x22a5b438> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
 at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
 - locked <0x22a5b438> (a org.jboss.classloader.spi.base.BaseClassLoader)
 at java.lang.Class.getDeclaredMethods0(Native Method)
 at java.lang.Class.privateGetDeclaredMethods(Class.java:2395)
 at java.lang.Class.getMethod0(Class.java:2642)
 at java.lang.Class.getMethod(Class.java:1579)
 at org.jboss.test.classloader.delegate.test.DelegateUnitTestCase$1.run(DelegateUnitTestCase.java:277)

"Low Memory Detector" daemon prio=6 tid=0x00a730f8 nid=0x290 runnable [0x00000000..0x00000000]

"CompilerThread0" daemon prio=10 tid=0x00a71d68 nid=0xb58 waiting on condition [0x00000000..0x02c1fa48]

"Signal Dispatcher" daemon prio=10 tid=0x00a71070 nid=0x964 runnable [0x00000000..0x00000000]

"Finalizer" daemon prio=8 tid=0x00a48b78 nid=0x304 in Object.wait() [0x02b9f000..0x02b9fa68]
 at java.lang.Object.wait(Native Method)
 - waiting on <0x22f456d8> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
 - locked <0x22f456d8> (a java.lang.ref.ReferenceQueue$Lock)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
 at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00a6ab30 nid=0xb50 in Object.wait() [0x02b5f000..0x02b5fae8]
 at java.lang.Object.wait(Native Method)
 - waiting on <0x22f45758> (a java.lang.ref.Reference$Lock)
 at java.lang.Object.wait(Object.java:474)
 at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
 - locked <0x22f45758> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x00037150 nid=0x858 in Object.wait() [0x0007e000..0x0007fc3c]
 at java.lang.Object.wait(Native Method)
 - waiting on <0x22a79850> (a org.jboss.test.classloader.delegate.test.DelegateUnitTestCase$1)
 at java.lang.Thread.join(Thread.java:1095)
 - locked <0x22a79850> (a org.jboss.test.classloader.delegate.test.DelegateUnitTestCase$1)
 at java.lang.Thread.join(Thread.java:1148)
 at org.jboss.test.thread.TestThread.doJoin(TestThread.java:66)
 at org.jboss.test.classloader.delegate.test.DelegateUnitTestCase.testAbstractFactoryConcurrent(DelegateUnitTestCase.java:306)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at junit.framework.TestCase.runTest(TestCase.java:154)
 at junit.framework.TestCase.runBare(TestCase.java:127)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:118)
 at junit.framework.TestSuite.runTest(TestSuite.java:208)
 at junit.framework.TestSuite.run(TestSuite.java:203)
 at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
 at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.extensions.TestSetup.run(TestSetup.java:23)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:138)
 at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:125)
 at org.apache.maven.surefire.Surefire.run(Surefire.java:132)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:314)
 at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:917)

"VM Thread" prio=10 tid=0x00a68628 nid=0x384 runnable

"VM Periodic Task Thread" prio=10 tid=0x00a70c80 nid=0xa0 waiting on condition

[adrian.brock]

This issue was raised before.
It needs somebody who can reproduce it to get a TRACE log.
It shouldn't have to wait to get a lock on something it is unlocking. ;-)

Or more accurately it shouldn't have to wait forever since the other thread
should give up the lock when it spots it doesn't own it.

LIke I said before, my guess is it is in the "ThreadTask.releaseInNextTask" logic,
since I just copied that from the old classloader code without really understanding
how it works.

i.e. It is probably releasing the lock twice or something similar to that?

[adrian.brock]

I think I've found a problem related to this?
Although I haven't managed to reproduce the problem so I can't be sure
it is actually this issue.

The issue I see is that the unlock() was trying to do a ClassLoader.notifyAll()
(which requires the classloader lock) even when it hadn't released the ReentrantLock.

I've moved the notifyAll() - i.e. tell other threads the lock is now available
inside the check for ReentrantLock.getHoldCount() == 0

So now the attempt to synchronize on the classloader in unlock() will only happen
when it doesn't hold the reentrant lock.

I'm guessing it is the holding of the ReentrantLock versus synchronization
on the classloader that is causing the deadlock?

[adrian.brock]

I think I've found a problem related to this?
Although I haven't managed to reproduce the problem so I can't be sure
it is actually this issue.

I found the problem but not the solution. :-)
I think I managed to find a way to reproduce the problem by putting a Thread.sleep() i
n a key place and was able to see what was really causing the problem.

The issue is a "sneaky thread".

Thread 1: managing classloading for somebody else does some classloading
Thread 2: starts to do classloading on the same classloader
Thread 1: finishes and tries to unlock (it doesn't hold the classloader monitor - but it does hold the lock on the classloader loading tasks)
Thread 1: It releases the ReentrantLock
Thread 2: checks the ReentrantLock and decides to continue
Thread 2: can't get the classloading tasks (held by thread 1)
Thread 1: Tries to do a notifyAll() which requires the classloader monitor (held by thread 2)

So basically, we need to stop the sneaky thread 2 from continuing into the
classloading until we've done the notifyAll(). The notifyAll is only there
to improve performance so waiting threads don't block for 10 seconds
between checks on the ReentrantLock - i.e. we wake up the waiting
threads immediately after we release lock.

So, I've fixed the problem by putting the release of the ReentrantLock
inside holding the classloader monitor.
This will force the "sneaky" thread to go into the acquireLock wait
(where it will release the classloader monitor)
until the releasing has done its notifyAll() and no longer needs the classloader monitor.

[sandy.saahil]

Hi Adrian,

I am trying to find a fix for the same defect but unable to find the patch suggested by you. I am using JBoss 5.1.0.GA and facing the same issue of BaseClassLoader. Could you please point me in right direction?

regards,

Sandeep