org.jboss.seam.international.Messages performance
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
