Logging duration of createView, buildView and renderView

Sometimes you'd like to measure how long JSF is taking to create, build and render the view. You can achieve this with a custom ViewDeclarationLanguage wrapper like below:

package com.example;

import java.io.IOException;
import java.util.logging.Logger;

import javax.faces.component.UIViewRoot;
import javax.faces.context.FacesContext;
import javax.faces.view.ViewDeclarationLanguage;
import javax.faces.view.ViewDeclarationLanguageWrapper;

public class VdlLogger extends ViewDeclarationLanguageWrapper {

    private static final Logger logger = Logger.getLogger(VdlLoggerFactory.class.getName());

    private ViewDeclarationLanguage wrapped;

    public VdlLogger(ViewDeclarationLanguage wrapped) {
        this.wrapped = wrapped;
    }

    @Override
    public UIViewRoot createView(FacesContext context, String viewId) {
        long start = System.nanoTime();
        UIViewRoot view = super.createView(context, viewId);
        long end = System.nanoTime();
        logger.info(String.format("create %s: %.6fms", viewId, (end - start) / 1e6));
        return view;
    }

    @Override
    public void buildView(FacesContext context, UIViewRoot view) throws IOException {
        long start = System.nanoTime();
        super.buildView(context, view);
        long end = System.nanoTime();
        logger.info(String.format("build %s: %.6fms", view.getViewId(), (end - start) / 1e6));
    }

    @Override
    public void renderView(FacesContext context, UIViewRoot view) throws IOException {
        long start = System.nanoTime();
        super.renderView(context, view);
        long end = System.nanoTime();
        logger.info(String.format("render %s: %.6fms", view.getViewId(), (end - start) / 1e6));
    }

    @Override
    public ViewDeclarationLanguage getWrapped() {
        return wrapped;
    }

}

In order to get it to run, create the below factory:

package com.example;

import javax.faces.view.ViewDeclarationLanguage;
import javax.faces.view.ViewDeclarationLanguageFactory;

public class VdlLoggerFactory extends ViewDeclarationLanguageFactory {

    private ViewDeclarationLanguageFactory wrapped;

    public VdlLoggerFactory(ViewDeclarationLanguageFactory wrapped) {
        this.wrapped = wrapped;
    }

    @Override
    public ViewDeclarationLanguage getViewDeclarationLanguage(String viewId) {
        return new VdlLogger(wrapped.getViewDeclarationLanguage(viewId));
    }

    @Override
    public ViewDeclarationLanguageFactory getWrapped() {
        return wrapped;
    }

}

And register it as below in faces-config.xml:

<factory>
    <view-declaration-language-factory>com.example.VdlLoggerFactory</view-declaration-language-factory>
</factory>

The createView() is the step of creating the concrete UIViewRoot instance based on <f:view> and <f:metadata> tags present in the view. When using Facelets (XHTML) as view, during this step all associated XHTML files will be parsed ("compiled") by the SAX parser and cached for a time as defined in the context parameter javax.faces.FACELETS_REFRESH_PERIOD. So it may happen that this step is one time relatively slow and the other time blazing fast. Use a value of -1 to cache them infinitely. When using Mojarra 2.2.11 or newer and the context parameter javax.faces.PROJECT_STAGE is already set to its default value of Production, then the refresh period already defaults to -1.

The buildView() is the step of populating the JSF component tree (the getChildren() of UIViewRoot) based on the view composition. During this step, all taghandlers (JSTL and friends) are executed and all EL expressions in those taghandlers and component's id and binding attributes are evaluated (for detail, see also JSTL in JSF2 Facelets... makes sense?). So if backing beans are constructed for first time during view build time and run some expensive business logic during e.g. @PostConstruct, then it may happen that this step is time consuming.

The renderView() is the step of generating the HTML output based on JSF component tree and the model, starting with UIViewRoot#encodeAll(). So if backing beans are constructed for first time during view render time and run some expensive business logic during e.g. @PostConstruct, then it may happen that this step is time consuming.

If a JSF page is loading slow in browser even though the above measurements run in milliseconds, then chances are big that the generated HTML DOM tree is simply big/bloated, and/or that the webbrowser is incapable of dealing with big HTML DOM trees, and/or that some JavaScript is inefficient on big HTML DOM trees. You'd then best profile the performance in the client side instead. For example, particularly Internet Explorer is slow with tables on big HTML DOM trees, and jQuery is slow with commaseparated selectors on big HTML DOM trees. Solutions would then be introducing filtering/pagination, and splitting into multiple selectors and passing each through a (callback) function, respectively.