Locating Performance Tuning JSF 4

Courtesy of Kees Broenink, here is some step-by-step advice on how to locate the source of slow performance in a JSF page.

When experiencing a bad performance you must first see if it is client, network or server.
I will explain how to measure the server. If you are working on a LAN the network is most of the time not the bottleneck. This leaves you with a way to have an idea about the client: total - server = client.

The server can best be measured by looking at the 6 JSF lifecycle phases.

The following log4j setting will show the lifecycle information:

   
    log4j.logger.org.apache.myfaces.lifecycle=DEBUG

If most time is spent in phase 1 or 6 then you can try to bring the number of components down or you enable the KEEP_STATE_IN_SESSION functionality in web.xml.

When one of the other phases is slow you must check your own Backing Bean code which probably goes to a database or other slow service. The following overview will tell you what phase is used to execute the Backing Bean listener code:

Phase 2 (apply request values):
* selectListener
* sortListener
* dragListener
* dropListener
* populateListener

Phase 3 (process validations):
* beforeUpdateListener
* valueChangeListener

Phase 4 (update model fields which means: call the setters of the attribute value bindings):
* updateListener

Phase 5 (invoke application):
* actionListener
* customActionListener
* action

When the event listener has an immediate option the phase will change if the default value of the immediate changes:

By default selectImmediate is true which means phase 2 is the default for the selectListener but phase 5 can be forced by setting it to false.
By default immediate on commandButton and commandLink is false which means phase 5 is the default for the actionListener but phase 2 can be forced by setting it to true.
By default immediate on input components is false which means phase 3 is the default for the valueChangeListener but phase 2 can be forced by setting it to true.
By default customImmediate is false which means phase 5 is the default for the customActionListener but phase 2 can be forced by setting it to true.

Here is an example of what one application was logging:

2007-10-08 20:18:25,846 DEBUG - entering RESTORE_VIEW(1) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - exiting RESTORE_VIEW(1) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - entering APPLY_REQUEST_VALUES(2) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - exiting APPLY_REQUEST_VALUES(2) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - entering PROCESS_VALIDATIONS(3) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - exiting PROCESS_VALIDATIONS(3) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - entering UPDATE_MODEL_VALUES(4) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - exiting UPDATE_MODEL_VALUES(4) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:25,856 DEBUG - entering INVOKE_APPLICATION(5) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:27,618 DEBUG - exiting from lifecycle.execute in INVOKE_APPLICATION(5) because getRenderResponse is true from one of the after listeners
2007-10-08 20:18:27,618 DEBUG - entering RENDER_RESPONSE(6) in org.apache.myfaces.lifecycle.LifecycleImpl
2007-10-08 20:18:27,799 DEBUG - exiting RENDER_RESPONSE(6) in org.apache.myfaces.lifecycle.LifecycleImpl

Kees