[seam-dev] Some profiling of blocking threads

Thu Sep 25 17:26:22 EDT 2008

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/seam-dev/attachments/20080925/4c87dc7f/attachment.html 