2:31 p.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.
8:32 p.m.
New subject: CompositiveClassLoader$CachingLoader#load method intermittently hangs
Does anyone have any thoughts on this issue?
I still haven't been able to get to the root of the concurrency issue.
Digging through some of the Drools implementations, but no luck. :)
--
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.
4:55 a.m.
We are also experiencing the same problems using 5.x and it is causing us
big problems.
I haven't had time to try it yet but do any developers know whether we
would be safe to change the HashMap the CompositiveClassLoader is using to
a ConcurrentHashMap?
thanks
Steve
-------------------------------------------------------------------
Steven Williams
On Wed, Mar 19, 2014 at 12:31 AM, mikerod <mjr4184(a)gmail.com> wrote:
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
4:21 a.m.
I was finally able to take some time and find out where multiple threads
could be showing up
in the environment where my application was not doing any multithreaded work
with the Drools
knowledge base or session.
One example I have can be seen by looking at the
`org.drools.rule.constraint.MvelConstraint` class.
This method `#jitEvaluator(Object, InternalWorkingMemory, LeftTuple)` has a
line:
`ExecutorHolder.executor.execute(new ConditionJitter(this, object,
workingMemory, leftTuple));`
This is roughly around this line in 5.5.0.Final, for example.
https://github.com/droolsjbpm/drools/blob/5.5.0.Final/drools-core/src/mai...
My understanding of this method functionality is that a
`java.util.concurrent.Executor` is used to execute a Runnable.
The Executor returned is configurable via the
`org.drools.util.ServiceRegistry`. There is a related Drools
RuleBaseConfiguration option
called "executorService" that allows the user to configure the details of
how this Runnable is executed.
e.g. a custom application thread pool, a simple thread, no new thread at all
- synchronously.
Drools has a default for this executorService, which is
@
https://github.com/droolsjbpm/drools/blob/5.5.0.Final/drools-core/src/mai...
This implementation runs the Runnable in a new thread, this is where a
concurrency issue is able to come into the picture.
So in the MvelConstraint#jitEvaluator example I mention above, uses this
executor to perform some of the Jit compilation
on MVEL constraints in a new thread, to not "burden" the current thread with
this work.
The issue is that the Runnable work that is done on another thread by the
ConditionJitter, ultimately works with the
same `org.drools.util.CompositeClassLoader$CachingLoader` as the main/other
thread(s).
This CachingLoader is not safe for concurrent access to its
`classLoaderResultMap` field, since it is implemented as a
`j.u.HashMap`.
e.g. if one thread is reading from the cache at the same time as another
thread is doing a #put into the cache and
the cache resizes, this can lead to the reading going into a
non-terminating loop.
So, in summary, my application has no multithreading being done with regard
to the main thread working with the Drools
knowledge base and session. However, when some of the knowledge base is
being compiled/Jitted there are multiple threads
doing work, and on some occasions they we run into a concurrent access to
the CachingLoader cache problem resulting in
a non-terminating loop.
I believe this would fall into the category of a "race condition" in that
I've only observed the issue happening about 1-5% of the time
of the same knowledge base being built. I'll am being general on saying
"built" here, as I am not sure this is the correct
terminology to describe the time that MvelConstraint's are being/attempted
to be Jitted and this is happening.
I'll note that "turning off" jitting didn't fix the problem.
There is a chance that I did not effectively stop all jitting though.
I attempted to turn it off, by what is explained @
http://mvel.codehaus.org/Disabling+the+JIT+Compiler.
I cannot remember if I've tried to turn it off via
"drools.permgenThreshold"
in my experiments with this issue though.
(That one is described @
http://drools.46999.n3.nabble.com/rules-users-Out-of-Mem-and-thousand-thr...)
I noticed that with jitting "turned off" this method was still being called
when a MvelConstraint was found to be "dynamic"
via the `isDynamic` boolean flag of the MvelConstraint class. I'm not clear
on what causes a constraint to be considered dynamic or not.
The workaround that *did* work for me was to just disable the CacheLoader
via the configuration property "drools.classLoaderCacheEnabled".
I do not believe I've seen significant performance degradation with this in
my use-case.
Another alternative to fixing this issue (I'd imagine) could be by
configuring the executorService to not use multiple-threads.
However, I'd assume that this is higher impact and more complicated than
disabling the CacheLoader.
I believe that using the `java.util.concurrent.ConcurrentHashMap` may solve
this particular issue.
However, I haven't done any further evaluation/analysis of the CacheLoader
class to ensure that
it is truly safe for use by multiple threads concurrently performaing reads
and writes.
I would say that the CacheLoader feature seems a bit broken right now in its
default use, due to the problem of Drools using multiple
threads internally when building the knowledge base.
I'm not sure how any of this relates to the Drools v6.x family.
--
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.
8:16 a.m.
On 19 May 2014, at 03:21, mikerod <mjr4184(a)gmail.com> wrote:
I'm not sure how any of this relates to the Drools v6.x family.
CompositeClassLoader is all gone, so I don’t think this issue will exist in 6.x. Would be
good if you could verify with beta3:
http://downloads.jboss.org/drools/release/6.1.0.Beta3/
We’ll look into 5.x too at some point in the next few weeks.
Mark
3:44 a.m.
Thanks for the response.
I thought I had read that the CompositeClassLoader was not being used in
v6.x.
I'd like to be able to experiment with the current version of Drools v6.x,
but I'm still trying to work
past the issue I have with the non-passive changes of protobuf v.2.5.0 that
Drools v6.x has been upgraded to.
I explained @
http://drools.46999.n3.nabble.com/Upgrade-to-protobuf-2-5-Prevents-Upgrad...
If I can come up with something and try out Drools v6.x, I'll update this
post with any issues seen regarding this issue.
--
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.
3621
days inactive
3684
days old
5 comments
3 participants
participants (3)
-
Mark Proctor -
mikerod -
Steven Williams