JavaBlog.fr / Java.lu DEVELOPMENT,Java,Spring Java : Annotation : Spring : AOP AspectJ: Measure performance and time processing with AOP and Annotation on server side

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

April 10, 2014April 10, 2014 | Huseyin OZVERENHuseyin OZVEREN | 0 Comment | 11:49 PM

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),
      view source
      print?
      01/**
      02 * Specify the class, interface or enum whose the performace must be measured and an admissible threshold (warning duration).
      03 * @author huseyin
      04 */
      05// RetentionPolicy.RUNTIME : Annotations are to be recorded in the class file by the compiler
      06//          and retained by the VM at runtime, so they may be read reflectively.
      07// ElementType.TYPE : Class, interface (including annotationtype) or enum declaration
      08@Retention(RetentionPolicy.RUNTIME)
      09@Target(ElementType.TYPE)
      10public @interface PerformanceWatcher {
      11    long msDurationWarning() default 1000;
      12}
    • 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”.
      view source
      print?
      01@Component
      02@Aspect
      03@Order(5)
      04public class AspectPerformanceWatcher {
      05 
      06    private static Log log = LogFactory.getLog(AspectPerformanceWatcher.class);
      07         
      08    @SuppressWarnings("unchecked")
      09    @Around("within(@com.ho.test.perf.measure.annotations.PerformanceWatcher *)")
      10    public Object calculatePerformance(ProceedingJoinPoint pjp) throws Throwable{
      11        final long start = System.currentTimeMillis();
      12             
      13        // Execution of target method
      14        final Object result = pjp.proceed();
      15             
      16        final long duration = System.currentTimeMillis() - start;
      17             
      18        // Get the definition of annotation and of this admissible threshold (warning duration)
      19        final PerformanceWatcher performanceWatcher = (PerformanceWatcher) pjp.getSourceLocation().getWithinType().getAnnotation(PerformanceWatcher.class);
      20             
      21        // Check if the method's execution time exceeds the admissible threshold
      22        if(performanceWatcher != null && performanceWatcher.msDurationWarning() < duration){
      23                log.warn("**** THE METHOD "+pjp.getSignature().getName()+" FROM "+pjp.getSignature().getDeclaringTypeName()+" TOOK "+duration+ " MS (max"+performanceWatcher.msDurationWarning()+"ms). ****");
      24        }//end-if
      25         
      26        return result;
      27    }
      28}

    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,
    view source
    print?
    01/**
    02 * Returns a number in milliseconds between 1000 (1sec) and 5000 (5sec)
    03 * @return
    04 */
    05public static long getRandomSleepTime(){
    06    int lower = 1000;
    07    int higher = 5000;
    08 
    09    long random = (long)(Math.random() * (higher-lower)) + lower;
    10    return random;
    11}

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

    view source
    print?
    01<?xml version="1.0" encoding="UTF-8"?>
    02<beans
    03    xmlns="http://www.springframework.org/schema/beans"
    04    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    05    xmlns:util="http://www.springframework.org/schema/util"
    06    xmlns:aop="http://www.springframework.org/schema/aop"
    07    xmlns:context="http://www.springframework.org/schema/context"
    08    xsi:schemaLocation="
    09        http://www.springframework.org/schema/beans
    10        http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
    11        http://www.springframework.org/schema/context
    12        http://www.springframework.org/schema/context/spring-context-2.5.xsd
    13        http://www.springframework.org/schema/util
    14        http://www.springframework.org/schema/util/spring-util-2.0.xsd
    15        http://www.springframework.org/schema/aop
    16        http://www.springframework.org/schema/aop/spring-aop.xsd">
    17 
    18<!-- To enable AOP -->
    19<aop:aspectj-autoproxy/>
    20 
    21<!-- Search annotations (@Autowired in particular) -->
    22<context:annotation-config/>
    23<context:component-scan base-package="com.ho.test.perf.measure"/>
    24 
    25<!-- Aspects -->
    26<bean id="aspectPerformanceWatcher" class="com.ho.test.perf.measure.annotations.AspectPerformanceWatcher"/>
    27 
    28<!-- PERSISTENCE LAYER JBDC SQL MOCK -->
    29<bean name="JdbcUtilsServiceImpl" class="com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl"/>
    30 
    31<!-- PERSISTENCE LAYER DAO HIBERNATE MOCK -->
    32<bean name="Business1DaoHibernateImpl" class="com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl"/>
    33<bean name="Business2DaoHibernateImpl" class="com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl"/>
    34 
    35</beans>

    … and singleton ApplicationContextContainer:

    view source
    print?
    01public class ApplicationContextContainer {
    02     
    03    // ------------------------------------------------------------------ LOG4J
    04    private static Log log = LogFactory.getLog(ApplicationContextContainer.class);
    05 
    06    // -------------------------------------------------------------- CONSTANTS
    07    private final static String SPRING_BUSINESS_CONFIG_XML = "spring-business-config.xml";
    08     
    09 
    10    // ----------------------------------------------------- PRIVATE ATTRIBUTES
    11    /**
    12     * Instance
    13     */
    14    private static ApplicationContextContainer instance = null;
    15     
    16    /**
    17     * Contains the spring configuration.
    18     */
    19    private ClassPathXmlApplicationContext ctx = null;
    20 
    21    // ------------------------------------------------------------- EXCEPTIONS
    22    // ------------------------------------------------------- INTERNAL CLASSES
    23    // ----------------------------------------------------------- CONSTRUCTORS
    24    private ApplicationContextContainer() {}
    25    // --------------------------------------------------------- PUBLIC METHODS
    26     
    27    /**
    28     * Getinstance method.
    29     */
    30    public static synchronized ApplicationContextContainer getInstance() {
    31        return getInstance(SPRING_BUSINESS_CONFIG_XML);
    32    }
    33    public static synchronized ApplicationContextContainer getInstance(String springContextFile) {
    34        if (null == instance) {
    35            instance = new ApplicationContextContainer();
    36            instance.ctx = new ClassPathXmlApplicationContext(); 
    37            instance.ctx.setConfigLocation(springContextFile);
    38            instance.ctx.refresh();
    39        } // end-if
    40        return instance;
    41    }
    42     
    43    /**
    44     * Retrieve the spring bean corresponding to the given key.
    45     * @param key
    46     * @return
    47     */
    48    public static Object getBean(String key) {
    49        return getInstance().ctx.getBean(key);
    50    }
    51     
    52    public ClassPathXmlApplicationContext getContext() {
    53        return ctx;
    54    }
    55     
    56     
    57 
    58    /**
    59     * Returns a number in milliseconds between 1000 (1sec) and 5000 (5sec)
    60     * @return
    61     */
    62    public static long getRandomSleepTime(){
    63        int lower = 1000;
    64        int higher = 5000;
    65 
    66        long random = (long)(Math.random() * (higher-lower)) + lower;
    67        return random;
    68    }
    69}

  3. Classes to monitor
    JdbcUtilsServiceImpl: This classes is monitored and contains an annotation @PerformanceWatcher(msDurationWarning=3500).

    view source
    print?
    01@PerformanceWatcher(msDurationWarning=3500)
    02public class JdbcUtilsServiceImpl implements IJdbcUtils {
    03    // ----------------------------------------------------- PRIVATE ATTRIBUTES
    04    private static Log log = LogFactory.getLog(JdbcUtilsServiceImpl.class);
    05 
    06    // --------------------------------------------------------- PUBLIC METHODS
    07    /**
    08     * Execute query.
    09     * @param sql the sql
    10     * @return the query execution result as a List
    11     */
    12    public List executeQuery(String sql) {
    13        log.info("JdbcUtilsServiceImpl:executeQuery START");
    14        try {
    15            Thread.currentThread().sleep(ApplicationContextContainer.getRandomSleepTime());
    16        } catch(Throwable th){
    17        }
    18        log.info("JdbcUtilsServiceImpl:executeQuery END");
    19        return new ArrayList();
    20    }
    21 }

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

    view source
    print?
    01@PerformanceWatcher(msDurationWarning=2000)
    02public class Business1DaoHibernateImpl implements IBusiness1 {
    03     
    04    private static Log log = LogFactory.getLog(Business1DaoHibernateImpl.class);
    05     
    06    /**
    07     * Save or update object into database.
    08     */
    09    public void saveOrUpdate() {
    10        log.info("Business1DaoHibernateImpl:saveOrUpdate START");
    11        try {
    12            Thread.currentThread().sleep(ApplicationContextContainer.getRandomSleepTime());
    13        } catch(Throwable th){
    14        }
    15        log.info("Business1DaoHibernateImpl:saveOrUpdate END");
    16    }
    17//...
    18}

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

    view source
    print?
    01@PerformanceWatcher(msDurationWarning=3000)
    02public class Business2DaoHibernateImpl implements IBusiness2 {
    03     
    04    private static Log log = LogFactory.getLog(Business2DaoHibernateImpl.class);
    05     
    06    /**
    07     * Save or update object into database.
    08     */
    09    public void saveOrUpdate() {
    10        log.info("Business2DaoHibernateImpl:saveOrUpdate START");
    11        try {
    12            Thread.currentThread().sleep(ApplicationContextContainer.getRandomSleepTime());
    13        } catch(Throwable th){
    14        }
    15        log.info("Business2DaoHibernateImpl:saveOrUpdate END");
    16    }
    17//...
    18}

  4. Tests
    The project in attachement contains a test class named PerfMeasureAnnotTest:

    view source
    print?
    01public class PerfMeasureAnnotTest {
    02     
    03    public static void main(String[] args) {
    04         
    05        ApplicationContextContainer context = ApplicationContextContainer.getInstance();
    06         
    07        IJdbcUtils jdbcUtils = (IJdbcUtils) context.getBean("JdbcUtilsServiceImpl");
    08        IBusiness1 business1 = (IBusiness1) context.getBean("Business1DaoHibernateImpl");
    09        IBusiness2 business2 = (IBusiness2) context.getBean("Business2DaoHibernateImpl");
    10 
    11        {
    12            jdbcUtils.executeQuery("");
    13            //
    14            business1.delete();
    15            business1.save();
    16            business1.saveOrUpdate();
    17            business1.update();
    18            //
    19            business2.delete();
    20            business2.save();
    21            business2.saveOrUpdate();
    22            business2.update();
    23        }//end-for
    24         
    25    }
    26}

    … os, the outputs in console could be:

    view source
    print?
    0110 avr. 2014 23:23:53 com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl executeQuery
    02INFO: JdbcUtilsServiceImpl:executeQuery START
    0310 avr. 2014 23:23:57 com.ho.test.perf.measure.commons.jdbc.JdbcUtilsServiceImpl executeQuery
    04INFO: JdbcUtilsServiceImpl:executeQuery END
    0510 avr. 2014 23:23:57 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl delete
    06INFO: Business1DaoHibernateImpl:delete START
    0710 avr. 2014 23:23:58 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl delete
    08INFO: Business1DaoHibernateImpl:delete END
    0910 avr. 2014 23:23:58 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl save
    10INFO: Business1DaoHibernateImpl:save START
    1110 avr. 2014 23:24:00 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl save
    12INFO: Business1DaoHibernateImpl:save END
    1310 avr. 2014 23:24:00 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl saveOrUpdate
    14INFO: Business1DaoHibernateImpl:saveOrUpdate START
    1510 avr. 2014 23:24:04 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl saveOrUpdate
    16INFO: Business1DaoHibernateImpl:saveOrUpdate END
    1710 avr. 2014 23:24:04 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    18ATTENTION: **** THE METHOD saveOrUpdate FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1 TOOK 3855 MS (max2000ms). ****
    1910 avr. 2014 23:24:04 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl update
    20INFO: Business1DaoHibernateImpl:update START
    2110 avr. 2014 23:24:08 com.ho.test.perf.measure.commons.dao.hibernate.Business1DaoHibernateImpl update
    22INFO: Business1DaoHibernateImpl:update END
    2310 avr. 2014 23:24:08 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    24ATTENTION: **** THE METHOD update FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness1 TOOK 4895 MS (max2000ms). ****
    2510 avr. 2014 23:24:08 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl delete
    26INFO: Business2DaoHibernateImpl:delete START
    2710 avr. 2014 23:24:10 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl delete
    28INFO: Business2DaoHibernateImpl:delete END
    2910 avr. 2014 23:24:10 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl save
    30INFO: Business2DaoHibernateImpl:save START
    3110 avr. 2014 23:24:11 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl save
    32INFO: Business2DaoHibernateImpl:save END
    3310 avr. 2014 23:24:11 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl saveOrUpdate
    34INFO: Business2DaoHibernateImpl:saveOrUpdate START
    3510 avr. 2014 23:24:16 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl saveOrUpdate
    36INFO: Business2DaoHibernateImpl:saveOrUpdate END
    3710 avr. 2014 23:24:16 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    38ATTENTION: **** THE METHOD saveOrUpdate FROM com.ho.test.perf.measure.commons.dao.hibernate.IBusiness2 TOOK 4213 MS (max3000ms). ****
    3910 avr. 2014 23:24:16 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl update
    40INFO: Business2DaoHibernateImpl:update START
    4110 avr. 2014 23:24:19 com.ho.test.perf.measure.commons.dao.hibernate.Business2DaoHibernateImpl update
    42INFO: Business2DaoHibernateImpl:update END
    4310 avr. 2014 23:24:19 com.ho.test.perf.measure.annotations.AspectPerformanceWatcher calculatePerformance
    44ATTENTION: **** 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

Tags: , , , , , , , , , ,

Leave a Reply

Your email address will not be published.

Time limit is exhausted. Please reload CAPTCHA.

Related Post