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.
- 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; } - an annotation PerformanceWatcher specifying the class, interface or enum whose the performace must be measured and an admissible threshold (warning duration),
- 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; } } - 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"); } //... } - 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