Search code examples
jsftimingjsf-2.2phaselistener

How to present JSF phase timings on page

I've made a class that implements PhaseListener and prints the timing for each phase to a log. Now I'd like to print this to the JSF page instead, so I can see how long time each phase took when the page was rendered.

I don't know if it's even possible; maybe it's a chicken-and-egg problem?

Code

As LaurentG told me, it's not possible to achieve what I looked for. If someone's looking for the code to time phases though, here's one way to do it:

import javax.faces.event.PhaseEvent;
import javax.faces.event.PhaseId;
import javax.faces.event.PhaseListener;

public class LogPhaseListener implements PhaseListener {

    private long startTimeP1;
    private long startTimeP2;
    private long startTimeP3;
    private long startTimeP4;
    private long startTimeP5;
    private long startTimeP6;
    private long timeP1;
    private long timeP2;
    private long timeP3;
    private long timeP4;
    private long timeP5;
    private long timeP6;
    private long timeAll;

    @Override
    public void afterPhase(PhaseEvent event) {

        if (event.getPhaseId() == PhaseId.RESTORE_VIEW) {
            timeP1 = (long) ((System.nanoTime() - startTimeP1) * 0.000001);
            System.err.println("|     Phase 1 Execution time -- RESTORE_VIEW -- " + timeP1 + "ms");
        }
        if (event.getPhaseId() == PhaseId.APPLY_REQUEST_VALUES) {
            timeP2 = (long) ((System.nanoTime() - startTimeP2) * 0.000001);
            System.err.println("|     Phase 2 Execution time -- APPLY_REQUEST_VALUES -- " + timeP2 + "ms");
        }
        if (event.getPhaseId() == PhaseId.PROCESS_VALIDATIONS) {
            timeP3 = (long) ((System.nanoTime() - startTimeP3) * 0.000001);
            System.err.println("|     Phase 3 Execution time -- PROCESS_VALIDATIONS -- " + timeP3 + "ms");
        }
        if (event.getPhaseId() == PhaseId.UPDATE_MODEL_VALUES) {
            timeP4 = (long) ((System.nanoTime() - startTimeP4) * 0.000001);
            System.err.println("|     Phase 4 Execution time -- UPDATE_MODEL_VALUES -- " + timeP4 + "ms");
        }
        if (event.getPhaseId() == PhaseId.INVOKE_APPLICATION) {
            timeP5 = (long) ((System.nanoTime() - startTimeP5) * 0.000001);
            System.err.println("|     Phase 5 Execution time -- INVOKE_APPLICATION -- " + timeP5 + "ms");
        }
        if (event.getPhaseId() == PhaseId.RENDER_RESPONSE) {
            timeP6 = (long) ((System.nanoTime() - startTimeP6) * 0.000001);
            timeAll = (long) ((System.nanoTime() - startTimeP1) * 0.000001);

            System.err.println("|     Phase 6 Execution time -- RENDER_RESPONSE -- " + timeP6 + "ms");
            System.err.println("|     Phase X Execution time -- ALL_PHASES -- " + timeAll + "ms");
        }
    }

    @Override
    public void beforePhase(PhaseEvent event) {

        if (event.getPhaseId() == PhaseId.RESTORE_VIEW) {
            startTimeP1 = System.nanoTime();
        }
        if (event.getPhaseId() == PhaseId.APPLY_REQUEST_VALUES) {
            startTimeP2 = System.nanoTime();
        }
        if (event.getPhaseId() == PhaseId.PROCESS_VALIDATIONS) {
            startTimeP3 = System.nanoTime();
        }
        if (event.getPhaseId() == PhaseId.UPDATE_MODEL_VALUES) {
            startTimeP4 = System.nanoTime();
        }
        if (event.getPhaseId() == PhaseId.INVOKE_APPLICATION) {
            startTimeP5 = System.nanoTime();
        }
        if (event.getPhaseId() == PhaseId.RENDER_RESPONSE) {
            startTimeP6 = System.nanoTime();
        }
    }

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

}

And add the following to faces-config.xml

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

Original code found at Andy Gibsons site: http://www.andygibson.net/blog/tutorial/timing-jsf-requests-using-a-phase-listener/

Solution

  • Obviously, you can't print the time of the RENDER_RESPONSE phase in the page you want to get the rendering time. But you could save the timing in a view or session scope [1] bean and call it later (e.g. using Ajax) in your page.

    Alternative: stores the process times in a bean and use it to render a special debug page where you can monitor all the timings of all the rendered page. This way you also don't mix debug information in a productive page.

    By the way, I find your idea quite strange. I usually simply look at the logs in the server logs. I also always configure a custom PhaseListener which logs the processing time for each phase and configure it to log times in a special log (e.g. perf.log).

    Links: