2 Replies Latest reply on Oct 5, 2008 4:18 PM by Pete Muir

    org.jboss.seam.international.Messages performance

    Karl Traunmüller Newbie

      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

        • 1. Re: org.jboss.seam.international.Messages performance
          Karl Traunmüller Newbie

          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

          • 2. Re: org.jboss.seam.international.Messages performance
            Pete Muir Master

            Checking the source, I found the message map implementation to be surprisingly complex (and tagged with a comment on the inefficiency of the implementation):

            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.