Re: Deadlock issue

Wednesday, April 18, 2012, 5:06:07 PM, Jacopo Cappellato wrote:

> Hi all,
>
> I know the question could be silly but we are struggling with a
> deadlock issue and I am wondering if any of you could give some hints to locate the problem.
> We are using Freemarker (2.3.10) in a server with high traffic and
> we are experiencing a deadlock that makes the server very unstable.
> 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.introspectClass 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.

> 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,
>
> Jacopo
>
> ===============
> For reference, here are the details about the two threads:
>
> @400000004f8e564b269dcbac "Thread 1":
> @400000004f8e564b269dcf94       at
> freemarker.ext.beans.BeansWrapper.introspectClass(BeansWrapper.java:924)
> @400000004f8e564b269dcf94       - waiting to lock
> <0x0000000785e62868> (a java.util.HashMap)
> @400000004f8e564b269dd764       at
> freemarker.ext.beans.BeanModel.<init>(BeanModel.java:139)
> @400000004f8e564b269ddb4c       at
> freemarker.ext.beans.StringModel.<init>(StringModel.java:90)
> @400000004f8e564b269ddb4c       at
> org.ofbiz.widget.screen.HtmlWidget$StringHtmlWrapperForFtl.<init>(HtmlWidget.java:87)
> @400000004f8e564b269ddf34       at
> org.ofbiz.widget.screen.HtmlWidget$ExtendedWrapper.wrap(HtmlWidget.java:76)
> @400000004f8e564b269df2bc       at
> freemarker.ext.beans.StaticModel.populate(StaticModel.java:170)
> @400000004f8e564b269df6a4       at
> freemarker.ext.beans.StaticModel.<init>(StaticModel.java:89)
> @400000004f8e564b269df6a4       at
> freemarker.ext.beans.StaticModels.createModel(StaticModels.java:75)
> @400000004f8e564b269dfa8c       at
> freemarker.ext.beans.ClassBasedModelFactory.get(ClassBasedModelFactory.java:82)
> @400000004f8e564b269dfa8c       - locked <0x0000000785f573a8> (a java.util.HashMap)
> @400000004f8e564b269e025c       at
> freemarker.core.DynamicKeyName.dealWithStringKey(DynamicKeyName.java:136)
> @400000004f8e564b269e0644       at
> freemarker.core.DynamicKeyName._getAsTemplateModel(DynamicKeyName.java:94)
> @400000004f8e564b269e0a2c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b269e3524       at
> freemarker.core.Dot._getAsTemplateModel(Dot.java:74)
> @400000004f8e564b269e390c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b269e390c       at
> freemarker.core.MethodCall._getAsTemplateModel(MethodCall.java:86)
> @400000004f8e564b269e3cf4       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b269e40dc       at
> freemarker.core.BuiltIn$if_existsBI._getAsTemplateModel(BuiltIn.java:677)
> @400000004f8e564b269e507c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b269e507c       at
> freemarker.core.Assignment.accept(Assignment.java:90)
> @400000004f8e564b269e601c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269e6fbc       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b269ea284       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269eb60c       at
> freemarker.core.IfBlock.accept(IfBlock.java:82)
> @400000004f8e564b269eb60c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269ec5ac       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b269ed934       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269ee8d4       at
> freemarker.core.IfBlock.accept(IfBlock.java:82)
> @400000004f8e564b269ef48c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269f042c       at
> freemarker.core.Environment.process(Environment.java:176)
> @400000004f8e564b269f17b4       at
> org.ofbiz.base.util.template.FreeMarkerWorker.renderTemplate(FreeMarkerWorker.java:258)
> @400000004f8e564b269f2754       at
> org.ofbiz.widget.screen.HtmlWidget.renderHtmlTemplate(HtmlWidget.java:225)
> @400000004f8e564b269f36f4       at
> org.ofbiz.widget.screen.HtmlWidget$HtmlTemplate.renderWidgetString(HtmlWidget.java:270)
> @400000004f8e564b269f4694       at
> org.ofbiz.widget.screen.HtmlWidget.renderWidgetString(HtmlWidget.java:130)
> @400000004f8e564b269f5a1c       at
> org.ofbiz.widget.screen.ModelScreenWidget$PlatformSpecific.renderWidgetString(ModelScreenWidget.java:915)
> @400000004f8e564b269f69bc       at
> org.ofbiz.widget.screen.ModelScreenWidget.renderSubWidgetsString(ModelScreenWidget.java:104)
> @400000004f8e564b269f795c       at
> org.ofbiz.widget.screen.ModelScreenWidget$Section.renderWidgetString(ModelScreenWidget.java:191)
> @400000004f8e564b269f88fc       at
> org.ofbiz.widget.screen.ModelScreen.renderScreenString(ModelScreen.java:396)
> @400000004f8e564b269f989c       at
> org.ofbiz.widget.screen.ScreenRenderer.render(ScreenRenderer.java:135)
> @400000004f8e564b269fac24       at
> org.ofbiz.widget.screen.ScreenRenderer.render(ScreenRenderer.java:97)
> @400000004f8e564b269fbbc4       at
> sun.reflect.GeneratedMethodAccessor70.invoke(Unknown Source)
> @400000004f8e564b26a02d0c       at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> @400000004f8e564b26a030f4       at
> java.lang.reflect.Method.invoke(Method.java:597)
> @400000004f8e564b26a04864       at
> freemarker.ext.beans.BeansWrapper.invokeMethod(BeansWrapper.java:825)
> @400000004f8e564b26a05bec       at
> freemarker.ext.beans.OverloadedMethodModel.exec(OverloadedMethodModel.java:111)
> @400000004f8e564b26a06b8c       at
> freemarker.core.MethodCall._getAsTemplateModel(MethodCall.java:93)
> @400000004f8e564b26a07b2c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b26a08acc       at
> freemarker.core.Expression.getStringValue(Expression.java:93)
> @400000004f8e564b26a09a6c       at
> freemarker.core.DollarVariable.accept(DollarVariable.java:76)
> @400000004f8e564b26a0aa0c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a0b9ac       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26a0c94c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a0d8ec       at
> freemarker.core.IteratorBlock$Context.runLoop(IteratorBlock.java:172)
> @400000004f8e564b26a0ec74       at
> freemarker.core.Environment.visit(Environment.java:351)
> @400000004f8e564b26a1176c       at
> freemarker.core.IteratorBlock.accept(IteratorBlock.java:95)
> @400000004f8e564b26a1176c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a12af4       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26a12af4       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a13a94       at
> freemarker.core.IteratorBlock$Context.runLoop(IteratorBlock.java:172)
> @400000004f8e564b26a14a34       at
> freemarker.core.Environment.visit(Environment.java:351)
> @400000004f8e564b26a159d4       at
> freemarker.core.IteratorBlock.accept(IteratorBlock.java:95)
> @400000004f8e564b26a16974       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a17914       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26a188b4       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a1bb7c       at
> freemarker.core.IfBlock.accept(IfBlock.java:82)
> @400000004f8e564b26a1bf64       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a1bf64       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26a1cf04       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26a1d2ec       at
> freemarker.core.Environment.process(Environment.java:176)
>
> @400000004f8e564b2690759c "Thread 2":
> @400000004f8e564b26907d6c       at
> freemarker.ext.beans.ClassBasedModelFactory.clearCache(ClassBasedModelFactory.java:98)
> @400000004f8e564b26908154       - waiting to lock
> <0x0000000785f573a8> (a java.util.HashMap)
> @400000004f8e564b2690853c       at
> freemarker.ext.beans.BeansWrapper.introspectClassInternal(BeansWrapper.java:950)
> @400000004f8e564b26908924       at
> freemarker.ext.beans.BeansWrapper.introspectClass(BeansWrapper.java:928)
> @400000004f8e564b26908924       - locked <0x0000000785e62868> (a java.util.HashMap)
> @400000004f8e564b2690bfd4       at
> freemarker.ext.beans.BeanModel.<init>(BeanModel.java:139)
> @400000004f8e564b2690c3bc       at
> freemarker.ext.beans.StringModel.<init>(StringModel.java:90)
> @400000004f8e564b2690c7a4       at
> freemarker.ext.beans.StringModel$1.create(StringModel.java:75)
> @400000004f8e564b2690cb8c       at
> freemarker.ext.util.ModelCache.getInstance(ModelCache.java:113)
> @400000004f8e564b2690cb8c       at
> freemarker.ext.beans.BeansWrapper.wrap(BeansWrapper.java:459)
> @400000004f8e564b2690db2c       at
> org.ofbiz.widget.screen.HtmlWidget$ExtendedWrapper.wrap(HtmlWidget.java:81)
> @400000004f8e564b2690fa6c       at
> freemarker.ext.beans.BeanModel.wrap(BeanModel.java:319)
> @400000004f8e564b2690fa6c       at
> freemarker.ext.beans.MapModel.invokeGenericGet(MapModel.java:134)
> @400000004f8e564b2690fe54       at
> freemarker.ext.beans.BeanModel.get(BeanModel.java:185)
> @400000004f8e564b2691023c       at
> freemarker.core.Environment.getGlobalVariable(Environment.java:979)
> @400000004f8e564b2691023c       at
> freemarker.core.Environment.getVariable(Environment.java:965)
> @400000004f8e564b269111dc       at
> freemarker.core.Identifier._getAsTemplateModel(Identifier.java:70)
> @400000004f8e564b269115c4       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b269115c4       at
> freemarker.core.Dot._getAsTemplateModel(Dot.java:74)
> @400000004f8e564b269119ac       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b26911d94       at
> freemarker.core.MethodCall._getAsTemplateModel(MethodCall.java:86)
> @400000004f8e564b2691294c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b2691294c       at
> freemarker.core.Assignment.accept(Assignment.java:90)
> @400000004f8e564b26912d34       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26912d34       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b269144a4       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b2691488c       at
> freemarker.core.IfBlock.accept(IfBlock.java:82)
> @400000004f8e564b26914c74       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26914c74       at
> freemarker.core.Environment.process(Environment.java:176)
> @400000004f8e564b2691505c       at
> org.ofbiz.base.util.template.FreeMarkerWorker.renderTemplate(FreeMarkerWorker.java:258)
> @400000004f8e564b26916bb4       at
> org.ofbiz.widget.screen.HtmlWidget.renderHtmlTemplate(HtmlWidget.java:225)
> @400000004f8e564b26916f9c       at
> org.ofbiz.widget.screen.HtmlWidget$HtmlTemplate.renderWidgetString(HtmlWidget.java:270)
> @400000004f8e564b26918af4       at
> org.ofbiz.widget.screen.HtmlWidget.renderWidgetString(HtmlWidget.java:130)
> @400000004f8e564b26918af4       at
> org.ofbiz.widget.screen.ModelScreenWidget$PlatformSpecific.renderWidgetString(ModelScreenWidget.java:915)
> @400000004f8e564b26919e7c       at
> org.ofbiz.widget.screen.ModelScreenWidget.renderSubWidgetsString(ModelScreenWidget.java:104)
> @400000004f8e564b2691ae1c       at
> org.ofbiz.widget.screen.ModelScreenWidget$Section.renderWidgetString(ModelScreenWidget.java:191)
> @400000004f8e564b2691bdbc       at
> org.ofbiz.widget.screen.ModelScreen.renderScreenString(ModelScreen.java:396)
> @400000004f8e564b2691d144       at
> org.ofbiz.widget.screen.ScreenRenderer.render(ScreenRenderer.java:135)
> @400000004f8e564b2691e0e4       at
> org.ofbiz.widget.screen.ScreenRenderer.render(ScreenRenderer.java:97)
> @400000004f8e564b2691f084       at
> sun.reflect.GeneratedMethodAccessor70.invoke(Unknown Source)
> @400000004f8e564b26920024       at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> @400000004f8e564b26920fc4       at
> java.lang.reflect.Method.invoke(Method.java:597)
> @400000004f8e564b26921f64       at
> freemarker.ext.beans.BeansWrapper.invokeMethod(BeansWrapper.java:825)
> @400000004f8e564b26922f04       at
> freemarker.ext.beans.OverloadedMethodModel.exec(OverloadedMethodModel.java:111)
> @400000004f8e564b26926d84       at
> freemarker.core.MethodCall._getAsTemplateModel(MethodCall.java:93)
> @400000004f8e564b2692716c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b2692ac04       at
> freemarker.core.Expression.getStringValue(Expression.java:93)
> @400000004f8e564b2692afec       at
> freemarker.core.DollarVariable.accept(DollarVariable.java:76)
> @400000004f8e564b2692afec       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b2692b3d4       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b2692c374       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b2692d314       at
> freemarker.core.IteratorBlock$Context.runLoop(IteratorBlock.java:160)
> @400000004f8e564b2692e2b4       at
> freemarker.core.Environment.visit(Environment.java:351)
> @400000004f8e564b2692f254       at
> freemarker.core.IteratorBlock.accept(IteratorBlock.java:95)
> @400000004f8e564b26944a14       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26944dfc       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26944dfc       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269451e4       at
> freemarker.core.ConditionalBlock.accept(ConditionalBlock.java:79)
> @400000004f8e564b269451e4       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b269455cc       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26946d3c       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26947124       at
> freemarker.core.Environment.process(Environment.java:176)
> @400000004f8e564b26947124       at
> org.ofbiz.base.util.template.FreeMarkerWorker.renderTemplate(FreeMarkerWorker.java:258)
> @400000004f8e564b2694750c       at
> org.ofbiz.widget.screen.HtmlWidget.renderHtmlTemplate(HtmlWidget.java:225)
> @400000004f8e564b269478f4       at
> org.ofbiz.widget.screen.HtmlWidget$HtmlTemplate.renderWidgetString(HtmlWidget.java:270)
> @400000004f8e564b26948894       at
> org.ofbiz.widget.screen.HtmlWidget.renderWidgetString(HtmlWidget.java:130)
> @400000004f8e564b26948894       at
> org.ofbiz.widget.screen.ModelScreenWidget$PlatformSpecific.renderWidgetString(ModelScreenWidget.java:915)
> @400000004f8e564b26948c7c       at
> org.ofbiz.widget.screen.ModelScreenWidget.renderSubWidgetsString(ModelScreenWidget.java:104)
> @400000004f8e564b2694a3ec       at
> org.ofbiz.widget.screen.ModelScreenWidget$Section.renderWidgetString(ModelScreenWidget.java:191)
> @400000004f8e564b2694a3ec       at
> org.ofbiz.widget.screen.ModelScreen.renderScreenString(ModelScreen.java:396)
> @400000004f8e564b2694a7d4       at
> org.ofbiz.widget.screen.ScreenRenderer.render(ScreenRenderer.java:135)
> @400000004f8e564b2694a7d4       at
> org.ofbiz.widget.screen.ScreenRenderer.render(ScreenRenderer.java:97)
> @400000004f8e564b2694b38c       at
> sun.reflect.GeneratedMethodAccessor70.invoke(Unknown Source)
> @400000004f8e564b2694b38c       at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> @400000004f8e564b2694b774       at
> java.lang.reflect.Method.invoke(Method.java:597)
> @400000004f8e564b2694c714       at
> freemarker.ext.beans.BeansWrapper.invokeMethod(BeansWrapper.java:825)
> @400000004f8e564b2694cafc       at
> freemarker.ext.beans.OverloadedMethodModel.exec(OverloadedMethodModel.java:111)
> @400000004f8e564b2694da9c       at
> freemarker.core.MethodCall._getAsTemplateModel(MethodCall.java:93)
> @400000004f8e564b2694da9c       at
> freemarker.core.Expression.getAsTemplateModel(Expression.java:89)
> @400000004f8e564b2694ea3c       at
> freemarker.core.Expression.getStringValue(Expression.java:93)
> @400000004f8e564b2694fdc4       at
> freemarker.core.DollarVariable.accept(DollarVariable.java:76)
> @400000004f8e564b26950d64       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26951d04       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26952ca4       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26953c44       at
> freemarker.core.ConditionalBlock.accept(ConditionalBlock.java:79)
> @400000004f8e564b26954be4       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b26955b84       at
> freemarker.core.MixedContent.accept(MixedContent.java:92)
> @400000004f8e564b26959234       at
> freemarker.core.Environment.visit(Environment.java:196)
> @400000004f8e564b2695c8e4       at
> freemarker.core.Environment.process(Environment.java:176)
>
>
> ------------------------------------------------------------------------------
> Better than sec? Nothing is better than sec when it comes to
> monitoring Big Data applications. Try Boundary one-second 
> resolution app monitoring today. Free.
> http://p.sf.net/sfu/Boundary-dev2dev
> _______________________________________________
> FreeMarker-user mailing list
> [email protected]
> https://lists.sourceforge.net/lists/listinfo/freemarker-user
>

-- 
Best regards,
 Daniel Dekany


------------------------------------------------------------------------------
Better than sec? Nothing is better than sec when it comes to
monitoring Big Data applications. Try Boundary one-second 
resolution app monitoring today. Free.
http://p.sf.net/sfu/Boundary-dev2dev