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.

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

Just FYI: http://jira.jboss.com/jira/browse/JBSEAM-2704

Siarhei Dudzin wrote on Mar 11, 2008 20:10:
Just FYI: http://jira.jboss.com/jira/browse/JBSEAM-2704

This is a great post, thanks a lot to Tobias. We ever tested Seam on our existing ICEfaces project, and found that its speed apparently slowed down. Now, we found the reason. Our beans have a lot of binding properties, which consume main call-times. Using outject/inject is option, but it is hard to outject/inject all properties, especially for the frame EntityHome's getInstance. For now, we are looking forward to seeing JBSEAM-2704 to be fixed. Thanks a lot to Seam Team in advance!

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

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!!

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.

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.

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.

Could you say me how I configure the filter? I read http://java.sun.com/products/servlet/Filters.html but don't realize how I must configure it.

Thanks.

I realized how to configure it.

<filter>
    <filter-name>Timing Filter</filter-name>
    <filter-class>br.unioeste.sadau.TimingFilter</filter-class>
</filter>
    
<filter-mapping>
    <filter-name>Timing Filter</filter-name>
    <url-pattern>/admin/*</url-pattern>
</filter-mapping>

Thanks for these tips Tobias! Very appreciated.

Carlos.

Hi Carlos,

Actually your way is the standard Servlet way of defining a filter. It works but mounts the filter outside all filters in Seam ... sometimes not what you want.

You could as well (or even better I would say) let Seam handle this for you. Just annotate your filter like this:

@Scope(ScopeType.APPLICATION)
@Name("timingFilter")
@BypassInterceptors
@Install(value = false, precedence = Install.APPLICATION)
@Filter
public class TimingFilter extends AbstractFilter {
.
.
.
}

Note that what we say above is that we don't want to install the filter by default (@Install(value=false ... )). This gives you the opportunity to instead define in components.xml whether you want the filter on or off for this particular config. For instance I have this filter turned on locally, in dev- and in test-environments, but not on stage or in prod.

For instance my local version of components.xml looks like this:

<component class="se.reco.web.filter.TimingFilter">
    <property name="regexUrlPattern">(^/.*.seam)|(^/[0-9a-zA-ZåäöÅÄÖ\-/]+$)</property>
    <property name="disabled">false</property>
    <property name="output">SCREEN</property>
</component>

See more examples of how @Filter is being used in some of the example applications provided with Seam.

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 ...

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.

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

Adam:

This is really quite cool. I don't know if there is any similar way to achieve this with the seam taglib (or with facelets). If not, I think it should be included. Pete?

The problem is that it alters the semantics of EL somewhat. Can you file a JIRA issue, and see how many votes it collects?

https://jira.jboss.org/jira/browse/JBSEAM-3428

Pete Muir wrote on Sep 17, 2008 11:22:
The problem is that it alters the semantics of EL somewhat. Can you file a JIRA issue, and see how many votes it collects?

How does it alter the semantics of EL? The implementation is really straightforward :).

-- Adam

EL is designed around the idea of late evaluation, and so you don't need to worry about inadventently extending the life of an object beyond its intended scope. Can you post a link to the source?

Hello,

the sources are in my private repo, but here's a package of them: link

The let-tag states explicitly that it uses eager. instead of lazy evaluation. Also, I guess it would be possible to write a proxy which evaluates the value binding the first time it is accesed and stores it for later usage.

btw.: I think e-mail notifications don't work :). I have the preference checked in my preferences, but I don't get any notifications.

Adam

I guess lack of http confused the wiki software and turned it to a file not found link. Here's the link again: link, and in text format just in case: http://www.warski.org/let-tag-sources.tar.gz

Adam

Yup, but people often don't read the docs. I suggest you host it as an external project for now - lets see how it gets on...

You only get email notifications if you are the topic author :(