org.jboss.seam.international.Messages performance
karl.traunmueller Aug 17, 2008 5:42 PMHi 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