Java deadlock when insert in t1 and find in t2 when using IBM JVM 1.5.0

• Key: OPENJPA-98
• Type: Bug
• Status: Closed
• Resolution: Fixed
• Priority: Major
• Assignee: Kevin Sutter
• Reporter: Vlad Tatavu
• Fix Version/s: 0.9.7

Environment

OpenJPA:
0.9.6

Java:
java version "1.5.0"
Java(TM) 2 Runtime Environment, Standard Edition (build pwi32dev-20061002a (SR3)
)
IBM J9 VM (build 2.3, J2RE 1.5.0 IBM J9 2.3 Windows XP x86-32 j9vmwi3223-2006100
1 (JIT enabled)
J9VM - 20060915_08260_lHdSMR
JIT - 20060908_1811_r8
GC - 20060906_AA)
JCL - 20061002

DB:
Derby 10.2.1.6

Description

I have a simple test program that uses OpenJPA 0.9.6 to insert an object into a db in one transaction (t1) and retrieve it in another transaction (t2). The program hangs in 30-50% of the executions right before the call to entitymanager.find() (used to retrieve the object in t2). I'm using OpenJPA runtime enhancement.


By looking at the JVM dump, I can see the following deadlock:
1LKDEADLOCK Deadlock detected !!!
NULL ---------------------
NULL
2LKDEADLOCKTHR Thread "main" (0x0015EC00)
3LKDEADLOCKWTR is waiting for:
4LKDEADLOCKMON sys_mon_t:0x41E40548 infl_mon_t: 0x41E40588:
4LKDEADLOCKOBJ java/lang/Object@00D41010/00D4101C:
3LKDEADLOCKOWN which is owned by:
2LKDEADLOCKTHR Thread "Finalizer thread" (0x41B36200)
3LKDEADLOCKWTR which is waiting for:
4LKDEADLOCKMON sys_mon_t:0x0035CD38 infl_mon_t: 0x0035CD78:
4LKDEADLOCKOBJ sun/misc/Launcher$AppClassLoader@00D4E5B0/00D4E5BC:
3LKDEADLOCKOWN which is owned by:
2LKDEADLOCKTHR Thread "main" (0x0015EC00)

Comments

[Vlad Tatavu]

Attachments:
play.zip - the Eclipse project used to reproduce this problem
javacore.20070109.114312.3868.zip - java dump after the deadlock occured
console.txt - java console of the test program after the deadlock occured

[Vlad Tatavu]

I cannot reproduce this problem with Sun JDK 1.5.0_04.

[Kevin Sutter]

I'll take ownership of this report (for now, at least).

I can now reproduce the problem. Using the runtime enhancement and using previously created database tables, the problem reproduces itself quite easily.

From looking at the resulting stack traces for the deadlock, the dynamic enhancement processing is definitely the source of the problem. If the classes were statically enhanced before the execution, this particular problem would not surface. But, I don't see any processing within the dynamic enhancement class loader that should cause this type of deadlock.

Here are snippets from the javacore thread dump for the two deadlocked threads:

3XMTHREADINFO "main" (TID:0x41DF8C00, sys_thread_t:0x0038B9D8, state:B, native ID:0x00001744) prio=5
4XESTACKTRACE at com/ibm/oti/vm/BootstrapClassLoader.loadClass(BootstrapClassLoader.java:63(Compiled Code))
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:587(Compiled Code))
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:587(Compiled Code))
4XESTACKTRACE at sun/misc/Launcher$AppClassLoader.loadClass(Launcher.java:327(Compiled Code))
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:563(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/jdbc/kernel/JDBCStoreManager.getManagedType(JDBCStoreManager.java:562)
4XESTACKTRACE at org/apache/openjpa/kernel/DelegatingStoreManager.getManagedType(DelegatingStoreManager.java:140)
4XESTACKTRACE at org/apache/openjpa/kernel/BrokerImpl.newStateManagerImpl(BrokerImpl.java:1136)
4XESTACKTRACE at org/apache/openjpa/kernel/BrokerImpl.find(BrokerImpl.java:826)
4XESTACKTRACE at org/apache/openjpa/kernel/BrokerImpl.find(BrokerImpl.java:743)
4XESTACKTRACE at org/apache/openjpa/kernel/DelegatingBroker.find(DelegatingBroker.java:169)
4XESTACKTRACE at org/apache/openjpa/persistence/EntityManagerImpl.find(EntityManagerImpl.java:346)
4XESTACKTRACE at com/ibm/ws/persistence/tests/simple/TestInsertAndFind.test001(TestInsertAndFind.java:51)
:

3XMTHREADINFO "Finalizer thread" (TID:0x41ED6200, sys_thread_t:0x42299718, state:B, native ID:0x00001078) prio=5
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:563(Compiled Code))
4XESTACKTRACE at java/lang/Class.forNameImpl(Native Method)
4XESTACKTRACE at java/lang/Class.forName(Class.java:160(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/lib/util/TemporaryClassLoader.loadClass(TemporaryClassLoader.java:55(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/lib/util/TemporaryClassLoader.loadClass(TemporaryClassLoader.java:40(Compiled Code))
4XESTACKTRACE at java/lang/Class.forNameImpl(Native Method)
4XESTACKTRACE at java/lang/Class.forName(Class.java:160(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/enhance/PCClassFileTransformer.needsEnhance(PCClassFileTransformer.java:171(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/enhance/PCClassFileTransformer.transform(PCClassFileTransformer.java:117(Compiled Code))
:

As the "find" operation is performed in the main thread, additional classes need to be loaded to satisfy the request. As part of that class loading, the runtime enhancement is kicked off to determine whether the classes being loaded need to be enhanced or not.

As part of this checking, the following conditional is executed:

        if (name.startsWith("java.") || name.startsWith("javax.")
            || name.startsWith("sun."))
            return Class.forName(name, resolve, getClass().getClassLoader());

This call to Class.forName() eventually requests the same lock that is already in place on the Main thread. Everytime I hit this deadlock, it's the same stack traces. And, it's always at the same spot in the testcode. But, like Vlad and I have mentioned, it doesn't deadlock on every execution.

My gut reaction at this point is that we have a problem with the IBM JDK. But, I wanted to post my findings to this Issue to see if this description jogs any memory bits from the original OpenJPA authors.

Thanks,
Kevin

[Marc Prud'hommeaux]

I've never seen any problem like this. It is interesting that the finalizer thread is causing the problem. Do you have a deeper stack for the "Finalizer thread"?

Also, I wonder if running your test with the "-verbose:class" would help identify the class in question, and thereby shed some more light on the problem (or alternately putting a printf in TemporaryClassLoader.loadClass()).

[Kevin Sutter]

Yes, I already did that printf thing. It varies on exactly which class is "caught", but, of course, it always starts with java.*, or javax.*, or sun.* (since that's the conditional).

As far as the rest of the call stack... I attached the javacore to this Issue so you can look at the whole thing. But, the complete finalizer thread is as follows:

3XMTHREADINFO "Finalizer thread" (TID:0x41ED5F00, sys_thread_t:0x42299718, state:B, native ID:0x0000165C) prio=5
4XESTACKTRACE at java/lang/ClassLoader.loadClass(ClassLoader.java:563(Compiled Code))
4XESTACKTRACE at java/lang/Class.forNameImpl(Native Method)
4XESTACKTRACE at java/lang/Class.forName(Class.java:160(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/lib/util/TemporaryClassLoader.loadClass(TemporaryClassLoader.java:56(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/lib/util/TemporaryClassLoader.loadClass(TemporaryClassLoader.java:40(Compiled Code))
4XESTACKTRACE at java/lang/Class.forNameImpl(Native Method)
4XESTACKTRACE at java/lang/Class.forName(Class.java:160(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/enhance/PCClassFileTransformer.needsEnhance(PCClassFileTransformer.java:171(Compiled Code))
4XESTACKTRACE at org/apache/openjpa/enhance/PCClassFileTransformer.transform(PCClassFileTransformer.java:117(Compiled Code))
4XESTACKTRACE at sun/instrument/TransformerManager.transform(TransformerManager.java:141(Compiled Code))
4XESTACKTRACE at sun/instrument/InstrumentationImpl.transform(InstrumentationImpl.java:174(Compiled Code))
4XESTACKTRACE at com/ibm/oti/vm/VM.findClassOrNull(Native Method)
4XESTACKTRACE at com/ibm/oti/vm/BootstrapClassLoader.loadClass(BootstrapClassLoader.java:64(Compiled Code))
4XESTACKTRACE at java/lang/ref/ReferenceQueue.enqueue(ReferenceQueue.java:125)
4XESTACKTRACE at java/lang/ref/Reference.enqueueImpl(Reference.java:93)

[Marc Prud'hommeaux]

I wonder what would happen if we replaced:

   return Class.forName(name, resolve, getClass().getClassLoader());

with:

  return super.loadClass(name, resolve);

We're thinking along the same lines... The super.loadClass just ends up in the same ClassLoader.loadClass code with the same deadlock. Sorry that I didn't post this earlier.

[Kevin Sutter]

This looks to be a problem with the IBM JDK. I reported the problem to IBM and I have just tested a possible fix for the problem. So far, it looks good. Since the original problem was intermittent, I guess I can't be sure that it's resolved. But, after a couple days of testing, it looks to be standing up. I am checking on the availability of a patch or updated version.

[Kevin Sutter]

IBM has indicated that the fix will be available in SR5 for JDK 5. I'm still checking on an interim iFix.

[Kevin Sutter]

This problem will be resolved in SR5 of the IBM v5 JDK. The availability of an interim iFix is still being investigated. The Sun v5 JDK does not seem to exhibit this behavior.

[Kevin Sutter]

This problem was resolved with IBM JDK 5 SR 5.