Java/Spring: Measure performance and time processing with AOP on server side

Hello,

In this article, I will present you a solution in order to measure performance and time processing on server side. This technical solution allow to quickly obtain a detailed report of performance in an application by the measure of the execution time (for example) for queries in persistence layer (Hibernate, JDBC) via AOP or “hard coding” and the display time of JSP with the possibility to indicate a significant task in a measurement made.

1. Technologies
   The monitor consists of a specific call to a method named “StopWatch.getInstance().start(‘TASKNAME’)” before the execution of the method to monitor, then another specific call to a method named “StopWatch.getInstance().stop(‘TASKNAME’)” after the execution of the method to monitor (StopWatch, StopWatchTask).

   To make these specific calls, we will use:

   • an AOP layer (AOPALLIANCE library in Spring framework) to measure the execution time of the methods in the persistence layer HIBERNATE;
   • direct calls (BEFORE, AFTER) to the business of monitoring in the methods of the persistence layer JDBC to monitor the performance of SQL (in the project in attachement, see JdbcUtilsServiceImpl);
   • direct calls (BEFORE, AFTER) to the business of monitoring in JSP to display in console the detailed report of performance at the end of the display of a JSP page;

   The detailed report of the execution stack diplayed in console helps developers to highlight the main bottlenecks.

To illustrate our previous explanations, we will create a Web project with:

• a Spring context defined in a XML file spring-business-config.xml,
• a servlet context listener named SpringContextLoader to load this Spring context,
• a singleton named ApplicationContextContainer which will give an access to the Spring context (see my post on this topic Access to Spring context in all places or layers of an application),
• a mock HIBERNATE persistence layer with the classes Business1DaoHibernateImpl, Business2DaoHibernateImpl,
• a mock JDBC persistence layer with the class JdbcUtilsServiceImpl,
• a JSP page index.jsp to display the detailed report in console,
• an AOP layer with a probe named PerformanceMonitor,
• a simple test class named PerfMeasureTest,
• the JARs cglib-2.2.2.jar, commons-collections-3.1.jar, commons-dbcp-1.4.jar, commons-logging-1.1.1.jar, commons-pool-1.4.jar, jstl.jar (version 1.1.2), jta-1.1.jar, spring-2.5.6.jar, spring-webmvc-2.5.6.jar and standard.jar (version 1.1.2).

More, in our project, the execution/processing time of methods to monitor in the persistence layers (Hibernate and JDBC) will be random between 1 second and 5 seconds:

• in the methods saveOrUpdate(), save(), update() and delete() of the classes Business1DaoHibernateImpl and Business2DaoHibernateImpl,
• in the method executeQuery(String sql) in the class JdbcUtilsServiceImpl,

/**
 * Returns a number in milliseconds between 1000 (1sec) and 5000 (5sec)
 * @return
 */
public static long getRandomSleepTime(){
	int lower = 1000;
	int higher = 5000;

	long random = (long)(Math.random() * (higher-lower)) + lower;
	return random;
}

2. Spring context
   The Spring context is defined in a XML file spring-business-config.xml:

   <?xml version="1.0" encoding="UTF-8"?>
   <!DOCTYPE beans PUBLIC 
       "-//SPRING//DTD BEAN//EN"
       "http://www.springframework.org/dtd/spring-beans.dtd">
   
   <beans default-autowire="no" default-lazy-init="true" default-dependency-check="none">
   
   <!-- PERSISTENCE LAYER JBDC SQL MOCK -->
   <bean name="JdbcUtilsServiceImpl" class="com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl"/> 
   
   <!-- PERSISTENCE LAYER DAO HIBERNATE MOCK -->
   <bean name="Business1DaoHibernateImpl" class="com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl"/>
   <bean name="Business2DaoHibernateImpl" class="com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl"/>
   
   <!-- AOP LAYER AOPALLIANCE -->
   <bean id="performanceMonitor" class="com.ho.test.perf.measure.commons.aop.PerformanceMonitor" />
   
   <bean name="performanceMonitor.proxy" class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
   	 	<property name="beanNames">
   			<list>
   				<value>Business1DaoHibernateImpl</value> 
   				<value>Business2DaoHibernateImpl</value> 
   	 		</list>
   	 	</property>
   	 	<property name="interceptorNames">
   	 		<list>
   	 			<value>performanceMonitor</value>
   	 		</list>
   	 	</property>
   </bean>
   </beans>
   

   … more, we declare a servlet context listener named SpringContextLoader to load this Spring context in the web deployment descriptor web.xml:

   <?xml version="1.0" encoding="UTF-8"?>
   <web-app ...>
   ...
     <listener>
       <listener-class>com.ho.test.perf.measure.utils.SpringContextLoader</listener-class>
     </listener>
     <context-param>
       <param-name>CONFIG_SPRING_FILE</param-name>
       <param-value>/WEB-INF/spring-business-config.xml</param-value>
     </context-param>
   </web-app>
   

   The code of servlet context listener SpringContextLoader:

   public class SpringContextLoader implements ServletContextListener {
   	/**
   	 * Method contextDestroyed
   	 * @param arg0
   	 * @see javax.servlet.ServletContextListener#contextDestroyed(javax.servlet.ServletContextEvent)
   	 */
   	public void contextDestroyed(ServletContextEvent arg0) {
   	}
   
   	/**
   	 * Method contextInitialized
   	 * @param arg0
   	 * @see javax.servlet.ServletContextListener#contextInitialized(javax.servlet.ServletContextEvent)
   	 */
   	public void contextInitialized(ServletContextEvent ctx) {
   		String springFileName = ctx.getServletContext().getInitParameter("CONFIG_SPRING_FILE");
   		ApplicationContextContainer.getInstance(springFileName, ctx.getServletContext());
   	}
   }
   

   … and singleton ApplicationContextContainer:

   public class ApplicationContextContainer {
   
       private static Log log = LogFactory.getLog(ApplicationContextContainer.class);
   
       private final static String SPRING_BUSINESS_CONFIG_XML = "/WEB-INF/spring-business-config.xml";
       
       /**
        * Instance
        */
       private static ApplicationContextContainer instance = null;
       
       /**
        * Contains the spring configuration.
        */
       private XmlWebApplicationContext ctx = null;
   
       private ApplicationContextContainer() {}
       
       /**
        * Getinstance method.
        */
       public static synchronized ApplicationContextContainer getInstance() {
           return getInstance(SPRING_BUSINESS_CONFIG_XML, null);
       }
       public static synchronized ApplicationContextContainer getInstance(String springContextFile, ServletContext servletContext) {
       	if (null == instance) {
       		instance = new ApplicationContextContainer();
       		instance.ctx = new XmlWebApplicationContext();  
       		instance.ctx.setConfigLocation(springContextFile);
       		instance.ctx.setServletContext(servletContext);
       		instance.ctx.refresh();
           } // end-if
           return instance;
       }
       
       /**
        * Retrieve the spring bean corresponding to the given key.
        * @param key
        * @return
        */
       public static Object getBean(String key) {
           return getInstance().ctx.getBean(key);
       }
       
       public XmlWebApplicationContext getContext() {
           return ctx;
       }
   }
   

3. TASK concept
   StopWatch: This singleton measures the duration of execution for a set of tasks. It contains all tasks to monitor in a MAP whose the key is the taskname of task. A task is defined by the class StopWatchTask.

   public class StopWatch {
   	//...
   
   	/**
   	 * Contains the unique instance of the class.
   	 */
   	private static StopWatch instance = null;
   	
   	/**
   	 * Contains all the tasks in the order of arrival.
   	 */
   	private Collection<StopWatchTask> tasks = new ArrayList<StopWatchTask>();
   	
   	/**
   	 * Contains all tasks. The task name is used as key in the map.
   	 */
   	private Map<String, StopWatchTask> tasksByName = new HashMap<String, StopWatchTask>();
   
   	//...
   
   	/**
   	 * Startup / create the task corresponding to the unique name of the given task.
   	 * @param taskname
   	 * @return
   	 */
   	public StopWatchTask start(String taskname) {		
   		// Try to retreive the corresponding task 
   		StopWatchTask correspondingTask = new StopWatchTask(taskname, ident); 
   		// The task doesn't exist, adds its reference in the lists of tasks
   		tasks.add(correspondingTask);
   		tasksByName.put(taskname, correspondingTask);
   
   		
   		// Start the task
   		{
   			correspondingTask.start();
   			ident++;
   		} // end-block
   		
   		return correspondingTask;
   	}
   	
   	/**
   	 * Stop the corresponding task to the unique reference of given task 
   	 * @param taskname
   	 * @return
   	 */
   	public StopWatchTask stop(String taskname) {
   		StopWatchTask correspondingTask = tasksByName.get(taskname);
   		correspondingTask.stop();
   		ident--;
   		//Output to the console because the measurements are performed 
   		//   on asynchronously calls in controllers from the JSP layer PRESENTATION
   		//System.out.println(correspondingTask.toString());
   		
   		return correspondingTask;
   	}
   	
   	//...
   	
   	/**
   	 * Method toString
   	 * @return
   	 * @see java.lang.Object#toString()
   	 */
   	@Override
   	public String toString() {
   		// Displaying the stack of execution of tasks
   		String output = "StopWatchReport execution Stack \n";
   		for (StopWatchTask currTask : tasks) {
   			output += currTask + "\n";
   		}
   		
   		// Showing the significant tasks
   		output += "\nStopWatchReport significant task \n";
   		for (StopWatchTask currTask : tasks) {
   			if (currTask.isSignificant()) {
   				output += currTask.dumpWithoutIdent() + "\n";	
   			}
   		}
   		
   		return output;
   	}
   }
   

   StopWatchTask: This class defines a monitored task and measures the duration of execution of this task.

   public class StopWatchTask {
   
   	//...
   	
   	/**
   	 * Hour (in ms) of tasks startup.
   	 */
   	private long startTime = 0;
   	
   	/**
   	 * Duration of execution of the task in ms.
   	 */
   	private long execTime = 0;
   	
   	/**
   	 * Name/Reference of task.
   	 */
   	private String name;
   	
   	/**
   	 * Constructor of task.
   	 */
   	public StopWatchTask(String name,  int indent) {
   		this.name = name;
   		this.indent = indent;
   	}
   
   	/**
   	 * Start the task.
   	 */
   	public final void start() {
   		startTime = Calendar.getInstance().getTimeInMillis();
   	}
   	
   	/**
   	 * Stop the task.
   	 * (and update the execution duration (exectime) and the accrued total duration (totalExecTime) of the task.
   	 */
   	public final void stop() {
   		long endTime = Calendar.getInstance().getTimeInMillis();
   		execTime = endTime - startTime;
   		//totalExecTime+= execTime;
   	}
   
   	public String dumpWithoutIdent() {
   		return "Task "  
   				+ "name='" + name + "' "  
   				+ "execTime='" + execTime + "' " 
   				//+ "total : " + totalExecTime 
   				;
   	}
   	
   	/**
   	 * Method toString
   	 * @return
   	 * @see java.lang.Object#toString()
   	 */
   	@Override
   	public String toString() {
   		String identStr = "";
   		for (int i=0; i<indent; i++) {
   			identStr += "\t";
   		}
   		
   		String output = identStr + dumpWithoutIdent();
   		if (!"".equals(log)) {
   			output += "\n" + identStr + log;
   		}
   
   		return output;
   	}
   
   	//...
   }
   

4. Classes to monitor
   JdbcUtilsServiceImpl: This classes is monitored and contains direct calls to “StopWatch.getInstance().start(…);” and “StopWatch.getInstance().stop(…);”.

   public class JdbcUtilsServiceImpl implements IJdbcUtils {
   	/**
   	 * Execute query.
   	 * @param sql the sql
   	 * @return the query execution result as a List
   	 */
   	public List executeQuery(String sql) {
   		StopWatch.getInstance().start(sql);
   		try {
   			Thread.currentThread().sleep(PerformanceMonitor.getRandomSleepTime());
   		} catch(Throwable th){
   		} finally {
   			StopWatch.getInstance().stop(sql);
   		}
   		return new ArrayList();
   	}
   }
   

   Business1DaoHibernateImpl: This classes will be monitor by AOP.

   public class Business1DaoHibernateImpl implements IBusiness1 {
   	
   	/**
   	 * Save or update object into database.
   	 */
   	public void saveOrUpdate() {
   		//...
   	}
   
   	/**
   	 * Save object into database.
   	 */
   	public void save() {
   		//...
   	}
   	/**
   	 * Update object into database.
   	 */
   	public void update() {
   		//...
   	}
   
   	/**
   	 * Delete object into database.
   	 */
   	public void delete() {
   		//...
   	}
   }
   

   Business2DaoHibernateImpl: This classes will be monitor by AOP.

   public class Business2DaoHibernateImpl implements IBusiness1 {
   		
   	/**
   	 * Save or update object into database.
   	 */
   	public void saveOrUpdate() {
   		//...
   	}
   	/**
   	 * Save object into database.
   	 */
   	public void save() {
   		//...
   	}
   	/**
   	 * Update object into database.
   	 */
   	public void update() {
   		//...
   	}
   
   	/**
   	 * Delete object into database.
   	 */
   	public void delete() {
   		//...
   	}
   }
   

5. AOP Alliance
   The class PerformanceMonitor is a probe used to intercept the calls to the methods of the beans Business1DaoHibernateImpl, Business2DaoHibernateImpl defined in the Spring Context via the bean performanceMonitor.proxy which is type of org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator. This probe allows the measure of the processing time in the methods of previous beans.As you could see in the below code, the probe:
   • generates the MethodKey of intercepted method with getMethodKey(…),
   • creates the task corresponding to the name generated (BEFORE the execution of intercepted method) with StopWatch.getInstance().start(…),
   • executes the intercepted method/business,
   • stops the corresponding task (AFTER the execution of intercepted method) with StopWatch.getInstance().stop(…),

   /**
    * <p>Title: PerformanceMonitor</p>
    * <p>
    * 		This probe is used to measure the response time functions Spring via AOP.
    * </p>
    * 
    * @a2.Version
    */
   public class PerformanceMonitor implements MethodInterceptor {
   
   	/**
   	 * @see org.aopalliance.intercept.MethodInterceptor#invoke(org.aopalliance.intercept.MethodInvocation)
   	 */
   	public Object invoke(MethodInvocation method) throws Throwable {
   		// Generates the MethodKey of intercepted method
   		String methodKey = getMethodKey(method);
   		
   		// Business executed BEFORE the execution of intercepted method
   		StopWatch.getInstance().start(methodKey);
   		
   		Object output = null;
   		try {
   			// Execution of intercepted method
   			output = method.proceed(); 
   		} finally {
   			// Business executed AFTER the execution of intercepted method
   			StopWatch.getInstance().stop(methodKey);
   		} // end-if
   
   		return output;
   	}
   	
   	/**
   	 * Generates the MethodKey of intercepted method
   	 * @return the key used to store the items in the cache.
   	 */
   	private String getMethodKey(MethodInvocation method) {
   	    StringBuffer cacheNameBuffer = new StringBuffer();
   	    //...
   	    return cacheNameBuffer.toString();
   	}
   }
   

6. Tests
   Test n°1: JSP page
   After the deployment of Web application on an AS, for example TOMCAT:

   INFO: Pre-instantiating singletons in org.springframework.beans.factory. support.DefaultListableBeanFactory@54956254: defining beans [JdbcUtilsServiceImpl,Business1DaoHibernateImpl,Business2DaoHibernateImpl, performanceMonitor,performanceMonitor.proxy]; root of factory hierarchy
   

   … open the URL http://localhost:8080/testPerfMeasure/index.jsp. This JSP page index.jsp is monitored and contains direct calls to several services in persistence layer (monitored too), “StopWatch.getInstance().start(…);” and “StopWatch.getInstance().stop(…);”.

   <%@ page language="java" import="java.util.*" %>
   <%@ page import="com.ho.test.perf.measure.commons.tools.StopWatch" %>
   <%@ page import="com.ho.test.perf.measure.utils.ApplicationContextContainer" %>
   <%@ page import="com.ho.test.perf.measure.commons.jdbc.IJdbcUtils" %>
   <%@ page import="com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1" %>
   <%
   	StopWatch.getInstance().clear();
   	StopWatch.getInstance().start("index.jsp");
   %>
   <%@page pageEncoding="UTF-8" contentType="text/html; charset=UTF-8"%>
   
   <HTML>
   <HEAD>
   <TITLE>TEST</TITLE>
   <META http-equiv="content-type" content="text/html; charset=UTF-8">
   </HEAD>
   <BODY>
   
   <%
   IBusiness1 business1 = (IBusiness1) ApplicationContextContainer.getInstance().getBean("Business1DaoHibernateImpl");
   IBusiness1 business2 = (IBusiness1) ApplicationContextContainer.getInstance().getBean("Business2DaoHibernateImpl");
   IJdbcUtils jdbcUtils = (IJdbcUtils) ApplicationContextContainer.getInstance().getBean("JdbcUtilsServiceImpl");
   
   jdbcUtils.executeQuery("SELECT * FROM HUO_TEST WHERE ID=123");
   business1.save();
   business2.delete();
   
   %>
   See in the console/log, the report of execution stack allowing to highlight the main bottlenecks.
   <%
   	StopWatch.getInstance().stop("index.jsp");
   	System.out.println(StopWatch.getInstance().toString());
   	StopWatch.getInstance().clear();
   %>
   
   </BODY>
   </HTML>
   

   … and the processing time report has been displayed in the browser and the ouputs in console could be:
   

   StopWatchReport execution Stack 
   Task name='index.jsp' execTime='7575' 
   	Task name='SELECT * FROM HUO_TEST WHERE ID=123' execTime='2181' 
   	Task name='com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1.save()' execTime='2464' 
   	Task name='com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1.delete()' execTime='2816' 
   
   StopWatchReport significant task 
   

   Test n°2: Main class
   The project in attachement contains a test class named PerfMeasureTest:

   	public static void main(String[] args) {
   		
   		// Clean the set of tasks
   		StopWatch.getInstance().clear();
   		
   		// Task 1
   		StopWatch.getInstance().start("task 1");
   		{
   			// Task 2
   			StopWatch.getInstance().start("task 2");
   			{
   				StopWatch.getInstance().start("task 2a");
   					try {Thread.sleep(500);} catch (InterruptedException e) {}
   				StopWatch.getInstance().stop("task 2a");
   				//
   				StopWatch.getInstance().start("task 2c");
   					try {Thread.sleep(125);} catch (InterruptedException e) {}
   				StopWatch.getInstance().stop("task 2c");
   				//
   				StopWatch.getInstance().start("task 2d");
   					try {Thread.sleep(30);} catch (InterruptedException e) {}
   					StopWatch.getInstance().start("task 2d1");
   						try {Thread.sleep(252);} catch (InterruptedException e) {}
   					StopWatch.getInstance().stop("task 2d1");
   				StopWatch.getInstance().stop("task 2d");
   			}
   			StopWatch.getInstance().stop("task 2");
   			
   			// Task 3
   			StopWatch.getInstance().start("task 3");
   			{
   				try {Thread.sleep(10);} catch (InterruptedException e) {}
   				StopWatch.getInstance().start("task 3a").setSignificant();
   					try {Thread.sleep(45);} catch (InterruptedException e) {}
   				StopWatch.getInstance().stop("task 3a");
   			}
   			StopWatch.getInstance().stop("task 3");
   
   			// Task 3a 
   			StopWatch.getInstance().start("task 3a");
   				try {Thread.sleep(55);} catch (InterruptedException e) {}
   			StopWatch.getInstance().stop("task 3a");
   			
   		}
   		StopWatch.getInstance().stop("task 1");
   		
   		// Task 3a 
   		StopWatch.getInstance().start("task 3a");
   			try {Thread.sleep(65);} catch (InterruptedException e) {}
   		StopWatch.getInstance().stop("task 3a");
   		
   		// Display the execution report of StopWatch
   		System.out.println(StopWatch.getInstance());
   	}
   

   … os, the outputs in console could be:

   StopWatchReport execution Stack 
   Task name='task 1' execTime='1056' 
   	Task name='task 2' execTime='945' 
   		Task name='task 2a' execTime='500' 
   		Task name='task 2c' execTime='163' 
   		Task name='task 2d' execTime='282' 
   			Task name='task 2d1' execTime='252' 
   	Task name='task 3' execTime='56' 
   		Task name='task 3a' execTime='45' 
   	Task name='task 3a' execTime='55' 
   Task name='task 3a' execTime='65' 
   
   StopWatchReport significant task 
   Task name='task 3a' execTime='45' 
   

7. Limitations and Evolutions of this solution
   Performance verification of the requests in the persistence layer and SQL queries should be performed on an isolated server dedicated to tests because the design / use of “taskName” in the classes StopWatch, StopWatchTask is not fixed/frozen…. i.e. if several users use the same server, the business will not create a TASK for each user query submitted but will use the same TASK because its “taskName” is identical for each control point. This is why when you get to index.jsp, there may be several TASKS already created in the list and display all the previous queries are also displayed.

   Submit “taskName” with a prefix, for exammple, the name of current user and the current date in milliseconds,
   o Create an instance of the list of tasks (StopWatch) by each entry point controls (index.jsp) and by user.
   o Use semaphores and synchronized,

8. Others solutions
   An other solution to get measures of performance and time processing on server side and display the results in comments of each JSP page, the processing time of the BUSINESS layer and PRESENTATION layer:
   In the front dispatcher (method “execute” of “DispatchAction” in Struts, in the Spring MVC “Controller”) or simply in a HTTP filter, we could save the processing time in a Session attribute named EXECTIME:

   Calendar perfBegin = Calendar.getInstance();
   //...
   long execTime = (Calendar.getInstance().getTimeInMillis() - perfBegin.getTimeInMillis());
   request.setAttribute("EXECTIME", execTime);
   //...				        
   

   ..then in the JPS page, dispay this time from the “EXECTIME” attribute:

   [...]
   <html>
   <head>	
   <%
   	Calendar perfStart = Calendar.getInstance();
   %>
   [...]		
   <!--
   EXECTIME BUSINESS LAYER : ${EXECTIME}
   EXECTIME PRESENTATION LAYER : <%=(Calendar.getInstance().getTimeInMillis() - perfStart.getTimeInMillis())%>
   -->
   </body>
   </html>	
   

I don’t have been exhaustive in this article, but, I hope that it will be useful for your needs about the measures of performance and time processing on server side.

For more informations, you could contact me.

Download: testPerfMeasure.zip

Best regards,

Huseyin OZVEREN