[seam-dev] Some profiling of blocking threads

[Pete Muir]

Thanks Ryan :-)

On 25 Sep 2008, at 16:27, Ryan Lubke wrote:

> Thanks,
>
> Jim and I will look into it.
>
> Pete Muir wrote:
>> Ryan, Ed,
>>
>> Jay has been working on performance analysis for Seam.
>>
>>> UIComponent$AttributesMap
>>> -----------------------------------------------------
>>> - Issues related to this were responsible for about 20% of the  
>>> blocked threads
>>> - Reported time spent blocked ranged from 30 ms - 848 ms with an  
>>> average estimated to be 400ms
>>> - I need to rerun the tests to be more specific.
>>> - One of the items that was strange with this block was that it  
>>> sometimes included completely unrelated actions or classes.
>>>   - after adjusting the filters, and rerunning the tests several  
>>> times I was able to narrow it down.
>>>
>>> * Investigation:
>>> Unfortunately this issue is in the RI JSF implementation itself.   
>>> The UIComponentBase implements its own Map (AttributeMap) ( see http://fisheye5.cenqua.com/browse/javaserverfaces-sources/jsf-api/src/javax/faces/component/UIComponentBase.java?r=1.158#l1521 
>>>  <http://fisheye5cenqua.com/browse/javaserverfaces-sources/jsf-api/src/javax/faces/component/UIComponentBase.java?r=1.158#l1521 
>>> >).  This is not an issue directly, but you will see calls to the  
>>> "getAttributesThatAreSet" method in the get, put, and remove  
>>> methods of the map.  This is implemented in the UIComponent class  
>>> ( see: http://fisheye5.cenqua.com/browse/javaserverfaces-sources/jsf-api/src/javax/faces/component/UIComponent.java?r=1.153#l1191) 
>>> .  The real issue is the call to "this.getClass().getPackage();".   
>>> This call will eventually synchronize in the  
>>> "ClassLoader.getPackage" method on the "packages" object for the  
>>> whole classloader.  This is why other threads were also blocked on  
>>> this - like  
>>> org.jboss.seam.contexts.Contexts.isApplicationContextActive()  
>>> which is accessing a ThreadLocal object.
>>>
>>> We really have 3 options for this issue.   - We can work with the  
>>> RI to get the handling of the package check changed so that the  
>>> values are some how cached in the component - how often do  
>>> packages change while running ;-)
>>> - We can take a look and try to find excessive use of the  
>>> components interactions with the AttributeMap.
>>> - We do nothing - but keep an eye on JSF 2 to make sure items like  
>>> this are handled better.
>>
>> Naively, I would assume it should be possible to cache the value of  
>> this.getClass().getPackage().
>>
>> HTH,
>>
>> Pete
>>
>> Begin forwarded message:
>>
>>> *From: *"Jay Balunas" <tech4j at gmail.com <mailto:tech4j at gmail.com>>
>>> *Date: *24 September 2008 22:05:51 BST
>>> *To: *"seam-dev at lists.jboss.org <mailto:seam-dev at lists.jboss.org>"  
>>> <seam-dev at lists.jboss.org <mailto:seam-dev at lists.jboss.org>>
>>> *Subject: **[seam-dev] Some profiling of blocking threads*
>>>
>>> I have been executing the 25 user performance tests through the  
>>> profiler to identify hot spots and areas of concern.  I am  
>>> initially looking at our blocking threads, and behavior around  
>>> them that is causing the problems.
>>>
>>> Test Description
>>> --------------------
>>> - Use the 25 user wiki forum front page jmeter tests discussed in  
>>> the previous email.
>>> - Uses same environment and procedures as defined in the previous  
>>> email.
>>> - Tests are executed through the profiler with CPU recording  
>>> turned on.
>>> - I have modified the default filters to allow the following  
>>> packages
>>>      - org.jboss.seam
>>>      - javax.faces
>>>      - most of the java.util collections and map classes
>>>
>>> Profile Results
>>> -------------------
>>> This is not a complete analysis of the entire application or even  
>>> all of the blocking threads - I will continue to work on them and  
>>> feed more information back to list.
>>>
>>> These items were detected via the thread usage history page, that  
>>> shows all blocked and waiting threads and their stack traces.
>>>
>>> javax.naming.InitialContext.lookup
>>> -----------------------------------
>>>  - as expected a large number of blocked threads were waiting or  
>>> blocked while attempting to lookup the initial context.
>>>  - One interesting thing is that not all of these were blocked on  
>>> a Hashtable - others were blocked on, or were related to calls to  
>>> Properties and WeakHashMap objects.  This is likely caused by  
>>> further method invocations that have been filtered out.
>>>    - I will look further, but wanted to look at some of the other  
>>> areas that were blocked.
>>>
>>> UIComponent$AttributesMap
>>> -----------------------------------------------------
>>> - Issues related to this were responsible for about 20% of the  
>>> blocked threads
>>> - Reported time spent blocked ranged from 30 ms - 848 ms with an  
>>> average estimated to be 400ms
>>> - I need to rerun the tests to be more specific.
>>> - One of the items that was strange with this block was that it  
>>> sometimes included completely unrelated actions or classes.
>>>   - after adjusting the filters, and rerunning the tests several  
>>> times I was able to narrow it down.
>>>
>>> * Investigation:
>>> Unfortunately this issue is in the RI JSF implementation itself.   
>>> The UIComponentBase implements its own Map (AttributeMap) ( see http://fisheye5.cenqua.com/browse/javaserverfaces-sources/jsf-api/src/javax/faces/component/UIComponentBase.java?r=1.158#l1521 
>>>  <http://fisheye5cenqua.com/browse/javaserverfaces-sources/jsf-api/src/javax/faces/component/UIComponentBase.java?r=1.158#l1521 
>>> >).  This is not an issue directly, but you will see calls to the  
>>> "getAttributesThatAreSet" method in the get, put, and remove  
>>> methods of the map.  This is implemented in the UIComponent class  
>>> ( see: http://fisheye5.cenqua.com/browse/javaserverfaces-sources/jsf-api/src/javax/faces/component/UIComponent.java?r=1.153#l1191) 
>>> .  The real issue is the call to "this.getClass().getPackage();".   
>>> This call will eventually synchronize in the  
>>> "ClassLoader.getPackage" method on the "packages" object for the  
>>> whole classloader.  This is why other threads were also blocked on  
>>> this - like  
>>> org.jboss.seam.contexts.Contexts.isApplicationContextActive()  
>>> which is accessing a ThreadLocal object.
>>>
>>> We really have 3 options for this issue.  - We can work with the  
>>> RI to get the handling of the package check changed so that the  
>>> values are some how cached in the component - how often do  
>>> packages change while running ;-)
>>> - We can take a look and try to find excessive use of the  
>>> components interactions with the AttributeMap.
>>> - We do nothing - but keep an eye on JSF 2 to make sure items like  
>>> this are handled better.
>>>
>>> org.ajax4jsf.application.AjaxViewHandler
>>> --------------------------------------------
>>> - This was not a large % of the blocked threads but caught my eye  
>>> as a potential trouble spot because it seemed directly related to  
>>> ajax calls.
>>> - This was easier to track down and the root cause is in the  
>>> org.ajax4jsf.application.ViewHandlerWrapper class.
>>> - see http://anonsvn.jboss.org/repos/richfaces/trunk/framework/api/src/main/java/org/ajax4jsf/application/ViewHandlerWrapper.java
>>> - The problem is all the calls to "fillChain" which is a  
>>> synchronized method in the class.
>>> - We need to find out how often the "_initialized" field is false  
>>> - is this once a request, once for each component, etc...
>>> - it appears to be called many times - I will look further into  
>>> this.
>>>
>>> -------------------------------------
>>> This is all I have had time for so far, but will continue to  
>>> investigate some of the other aspects of the application.  After  
>>> completing the analysis of the primary blocking thread issues I  
>>> will move on to other areas to profile.  These will focus on  
>>> specific issues raised by the team and the forums.  I will also  
>>> add performance tests and analysis for the dvd store example.
>>>
>>> Regards,
>>> Jay
>>>
>>>
>>> -- 
>>> blog: http://in.relation.to/Bloggers/Jay
>>> _______________________________________________
>>> seam-dev mailing list
>>> seam-dev at lists.jboss.org <mailto:seam-dev at lists.jboss.org>
>>> https://lists.jboss.org/mailman/listinfo/seam-dev
>>
>