[seam-dev] Some profiling of blocking threads

[Gavin King]

Great work, Jay, this is all very useful!

On Wed, Sep 24, 2008 at 3:05 PM, Jay Balunas <tech4j at gmail.com> wrote:
> 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).
> 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
> 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