Hi, we are using Hibernate 3.5.5.85 as ORM tool on our Lucee application server. Occasionally, during the day, Hibernate brings our application practically to a halt. That always happens when the website is receiving a lot of traffic. Then requests keep getting blocked and, withing minutes, there is a pile-up of requests.
Invariably, the cause is something like “Waiting on lock <0x754d0045> (a org.hibernate.boot.registry.classloading.internal.AggregatedClassLoader)”. Here is an excerpt from a typical stacktrace:
dvnt.stdmtr.orm.leveltestuserstatusforoverview_cfc$cf.udfCall(/nl/devnt/stdmtr/orm/LevelTestUserStatusForOverview.cfc)
lucee.runtime.functions.orm.EntityLoad.call(EntityLoad.java)
org.lucee.extension.orm.hibernate.HibernateORMSession.loadAsArray(HibernateORMSession.java) (hide)
org.lucee.extension.orm.hibernate.HibernateORMSession.load(HibernateORMSession.java)
org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java)
org.hibernate.internal.SessionImpl.list(SessionImpl.java)
org.hibernate.metamodel.internal.MetamodelImpl.getImplementors(MetamodelImpl.java)
org.hibernate.boot.registry.classloading.internal.ClassLoaderServiceImpl.classForName(ClassLoaderServiceImpl.java)
java.lang.Class.forName(Unknown Source)
java.lang.Class.forName0(Native Method)
Waiting on lock <0x754d0045> (a org.hibernate.boot.registry.classloading.internal.AggregatedClassLoader)
Could you please give me any tips on how to solve this?
I don’t know what Hibernate version this application server is exactly using, but it seems to be a very old one. There is nothing we can do to help you here. You will have to ask the community of that app server.
Thanks, Beikov.
I read off the wrong version. Correct is: 5.4.29.15-BETA. Sorry about that.
In any case, the question is about “Waiting on lock <0x754d0045> (a org.hibernate.boot.registry.classloading.internal.AggregatedClassLoader)”.
That is a Hibernate classloader, which is why I came here. I am hoping someone will know something about it.
Thread dumps show dozens of request threads being blocked by the AggregatedClassLoader:
Blockquote
‘“XNIO-1 task-13” Id=10898 BLOCKED on org.hibernate.boot.registry.classloading.internal.AggregatedClassLoader@4ce3a236 owned by “XNIO-1 task-7” Id=10651
java.lang.Thread.State: BLOCKED’
The “waiting on lock” suggests that the classloader is single-threaded. Is there, for example, a solution that enables multithreaded classloading?.
Class loaders usually need some sort of locking because they may only load a class once. This shouldn’t be an issue though, because at some point you loaded all classes of you app and no new loading will happen. I don’t know what this application server is doing, but either way, I don’t see an issue with Hibernate here.
I am returning with new information. Lucee is an application server built in Java. It is based on the weakly-type language of the same name (Lucee).
Hence the following question: could the Hibernate setting hibernate.query.conventional_java_constants=false help solve the problem? I got this idea from Vlad Mihalcea.
Hence the following question: could the Hibernate setting hibernate.query.conventional_java_constants=false help solve the problem?
Did you try it out? You didn’t share stack traces for these lock scenarios, so it’s hard for me to understand what is calling into the class loader, but this flag could indeed help to avoid some class loader interaction. Either way, the class loader is only hit when queries are freshly compiled which shouldn’t happen anymore once your application is warmed up. After that, the compiled query is served from a cache. Are you using some sort of dynamic querying?
We’re currently testing the flag, and have yet to run it in production where the necessary load is.
No, we’re not using dynamic queries here.
In any case, your remark and question,
“the class loader is only hit when queries are freshly compiled which shouldn’t happen anymore once your application is warmed up. After that, the compiled query is served from a cache. Are you using some sort of dynamic querying?”
There is new information. Thread dumps show the following phenomenon time and time again: one entityload request to Hibernate may block every other subsequent entityLoad request. As a result users may be kept waiting for up to 2 minutes! Their request then gets timed out anyway.
You will find below an example of the stacktrace of a request that blocks every other entityLoad request.
In other words, such access to Hibernate is apparently single-threaded. That is a shortcoming in Hibernate, wouldn’t you say?
“XNIO-1 task-31” Id=28567 RUNNABLE
java.lang.Thread.State: RUNNABLE
at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1967)
at java.base@11.0.15/java.lang.ClassLoader.loadClass(Unknown Source)
at org.hibernate.boot.registry.classloading.internal.AggregatedClassLoader.findClass(AggregatedClassLoader.java:202)
at java.base@11.0.15/java.lang.ClassLoader.loadClass(Unknown Source)
- locked org.hibernate.boot.registry.classloading.internal.AggregatedClassLoader@18367cd
at java.base@11.0.15/java.lang.ClassLoader.loadClass(Unknown Source)
at java.base@11.0.15/java.lang.Class.forName0(Native Method)
at java.base@11.0.15/java.lang.Class.forName(Unknown Source)
at org.hibernate.boot.registry.classloading.internal.ClassLoaderServiceImpl.classForName(ClassLoaderServiceImpl.java:130)
at org.hibernate.metamodel.internal.MetamodelImpl.getImplementors(MetamodelImpl.java:661)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1851)
at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:370)
at org.lucee.extension.orm.hibernate.HibernateORMSession.load(HibernateORMSession.java:851)
at org.lucee.extension.orm.hibernate.HibernateORMSession.loadAsArray(HibernateORMSession.java:676)
at org.lucee.extension.orm.hibernate.HibernateORMSession.loadAsArray(HibernateORMSession.java:653)
at lucee.runtime.functions.orm.EntityLoad.call(EntityLoad.java:67)
at lucee.runtime.functions.orm.EntityLoad.call(EntityLoad.java:39)
at dvnt.stdmtr.service.userdata_cfc$cf.udfCall2(/nl/dvnt/stdmtr/service/UserData.cfc:949)
at dvnt.stdmtr.service.userdata_cfc$cf.udfCall(/nl/dvnt/stdmtr/service/UserData.cfc)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585)
at lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1951)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1784)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall4(/nl/dvnt/stdmtr/service/Exercises.cfc:3679)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall(/nl/dvnt/stdmtr/service/Exercises.cfc)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1784)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall5(/nl/dvnt/stdmtr/service/Exercises.cfc:3780)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall(/nl/dvnt/stdmtr/service/Exercises.cfc)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1784)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall2(/nl/dvnt/stdmtr/service/Exercises.cfc:597)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall(/nl/dvnt/stdmtr/service/Exercises.cfc)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.type.scope.UndefinedImpl.callWithNamedValues(UndefinedImpl.java:804)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1784)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall1(/nl/dvnt/stdmtr/service/Exercises.cfc:505)
at dvnt.stdmtr.service.exercises_cfc$cf.udfCall(/nl/dvnt/stdmtr/service/Exercises.cfc)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585)
at lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1951)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:866)
at lucee.runtime.PageContextImpl.getFunctionWithNamedValues(PageContextImpl.java:1784)
at nl.dvnt.stdmtr.facades.exercisesfacade_cfc$cf.udfCall(/nl/dvnt/stdmtr/facades/ExercisesFacade.cfc:48)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:213)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585)
at lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1951)
at lucee.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:900)
at lucee.runtime.functions.dynamicEvaluation.Invoke.call(Invoke.java:49)
at application_cfc$cf.udfCall(/Application.cfc:87)
at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:697)
at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585)
at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1932)
at lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java:444)
at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:200)
at lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:44)
at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2482)
at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2468)
at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2439)
at lucee.runtime.engine.Request.exe(Request.java:45)
at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1198)
at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1144)
at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
at app//javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at app//io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at app//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at app//org.cfmlprojects.regexpathinfofilter.RegexPathInfoFilter.doFilter(RegexPathInfoFilter.java:47)
at app//io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at app//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at jdk.internal.reflect.GeneratedMethodAccessor53.invoke(Unknown Source)
at java.base@11.0.15/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base@11.0.15/java.lang.reflect.Method.invoke(Unknown Source)
at com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134)
at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:772)
at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:344)
at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:207)
at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:809)
at com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36)
at jdk.internal.reflect.GeneratedMethodAccessor51.invoke(Unknown Source)
at java.base@11.0.15/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base@11.0.15/java.lang.reflect.Method.invoke(Unknown Source)
at com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71)
at jdk.internal.reflect.GeneratedMethodAccessor48.invoke(Unknown Source)
at java.base@11.0.15/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base@11.0.15/java.lang.reflect.Method.invoke(Unknown Source)
at app//com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:54)
at app//com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:42)
at app//io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java)
at app//io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at app//io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at app//io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at app//io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at app//io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at app//io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
at app//io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at app//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at app//io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at app//io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at app//io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at app//io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at app//io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at app//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at app//io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
at app//io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at app//io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:275)
at app//io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:79)
at app//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:134)
at app//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:131)
at app//io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at app//io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at app//io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
at app//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:255)
at app//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:79)
at app//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:100)
at app//io.undertow.server.Connectors.executeRootHandler(Connectors.java:387)
at app//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:852)
at app//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at app//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2019)
at app//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1558)
at app//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1433)
at app//org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1280)
at java.base@11.0.15/java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- java.util.concurrent.locks.ReentrantReadWriteLock$FairSync <0x541bbaa>
Look, I understand that this isn’t ideal, and we fixed that in Hibernate 6, but you usually don’t run into this unless you are creating a ton of “unique” queries that trash the query plan cache. So IMO you should size the query plan cache accordingly.
Thanks for the information, @beikov .
I am thrilled to hear that this issue has been fixed in Hibernate 6.
We are now going to check whether we can upgrade our application to Hibernate 6.