[seam-dev] Some profiling of blocking threads

Gavin King gavin at hibernate.org
Thu Sep 25 18:00:16 EDT 2008 

Very nice!

On Thu, Sep 25, 2008 at 3:26 PM, Jay Balunas <tech4j at gmail.com> wrote:
> Good news and excellent turn around from Ryan on the UIComponent issue in
> the JSF RI.
>
> Ryan was able to provide a set of test jars with his fix and I reran the
> tests.  I found ZERO UIComponent related blocking threads!!
>
> I ran it through my performance benchmarks that I described in my original
> email with the following results:
>
> For the 25 user tests I saw a 12-17% improvement in both average and mean
> response time.
>
> Sample:
> 25 user avg before : 3088ms
> 25 user avg after    : 2545ms
>
> For the 50 user tests I saw a 4.5 - 5.3% improvement in both average and
> mean response time.
>
> Sample:
> 50 user avg before : 10283ms
> 50 user avg after  : 9815ms
>
> While these are not scientifically exhaustive statistics it does show a
> valid increase in performance from the change.
>
> Ryan created a bug to cover his change
> https://javaserverfaces.dev.java.net/issues/show_bug.cgi?id=806 and plans on
> including in the next release of JSF RI 1.2_10
>
> Regards,
> Jay
>
> On Thu, Sep 25, 2008 at 12:21 PM, Pete Muir <pmuir at redhat.com> wrote:
>>
>> 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
>>>>
>>>
>>
>> _______________________________________________
>> seam-dev mailing list
>> seam-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/seam-dev
>
>
>
> --
> blog: http://in.relation.to/Bloggers/Jay
>
> _______________________________________________
> seam-dev mailing list
> seam-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/seam-dev
>
>



-- 
Gavin King
gavin.king at gmail.com
http://in.relation.to/Bloggers/Gavin
http://hibernate.org
http://seamframework.org

More information about the seam-dev mailing list