Wednesday, January 1, 2014

Measuring Execution Time of ADF Faces Lifecycle

Happy New Year first of all to all of you.

Recently in one of my project, I have a requirement to measure the amount of time that my application takes to render the view. Googling not much reveals anything, except one solution[1] which is for applicable for JSF. Although ADF is built upon JSF Framework, the Lifecycle of ADF is much bigger than JSF so I can't really use that approach completely. But the building block of my solution starts from there.

In my solution I dealt with the class oracle.adf.controller.v2.lifecycle.PagePhaseListener. It is an interface implemented by the objects that wish to be notified before and after the processing of each of the ADF Page Lifecycle phase.

First you need to register your custom page phase listener through the adf-settings.xml. Follow the instruction given in the second link of the reference section[2]. Here is my adf-settings.xml:
<?xml version="1.0" encoding="UTF-8" ?>
<adf-settings xmlns="http://xmlns.oracle.com/adf/settings">
 <adfc-controller-config xmlns="http://xmlns.oracle.com/adf/controller/config">
  <lifecycle>
   <phase-listener>
    <listener-id>PhaseProcessingTimeAnalyserListener</listener-id>
    <class>com.myproject.web.lifecycle.PhaseProcessingTimeAnalyserListener</class>
   </phase-listener>
  </lifecycle>
 </adfc-controller-config> 
</adf-settings>
The class PhaseProcessingTimeAnalyserListener pushes the phase which is currently executing into a collection from the method beforePhase and kind of pop it from that collection from the method afterPhase. The code is pretty much self explanatory.
import java.io.Serializable;
import java.net.URLEncoder;
import java.util.Enumeration;
import java.util.Map;

import javax.faces.context.FacesContext;
import javax.servlet.http.HttpServletRequest;

import oracle.adf.controller.v2.lifecycle.Lifecycle;
import oracle.adf.controller.v2.lifecycle.PagePhaseEvent;
import oracle.adf.controller.v2.lifecycle.PagePhaseListener;
import oracle.adf.share.ADFContext;

import com.mhis.posm.web.lifecycle.helper.PhaseProcessor;

/**
 * Class PhaseProcessingTimeAnalyserListener calculates the execution time of each Phase of ADF
 * @author TapasB
 */
public class PhaseProcessingTimeAnalyserListener implements PagePhaseListener, Serializable {

 private static final long serialVersionUID = 6814928970314659328L;

 /**
  * Method beforePhase notifies the listener before the execution of a specific phase of the ADF Page Lifecycle.
  * @author TapasB
  * @param phaseEvent
  * @see oracle.adf.controller.v2.lifecycle.PagePhaseListener#beforePhase(oracle.adf.controller.v2.lifecycle.PagePhaseEvent)
  */
 @Override
 public void beforePhase(PagePhaseEvent phaseEvent) {
  int phaseId = phaseEvent.getPhaseId();
  String phaseName = Lifecycle.getPhaseName(phaseId);
  PhaseProcessor.getInstance().process(getRequestId(), getURL(), phaseId, phaseName, PhaseProcessor.PhaseType.BEGIN);
 }

 /**
  * Method afterPhase notifies the listener after the execution of a specific phase of the ADF Page Lifecycle.
  * @author TapasB
  * @param phaseEvent
  * @see oracle.adf.controller.v2.lifecycle.PagePhaseListener#afterPhase(oracle.adf.controller.v2.lifecycle.PagePhaseEvent)
  */
 @Override
 public void afterPhase(PagePhaseEvent phaseEvent) {
  int phaseId = phaseEvent.getPhaseId();
  String phaseName = Lifecycle.getPhaseName(phaseId);
  PhaseProcessor.getInstance().process(getRequestId(), getURL(), phaseId, phaseName, PhaseProcessor.PhaseType.END);
 }

 /**
  * Method getRequestId generates and returns an unique ID value for each Request
  * @author TapasB
  * @return requestId
  */
 private Integer getRequestId() {
  @SuppressWarnings("unchecked")
  Map<String, Object> requestScope = ADFContext.getCurrent().getRequestScope();
  Integer requestId = (Integer) requestScope.get("requestId");

  if (requestId == null) {
   requestId = PhaseProcessor.getInstance().getNextRequestId();
   requestScope.put("requestId", requestId);
  }

  return requestId;
 }

 /**
  * Method getURL returns the URL in which the application is requested
  * @author TapasB
  * @return a String URL
  */
 private String getURL() {
  Enumeration<String> parameterNames = null;
  String parameterName = null;
  StringBuilder urlBuilder = new StringBuilder();
  Object request = FacesContext.getCurrentInstance().getExternalContext().getRequest();

  try {
   if (request instanceof HttpServletRequest) {
    HttpServletRequest servletRequest = (HttpServletRequest) request;
    urlBuilder.append(servletRequest.getRequestURL().toString());
    parameterNames = servletRequest.getParameterNames();

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

    while (parameterNames.hasMoreElements()) {
     parameterName = parameterNames.nextElement();

     urlBuilder.append(parameterName);
     urlBuilder.append("=");
     urlBuilder.append(URLEncoder.encode(servletRequest.getParameter(parameterName), "UTF-8"));

     if (parameterNames.hasMoreElements()) {
      urlBuilder.append("&");
     }
    }
   }
  } catch (Exception ex) {
  }

  return urlBuilder.toString();
 }
}
The class PhaseProcessor is Session Singleton.  One instance per session so it is kept in the session scope. Here it is:
import java.io.Serializable;
import java.util.ArrayList;
import java.util.Date;
import java.util.List;
import java.util.ListIterator;
import java.util.Map;
import java.util.concurrent.atomic.AtomicInteger;

import oracle.adf.share.ADFContext;

import com.edifixio.osrd.generic.log.Log;

/**
 * Class PhaseProcessor processes the Phase execution time
 * @author TapasB
 */
public class PhaseProcessor implements Serializable {

 private static final long serialVersionUID = 6658181867505616109L;

 private List<Phase> phases = new ArrayList<Phase>();
 private AtomicInteger nextRequestId = new AtomicInteger(1);

 /**
  * Constructor PhaseProcessor is private
  * @author TapasB
  */
 private PhaseProcessor() {

 }

 /**
  * Class PhaseType
  * @author TapasB
  */
 public static enum PhaseType {
  BEGIN,
  END;
 }

 /**
  * Method getInstance returns a Session Instance of this class 
  * @author TapasB
  * @return an PhaseProcessor instance
  */
 public static PhaseProcessor getInstance() {
  @SuppressWarnings("unchecked")
  Map<String, Object> sessionScope = ADFContext.getCurrent().getSessionScope();
  PhaseProcessor phaseProcessor = (PhaseProcessor) sessionScope.get("phases");

  if (phaseProcessor == null) {
   phaseProcessor = new PhaseProcessor();
   sessionScope.put("phases", phaseProcessor);
  }

  return phaseProcessor;
 }

 /**
  * Method process processes the {@link Phase} 
  * @author TapasB
  * @param requestId - the unique ID for each request
  * @param url - the url in which the application is requested
  * @param phaseId - ADF's Phase ID
  * @param phaseName - ADF's Phase Name
  * @param phaseType - BEGIN or END
  */
 public void process(int requestId, String url, int phaseId, String phaseName, PhaseType phaseType) {
  Phase phase;

  switch (phaseType) {
   case BEGIN:
    phase = new Phase();

    phase.setRequestId(requestId);
    phase.setUrl(url);
    phase.setPhaseId(phaseId);
    phase.setPhaseName(phaseName);
    phase.setStartTime(new Date());

    phases.add(phase);

    Log.info(this, "The Phase: " + phase.getPhaseName(phaseId) + " begins. Requested URL: " + phase.getUrl());
    break;

   case END:
    ListIterator<Phase> phaseIterator = phases.listIterator(phases.size());

    while (phaseIterator.hasPrevious()) {
     phase = phaseIterator.previous();

     if (phase.getRequestId() == requestId && phase.getPhaseId() == phaseId && phase.getPhaseName().equals(phaseName)) {
      phase.setEndTime(new Date());
      Log.info(this, "The Phase: " + phase.getPhaseName(phaseId) + " ends with execution time: '" + (phase.getEndTime().getTime() - phase.getStartTime().getTime()) + "' millisecondes. Requested URL: " + phase.getUrl());
      phaseIterator.remove();
      break;
     }

    }

    break;
  }
 }

 /**
  * Method getNextRequestId returns and increment the unique ID 
  * @author TapasB
  * @return the ID
  */
 public Integer getNextRequestId() {
  return nextRequestId.getAndIncrement();
 }
}
In the method process it switches the control between two cases. This switching is based on the enum value of the type PhaseType. The idea is, when the phase begins, it creates a new instance of Phase, add it into the List<Phase> phases and log it; and when the phase ends it traverse backward the list, matches the phase with the given requestId, phaseId and phaseName; and when the match is found, it set the endTime to that matched instance of Phase, log it and then remove that instance from the list.
Note that the nextRequestId is an AtomicInteger so the value get updated atomically.

Lastly the model class Phase:
import java.io.Serializable;
import java.util.Date;

import oracle.adf.controller.faces.lifecycle.JSFLifecycle;

/**
 * Class Phase represent a phase
 * @author TapasB
 */
public class Phase implements Serializable {

 private static final long serialVersionUID = -461595462579265128L;

 private int requestId;
 private String url;
 private Date startTime;
 private Date endTime;
 private int phaseId;
 private String phaseName;

 /**
  * Constructor Phase is default
  * @author TapasB
  */
 public Phase() {

 }

 /**
  * Method getRequestId returns requestId
  * @author TapasB
  * @return requestId
  */
 public int getRequestId() {
  return requestId;
 }

 /**
  * Method setRequestId sets the requestId
  * @author TapasB
  * @param requestId the requestId to set
  */
 public void setRequestId(int requestId) {
  this.requestId = requestId;
 }

 /**
  * Method getUrl returns url
  * @author TapasB
  * @return url
  */
 public String getUrl() {
  return url;
 }

 /**
  * Method setUrl sets the url
  * @author TapasB
  * @param url the url to set
  */
 public void setUrl(String url) {
  this.url = url;
 }

 /**
  * Method getStartTime returns startTime
  * @author TapasB
  * @return startTime
  */
 public Date getStartTime() {
  return startTime;
 }

 /**
  * Method setStartTime sets the startTime
  * @author TapasB
  * @param startTime the startTime to set
  */
 public void setStartTime(Date startTime) {
  this.startTime = startTime;
 }

 /**
  * Method getEndTime returns endTime
  * @author TapasB
  * @return endTime
  */
 public Date getEndTime() {
  return endTime;
 }

 /**
  * Method setEndTime sets the endTime
  * @author TapasB
  * @param endTime the endTime to set
  */
 public void setEndTime(Date endTime) {
  this.endTime = endTime;
 }

 /**
  * Method getPhaseId returns phaseId
  * @author TapasB
  * @return phaseId
  */
 public int getPhaseId() {
  return phaseId;
 }

 /**
  * Method setPhaseId sets the phaseId
  * @author TapasB
  * @param phaseId the phaseId to set
  */
 public void setPhaseId(int phaseId) {
  this.phaseId = phaseId;
 }

 /**
  * Method getPhaseName returns phaseName
  * @author TapasB
  * @return phaseName
  */
 public String getPhaseName() {
  return phaseName;
 }

 /**
  * Method setPhaseName sets the phaseName
  * @author TapasB
  * @param phaseName the phaseName to set
  */
 public void setPhaseName(String phaseName) {
  this.phaseName = phaseName;
 }

 /**
  * Method getPhaseName returns the name of the Phase
  * @author TapasB
  * @param phaseId
  * @return the phase name
  */
 public String getPhaseName(int phaseId) {
  if (phaseId == JSFLifecycle.INIT_CONTEXT_ID) {
   return "INIT_CONTEXT";
  } else if (phaseId == JSFLifecycle.PREPARE_MODEL_ID) {
   return "PREPARE_MODEL";
  } else if (phaseId == JSFLifecycle.APPLY_INPUT_VALUES_ID) {
   return "APPLY_INPUT_VALUES";
  } else if (phaseId == JSFLifecycle.VALIDATE_INPUT_VALUES_ID) {
   return "VALIDATE_INPUT_VALUES";
  } else if (phaseId == JSFLifecycle.PROCESS_UPDATE_MODEL_ID) {
   return "PROCESS_UPDATE_MODEL";
  } else if (phaseId == JSFLifecycle.VALIDATE_MODEL_UPDATES_ID) {
   return "VALIDATE_MODEL_UPDATES";
  } else if (phaseId == JSFLifecycle.PROCESS_COMPONENT_EVENTS_ID) {
   return "PROCESS_COMPONENT_EVENTS";
  } else if (phaseId == JSFLifecycle.METADATA_COMMIT_ID) {
   return "METADATA_COMMIT";
  } else if (phaseId == JSFLifecycle.PREPARE_RENDER_ID) {
   return "PREPARE_RENDER";
  } else if (phaseId == JSFLifecycle.JSF_RESTORE_VIEW_ID) {
   return "RESTORE_VIEW";
  } else if (phaseId == JSFLifecycle.JSF_APPLY_REQUEST_VALUES_ID) {
   return "JSF_APPLY_REQUEST_VALUES";
  } else if (phaseId == JSFLifecycle.JSF_PROCESS_VALIDATIONS_ID) {
   return "JSF_PROCESS_VALIDATIONS";
  } else if (phaseId == JSFLifecycle.JSF_UPDATE_MODEL_VALUES_ID) {
   return "JSF_UPDATE_MODEL_VALUES";
  } else if (phaseId == JSFLifecycle.JSF_INVOKE_APPLICATION_ID) {
   return "JSF_INVOKE_APPLICATION";
  } else {
   return "JSF_RENDER_RESPONSE";
  }
 }
}
It is a simple POJO and pretty much self explanatory. Though I would like to explain the method public String getPhaseName(int phaseId). As you can see this method uses a class oracle.adf.controller.faces.lifecycle.JSFLifecycle; it is kind of constant class used by ADF Controllers define the phase ids for the set of phases of the ADF Page Lifecycle that match the JSF lifecycle.

I would greatly appreciate your comments and share.

References:
  1. Ideas on page load time measurements
  2. Understanding the Fusion Page Lifecycle
  3. How to configure an ADF Phase Listener and where to put the file

No comments:

Post a Comment