Re: [rules-users] CompositiveClassLoader$CachingLoader$load method intermittently hangs

I cannot easily reproduce an issue that I'm seeing. This is an intermittent issue that happens probably 3% of the time or less. This is observed behavior in * Drools v5.6.0.Final, using * Janino compiler v2.5.16 && transitively Drools brings * mvel2 v2.1.8.Final We have an environment that loads around 10 different KnowledgeBases into a list. Then one-by-one a single StatefulKnowledgeSession is created for a single KnowledgeBase, facts are inserted, and then fireAllRules is called. Every so often, we noticed that we were getting what seemed to be ininite looping behavior for during either insertion time or fireAllRules time. When we subsequently re-run the *same* session with the *same* KnowledgeBase and the *same* facts inserted, it was successful and finished in milliseconds (the average for our successful runs). We have repeatedly seen this behavior of 1 failure, followed by a re-run that is successful. We were able to attach a profiler to several of these hung sessions to determine what was happening. It turns out that in both the scenario where we saw a hang up on fact insertion and on fireAllRules call, the thread dump was the same. The stack looks like: ``` "main" - Thread t@1 java.lang.Thread.State: RUNNABLE at java.util.HashMap.getEntry(HashMap.java:347) at java.util.HashMap.containsKey(HashMap.java:335) at org.drools.util.CompositeClassLoader$CachingLoader.load(CompositeClassLoader.java:244) at org.drools.util.CompositeClassLoader$CachingLoader.load(CompositeClassLoader.java:237) at org.drools.util.CompositeClassLoader.loadClass(CompositeClassLoader.java:88) at java.lang.ClassLoader.loadClass(ClassLoader.java:247) at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:247) at org.mvel2.ParserConfiguration.checkForDynamicImport(ParserConfiguration.java:163) at org.mvel2.ParserConfiguration.hasImport(ParserConfiguration.java:191) at org.mvel2.ParserContext.hasImport(ParserContext.java:360) at org.mvel2.ParserContext.isVariableVisible(ParserContext.java:715) at org.mvel2.compiler.ExpressionCompiler.verify(ExpressionCompiler.java:394) at org.mvel2.compiler.ExpressionCompiler._compile(ExpressionCompiler.java:250) at org.mvel2.compiler.ExpressionCompiler.compile(ExpressionCompiler.java:62) at org.mvel2.MVEL.compileExpression(MVEL.java:810) at org.drools.base.mvel.MVELCompilationUnit.compile(MVELCompilationUnit.java:417) at org.drools.base.mvel.MVELCompilationUnit.getCompiledExpression(MVELCompilationUnit.java:238) at org.drools.rule.constraint.MvelConstraint.createMvelConditionEvaluator(MvelConstraint.java:224) at org.drools.rule.constraint.MvelConstraint.evaluate(MvelConstraint.java:208) at org.drools.rule.constraint.MvelConstraint.isAllowed(MvelConstraint.java:175) at org.drools.reteoo.AlphaNode.assertObject(AlphaNode.java:133) at org.drools.reteoo.CompositeObjectSinkAdapter.doPropagateAssertObject(CompositeObjectSinkAdapter.java:497) at org.drools.reteoo.CompositeObjectSinkAdapter.propagateAssertObject(CompositeObjectSinkAdapter.java:382) at org.drools.reteoo.ObjectTypeNode.assertObject(ObjectTypeNode.java:302) at org.drools.reteoo.EntryPointNode.assertObject(EntryPointNode.java:254) at org.drools.common.NamedEntryPoint.insert(NamedEntryPoint.java:366) at org.drools.common.SimpleBeliefSystem.insert(SimpleBeliefSystem.java:38) at org.drools.common.TruthMaintenanceSystem.addLogicalDependency(TruthMaintenanceSystem.java:207) at org.drools.common.TruthMaintenanceSystem.addLogicalDependency(TruthMaintenanceSystem.java:179) at org.drools.common.NamedEntryPoint.insert(NamedEntryPoint.java:247) at org.drools.common.AbstractWorkingMemory.insert(AbstractWorkingMemory.java:950) at org.drools.base.DefaultKnowledgeHelper.insertLogical(DefaultKnowledgeHelper.java:263) at org.drools.base.DefaultKnowledgeHelper.insertLogical(DefaultKnowledgeHelper.java:228) at org.drools.base.DefaultKnowledgeHelper.insertLogical(DefaultKnowledgeHelper.java:223) <application-stack> at some.drools.generated.rule.package.Rule_<drools-generated2> at some.drools.generated.rule.package.Rule_<drools-generated1> at org.drools.common.DefaultAgenda.fireActivation(DefaultAgenda.java:1282) - locked <656dd9a0> (a org.drools.common.DefaultAgenda) at org.drools.common.DefaultAgenda.fireNextItem(DefaultAgenda.java:1216) - locked <656dd9a0> (a org.drools.common.DefaultAgenda) at org.drools.common.DefaultAgenda.fireAllRules(DefaultAgenda.java:1451) at org.drools.common.AbstractWorkingMemory.fireAllRules(AbstractWorkingMemory.java:756) at org.drools.common.AbstractWorkingMemory.fireAllRules(AbstractWorkingMemory.java:718) at org.drools.impl.StatefulKnowledgeSessionImpl.fireAllRules(StatefulKnowledgeSessionImpl.java:230) <facts-inserted-previously> ``` We were able to get the same hung thread dump prior to fireAllRules. I think the related entry point is during one of the #assertObject calls midway through the stack. The CompositiveClassLoader$CachingLoader definitely seems to be the issue. When we found this behavior consistently occurring (although rare), I found the option of turning off the use of the caching loader by setting the "drools.classLoaderCacheEnabled"="false" option referenced in the ClassLoaderCacheOption class. With this setting, we have done extensive retries to find this behavior and it has vanished. This CompositiveClassLoader$CachingLoader uses an internal j.u.HashMap that is not safe for concurrent access. I have listed below several related posts on the topic. I'm fairly sure if this used a j.u.c.ConcurrentHashMap, this hanging thread scenario would not happen. However, most of the posts I've seen on this subject are from use-cases where the application is explicitly doing some sort of multithreaded access to the Drools KnowledgeBase and/or StatefulKnowledgeSession. In my case, I do not know of *any* multithreaded actions taking place within my application around the Drools KnowledgeBase or StatefulKnowledgeSession. I am not seeing ConcurrentModificationException though. Instead I'm seeing a, seemingly infinite, loop in the j.u.HashMap#getEntry. Hanging in a "get" method of the j.u.HashMap would suggest to me that there is a race condition where sometimes the j.u.HashMap#put on the `classLoaderResultMap` field in the CompositiveClassLoader$CachingLoader#load method is being executed at the same time as another thread is doing the j.u.HashMap#getEntry. If the j.u.HashMap were to resize at this point, it could cause an infinite looping behavior. Does Drools internally use multithreading? Is there somewhere in the MVEL lib or the Janino compiler where it may be concurrently accessing the CompositiveClassLoader$CachingLoader$load method? I have been digging around a lot and I cannot find what could be the root cause of this behavior. I think this relates directly to these: * http://lists.jboss.org/pipermail/rules-users/2013-July/032446.html * http://lists.jboss.org/pipermail/rules-users/2013-July/032446.html However, I do not see a real resolution to the problem. I also see several related issues: * http://lists.jboss.org/pipermail/rules-users/2013-July/032446.html * https://issues.jboss.org/browse/JBRULES-3552 -- View this message in context: http://drools.46999.n3.nabble.com/CompositiveClassLoader-CachingLoader-lo... Sent from the Drools: User forum mailing list archive at Nabble.com. _______________________________________________ rules-users mailing list rules-users(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/rules-users