jsf 2 - Measure the render time of a JSF view after a server request

Question

I would like to measure the rendering time of a JSF application. Because of out of my power reasons, the application can't be populated with logs.

Therefore, my question would be, is there any way in which I can measure the rendering time of the application after doing a certain action that includes a back-end(server) call using any browser?

So far,after using the Chrome Developer Tools,I spotted the following. On the Network tab, each request has the "Time" displayed. In addition, after selecting a certain entry, on the "Timing" tab, a more detailed visualization it's displayed. Now, I can tell from that that the "Waiting" that the round-trip to the server it's captured here, but what about the actual rendering time.

Assuming that the whole request took 1sec, and the Waiting section it's 500ms, can I deduct that the rendering it's the 1sec-500ms ? I assume not, thats why I am asking this question.

Long story short, I would need to know from the browser, for a certain request how long was the server processing and how long was the actual UI rendering.

Any tips would be greatly appreciated. Thank you.

Answer 1

You can do that with a custom ViewDeclarationLanguage whereby you measure the createView(), buildView(), renderView() and if necessary restoreView() methods.

Here's a kickoff example:

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;
    }

}

To get it to run, create the below factory:

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> present in the view files. When using Facelets (XHTML) as view, during this step all associated XHTML files will be parsed by the SAX parser and cached for a time as defined in javax.faces.FACELETS_REFRESH_PERIOD. So it may happen that it's one time relatively slow and the other time blazing fast.

The buildView() is the step of populating the JSF component tree (the getChildren() of UIViewRoot) based on the view (XHTML) 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 invoking business logic during @PostConstruct, then it may happen that this 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 invoking business logic during @PostConstruct, then it may happen that this is time consuming.

If backing beans are incorrectly performing business logic in getter methods instead of in @PostConstruct or any other one-time-occurring life cycle event listener, then it may happen that this consumes yet more time. See also Why JSF calls getters multiple times.