Timing JSF Requests Using a Phase Listener

One easy way of determining how long it takes to return a page from Seam, and/or JSF is to use a phase listener. This phase listener below logs the end of each phase of the JSF lifecycle and measures the time from the start of the RESTORE_VIEW phase (the first phase in the lifecycle and the start of the request) to the end of the RENDER_RESPONSE phase which is the last one. Logging the end of each stage of the cycle lets you see what else is going on during each phase of the cycle.

public class LogPhaseListener implements PhaseListener {

	public long startTime;

	private static final LogProvider log = Logging
			.getLogProvider(LogPhaseListener.class);

	public void afterPhase(PhaseEvent event) {
		if (event.getPhaseId() == PhaseId.RENDER_RESPONSE) {
			long endTime = System.nanoTime();
			long diffMs = (long) ((endTime - startTime) * 0.000001);
			if (log.isDebugEnabled()) {
				log.debug("Execution Time = " + diffMs + "ms");
			}
		}
		if (log.isDebugEnabled()) {
			log.debug("Executed Phase " + event.getPhaseId());
		}
	}

	public void beforePhase(PhaseEvent event) {

		if (event.getPhaseId() == PhaseId.RESTORE_VIEW) {
			startTime = System.nanoTime();
		}
	}

	public PhaseId getPhaseId() {
		return PhaseId.ANY_PHASE;
	}

}

To use this, simply add the class to your project and insert a new phase listener in the faces-config.xml file.

  <lifecycle>
    <phase-listener>package.name.LogPhaseListener</phase-listener>
  </lifecycle>

While it may not be totally accurate, it at least gives you an idea of the scale of the duration of a request (i.e. 68ms versus 394ms). I’ve used this fairly effectively in a few projects to cut out some bottlenecks as well as comparing and contrasting different JSF frameworks.

7 thoughts on “Timing JSF Requests Using a Phase Listener

  1. I have a question, what if I want to log the total time spent to process all the phases, not the current one? What could be done to achieve this?

  2. This implementation does time the whole lifecycle from restore view to the completion of the rendering. Reading back the post, it does say it logs the end of each phase, but it only writes out the the log file the end of each phase.

    Cheers,

    Andy Gibson

  3. Hi, isn’t there only one instance of this and shared accross all users and requests which would then mean that the private field startTime will be overwritten with each request?

    1. Camilo Correa

      Agree with @Daniel… just one instance of listener. Just use this solution in a controlled envirnonment… never as diagnostic tool in production

  4. Hey Daniel,

    Yes, you are correct, this isn’t thread safe which I don’t worry about since I never deploy this into production. I just use it for development to see when I wrote some code that is slow. You could pop the timestamp into the session and read it back in when the phase is complete.

    Cheers,

    Andy Gibson

  5. better will be like this
    public void afterPhase(PhaseEvent event) {
    12 if (!log.isDebugEnabled()) return;
    09 if (event.getPhaseId() == PhaseId.RENDER_RESPONSE) {
    10 long endTime = System.nanoTime();
    11 long diffMs = (long) ((endTime – startTime) * 0.000001);
    13 log.debug(“Execution Time = ” + diffMs + “ms”);
    15 }
    17 log.debug(“Executed Phase ” + event.getPhaseId());
    19 }