Simple Introduction to AOP - Session 5

This will be a wrap up of the AOP intro, with an example that will comprehensively exercise the concepts introduced in the previous sessions.

The use case is simple, I am going to define a custom annotation, PerfLog, I expect the calls to methods annotated with this annotation to be timed and logged.

Let me start by defining the annotation:

package org.bk.annotations;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Target({ElementType.TYPE, ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface PerfLog {
    
}

Now to annotate some service methods with this annotation:

@Service
public class DefaultInventoryService implements InventoryService{
    
    private static Logger logger = LoggerFactory.getLogger(InventoryService.class);

    
    @Override
    public Inventory create(Inventory inventory) {
        logger.info("Create Inventory called");
        inventory.setId(1L);
        return inventory; 
    }

    @Override
    public List<Inventory> list() {
        return new ArrayList<Inventory>();
    }

    @Override
    @PerfLog
    public Inventory update(Inventory inventory) {
        return inventory;
    }

    @Override
    public boolean delete(Long id) {
        logger.info("Delete Inventory called");
        return true;
    }

    @Override
    @PerfLog
    public Inventory findByVin(String vin) {
        logger.info("find by vin called");
        return new Inventory("testmake", "testmodel","testtrim","testvin" );
    }

    @Override
    @PerfLog
    public Inventory compositeUpdateService(String vin, String newMake) {
        logger.info("composite Update Service called");
        Inventory inventory = findByVin(vin);
        inventory.setMake(newMake);
        update(inventory);
        return inventory;
    }
}

Here three methods of DefaultInventoryService have been annotated with @PerfLog annotation - update, findByVin, compositeUpdateService which internally invokes the methods findByVin and update.

Now for the Aspect which will intercept all calls to methods annotated with @PerfLog and log the time taken for the method call:

package org.bk.inventory.aspect;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Aspect
public class AuditAspect {

    private static Logger logger = LoggerFactory.getLogger(AuditAspect.class);

    @Pointcut("execution(@org.bk.annotations.PerfLog * *.*(..))")
    public void performanceTargets(){}
   

    @Around("performanceTargets()")
    public Object logPerformanceStats(ProceedingJoinPoint joinpoint) {
        try {
            long start = System.nanoTime();
            Object result = joinpoint.proceed();
            long end = System.nanoTime();
            logger.info(String.format("%s took %d ns", joinpoint.getSignature(), (end - start)));
            return result;
        } catch (Throwable e) {
            throw new RuntimeException(e);
        }
    }
}

Here the pointcut expression -

@Pointcut("execution(@org.bk.annotations.PerfLog * *.*(..))")

selects all methods annotated with @PerfLog annotation, and the aspect method logPerformanceStats logs the time taken by the method calls.

To test this:

package org.bk.inventory;

import static org.hamcrest.CoreMatchers.*;
import static org.junit.Assert.*;

import org.bk.inventory.service.InventoryService;
import org.bk.inventory.types.Inventory;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration("classpath:/testApplicationContextAOP.xml")
public class AuditAspectTest {

    @Autowired 
    InventoryService inventoryService;
        
    @Test
    public void testInventoryService() {
        Inventory inventory = this.inventoryService.create(new Inventory("testmake", "testmodel","testtrim","testvin" ));
        assertThat(inventory.getId(), is(1L));
        
        assertThat(this.inventoryService.delete(1L), is(true));
        assertThat(this.inventoryService.compositeUpdateService("vin","newmake").getMake(),is("newmake"));
    }

}

When this test is invoked the output is the following:

2011-09-08 20:54:03,521 org.bk.inventory.service.InventoryService - Create Inventory called
2011-09-08 20:54:03,536 org.bk.inventory.service.InventoryService - Delete Inventory called
2011-09-08 20:54:03,536 org.bk.inventory.service.InventoryService - composite Update Service called
2011-09-08 20:54:03,536 org.bk.inventory.service.InventoryService - find by vin called
2011-09-08 20:54:03,536 org.bk.inventory.aspect.AuditAspect - Inventory org.bk.inventory.service.DefaultInventoryService.findByVin(String) took 64893 ns
2011-09-08 20:54:03,536 org.bk.inventory.aspect.AuditAspect - Inventory org.bk.inventory.service.DefaultInventoryService.update(Inventory) took 1833 ns
2011-09-08 20:54:03,536 org.bk.inventory.aspect.AuditAspect - Inventory org.bk.inventory.service.DefaultInventoryService.compositeUpdateService(String, String) took 1371171 ns

the advice is correctly invoked for findByVin, update and compositeUpdateService.

This sample is available at : git://github.com/bijukunjummen/AOP-Samples.git


Links to all sessions on AOP:
AOP Session 1 - Decorator Pattern using Java Dynamic Proxies
AOP Session 2 - Using Spring AOP - xml based configuration
AOP Session 3 - Using Spring AOP - @AspectJ based configuration - with/without compile time weaving
AOP Session 4 - Native AspectJ with compile time weaving
AOP Session 5 - Comprehensive Example