Automating Performance Monitoring of a web application using AspectJ

Home / Blog / Java / Automating Performance Monitoring of a web application using AspectJ

There are tons of Performance monitoring tools available, so why to get your hands dirty writing code to do something similar. Here is the issue, finding performance issues before you ship a release out the door is a dedicated effort. A performance engineer runs a load test, and then analyzes the reports to find if the system is performing as per defined in SLA. If not, run the use case with the performance tool to find the bottleneck. It gets even worse, when the Performance tool itself adds a lot of overhead and slows the performance down. And overall procedure is deadly slow and time consuming. So, how can we automate the entire process, so we can gauge the performance of the application and compare with previous shipped releases, without going through this tedious process. Even better would be if we can find the component which is slowing down the entire application, down to the method level.

This is where AOP comes to rescue. I used AspectJ since the syntax is very similar to Java, and the learning curve is too small. The benefits, my original application code does not need any modification, just the JVM startup parameter to include aspectJWeaver.jar as my “-agent”, and my aspects jar in the classpath, and the magic happens using load time weaving. You can use other AOP frameworks.

Before I start, I assume that you have automated the use cases using Selenium or Canoe (or any other framework/tool), if not, its always a good idea so you can execute an Ant task to execute your entire test suite and also integrate it with the Continuous integration environment.

In a layered architecture, you have several components collaborating with each other. Ideally, they will have separate package names to identify which layer they belong to. Thats an implementation detail, but will help for reporting. I assume thats the case.

Lets start with the information we need to log for a usecase. Here is an execution record which I used based on my requirements.
This blog suggests how we can use an AOP framework for performance monitoring and is highly customized to a specific project. I am sure there are better ways to implement the same solution, but this was easy enough to code and execute with little overhead.


package com.brimllc.aspects.record;
 /**
 * This record keeps the information in a ThreadLocal for each request. A parser
 * can later parse this information. The idea is if method A calls B, B calls C, and C calls D, then this will record
   the time it took only in that method. Like, A took 50 milli seconds in whole, and B took 30 millis, so the time spent in 
   method A is just 20 millis.
 * 
 */
public class ExecutionRecord {

	// client IP address, can be fetched from request header
	private String myClientIP;
	
	// request sequence, a single request processing can call multiple methods. Used for reporting
	private int myRequestSequenceNumber;
	
	// user who invoked the request, fetched from cookie or request session, for reporting
	private String myUserId;

	// session id to match the same, used for reporting
	private String mySessionId;

	// use case scenario, can be fetched from cookie, used for reporting
	private String myUseCaseScenario;
	
	// use case suite, selenium or canoe suite name
	private String mySuiteName;
	
	// execution path
	private String myExecutionPath;
	
	// request uri, used for reporting
	private String myRequestURI;

	// package name, identify the layer in which this method resides
	private String myPackageName;

	// method name
	private String myMethodName;

	// method execution count
	private int myMethodExecutionCount;

	// start time
	protected long myStartExecutionTime;

	// end time
	protected long myEndExcecutionTime;

	// total execution time
	protected long myTotalExecutionTime;

	// parent method
	private String myParentMethod;
	
	// has children flag
	private boolean myHasChildren = false;
	
	// total execution time of children
	private long myChildrenTotalExecutionTime;

	

	public ExecutionRecord() {

	}

	public ExecutionRecord(String userId, String sessionId, String useCase,
			String packageName, String method, int executionCount,
			long startTime, long endTime) {
		this.myUserId = userId;
		this.mySessionId = sessionId;
		this.myUseCaseScenario = useCase;
		this.myPackageName = packageName;
		this.myMethodName = method;
		this.myMethodExecutionCount = executionCount;
		this.myStartExecutionTime = startTime;
		this.myEndExcecutionTime = endTime;
	}

	public String getUserId() {
		return myUserId;
	}

	public void setUserId(String myUserId) {
		this.myUserId = myUserId;
	}

	// other getter and setters for the properties ...........

	public long getTotalExecutionTime(){
		this.myTotalExecutionTime = this.myEndExcecutionTime - this.myStartExecutionTime;
		return this.myTotalExecutionTime;
	}
	
	public long getExactExecutionTime() {
		return this.myEndExcecutionTime
		- this.myStartExecutionTime - this.myChildrenTotalExecutionTime;		 
	}
    
	// the method in whose scope this method is getting called.
	public String getParentMethod() {
		return myParentMethod;
	}

	public void setParentMethod(String myParentMethod) {
		this.myParentMethod = myParentMethod;
	}

	// overridden toString to dump to the log file.
	public String toString() {
		StringBuffer buff = new StringBuffer(100);
		buff.append(this.getClientIP()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getSequenceNumber())
		.append("."+Thread.currentThread().getId()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getUserId())
				.append(PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getSessionId()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getUseCaseScenario()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getSuiteName()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getExecutionPath()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getRequestURI()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getPackageName()).append(
				PerformanceLogger.COLUMN_SEPARATOR);
		buff.append(this.getMethodName()).append(PerformanceLogger.
		 COLUMN_SEPARATOR);
		// buff.append(this.getParentMethod()).append(PerformanceLogger.
		//		 COLUMN_SEPARATOR);
		buff.append(this.getStartExecutionTime()).append(PerformanceLogger.
				 COLUMN_SEPARATOR);
		buff.append(this.getEndExecutionTime()).append(PerformanceLogger.
				 COLUMN_SEPARATOR);
		// For debugging purposes only, enable this for each method's cumulative execution time
		// Also enable the Performance Logger to add another column in the file for Cumulative Execution time
		//buff.append(this.getTotalExecutionTime()()).append(PerformanceLogger.
		//		 COLUMN_SEPARATOR);
		buff.append(this.getExactExecutionTime());
		
		return buff.toString();
	}

	public boolean hasChildren() {
		return myHasChildren;
	}

	public void setHasChildren(boolean myHasChildren) {
		this.myHasChildren = myHasChildren;
	}
	
	public long getChildrenTotalExecutionTime() {
		return myChildrenTotalExecutionTime;
	}

	public void setChildrenTotalExecutionTime(long myChildrenTotalExecutionTime) {
		this.myChildrenTotalExecutionTime = myChildrenTotalExecutionTime;
	}
	
}

Now, lets put some basic bone structure, which handles the before and after execution of a method and populates this POJO.


  package com.brimllc.aspects;
  
  import java.util.Iterator;
  import java.util.Stack;
  import java.util.regex.Matcher;
  import java.util.regex.Pattern;
  import javax.servlet.http.Cookie;
  import javax.servlet.http.HttpServletRequest;
  import javax.servlet.http.HttpServletRequestWrapper;
  import org.aspectj.lang.Signature;
  
  public abstract class AbstractLoggingAspect {
    // each HttpRequest is captured in this threadLocal to get access to request cookies and HttpSession
	protected static ThreadLocal myCurrentRequest = new ThreadLocal();
	protected static final String CURRENT_REQUEST_SEQUENCE_NUMBER = "CURRENT_REQUEST_SEQUENCE_NUMBER";
	protected static int MAX_REQUEST_NUMBER = 100000;
	// you dont want to monitor request for images, javascript etc, so lets ignore them
	protected static final Pattern PATTERN = Pattern.compile(".*/view/help/.*|.*/js/.*|.*/compressedJs/.*|.*/dynamicImage/.*|.*/images/.*|.*/css/.*|.*/a4j/.*");
	
	// here is the nuts and bolts, which does the calculation. Method A is the entry point, goes on the stack. A calls B, 
	B goes on the stack over A, so the method just below is always the parent of the current method and so on. As each method ends execution, it pops from the stack. 
	protected static ThreadLocal<Stack> myMethodCallStack = new ThreadLocal<Stack>(){
		protected synchronized Stack initialValue(){
			return new Stack();
		}		
	};	

		
	/**
	 * Pointcut to exclude some packages. You dont want some methods defined which falls in the same packages, and will 
	   match the pointcut, like EJB initilialization or MDB's onMessage which does not execute synchronously. You can get rid of it
       if you wish.	   
	 */
	public pointcut exclude():
		// do not include the aspects itself. Make sure the package of aspects is included,
		// else it will cause an infinite loop while weaving.
		!within(com.brimllc.aspects..*)		
	   	// do not weave EJB container callbacks
		&& ! execution(* *.ejb*(..)) 
		&& ! execution(* *.setSessionContext(..))
		// do not weave JMS beans callbacks
		&& ! execution(* *.onMessage(..)) 
		&& ! cflowbelow(execution(* *.onMessage(..)))
		// do not weave any method which starts with WL
		&& ! execution(* *.__WL*(..))
		// do not include any exceptions
		&& ! within(java.lang.Exception+)
		&& !cflow(ping());
		
	
	/**
	 * This gets the information from the request
	 * @param parameter
	 * @return
	 */
	protected String getRequestInfo(HttpServletRequest request , String parameter){
		Cookie[] cookies = null;
		if(request.getRequestURI() == null || request.getRequestURI().length() == 0){
			logger.logDebug(" Request generated null pointer");
		}
		try{
			cookies = request.getCookies();
		}catch(Exception ex){
			cookies = null;
			
		}
		if(cookies == null || cookies.length == 0){
			return null;
		}
		
		String paramValue = null;
		for(Cookie c : cookies) {
	       if(c.getName().equals(parameter)) {
	    	   paramValue = c.getValue().replaceAll("%3A",":");
	    	   break;
	       }
	    }
		return paramValue;
	}
	
	/**
	 * Factory method to create ExecutionRecord
	 * @return
	 */
	protected ExecutionRecord createMethodExecutionRecord(){
		return new ExecutionRecord();
	}
	
	/**
	 * Updates the record with information from the request 
	 * @param record
	 * @param signature
	 * @return
	 */
	protected ExecutionRecord updatedMethodExecutionRecord(HttpServletRequest request, ExecutionRecord record, Signature signature){
		if (request.getHeader("Proxy-Client-IP") == null){
			record.setClientIP(request.getRemoteAddr());
		} else {
			record.setClientIP(request.getHeader("Proxy-Client-IP"));
		}
		record.setRequestURI(request.getRequestURI());
		record.setSequenceNumber(getSequenceNumber(request));
		record.setUserId(getRequestInfo(request, "USERID"));
		record.setSessionId(getRequestInfo(request, "JSESSIONID"));
		record.setUseCaseScenario(getRequestInfo(request, "sfowTestCase"));
		record.setSuiteName(getRequestInfo(request, "testSuiteName"));
		record.setExecutionPath(getRequestInfo(request, "testSuiteCategory"));
		record.setPackageName(signature.getDeclaringType().getPackage().getName());
		record.setMethodName(signature.getDeclaringTypeName()+"."+signature.getName());
		record.setStartExecutionTime(System.currentTimeMillis());
		// check the top of the stack, thats the parent method which called this method
		ExecutionRecord parentRecord = myMethodCallStack.get().size() > 0 ? myMethodCallStack.get().peek() : null;
		if(parentRecord != null){
			record.setParentMethod(parentRecord.getMethodName());
			parentRecord.setHasChildren(true);
		}
		return record;
	}
	
	/**
	 * Adds a record for method execution on the stack
	 * @param obj
	 */

	public void doBefore(Signature signature)
	{		
		// no need to record till the request is sent to server
		HttpServletRequest request = myCurrentRequest.get();
		if(request == null){
			return;
		}
		// if the request is not a valid request then dont log
		if(!isValidRequest(request)){
			return;
		}
		// create a record
		ExecutionRecord record = createMethodExecutionRecord();
		// populate the record with information from request and method info
		updatedMethodExecutionRecord(request, record, signature);	
		// push the record on top of the stack
		myMethodCallStack.get().push(record);	
      }
	
	/**
	 * Pop the method record from the stack,
	 * add the end time of method
	 * calculate the total time executed for this method	 *
	 * @param obj
	 */
	public void doAfter(Signature signature) 
	{
		// no need to record till the request is sent to server
		HttpServletRequest request = myCurrentRequest.get();
		if(request == null){
			return;
		}
		// if the request is not a valid request then dont log
		if(!isValidRequest(request)){
			return;
		}
		// pop the method from method call stack
		ExecutionRecord record =  myMethodCallStack.get().size() > 0 ? myMethodCallStack.get().pop() : null;
		if(record == null){
			return;
		}
		// update the end time for method call
		record.setEndExecutionTime(System.currentTimeMillis());
		if(record.getTotalExecutionTime() > 0){
			// now let the parents know I am done
			incrementParentsChildrenExecutionTime(record);			
		}
		
		// log this record to the log file
		LogUtils.logTiming(record);
	}

	
	/**
	 * This method increments the childExecutionTime in the immediate parent record.
	 * Every method on the stack is still executing. Method on stack top is the current executing method (smallest child),
	 * while all others are its parents and waiting for it to finish to resume.
	 * When child method is finished executing, its execution time can be deducted from parent's execution time.
	 * * @param childRecord
	 */
	protected void incrementParentsChildrenExecutionTime(ExecutionRecord childMethodRecord){
		// increment the childExecutionTime of the immediate parent with childMethodRecord's total
		// execution time. 
		ExecutionRecord parentRecord = myMethodCallStack.get().size() > 0 ? myMethodCallStack.get().peek() : null;
		if(parentRecord == null){
			return;
		}
		parentRecord.setChildrenTotalExecutionTime(parentRecord.getChildrenTotalExecutionTime() + childMethodRecord.getTotalExecutionTime());			
	}		
		
	
	
	 
	 protected boolean isValidRequest(HttpServletRequest request){
		 if(request == null){
			 return false;
		 }
		 
		 String requestURI = request.getRequestURI();
		 if(requestURI == null || requestURI.trim().length() == 0){
			 return false;
		 }
		 
		// exclude any request for image, css or javascript		 
		 Matcher excludeMatcher = PATTERN.matcher(requestURI);
		 if(excludeMatcher.matches()){
			 return false;
		 }
		 
		 return true;
	 }
	  
	  // Other helper methods, no magic here
	 public synchronized int getSequenceNumber(HttpServletRequest request){
		 if(request.getSession(false) == null){
			 return 1;
		 }
		 Object currentReqSequenceObj = request.getSession(false).getAttribute(CURRENT_REQUEST_SEQUENCE_NUMBER);
		 if(currentReqSequenceObj == null){
			 return 1;
		 }
		 return ((Integer)currentReqSequenceObj).intValue();
	 }
	 
	 public synchronized void incrementSequenceNumber(HttpServletRequest request){
		 if(request.getSession(false) == null){
			 return;
		 }
		 int currentReqSequence = getSequenceNumber(request);
		 if(currentReqSequence < MAX_REQUEST_NUMBER){
			 currentReqSequence++;
		 }else{
			 currentReqSequence = 1;
		 }
		 
		 request.getSession(false).setAttribute(CURRENT_REQUEST_SEQUENCE_NUMBER, new Integer(currentReqSequence));
	 }
}
 

Now lets create the meat over the skeleton. Write some real aspects.
For every request sent to an Application server, there is always a base controller, or a filter which handle the request. In my case, I assume that there is a filter which gets the request first. Thats where we can get a handle to HttpRequest and check if it is not a valid request (ie. not image/css/javascript request).


    package com.brimllc.aspects; 
	/**
 * This aspect captures the HttpRequest in a ThreadLocal variable.
 * The idea is to capture the request from the first filter the request hits.
 *
 */
public aspect CaptureRequest extends AbstractLoggingAspect {

    
	public pointcut entireExecutionOfOneRequest() :
		execution(public void com.brimllc.filter.FirstFilter.doFilter(..));
	
	
	
	 before() : entireExecutionOfOneRequest()
	    {
		  
	      // capture the request from the doFilter method arguments	
		  Object[] args = thisJoinPoint.getArgs();
	    	HttpServletRequest request = (HttpServletRequest)args[0];
			// check if the request is not an img/css/javascript request
	    	if(isValidRequest(request)){
		    	synchronized(this){
		    		HttpServletRequestWrapper reqWrapper = new HttpServletRequestWrapper(request);
					// set this request to the threadLocal defined in AbstractLoggingAspect
	    			myCurrentRequest.set(reqWrapper);
	    			incrementSequenceNumber(request);

		    	}
		    	// keep record, calls the AbstractLoggingAspect (the skeleton) passing the method signature	
		    	doBefore(thisJoinPointStaticPart.getSignature());
	    	}
	     
	    	
	    }	 
	
	 
	    // since this is the entry point for the request, some more stuff is needed here, like clearing the Thread-Local,
		// the method stack used for calculation is reset.
	    after() : entireExecutionOfOneRequest()
	    {     	
	    	// process only when request is valid
	    	 // capture the request	
		      Object[] args = thisJoinPoint.getArgs();
		      HttpServletRequest request = (HttpServletRequest)args[0];
		      if(isValidRequest(request)){
		    	doAfter(thisJoinPointStaticPart.getSignature());
		      }
		      // now get rid of request and any methods lying on the stack
		     myCurrentRequest.set(null);
		     myMethodCallStack.set(new Stack());
	     }
	    		
}
 

So, we hooked our framework to capture the entry point of the request to the filter, to capture the HttpRequest. Now lets capture one layer of the application. For example, we want to see how much time the request is taking in the data-access layer. Luckily, our package name for DAO layer is com.brimllc.dao (somebody thought ahead :))

And this is all thats needed -


   package com.brimllc.aspects; 
   public aspect DAOAspect extends AbstractLoggingAspect {

	public pointcut daoCall():
		  // packages in Dao layer to weave
		 execution(public * com.brimllc.dao..*DaoImpl.*(..));		
		
	
	// exclude the calls to methods in the exclude list
	before() : daoCall() && exclude(){
		doBefore(thisJoinPointStaticPart.getSignature());
	}
	
	after() : daoCall() && exclude(){
		doAfter(thisJoinPointStaticPart.getSignature());
	}
}

  

For any other layer, just define a new aspect, with its own pointcut and call doBefore or doAfter defined in AbstractLoggingAspect in before or after advice.

This was the coding part, now come to the execution part. For that you need to define an aop-ajc.xml for doing Load-Time weaving. AspectJ provides options of doing compile time or load time weaving. The difference is, the byte-code manipulation happens either when compiling the code, or AspectJ loads the class using its custom class-loader and then checks the aspects defined in aop-ajc.xml and injects the byte code if it matches the pointcut defined in the aspects.


     <?xml version="1.0" encoding="UTF-8"?>
    <aspectj>
     <!-- configure the aspects we just created above -->
		<aspects>
			<aspect name="com.brimllc.aspects.CaptureRequest"/>
			<aspect name="com.brimllc.aspects.DAOAspect"/>
		</aspects>
		<!-- configure the weaver -->
		<weaver options="-verbose -proceedOnError -Xset:fastWeaving=true,weaveJavaPackages=true,weaveJavaxPackages=true ">
	     <!--  -showWeaveInfo-->
			<include within="com.brimllc..*"/>		
			<!-- incase you are using JSF libraries, yes you can define aspects and capture information on their methods as well -->
			<include within="com.sun.faces..*"/>
			<include within="javax.faces..*"/>
			<include within="org.ajax4jsf..*"/>
			<include within="com.sun.facelets..*"/>
			
	<!--  exclude list, packages that will not be weaved -->

	<!--  Other packages to exclude -->
			<exclude within="org.apache.commons.collections..*"/>
			<exclude within="org.apache.commons.logging..*"/>
			<exclude within="org.apache.naming..*"/>
			<exclude within="org.apache.log4j..*"/>
			<exclude within="org.apache.taglibs..*"/>
			<exclude within="org.apache.tools..*"/>
			<exclude within="org.apache.xerces..*"/>
			<exclude within="org.apache.xmlbeans..*"/>
			<exclude within="org.hibernate..*"/>
			<exclude within="net.sf.hibernate..*"/>
			<exclude within="weblogic.apache..*"/>
			<exclude within="weblogic.application..*"/>
			<exclude within="weblogic.deploy..*"/>
			<exclude within="weblogic.diagnostics..*"/>
			<exclude within="weblogic.ejb..*"/>
			<exclude within="weblogic.j2ee.descriptor..*"/>
			<exclude within="weblogic.jms..*"/>
			<exclude within="weblogic.management..*"/>
			<exclude within="weblogic.messaging..*"/>
			<exclude within="weblogic.rmi..*"/>
			<exclude within="weblogic.security..*"/>
			<exclude within="weblogic.store..*"/>
			<exclude within="weblogic.transaction..*"/>
			<exclude within="weblogic.utils..*"/>
			<exclude within="com.bea.common..*"/>
			<exclude within="com.bea.security..*"/>
			<exclude within="com.bea.staxb..*"/>
			<exclude within="com.bea.xbean..*"/>
			<exclude within="com.bea.xml..*"/>
			<exclude within="*..*CGLIB*" /> 
			<exclude within='org.jboss..*'/>
		</weaver>
	</aspectj>	

Now create a jar for this. I used Maven, so here is the POM.xml


		 <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
		xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">

		<modelVersion>4.0.0</modelVersion>

		<name>Brim aspects</name>
		<description>Aspects used to collect performance data </description>

		<parent>
			<groupId>org.brimllc.perfAspects</groupId>
			<artifactId>brim-perf-test</artifactId>
			<version>1.0-SNAPSHOT</version>
		</parent>

		<artifactId>perf-aspects</artifactId>

		<packaging>jar</packaging>

		<dependencies>
			<dependency>
				<groupId>javax.servlet</groupId>
				<artifactId>servlet-api</artifactId>
				<scope>provided</scope>
			</dependency>
			<dependency>
				<groupId>aspectj</groupId>
				<artifactId>aspectj-tools</artifactId>
			</dependency>
			<dependency>
				<groupId>org.aspectj</groupId>
				<artifactId>aspectjrt</artifactId>
			</dependency>
		</dependencies>

		<build>
			<plugins>
				<plugin>
					<groupId>org.codehaus.mojo</groupId>
					<artifactId>aspectj-maven-plugin</artifactId>
					<version>1.2</version>
					<executions>
						<execution>
							<goals>
								<goal>compile</goal>
							</goals>
						</execution>
					</executions>
					<configuration>
						<complianceLevel>1.6</complianceLevel>
					</configuration>
				</plugin>
			</plugins>
		</build>

	</project>

To execute this, just add the jvm arg -agent=aspectjweaver.jar and in classpath add the jar for aspects you created and run your usecases using Selenium/Canoe.

From the log file generated, you can create customized reports using JFreeChart or another framework.
Another use of this framework, if you are assigned to a new project with poor documentation and spaghetti design. Putting this framework in place you can capture the exact execution sequence of the class methods, and then refractor.

Leave a Comment