8:31 a.m.
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.