Hi,

After my last post presenting an example about the annotation in JAVA Java : Annotation : Example of validation with annotation (mandatory, target, maxlength…) I would expose another example of JAVA annotation and AOP to measure performance and time processing on server side.

In a previous article Java/Spring: Measure performance and time processing with AOP on server side, I presented a solution allowing a detailed report of performance based on AOP technologies.

  1. Technologies
    So, our solution is based on:

    • an annotation PerformanceWatcher specifying the class, interface or enum whose the performace must be measured and an admissible threshold (warning duration),
      /**
       * Specify the class, interface or enum whose the performace must be measured and an admissible threshold (warning duration).
       * @author huseyin
       */
      // RetentionPolicy.RUNTIME : Annotations are to be recorded in the class file by the compiler 
      //			and retained by the VM at runtime, so they may be read reflectively.
      // ElementType.TYPE : Class, interface (including annotationtype) or enum declaration
      @Retention(RetentionPolicy.RUNTIME) 
      @Target(ElementType.TYPE)
      public @interface PerformanceWatcher {
      	long msDurationWarning() default 1000;
      }
      
    • an AOP AspectJ AspectPerformanceWatcher applying on the elements annotated by the annotation PerformanceWatcher to check if the execution time of a method for this element exceeds the specified admissible threshold (warning duration). This aspect AOP “Arround” allows the calculation of the execution time of a method and add a trace in the logs via méhode “calculatePerformance”.
      @Component
      @Aspect
      @Order(5)
      public class AspectPerformanceWatcher {
      
      	private static Log log = LogFactory.getLog(AspectPerformanceWatcher.class);
      		
      	@SuppressWarnings("unchecked")
      	@Around("within(@com.ho.test.perf.measure.annotations.PerformanceWatcher *)")
      	public Object calculatePerformance(ProceedingJoinPoint pjp) throws Throwable{
      		final long start = System.currentTimeMillis();
      			
      		// Execution of target method
      		final Object result = pjp.proceed();
      			
      		final long duration = System.currentTimeMillis() - start;
      			
      		// Get the definition of annotation and of this admissible threshold (warning duration)
      		final PerformanceWatcher performanceWatcher = (PerformanceWatcher) pjp.getSourceLocation().getWithinType().getAnnotation(PerformanceWatcher.class);
      			
      		// Check if the method's execution time exceeds the admissible threshold
      		if(performanceWatcher != null && performanceWatcher.msDurationWarning() < duration){
      				log.warn("**** THE METHOD "+pjp.getSignature().getName()+" FROM "+pjp.getSignature().getDeclaringTypeName()+" TOOK "+duration+ " MS (max"+performanceWatcher.msDurationWarning()+"ms). ****");
      		}//end-if
      		
      		return result;
      	}
      }
      

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

    • a Spring context defined in a XML file spring-business-config.xml,
    • 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 simple test class named PerfMeasureTestAnnot,
    • the JARs aspectjrt-1.5.4.jar, aspectjtools-1.5.4.jar, aspectjweaver-1.5.4.jar, cglib-2.2.2.jar, commons-logging-1.1.1.jar, spring-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"?>
    <beans
    	xmlns="http://www.springframework.org/schema/beans"
    	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    	xmlns:util="http://www.springframework.org/schema/util"
    	xmlns:aop="http://www.springframework.org/schema/aop"
    	xmlns:context="http://www.springframework.org/schema/context"
    	xsi:schemaLocation="
    		http://www.springframework.org/schema/beans
    		http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
    		http://www.springframework.org/schema/context
    		http://www.springframework.org/schema/context/spring-context-2.5.xsd
    		http://www.springframework.org/schema/util
    		http://www.springframework.org/schema/util/spring-util-2.0.xsd
    		http://www.springframework.org/schema/aop
    		http://www.springframework.org/schema/aop/spring-aop.xsd">
    
    <!-- To enable AOP -->
    <aop:aspectj-autoproxy/>
    
    <!-- Search annotations (@Autowired in particular) -->
    <context:annotation-config/>
    <context:component-scan base-package="com.ho.test.perf.measure"/>
    
    <!-- Aspects -->
    <bean id="aspectPerformanceWatcher" class="com.ho.test.perf.measure.annotations.AspectPerformanceWatcher"/>
    
    <!-- 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"/>
    
    </beans>
    

    … and singleton ApplicationContextContainer:

    public class ApplicationContextContainer {
    	
        // ------------------------------------------------------------------ LOG4J
    	private static Log log = LogFactory.getLog(ApplicationContextContainer.class);
    
        // -------------------------------------------------------------- CONSTANTS
    	private final static String SPRING_BUSINESS_CONFIG_XML = "spring-business-config.xml";
        
    
        // ----------------------------------------------------- PRIVATE ATTRIBUTES
        /**
         * Instance
         */
        private static ApplicationContextContainer instance = null;
        
        /**
         * Contains the spring configuration.
         */
        private ClassPathXmlApplicationContext ctx = null;
    
        // ------------------------------------------------------------- EXCEPTIONS
        // ------------------------------------------------------- INTERNAL CLASSES
        // ----------------------------------------------------------- CONSTRUCTORS
        private ApplicationContextContainer() {}
        // --------------------------------------------------------- PUBLIC METHODS
        
        /**
         * Getinstance method.
         */
        public static synchronized ApplicationContextContainer getInstance() {
            return getInstance(SPRING_BUSINESS_CONFIG_XML);
        }
        public static synchronized ApplicationContextContainer getInstance(String springContextFile) {
        	if (null == instance) {
        		instance = new ApplicationContextContainer();
        		instance.ctx = new ClassPathXmlApplicationContext();  
        		instance.ctx.setConfigLocation(springContextFile);
        		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 ClassPathXmlApplicationContext getContext() {
            return ctx;
        }
        
        
    
    	/**
    	 * 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;
    	}
    }
    
  3. Classes to monitor
    JdbcUtilsServiceImpl: This classes is monitored and contains an annotation @PerformanceWatcher(msDurationWarning=3500).

    @PerformanceWatcher(msDurationWarning=3500)
    public class JdbcUtilsServiceImpl implements IJdbcUtils {
    	// ----------------------------------------------------- PRIVATE ATTRIBUTES
    	private static Log log = LogFactory.getLog(JdbcUtilsServiceImpl.class);
    
    	// --------------------------------------------------------- PUBLIC METHODS
    	/**
    	 * Execute query.
    	 * @param sql the sql
    	 * @return the query execution result as a List
    	 */
    	public List executeQuery(String sql) {
    		log.info("JdbcUtilsServiceImpl:executeQuery START");
    		try {
    			Thread.currentThread().sleep(ApplicationContextContainer.getRandomSleepTime());
    		} catch(Throwable th){
    		}
    		log.info("JdbcUtilsServiceImpl:executeQuery END");
    		return new ArrayList();
    	}
     }
    

    Business1DaoHibernateImpl: This classes is monitored and contains an annotation @PerformanceWatcher(msDurationWarning=2000).

    @PerformanceWatcher(msDurationWarning=2000)
    public class Business1DaoHibernateImpl implements IBusiness1 {
    	
    	private static Log log = LogFactory.getLog(Business1DaoHibernateImpl.class);
    	
    	/**
    	 * Save or update object into database.
    	 */
    	public void saveOrUpdate() {
    		log.info("Business1DaoHibernateImpl:saveOrUpdate START");
    		try {
    			Thread.currentThread().sleep(ApplicationContextContainer.getRandomSleepTime());
    		} catch(Throwable th){
    		}
    		log.info("Business1DaoHibernateImpl:saveOrUpdate END");
    	}
    //...
    }
    

    Business2DaoHibernateImpl: This classes is monitored and contains an annotation @PerformanceWatcher(msDurationWarning=3000).

    @PerformanceWatcher(msDurationWarning=3000)
    public class Business2DaoHibernateImpl implements IBusiness2 {
    	
    	private static Log log = LogFactory.getLog(Business2DaoHibernateImpl.class);
    	
    	/**
    	 * Save or update object into database.
    	 */
    	public void saveOrUpdate() {
    		log.info("Business2DaoHibernateImpl:saveOrUpdate START");
    		try {
    			Thread.currentThread().sleep(ApplicationContextContainer.getRandomSleepTime());
    		} catch(Throwable th){
    		}
    		log.info("Business2DaoHibernateImpl:saveOrUpdate END");
    	}
    //...
    }
    
  4. Tests
    The project in attachement contains a test class named PerfMeasureAnnotTest:

    public class PerfMeasureAnnotTest {
    	
    	public static void main(String[] args) {
    		
    		ApplicationContextContainer context = ApplicationContextContainer.getInstance();
    		
    		IJdbcUtils jdbcUtils = (IJdbcUtils) context.getBean("JdbcUtilsServiceImpl");
    		IBusiness1 business1 = (IBusiness1) context.getBean("Business1DaoHibernateImpl");
    		IBusiness2 business2 = (IBusiness2) context.getBean("Business2DaoHibernateImpl");
    
    		{
    			jdbcUtils.executeQuery("");
    			//
    			business1.delete();
    			business1.save();
    			business1.saveOrUpdate();
    			business1.update();
    			//
    			business2.delete();
    			business2.save();
    			business2.saveOrUpdate();
    			business2.update();
    		}//end-for
    		
    	}
    }
    

    … os, the outputs in console could be:

    10 avr. 2014 23:23:53 com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl executeQuery
    INFO: JdbcUtilsServiceImpl:executeQuery START
    10 avr. 2014 23:23:57 com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl executeQuery
    INFO: JdbcUtilsServiceImpl:executeQuery END
    10 avr. 2014 23:23:57 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl delete
    INFO: Business1DaoHibernateImpl:delete START
    10 avr. 2014 23:23:58 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl delete
    INFO: Business1DaoHibernateImpl:delete END
    10 avr. 2014 23:23:58 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl save
    INFO: Business1DaoHibernateImpl:save START
    10 avr. 2014 23:24:00 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl save
    INFO: Business1DaoHibernateImpl:save END
    10 avr. 2014 23:24:00 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl saveOrUpdate
    INFO: Business1DaoHibernateImpl:saveOrUpdate START
    10 avr. 2014 23:24:04 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl saveOrUpdate
    INFO: Business1DaoHibernateImpl:saveOrUpdate END
    10 avr. 2014 23:24:04 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    ATTENTION: **** THE METHOD saveOrUpdate FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1 TOOK 3855 MS (max2000ms). ****
    10 avr. 2014 23:24:04 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl update
    INFO: Business1DaoHibernateImpl:update START
    10 avr. 2014 23:24:08 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl update
    INFO: Business1DaoHibernateImpl:update END
    10 avr. 2014 23:24:08 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    ATTENTION: **** THE METHOD update FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1 TOOK 4895 MS (max2000ms). ****
    10 avr. 2014 23:24:08 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl delete
    INFO: Business2DaoHibernateImpl:delete START
    10 avr. 2014 23:24:10 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl delete
    INFO: Business2DaoHibernateImpl:delete END
    10 avr. 2014 23:24:10 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl save
    INFO: Business2DaoHibernateImpl:save START
    10 avr. 2014 23:24:11 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl save
    INFO: Business2DaoHibernateImpl:save END
    10 avr. 2014 23:24:11 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl saveOrUpdate
    INFO: Business2DaoHibernateImpl:saveOrUpdate START
    10 avr. 2014 23:24:16 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl saveOrUpdate
    INFO: Business2DaoHibernateImpl:saveOrUpdate END
    10 avr. 2014 23:24:16 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    ATTENTION: **** THE METHOD saveOrUpdate FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness2 TOOK 4213 MS (max3000ms). ****
    10 avr. 2014 23:24:16 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl update
    INFO: Business2DaoHibernateImpl:update START
    10 avr. 2014 23:24:19 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl update
    INFO: Business2DaoHibernateImpl:update END
    10 avr. 2014 23:24:19 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    ATTENTION: **** THE METHOD update FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness2 TOOK 3034 MS (max3000ms). ****
    

For more informations, you could contact me.

Download: testPerfMeasureAnnot.zip

Best regards,

Huseyin OZVEREN