Ideas on page load time measurements

Question

The question is - how do you measure the time of page load, which technics you use, which recomendations can you give, and what positive and negative experience do you have.

The trouble is that even light pages in jsf can take up to 10 seconds to load. These pages don't require any evaluations, resources on rendering, etc. The obvious answer - it is in the queue on rendering... Ok, but may be something else?

Seems, it is needed to measure time starting from the request, including rendering, evaluations, data transfer time, client-side rendering time, etc.

Do you have any well working ways, tool chains, tools for a full lifetime trace of time of the page in JSF?

Glassfish-3, JSF-2 is used. Machine with 64 CPUs.

Answer 1

Here is a simple custom solution I've just made and tested. It provides some statistics on execution and rendering time. Of course all informations are only from serverside processing.

Result example :

Date                     ID request  URL                                  Phase              Execution time
2013-05-16 21:10:29.781  34          http://localhost:8080/web/page.jspx  RESTORE_VIEW 1     15
2013-05-16 21:10:29.796  34          http://localhost:8080/web/page.jspx  RENDER_RESPONSE 6  4438
2013-05-16 21:10:39.437  35          http://localhost:8080/web/page.jspx  RESTORE_VIEW 1     16
2013-05-16 21:10:39.453  35          http://localhost:8080/web/page.jspx  RENDER_RESPONSE 6  3937

The implementation is pretty straigth forward. First you have ton configure a PhaseListener inside faces-config.xml

<lifecycle>
    <phase-listener>com.spectotechnologies.jsf.phaselisteners.PhaseProcessesAnalyserListener</phase-listener>
</lifecycle>

Here is helper class that keep information on each processing :

package com.spectotechnologies.website.common.helper;

import java.util.Date;
import javax.faces.event.PhaseId;

/**
 *
 * @author Alexandre Lavoie
 */
public class PhaseProcess
{
    private int m_nIDRequest;
    private String m_sURL;
    private Date m_oStart;
    private Date m_oEnd;
    private PhaseId m_oPhase;

    public void setIdRequest(int p_nIDRequest)
    {
        m_nIDRequest = p_nIDRequest;
    }

    public int getIdRequest()
    {
        return m_nIDRequest;
    }

    public void setUrl(String p_sURL)
    {
        m_sURL = p_sURL;
    }

    public String getUrl()
    {
        return m_sURL;
    }

    public void setStart(Date p_oStart)
    {
        m_oStart = p_oStart;
    }

    public Date getStart()
    {
        return m_oStart;
    }

    public void setEnd(Date p_oEnd)
    {
        m_oEnd = p_oEnd;
    }

    public Date getEnd()
    {
        return m_oEnd;
    }

    public void setPhase(PhaseId p_oPhase)
    {
        m_oPhase = p_oPhase;
    }

    public PhaseId getPhase()
    {
        return m_oPhase;
    }

    public long getExecutionTime()
    {
        long lExecutionTime = -1;

        if(getEnd() != null)
        {
            lExecutionTime = getEnd().getTime() - getStart().getTime();
        }

        return lExecutionTime;
    }
}

Here is the class with the business logic, note that for the moment the stats will only grow and it is never deleted, could be a nice update to keep only last hour for example :

package com.spectotechnologies.website.common.helper;

import java.util.ArrayList;
import java.util.Date;
import java.util.List;
import javax.faces.context.FacesContext;
import javax.faces.event.PhaseId;

/**
 *
 * @author Alexandre Lavoie
 */
public class PhaseProcesses
{
    private List<PhaseProcess> m_lItems = new ArrayList();
    private int m_nNextIDRequest = 0;

    public static PhaseProcesses getInstance()
    {
        FacesContext oFaces = FacesContext.getCurrentInstance();

        PhaseProcesses oPhaseProcesses = (PhaseProcesses)oFaces.getExternalContext().getSessionMap().get("sessionPhaseProcesses");

        if(oPhaseProcesses == null)
        {
            oPhaseProcesses = new PhaseProcesses();

            FacesContext.getCurrentInstance().getExternalContext().getSessionMap().put("sessionPhaseProcesses",oPhaseProcesses);
        }

        return oPhaseProcesses;
    }

    public void set(int p_nIDRequest, String p_sURL, PhaseId p_oPhase, int p_nType)
    {
        PhaseProcess oPhaseProcess;

        // Phase start
        switch(p_nType)
        {
            case 0:
                // start
                oPhaseProcess = new PhaseProcess();

                oPhaseProcess.setIdRequest(p_nIDRequest);
                oPhaseProcess.setUrl(p_sURL);
                oPhaseProcess.setPhase(p_oPhase);
                oPhaseProcess.setStart(new Date());

                if(m_lItems.size() > 250)
            {
                m_lItems.remove(0);
            }

                m_lItems.add(oPhaseProcess);
                break;
            case 1:
                // end
                for(int nPhase = m_lItems.size() - 1;nPhase >= 0;nPhase--)
                {
                    if(m_lItems.get(nPhase).getIdRequest() == p_nIDRequest && m_lItems.get(nPhase).getPhase() == p_oPhase)
                    {
                        m_lItems.get(nPhase).setEnd(new Date());
                        break;
                    }
                }
                break;
        }
    }

    public List<PhaseProcess> getList()
    {
        return m_lItems;
    }

    public Integer getNextIDRequest()
    {
        return m_nNextIDRequest++;
    }
}

Here is the famous PhaseListener, where informations are tracked :

package com.spectotechnologies.jsf.phaselisteners;

import com.spectotechnologies.website.common.helper.PhaseProcesses;
import java.net.URLEncoder;
import java.util.Enumeration;
import javax.faces.context.FacesContext;
import javax.faces.event.PhaseEvent;
import javax.faces.event.PhaseId;
import javax.faces.event.PhaseListener;
import javax.servlet.http.HttpServletRequest;

/**
 *
 * @author Alexandre Lavoie
 */
public class PhaseProcessesAnalyserListener implements PhaseListener
{
    @Override
    public PhaseId getPhaseId()
    {
        return PhaseId.ANY_PHASE;
    }

    @Override
    public void beforePhase(PhaseEvent p_oEvent)
    {
        PhaseProcesses.getInstance().set(getIDRequest(),getURL(),p_oEvent.getPhaseId(),0);
    }

    @Override
    public void afterPhase(PhaseEvent p_oEvent)
    {
        PhaseProcesses.getInstance().set(getIDRequest(),getURL(),p_oEvent.getPhaseId(),1);
    }

    private Integer getIDRequest()
    {
        Integer iIDRequest = (Integer)FacesContext.getCurrentInstance().getExternalContext().getRequestMap().get("idrequest");

        if(iIDRequest == null)
        {
            iIDRequest = PhaseProcesses.getInstance().getNextIDRequest();

            FacesContext.getCurrentInstance().getExternalContext().getRequestMap().put("idrequest",iIDRequest);
        }

        return iIDRequest;
    }

    private String getURL()
    {
        Enumeration<String> lParameters;
        String sParameter;
        StringBuilder sbURL = new StringBuilder();
        Object oRequest = FacesContext.getCurrentInstance().getExternalContext().getRequest();

        try
        {
            if(oRequest instanceof HttpServletRequest)
            {
                sbURL.append(((HttpServletRequest)oRequest).getRequestURL().toString());

                lParameters = ((HttpServletRequest)oRequest).getParameterNames();

                if(lParameters.hasMoreElements())
                {
                    if(!sbURL.toString().contains("?"))
                    {
                        sbURL.append("?");
                    }
                    else
                    {
                        sbURL.append("&");
                    }
                }

                while(lParameters.hasMoreElements())
                {
                    sParameter = lParameters.nextElement();

                    sbURL.append(sParameter);
                    sbURL.append("=");
                    sbURL.append(URLEncoder.encode(((HttpServletRequest)oRequest).getParameter(sParameter),"UTF-8"));

                    if(lParameters.hasMoreElements())
                    {
                        sbURL.append("&");
                    }
                }
            }
        }
        catch(Exception e)
        {
            // Do nothing
        }

        return sbURL.toString();
    }
}

Finally, here is the simple page I created to show statistics. A good improvement could be to add averages on pages processing, a per-idrequest processing time also.

Bean code :

package com.spectotechnologies.website.common.beans;

import com.spectotechnologies.website.common.helper.PhaseProcess;
import com.spectotechnologies.website.common.helper.PhaseProcesses;
import java.util.List;
import javax.faces.bean.ManagedBean;
import javax.faces.bean.RequestScoped;

/**
 *
 * @author Alexandre Lavoie
 */
@ManagedBean
@RequestScoped
public class PagesStatisticsActions
{
    public List<PhaseProcess> getList()
    {
        return PhaseProcesses.getInstance().getList();
    }
}

View code :

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html xmlns="http://www.w3.org/1999/xhtml"
    xmlns:ui="http://java.sun.com/jsf/facelets"
    xmlns:h="http://java.sun.com/jsf/html"
    xmlns:f="http://java.sun.com/jsf/core">

    <f:view contentType="application/xhtml+xml">
        <h:head>
            <meta http-equiv="Content-Type" content="application/xhtml+xml;charset=UTF-8" />
        </h:head>

        <h:body>
            <h:dataTable value="#{pagesStatisticsActions.list}" var="item">
                <h:column>
                    <f:facet name="header">
                        Date
                    </f:facet>

                    <h:outputText value="#{item.start}">
                        <f:convertDateTime timeZone="America/Montreal" pattern="yyyy-MM-dd HH:mm:ss.SSS" />
                    </h:outputText>
                </h:column>

                <h:column>
                    <f:facet name="header">
                        ID request
                    </f:facet>

                    #{item.idRequest}
                </h:column>

                <h:column>
                    <f:facet name="header">
                        URL
                    </f:facet>

                    #{item.url}
                </h:column>

                <h:column>
                    <f:facet name="header">
                        Phase
                    </f:facet>

                    #{item.phase}
                </h:column>

                <h:column>
                    <f:facet name="header">
                        Execution time (ms)
                    </f:facet>

                    #{item.executionTime}
                </h:column>
            </h:dataTable>
        </h:body>
    </f:view>
</html>

UPDATE 1 :

• Added parameters in URL
• Added a limitation of 250 logs