1 2 3 Previous Next 38 Replies Latest reply: Oct 25, 2011 6:54 PM by Jake C RSS

Seam performance problem + rewarding workaround...

Tobias Hill Newbie

During a quite recent performance sprint in my team I found out (much to my surprise) that Seam itself (or our usage of)  was the major performance bottleneck. I like to share what I found and how I refactored parts of the application to workaround it, possibly helping someone else not making the same mistakes as we did, possibly reclaiming a bunch of ms for you.


Here goes...


It all started when I realized that no matter how fast I made the logic preparing data for one of our slower views it nevertheless took about 1200 ms to render it. To examine further I made an interceptor measuring call-times for all beans managed by seam in our application. Summing all call-times I landed at approximately 200 ms ... which indicated that 1000 ms got lost in Seam itself. Yes. One second.


To verify that suspicion I changed my interceptor so that it was mounted outside all internal interceptors of seam (actually it should have been all the time). Summing all call-times once again resulted in approx 1200 ms - hence confirming my suspicion that approx. one second in each request was lost in Seam.


The timing interceptor also showed that two methods of one of the view backing beans had been called 60 times each, each invocation taking about 8 ms. Voilà, there it was!, (almost) the explanation for the lost second.


I suspect that the bean is being rigged for each request, i.e. there is a lot of injections and preparations going on for every single call even though the view backing bean is in conversation scope. Please correct me if I am wrong.


Digging further I found that the view was looping over a collection and in each iteration calls were being made (via an innocent looking EL-expression) to the two methods on the view backing bean.


The first thought was to break out those calls within the view itself - the result from the methods were static per rendered view so there was no need to call them in the loop. JSTL and c:set seemed to be the way forward ... but to my surprise c:set only served as an EL-expression-alias and hence the calls still were being fired from within the loop. Equally slow. Bad.


Next thing I did was to let the view backing beans instead prepare data-holders containing all data for each view which were outjected into the request-scope. Those data-holders I annotated with @BypassInterceptors.


This solved it all for me. After I was done several views in our system became considerably faster (between 2 and up to 8 times). My interceptor now shows that the main part of each reqeust is due to our code, not due to seam prep ... i.e as expected and as it should be.


I am writing this to shed light on a mistake that (frankly) is very easy to make (just an EL on the wrong place) not understanding the cost of a method call against a managed bean with several injections.


Probably there are other ways out of this performance problem than the one I suggest. If you have other suggestions please feel free to enlight me (and the forum).


  • 1. Re: Seam performance problem + rewarding workaround...
    Damian Harvey Apprentice

    Can you show the EL expression that caused the pain?


    Thanks,


    Damian.

  • 2. Re: Seam performance problem + rewarding workaround...
    Tobias Hill Newbie

    Sure. But the EL itself is not the problem. The repeated usage of  bean with injections is.


    Loop starts
    ...
    <f:param name="searchString" value="#{searchPageBean.searchString}"/>
    ...
    Loop ends
    



    ... where searchPageBean is (or was) a managed bean (POJO) with some injections and a getter getSearchString() which simply returned a String.


  • 3. Re: Seam performance problem + rewarding workaround...
    Pete Muir Master

    Yes, you are correct in your analysis. And your solution is the one I would use.


    In general, over the next couple of months we will be working both on Seam performance and scalability analysis (and any resulting fixes) and also on tips like this for improving the performance of your app.

  • 4. Re: Seam performance problem + rewarding workaround...
    Tobias Hill Newbie

    Ok. Good to hear. Looking forward to upcoming performance fixes/best practises then.

  • 5. Re: Seam performance problem + rewarding workaround...
    Andrei Gh Newbie

    Hi Tobias,


    Thanks for this article - it is very helpful! We have performance problems too, and I am still digging.


    One question: regarding the timing interceptor you have created:
    I guess is important to specify the order of the interceptor among others(like bijection interceptor), right? Can you please post the header of the interceptor here (the part with the annotations).


    Thank you.

  • 6. Re: Seam performance problem + rewarding workaround...
    Lars Huber Newbie

    It would be great if you would post a complete example of your workaround. thanks

  • 8. Re: Seam performance problem + rewarding workaround...
    Bill Evans Newbie

    I had similar experience a few months ago. I used YourKit (highly recommended) to highlight the excessive Seam interceptions. Then I plugged in @BypassInterceptors appropriately and, hey presto, performance problem fixed!


    This highly important annotation is barely mentioned in the docs and yet it is critical in any production app. I would very much welcome more explanation of it and some simple tips on where it can be judiciously employed. Other performance tips also VERY WELCOME!!

  • 9. Re: Seam performance problem + rewarding workaround...
    Tobias Hill Newbie

    Yes. YourKit is very good. Sometimes however I find it just as easy (and less bulky)
    to just add (or reuse) an interceptor. The interceptor also has the great benefit of always
    being accessible in our dev-, test- and stage-environments - i.e. we can always monitor how
    new functionality affects performance (as a complement to our automated performance tests).


    My bean-timing interceptor looks like this:


    @Interceptor(around = {
            BijectionInterceptor.class,
            MethodContextInterceptor.class,
            ConversationInterceptor.class,
            SynchronizationInterceptor.class,
            ConversationalInterceptor.class,
            RemoveInterceptor.class,
            SeamInterceptor.class,
            SecurityInterceptor.class,
            TransactionInterceptor.class,
            EventInterceptor.class,
            HibernateSessionProxyInterceptor.class,
            ManagedEntityIdentityInterceptor.class
            }
    )
    
    public class TimingInterceptor {
    
        public final static CallChain callChain = new CallChain();
    
        @AroundInvoke
        public Object timeCall(InvocationContext invocation) throws Exception {
            long t0 = System.nanoTime();
            try {
                return invocation.proceed();
            } finally {
                long dt = System.nanoTime() - t0;
                callChain.addInvocation(invocation, dt);
            }
        }
    
        // -----------------------------------------------------------------------------
    
        /**
         * A call chain is the set of invocations on methods (annotated 
         * with MeasureCalls) that a request issued on its way through 
         * the application stack.
         */
        public static class CallChain extends ThreadLocal<Map<Method, TimedInvocation>> {
    
            @Override
            protected Map<Method, TimedInvocation> initialValue() {
                return new HashMap<Method, TimedInvocation>();
            }
    
            public void addInvocation(InvocationContext invocation, long dt) {
                Map<Method, TimedInvocation> invocations = get();
                Method method = invocation.getMethod();
                if (!invocations.containsKey(method)) {
                    invocations.put(method, new TimedInvocation(invocation.getMethod(), dt));
                } else {
                    TimedInvocation timedInvocation = invocations.get(method);
                    timedInvocation.anotherCall(dt);
                }
            }
    
            public int totalNumberOfInvocations() {
                Map<Method, TimedInvocation> invocations = get();
                Collection<TimedInvocation> timedInvocationCollection = invocations.values();
                int totCalls = 0;
                for (TimedInvocation invocation : timedInvocationCollection)
                    totCalls += invocation.getCalls();
                return totCalls;
            }
        }
    }
    



    which uses:


    /**
     * TimedInvocation is an invocation (i.e. a method call) which is being
     * counted and timed. 
     */
    public class TimedInvocation implements Comparable<TimedInvocation> {
    
        private long dt;
        private int calls = 1;
        private Method method;
    
        public TimedInvocation(Method method, long dt) {
            this.method = method;
            this.dt = dt;
        }
    
        public long getDt() {
            return dt;
        }
    
        public Method getMethod() {
            return method;
        }
    
        public String toString() {
            String className = method.getDeclaringClass().getName();
            String shortendName = className.substring(method.getDeclaringClass().getPackage().getName().length() + 1);
            String duration = StringUtils.leftPad(StrUtil.format(dt / 1e6) + " ms", 11);
            String nCallStr = StringUtils.leftPad(String.valueOf(calls), 4);
            return duration + nCallStr + "   " + shortendName + "." + method.getName() + "()";
        }
    
        public void anotherCall(long dt) {
            this.dt += dt;
            calls++;
        }
    
        public int compareTo(TimedInvocation o) {
            return -Long.valueOf(dt).compareTo(o.dt);
        }
    
        public int getCalls() {
            return calls;
        }
    }
    



    I also defined a shortcut-annotation, like this:


    @Target(ElementType.TYPE)
    @Retention(RetentionPolicy.RUNTIME)
    @Interceptors(TimingInterceptor.class)
    public @interface MeasureCalls {}
    



    I use it like this:


    @AutoCreate
    @Name("theBeanILikeToInvestigate")
    @MeasureCalls
    public class TheBeanILikeToInvestigare ...
    





    Now TimingInterceptor.callChain contains the data you need (per thread).


    I use it together with a javax.servlet.Filter which I put around the whole application. That filter just clears callChain (which happens per thread, so this is safe) on the way down the application and then displays the result (by fetching the data in callChain) on the way up.


    I interleave the timing data on the HTML-page ... but it is perfectly fine to just log it (if you prefer).


    Typically I display it like this (slightly obfuscated). The first column contains the accumulated time spent in this method. The second column contains the number of times the method has been called.


    284.94 ms   1   FooBean.getRandomDroplets()
    284.56 ms   1   GahBean.getRandomDroplets()
    201.60 ms   2   SohBean.searchRatedDoodlesWithinHead()
    185.94 ms   1   FroBean.doSearchPopular()
    157.63 ms   1   FroBean.doSearchRecent()
     42.34 ms   1   FooBean.fetchMostRecentYodel()
     41.94 ms   1   GahBean.getMostRecentYodel()
     15.89 ms   1   FooBean.getNoOfYodels()
     15.00 ms   1   GahBean.getNoOfYodels()
      9.14 ms   1   SohBean.mainYodels()
      1.11 ms   2   SohBean.trackHoorayEvent()
      0.32 ms   1   FroBean.reset()
      0.22 ms  43   NohBean.thumbPicture()
      0.03 ms  18   FooBean.getMostRecentYodels()
      0.01 ms   1   NohBean.profilePicture()
      0.01 ms   1   FroBean.setToDefault()
      0.01 ms   1   FroBean.getRecentMarker()
    



    Before my work where I moved the view data from managed beans to bypassed dittos the timing typically looked like this.


    2114.94 ms  80   FooBean.getRandomDroplets()
    2024.56 ms  80   GahBean.getRandomDroplets()
     601.60 ms  12   SohBean.searchRatedDoodlesWithinHead()
     185.94 ms   1   FroBean.doSearchPopular()
     157.63 ms   1   FroBean.doSearchRecent()
      42.34 ms   1   FooBean.fetchMostRecentYodel()
      41.94 ms   1   GahBean.getMostRecentYodel()
      15.89 ms   1   FooBean.getNoOfYodels()
      15.00 ms   1   GahBean.getNoOfYodels()
       9.14 ms   1   SohBean.mainYodels()
       1.11 ms   2   SohBean.trackHoorayEvent()
       0.32 ms   1   FroBean.reset()
       0.22 ms  43   NohBean.thumbPicture()
       0.03 ms  18   FooBean.getMostRecentYodels()
       0.01 ms   1   NohBean.profilePicture()
       0.01 ms   1   FroBean.setToDefault()
       0.01 ms   1   FroBean.getRecentMarker()
    



    Clearly revealing the problem and where to focus coming performance work.

  • 10. Re: Seam performance problem + rewarding workaround...
    Tobias Hill Newbie

    Hi Lars,


    See the interceptor I posted for an example of how to diagnose expansive-bean-calls-problems in your applications (if any).


    Now put focus on those items in the timing-result list which are called many times during a request which also are having a high accumulated total time. If those items just are serving static data you better extract that to beans which are bypassed by seams interceptor facilities.


    Before:


    @Name("heavyBean")
    @Scope(CONVERSATION)
    @MeasureCalls
    public class HeavyBean implements Serializable {
    
        @Logger
        static private Log log;
    
        @In
        private ... 
    
        @In
        private ... 
    
        @In(create = true)
        private ...
    
        @In(required = false)
        private ... 
    
        @In(create = true)
        private ...
    
        @In
        private ...
    
        @In
        private ...
    
        public String getStaticData() {
            return theStaticData;
        }
    
        public List getTopList() {
            return topList;
        }
    



    After:


    @Name("heavyBean")
    @Scope(CONVERSATION)
    @MeasureCalls
    public class HeavyBean implements Serializable {
    
        @Logger
        static private Log log;
    
        @In
        private ... 
    
        @In
        private ... 
    
        @In(create = true)
        private ...
    
        @In(required = false)
        private ... 
    
        @In(create = true)
        private ...
    
        @In
        private ...
    
        @In
        private ...
    
        @Out 
        private ViewData viewData;
    
    



    public class ViewData {
    
        public String getStaticData() {
            return theStaticData;
        }
    
        public List<TopListData> getTopList() {
            return topList;
        }
    



    ... as easy as that.


    Note that I don't use the @BypassInterceptor in this case (it is not needed for just dispalying outjected data as a one time shot).


    If you need to have a managed bean (which can be accessed by its named for instance) containing data used frequently in views just create it with the BypassInterceptors-annotations to make it as lean as possible (Note however that this means you can't use @In-annotations on it). 


    @Name("userData")
    @AutoCreate
    @Scope(SESSION)
    @BypassInterceptors
    public class UserData implements Serializable ...
    



  • 11. Re: Seam performance problem + rewarding workaround...
    Damian Harvey Apprentice

    Tobias,


    Thanks for this. I've just put it into my app and it works a treat. Much appreciated.


    Do you do anything in your filter other than:


    public void doFilter(ServletRequest req, ServletResponse resp,
              FilterChain chain) throws IOException, ServletException {
    
         TimingInterceptor.callChain.remove();
    
         chain.doFilter(req, resp);
    
         Map<Method, TimedInvocation> invocations = TimingInterceptor.callChain.get();
         for(TimedInvocation timedInvocation : invocations.values()) {
              //Dump to sysout for now. Should be logged properly
              System.out.println(timedInvocation.toString());
         }
    
    }
    


    Cheers,


    Damian.

  • 12. Re: Seam performance problem + rewarding workaround...
    Tobias Hill Newbie

    As said I interleave results on the served page which of course makes my filter look a bit different. The timing extraction looks like this in my filter (which essentially looks like yours btw): 


    TimingInterceptor.callChain.get().clear();
    
    chain.doFilter(servletRequest, wrapper);
    
    Collection<TimedInvocation> invocations = TimingInterceptor.callChain.get().values();
    
    List<TimedInvocation> list = new ArrayList<TimedInvocation>(invocations);
    Collections.sort(list);
    
    // ... and then log it.  
    



    Glad I could be of help.

  • 13. Re: Seam performance problem + rewarding workaround...
    Tobias Hill Newbie

    And by the way


    String className = method.getDeclaringClass().getName();
    String shortendName = className.substring(method.getDeclaringClass().getPackage().getName().length() + 1);
    



    ... could/should of course be replaced by getSimpleName() on Class. I'd forgot about it.

  • 14. Re: Seam performance problem + rewarding workaround...
    Lars Huber Newbie

    Hi Tobias


    thank you very much for this great explanation. This are informations which I believe would be an essential part in Seam documentations.


    greets Lars

1 2 3 Previous Next