Thursday, September 8, 2011

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})
public @interface PerfLog {
Now to annotate some service methods with this annotation:

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

    public Inventory create(Inventory inventory) {"Create Inventory called");
        return inventory; 

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

    public Inventory update(Inventory inventory) {
        return inventory;

    public boolean delete(Long id) {"Delete Inventory called");
        return true;

    public Inventory findByVin(String vin) {"find by vin called");
        return new Inventory("testmake", "testmodel","testtrim","testvin" );

    public Inventory compositeUpdateService(String vin, String newMake) {"composite Update Service called");
        Inventory inventory = findByVin(vin);
        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;

public class AuditAspect {

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

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

    public Object logPerformanceStats(ProceedingJoinPoint joinpoint) {
        try {
            long start = System.nanoTime();
            Object result = joinpoint.proceed();
            long end = System.nanoTime();
  "%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;

public class AuditAspectTest {

    InventoryService inventoryService;
    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));


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://

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

1 comment:

  1. Laddad's book, AspectJ in Action, describes how to introduce a logger into the class with an aspect. Then, you can have more advices to log the "method called" messages.

    In general, you might want after returning advice and after throwing advice, though this toy implementation does not throw.

    The Spring manuals describe a common set of advice that will let the system retry database operations that might deadlock and time out.