[seam-dev] Some profiling of blocking threads

[Jay Balunas]

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