[hibernate-dev] large hql queries holding classloader lock for too long in weblogic

Tue Dec 30 02:48:49 EST 2008

Hi,

We had an issue in our project where large hql expressions holding on lock to ChangeAwareClassloader in weblogic. 
We had an hql query which was like 

select * from ClassA a where a.identifier = 'id1' or a.identifier='id2' or .....          a.identifier='id1000'.

This was certainly bad to have this big or expression, but an issue this caused in weblogic is something interesting.
Hibernate query engine processes each identifier in a query to see if its a Java Class. So for each one of ClassA, a.identifier etc it calls Class.forName, if NoClassDefFound exception is thrown, ReflectHelper.getConstantValue returns null.

Now the problem is, if the expression is huge, recursive calls to /NodeTraverser.visitDepthFirst create huge stack trace. While building ClassNotFoundException, system class loader gets stuck to build all this stack trace. Because weblogic/utils/classloaders/ChangeAwareClassLoader.loadClass method is synchronized, any other thread trying to load any other class is blocked. If the stack trace is huge and taking consideratble amount of time to create Exception object, the lock is held for that much time, blocking every other thread trying to any the class. It brought down our servers in test environment.

Is this a known issue in weblogic and hibernate? I know that building such a large expression is bad(and we have already changed the code which was doing that), but the way its blocking the classloader in weblogic is an issue I think. 

Following is the thread dump.

"[STUCK] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'" id=614 idx=0x3f8 tid=15385 prio=1 alive, in native, daemon
    at pthread_cond_wait@@GLIBC_2.3.2+170(:0)@0x318c008a7a
    at vmtWaitUntilNotSoftSuspended+66(:0)@0x2a955e35c2
    at find_codeinfo+138(:0)@0x2a955b032e
    at cmFindStackCodeInfoWithHint+44(:0)@0x2a955b040e
    at frameIterFindCodeInfo+19(:0)@0x2a9571b11f
    at frameIterGetCurrentAndStep+130(:0)@0x2a9571b489
    at jniFillInStackTrace+368(:0)@0x2a95630d25
    at JVM_FillInStackTrace+9(:0)@0x2a95647661
    at RJNI_jrockit_vm_Reflect_fillInStackTrace0+9(:0)@0x2a956f5983
    at jrockit/vm/Reflect.fillInStackTrace0(Ljava/lang/Throwable;)V(Native Method)
    at java/lang/Throwable.fillInStackTrace()Ljava/lang/Throwable;(Native Method)[optimized]
    at java/lang/Throwable.<init>(Throwable.java:218)[optimized]
    at java/lang/Exception.<init>(Exception.java:59)[inlined]
    at java/lang/ClassNotFoundException.<init>(ClassNotFoundException.java:65)[optimized]
    at java/net/URLClassLoader$1.run(URLClassLoader.java:200)[inlined]
    at jrockit/vm/AccessController.doPrivileged(AccessController.java:255)[inlined]
    at java/net/URLClassLoader.findClass(URLClassLoader.java:188)[optimized]
    at java/lang/ClassLoader.loadClass(ClassLoader.java:306)[optimized]
    ^-- Holding lock: java/net/URLClassLoader at 0x4993580[thin lock]
    at java/lang/ClassLoader.loadClass(ClassLoader.java:299)[optimized]
    ^-- Holding lock: weblogic/utils/classloaders/GenericClassLoader at 0x469e900[thin lock]
    at java/lang/ClassLoader.loadClass(ClassLoader.java:251)[inlined]
    at weblogic/utils/classloaders/GenericClassLoader.loadClass(GenericClassLoader.java:158)[optimized]
    at weblogic/utils/classloaders/FilteringClassLoader.findClass(FilteringClassLoader.java:83)[inlined]
    at weblogic/utils/classloaders/FilteringClassLoader.loadClass(FilteringClassLoader.java:68)[optimized]
    at java/lang/ClassLoader.loadClass(ClassLoader.java:299)[optimized]
    ^-- Holding lock: weblogic/utils/classloaders/GenericClassLoader at 0x4969138[thin lock]
    at java/lang/ClassLoader.loadClass(ClassLoader.java:299)[inlined]
    at java/lang/ClassLoader.loadClass(ClassLoader.java:251)[inlined]
    at weblogic/utils/classloaders/GenericClassLoader.loadClass(GenericClassLoader.java:158)[inlined]
    at weblogic/utils/classloaders/ChangeAwareClassLoader.loadClass(ChangeAwareClassLoader.java:35)[optimized]
    ^-- Holding lock: weblogic/utils/classloaders/ChangeAwareClassLoader at 0x4915178[recursive]
    at jrockit/vm/Classes.loadClassInternal(Classes.java:75)[optimized]
    ^-- Holding lock: weblogic/utils/classloaders/ChangeAwareClassLoader at 0x4915178[fat lock]
    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
    at jrockit/vm/Classes.forName0(Ljava/lang/String;ZLjava/lang/ClassLoader;)Ljava/lang/Class;(Native Method)
    at jrockit/vm/Classes.forName(Classes.java:125)[inlined]
    at java/lang/Class.forName(Class.java:164)[inlined]
    at org/hibernate/util/ReflectHelper.classForName(ReflectHelper.java:100)[inlined]
    at org/hibernate/util/ReflectHelper.getConstantValue(ReflectHelper.java:122)[inlined]
    at org/hibernate/hql/ast/QueryTranslatorImpl$JavaConstantConverter.handleDotStructure(QueryTranslatorImpl.java:569)[inlined]
    at org/hibernate/hql/ast/QueryTranslatorImpl$JavaConstantConverter.visit(QueryTranslatorImpl.java:564)[optimized]
    at org/hibernate/hql/ast/util/NodeTraverser.visitDepthFirst(NodeTraverser.java:40)[optimized]

Following is part of thread dump which shows a thread waiting for Classloader lock.

"[ACTIVE] ExecuteThread: '51' for queue: 'weblogic.kernel.Default (self-tuning)'" id=7096 idx=0x6f8 tid=7459 prio=5 alive, in native, blocked, daemon
    -- Blocked trying to get lock: weblogic/utils/classloaders/ChangeAwareClassLoader at 0x4915178[fat lock]
    at pthread_cond_wait@@GLIBC_2.3.2+170(:0)@0x318c008a7a
    at tsiWaitForSignalForever+58(:0)@0x2a957035b5
    at tsiWaitForSignal+39(:0)@0x2a95703610
    at tsiWaitForLockSignal+39(:0)@0x2a957036f6
    at tsWaitForJavaLockSignal+31(:0)@0x2a957037a5
    at RJNI_jrockit_vm_Threads_waitForUnblockSignal+14(:0)@0x2a956f7620
    at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)
    at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1674)[optimized]
    at jrockit/vm/Locks.lockFat(Locks.java:1775)[optimized]
    at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1311)[optimized]
    at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1258)[optimized]
    at weblogic/utils/classloaders/ChangeAwareClassLoader.loadClass(ChangeAwareClassLoader.java:35)[optimized]
    at com/sun/org/apache/xerces/internal/impl/dv/ObjectFactory.findProviderClass(ObjectFactory.java:403)[inlined]
    at com/sun/org/apache/xerces/internal/impl/dv/ObjectFactory.newInstance(ObjectFactory.java:354)[inlined]
    at com/sun/org/apache/xerces/internal/impl/dv/DTDDVFactory.getInstance(DTDDVFactory.java:98)[optimized]
    ^-- Holding lock: java/lang/Class at 0x4fba6b8[recursive]
    at com/sun/org/apache/xerces/internal/impl/dv/DTDDVFactory.getInstance(DTDDVFactory.java:83)[inlined]
    at com/sun/org/apache/xerces/internal/parsers/XML11Configuration.<init>(XML11Configuration.java:565)[inlined]

Thanks,
Unmesh

Make sure your wardrobe reflects the latest trends and styles in the world of fashion. Try it!
_________________________________________________________________
Drag n’ drop—Get easy photo sharing with Windows Live™ Photos.

http://www.microsoft.com/windows/windowslive/photos.aspx
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/hibernate-dev/attachments/20081230/ff4992d6/attachment.html 