Re: Deadlock issue

Thursday, April 19, 2012, 7:44:40 AM, Jacopo Cappellato wrote:

> Thank you Daniel,
>
> please see my comments inline:
>
> On Apr 18, 2012, at 9:27 PM, Daniel Dekany wrote:
>
>> Wednesday, April 18, 2012, 5:06:07 PM, Jacopo Cappellato wrote:
>> 
>>> ...
>>> Here are the details of the deadlock:
>>> 
>>> Thread 1:
>>> a) ClassBasedModelFactory.get is called: this method acquires a lock on the "cache" variable
>>> b) the method then calls BeansWrapper.introspectClass: this method
>>> attempts to acquire a lock on "classCache" variable
>>> 
>>> Thread 2:
>>> x) BeansWrapper.introspectClass is called: this method acquires a lock on the "classCache" variable
>>> y) the method then calls BeansWrapper.introspectClassInternal that in turn
>>> calls ClassBasedModelFactory.clearCache: this method attempts to
>>> acquire a lock on "cache" variable
>> 
>> Yeah, that's wrong. And I see 2.3.19 does this too.
>
> Please let me know if you want me to file a ticket in the issue tracker.

You can do it, so it won't be forgotten. The issue is simply that FM
syncs on the same two monitors on different parts of the code, but not
in the same order. That in itself is a bug.

>>> If the two threads are concurrent and perform the tasks in the following order:
>>> a
>>> x
>>> b
>>> y
>>> we get the deadlock.
>>> 
>>> Now: we are sure this is the cause of the problem; what we do not
>>> know, and I am hoping on your help, is what could be cause that 2
>>> threads perform the calls axby on the two objects
>>> ClassBasedModelFactory and BeansWrapper
>>> I suspect it may be something wrong we are doing with Freemarker
>>> templates, include directives etc...
>> 
>> It's a bug in FreeMarker, so it's not because you do something wrong.
>> It has to be fixed in FreeMarker. However, I smell something fishy
>> here... This deadlock can occur only if FreeMarker detects a
>> class-reloading, and then you also must be rather unlucky with the
>> timings. So it looks like class-reloading is frequent on your
>> production server, or at FreeMarker believes that. Is it possible that
>> you load the same class with different ClassLoader-s (like, different
>> versions of the same class)? Having different versions of the same
>> class around is normal with OSGi and like, but as far as I see (only
>> from a quick look though), the author of BeansWrapper haven't
>> considered that. So if you have that situation, FreeMarker will drop
>> the introspection caches often, which is already a bad thing, as it
>> can slow down things.
>
> Thanks for the useful information.
> We are actually using Freemarker in OFBiz (http://ofbiz.apache.org)
> and we have several production instances running without experiencing this deadlock.
> So I suspect (and I am investigating) we have some custom template
> that is causing the issue in this instance only.
> Could it be possible that the following condition causes the deadlock under high traffic?
>
> We have 2 ftl templates:
>
> template1.ftl: it contains content ftl directives etc...
> template2.ftl: it contains the following code:
> <header id="header">
>   <#include "template1.ftl"/>
> </header>

I have no idea why would this cause any problem. It seems to be
completely unrelated to what you have shown in the source code. I
suspect it's just an accidental timing thing...

> and we have several threads that may render template1.ftl directly or template2.ftl
>
> Could this contribute to cause the deadlock? I am asking because we
> did the attempt to remove the <#include> directive and copy the
> content of template1.ftl directly in template2.ftl and this *seems*
> to resolve the problem (but we are still testing it).

What you have shown in the source code clearly can cause a dead-lock.
But, again, that code-path is only executed if FreeMarker thinks it
has to clear the introspection caches, because a class has changed.
Why does that happening on your production server, especially why so
often that you keep running into the unlucky timing? Figure that out,
because that's not healthy even if there's no deadlock, and that's
also why you run into this dead-lock bug. Form your answer I take you
aren't using OSGi of similar. Then maybe you share the same
freemarker.jar file (same full-path) for multiple applications, and
are also using the deprecated default shared (static) ObjectWrapper
instance (or some other ObjectWrapper instance which is somehow shared
between applications). If two applications has the same classes from
non-shared defining class-loaders (usually, from jar files from
different directories), and you pass instances of those classes to the
templates, FreeMarker will constantly believe that the classes were
reloaded, because it gets classes of the same name which aren't
equivalent objects. Each application needs to have its own
ObjectWrapper in this case (see Configuration.setObjectWrapper), which
is how it's normally done regardless of this issue anyway.

Let's try a few things instead of just trying to run into a dead-lock:

When FreeMarker detects a class change, it logs on info-level that
"Detected a reloaded class [com.example.SomeClass]". For which classes
does this happening? Do you understand why are those classes
(apparently) changing?

Also, what ObjectWrapper is in use can be checked while the template
is running with
freemarker.core.Environment.getCurrentEnvironment().getConfiguration().getObjectWrapper().
Write a TempalteMethodModel that returns that, print it the result
into the template, and then you will see if its the same *instance* in
multiple applications.

> Thanks
>
> Jacopo

-- 
Best regards,
 Daniel Dekany


------------------------------------------------------------------------------
For Developers, A Lot Can Happen In A Second.
Boundary is the first to Know...and Tell You.
Monitor Your Applications in Ultra-Fine Resolution. Try it FREE!
http://p.sf.net/sfu/Boundary-d2dvs2