Built with Seam
You can find the full source code for this website in the Seam package in the directory /examples/wiki. It is licensed under the LGPL.
| Online: | 11 Members of 4090 |
| Forum: Seam Users |
 |
17. Aug 2008, 17:42 CET | Link |
Hi all,
we have been observing really bad performance in our run-off-the-mill Seam application, so I started investigating.
Environment: JBoss EAP 4.3.0.CP01, JBoss Seam 2.0.1.GA
I wrote a simple AOP-based configurable stats collector stack for per-request method profiling (based on source by Tobias Hill), which revealed the following.
Note that the timings are rather distorted, since we're also collecting invocation arguments for select methods - nevertheless, the relative proportions reflect the problem.
Before (Seam-2.0.1.GA):
13:29:43,415 DEBUG [ProfilerFilter] >> total round-trip time: 140.837,90 ms for http://localhost:8080/green/home.seam 13:29:43,428 DEBUG [AopStatsCollector] MethodProfiler stats: ---------------+--------+------------------------------------------------------------------ accum. time | #calls | method ---------------+--------+------------------------------------------------------------------ 153.112,64 ms | 8 | java.util.Set org.jboss.seam.international.Messages$1.entrySet() 140.837,07 ms | 2 | void org.jboss.seam.debug.hot.HotDeployFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 140.836,12 ms | 2 | void org.jboss.seam.web.LoggingFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 140.835,65 ms | 2 | void org.jboss.seam.web.Ajax4jsfFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 140.834,12 ms | 2 | void org.jboss.seam.web.RedirectFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 140.833,81 ms | 2 | void org.jboss.seam.web.ExceptionFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 140.833,54 ms | 2 | void org.jboss.seam.web.MultipartFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 139.962,73 ms | 4 | void org.jboss.seam.ui.util.cdk.RendererBase.encodeBegin(javax.faces.context.FacesContext, javax.faces.component.UIComponent) 139.962,44 ms | 4 | void org.jboss.seam.ui.renderkit.LinkRendererBase.doEncodeBegin(javax.faces.context.ResponseWriter, javax.faces.context.FacesContext, javax.faces.component.UIComponent) 139.954,98 ms | 49 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.String, boolean) 139.912,64 ms | 17 | java.lang.Object org.jboss.seam.el.SeamELResolver.getValue(javax.el.ELContext, java.lang.Object, java.lang.Object) 139.912,02 ms | 9 | java.lang.Object org.jboss.seam.el.SeamELResolver.resolveBase(javax.el.ELContext, java.lang.Object) 139.910,03 ms | 45 | java.lang.Object org.jboss.seam.Namespace.getComponentInstance(java.lang.String) 139.909,06 ms | 45 | java.lang.Object org.jboss.seam.Namespace.getComponentInstance(java.lang.String, boolean) 46.646,45 ms | 2605 | java.lang.String org.jboss.seam.international.Messages$1.get(java.lang.Object) 46.633,05 ms | 2611 | java.lang.Object org.jboss.seam.core.SeamResourceBundle.handleGetObject(java.lang.String) 33.275,49 ms | 2618 | java.util.List org.jboss.seam.core.SeamResourceBundle.getPageResourceBundles() 31.886,17 ms | 2618 | java.util.List org.jboss.seam.navigation.Pages.getResourceBundles(java.lang.String) 31.761,68 ms | 2618 | java.util.ResourceBundle org.jboss.seam.navigation.Page.getResourceBundle() 29.239,10 ms | 2618 | java.util.ResourceBundle org.jboss.seam.core.ResourceLoader.loadBundle(java.lang.String) 25.568,47 ms | 28227 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.Class, org.jboss.seam.ScopeType) 24.928,81 ms | 28235 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.Class, org.jboss.seam.ScopeType, boolean) 23.012,93 ms | 28239 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.String, org.jboss.seam.ScopeType, boolean) 20.551,71 ms | 28287 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.String, boolean, java.lang.Object)
What immediately strikes out is that org.jboss.seam.international.Messages$1.entrySet() seems to take up the largest portion of request processing (note that the timings aren't completely accurate, since nested method invocations aren't counted correctly).
Checking the source, I found the message map implementation to be surprisingly complex (and tagged with a comment on the inefficiency of the implementation):
@Scope(ScopeType.STATELESS)
@BypassInterceptors
@Name("org.jboss.seam.international.messagesFactory")
@Install(precedence=BUILT_IN)
public class Messages
{
protected Map createMap()
{
// AbstractMap uses the implementation of entrySet to perform all its
// operations - for a resource bundle this is very inefficient for keys
return new AbstractMap<String, String>()
{
private java.util.ResourceBundle bundle = SeamResourceBundle.getBundle();
@Override
public String get(Object key)
{
if (key instanceof String)
{
String resourceKey = (String) key;
String resource=null;
if (bundle!=null)
{
try
{
resource = bundle.getString(resourceKey);
}
catch (MissingResourceException mre)
{
//Just swallow
}
}
return resource==null ? resourceKey : resource;
}
else
{
return null;
}
}
@Override
public Set<Map.Entry<String, String>> entrySet()
{
Enumeration<String> keys = bundle.getKeys();
Map<String, String> map = new HashMap<String, String>();
while ( keys.hasMoreElements() )
{
String key = keys.nextElement();
map.put( key, get(key) );
}
return Collections.unmodifiableSet(map.entrySet());
}
@Override
public boolean containsKey(Object key)
{
return get(key) != null;
}
@Override
public Set<String> keySet()
{
Enumeration<String> keys = bundle.getKeys();
return new HashSet<String>(Collections.list(keys));
}
@Override
public int size()
{
return keySet().size();
}
};
}
/**
* Create the Map and cache it in the EVENT scope. No need to cache
* it in the SESSION scope, since it is inexpensive to create.
*
* @return a Map that interpolates messages in the Seam ResourceBundle
*/
@Factory(value="org.jboss.seam.international.messages", autoCreate=true, scope=EVENT)
public Map<String, String> getMessages()
{
return createMap();
}
I replaced this with the following code:
@Scope(ScopeType.STATELESS)
@BypassInterceptors
@Name("org.jboss.seam.international.messagesFactory")
@Install(precedence=BUILT_IN)
public class Messages
{
private static class MessageMap extends HashMap<String, String> {
private static final long serialVersionUID = 1L;
private java.util.ResourceBundle bundle = SeamResourceBundle.getBundle();
public MessageMap() {
}
@Override
public String get(Object o) {
if (!(o instanceof String))
return null;
String key = (String)o;
String value = super.get(key);
if (value == null) {
value = bundle.getString(key);
value = value != null ? value : key;
put(key, value);
}
return value;
}
}
/**
* Create the Map and cache it in the EVENT scope. No need to cache
* it in the SESSION scope, since it is inexpensive to create.
*
* @return a Map that interpolates messages in the Seam ResourceBundle
*/
@Factory(value="org.jboss.seam.international.messages", autoCreate=true, scope=EVENT)
public Map<String, String> getMessages()
{
return new MessageMap();
}
Now, the timings looked like this:
15:34:24,458 DEBUG [ProfilerFilter] >> total round-trip time: 13.794,29 ms for http://localhost:8080/green/home.seam 15:34:24,477 DEBUG [AopStatsCollector] MethodProfiler stats: ---------------+--------+------------------------------------------------------------------ accum. time | #calls | method ---------------+--------+------------------------------------------------------------------ 13.790,50 ms | 2 | void org.jboss.seam.debug.hot.HotDeployFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 13.789,88 ms | 2 | void org.jboss.seam.web.LoggingFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 13.783,26 ms | 2 | void org.jboss.seam.web.Ajax4jsfFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 13.546,40 ms | 2 | void org.jboss.seam.web.RedirectFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 13.397,89 ms | 2 | void org.jboss.seam.web.ExceptionFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 13.397,66 ms | 2 | void org.jboss.seam.web.MultipartFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) 3.572,77 ms | 3 | void org.jboss.seam.jsf.SeamPhaseListener.afterPhase(javax.faces.event.PhaseEvent) 3.569,61 ms | 3 | void org.jboss.seam.jsf.SeamPhaseListener.afterServletPhase(javax.faces.event.PhaseEvent) 3.548,83 ms | 678 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.String, boolean, java.lang.Object) 3.180,40 ms | 441 | java.lang.Object org.jboss.seam.Component.newInstance() 3.095,93 ms | 2 | void org.jboss.seam.jsf.SeamPhaseListener.afterRestoreView(javax.faces.context.FacesContext) 2.094,75 ms | 51 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.String, boolean) 2.070,60 ms | 32 | javax.faces.component.UIComponent org.jboss.seam.jsf.SeamApplication.createComponent(java.lang.String) 1.935,81 ms | 441 | java.lang.Object org.jboss.seam.Component.instantiate() 1.926,62 ms | 441 | java.lang.Object org.jboss.seam.Component.instantiateJavaBean() 1.659,87 ms | 628 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.String, org.jboss.seam.ScopeType, boolean) 1.655,74 ms | 624 | java.lang.Object org.jboss.seam.Component.getInstance(java.lang.Class, org.jboss.seam.ScopeType, boolean)
My replacement implementation is probably incorrect, or naive, but resulted in a speed-up of approx. 10, and the method profiler stats now looked plausible.
Can anyone comment on this?
many thanks,
Karl
Karl Traunmüller
Objectbay Software & Consulting GmbH
Softwarepark 35
4232 Hagenberg, Austria
www.objectbay.com
Tags: Performance
My implementation was actually incorrect, the MissingResourceException thrown by bundle.getString() wasn't caught:
private static class MessageMap extends HashMap<String, String> { private static final long serialVersionUID = 1L; private java.util.ResourceBundle bundle = SeamResourceBundle.getBundle(); @Override public String get(Object o) { if (!(o instanceof String)) return null; String key = (String)o; String value = super.get(key); if (value == null) { try { value = bundle.getString(key); } catch (MissingResourceException e) { } value = value != null ? value : key; put(key, value); } return value; } }Other than that, this seems to work, even though the Map semantics are severely violated (the lazy value loading clearly affects entrySet() and other Map methods).
I have overriden all relevant methods of HashMap and set breakpoints in each of them - none of them fired, which confirms the conjecture that the message map is only accessed by get(), which is why this crazy hack seems to work.
regards,
Karl
Yes, the reason for the complexity of the implementation is to solve this noted performance problem. Your implementation isn't correct, it's missing the entrySet() method, try reading the javadoc for HashMap, you'll find it doesn't call get() to create the entry set!
Anyway, you need to run your profiling NOT in debug mode. If you still observe this problem not in debug mode, please file an issue in JIRA with instructions to reproduce in one of the standard Seam examples, or from a seam-gen app.
Read about how to report a bug.