CompositiveClassLoader$CachingLoader#load method intermittently hangs

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

CompositiveClassLoader$CachingLoader#load method intermittently hangs

mikerod
This post was updated on .
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
Reply | Threaded
Open this post in threaded view
|

Re: CompositiveClassLoader$CachingLoader#load method intermittently hangs

mikerod
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.  :)
Reply | Threaded
Open this post in threaded view
|

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

stevearoonie
In reply to this post by mikerod
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 <[hidden email]> 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-load-method-intermittently-hangs-tp4028780.html
Sent from the Drools: User forum mailing list archive at Nabble.com.
_______________________________________________
rules-users mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/rules-users


_______________________________________________
rules-users mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/rules-users
Reply | Threaded
Open this post in threaded view
|

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

mikerod
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/main/java/org/drools/rule/constraint/MvelConstraint.java#L232

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/main/java/org/drools/concurrent/ExecutorProviderImpl.java#L11

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-threads-Disabling-JIT-td4026694.html)

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.
Reply | Threaded
Open this post in threaded view
|

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

Mark Proctor

On 19 May 2014, at 03:21, mikerod <[hidden email]> 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:

We’ll look into 5.x too at some point in the next few weeks.

Mark


_______________________________________________
rules-users mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/rules-users
Reply | Threaded
Open this post in threaded view
|

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

mikerod
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-Upgrading-to-Drools-6-x-tp4028636.html

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.