AOP for logging and perfomance testing

1. Intro

From wiki, what is AOP ?  :
In computing, aspect-oriented programming (AOP) is a patented^[1] programming paradigm that aims to increase modularity by allowing the separation of cross-cutting concerns. It does so by adding additional behavior to existing code (an advice) without modifying the code itself, instead separately specifying which code is modified via a "pointcut" specification, such as "log all function calls when the function's name begins with 'set'". This allows behaviors that are not central to the business logic (such as logging) to be added to a program without cluttering the code core to the functionality. AOP forms a basis for aspect-oriented software development.

Little bit complicated explanation, as for me :) In shorts, AOP - technology which can give you ability to create for existing code(without it modification) "triggers" (by analogy to DB) . Triggers(aspects) can be activated when program execution, for example reaches some method. That behaviour can be very usefull for : 
1. Logging 
2. Perfomance testing. 
For example we have an application which is working, but, one day, we found that something is working too slow, and we have no idea where exactly. So we decided to add aditional logging with information regarding time of method execution. 
Advantages with using AOP for that purpose are obvious : we have just to create "logger" class without any code changes in our application. 

2. project structure

I created several "levels" to demonstarte logging: 
- UI level : TestUIController
- Service level : TestService
- Dao level : TestDao 

Also : 
- App - main application runner. 
- AopInterceptor - our class which will use AOP for logging 

3. pom.xml file 

Here are just dependencies for spring and aspectj: 

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>com.demien.aoplogging</groupId>
    <artifactId>aoplogging</artifactId>
    <version>1.0-SNAPSHOT</version>

    <dependencies>

        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-context</artifactId>
            <version>4.0.0.RELEASE</version>
        </dependency>

        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjtools</artifactId>
            <version>1.8.6</version>
        </dependency>

    </dependencies>

</project>

4. application context file 

There are few classes with "logic" and logger class. Also I showed that logger can be configured by entering parameters in context file. If logger is not needed anymore - logger bean can be just commented in context file. 

<?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:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="http://www.springframework.org/schema/beans
                           http://www.springframework.org/schema/beans/spring-beans.xsd
                           http://www.springframework.org/schema/aop
                        http://www.springframework.org/schema/aop/spring-aop-3.0.xsd"

        >

    <bean id="dao" class="com.demien.aoplogging.TestDao"/>
    <bean id="service" class="com.demien.aoplogging.TestService">
        <property name="dao">
            <ref bean="dao"/>
        </property>
    </bean>

    <bean id="controller" class="com.demien.aoplogging.TestUIController">
        <property name="service">
            <ref bean="service"/>
        </property>
    </bean>

    <!-- The Aspect itself. -->
    <aop:aspectj-autoproxy />
    <bean id="aopInterceptor" class="com.demien.aoplogging.AopInterceptor">
       
        <constructor-arg>
            <map>
                <entry key="TIME_FORMAT"  value="sec"></entry>
            </map>
        </constructor-arg>
        
    </bean>


</beans>

5. AOP Logger. 

All logic are located in doAround method. Also, for example,  I added logic with parameters which can be passed from context file. Here we can configure format of time intervals : miliseconds/seconds/minutes. 

package com.demien.aoplogging;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import java.util.Date;
import java.util.Map;

@Aspect
public class AopInterceptor {

    enum TIME_FORMAT {ms, sec, min};
    TIME_FORMAT currentTimeFormat=TIME_FORMAT.ms;


    public AopInterceptor() {}

    public AopInterceptor(Map<String, String> params) {
        String timeFormat=params.get("TIME_FORMAT");
        if (timeFormat!=null) {
            currentTimeFormat=TIME_FORMAT.valueOf(timeFormat);
        }
    }

    @Around("execution(* *(..))")
    public void doAround(ProceedingJoinPoint joinPoint) throws Throwable {
        String className=joinPoint.getTarget().getClass().getName();
        String methodName=joinPoint.getSignature().getName();

        Long startTime=getCurrentTime();
        log("Started : ["+className+"] : " + methodName);
        joinPoint.proceed();
        Long endTime=getCurrentTime();

        log("Finished : [" + className + "] : " + methodName+" ExecutionTime is: "+getExecutionInterval(startTime)+currentTimeFormat);
    }

    private Long getCurrentTime() {
        return (new Date()).getTime();
    }

    private Long getExecutionInterval(Long startTime) {
        Long endTime=getCurrentTime();
        Long interval=endTime-startTime;
        switch (currentTimeFormat) {
            case min: interval=interval/60;
            case sec: interval=interval/1000;
            default: break;
        }
        return interval;
    }


    private void log(final String messageToLog)
    {
        // here have to be logging to some specific location
        System.out.println(messageToLog);
    }
}

6. Other classes.

Few very simple classes with dependencies managed by Spring. it's just a simulation of big complex application:   UI is calling controller method, controller is calling service method, service method is calling  dao method. 

package com.demien.aoplogging;

public class TestUIController {
    private TestService service;

    public void setService(TestService service) {
        this.service = service;
    }

    public void doSomeAction() {
            service.doServiceAction();
    }
}

package com.demien.aoplogging;

public class TestService {
    private TestDao dao;

    public void setDao(TestDao dao) {
        this.dao = dao;
    }


    public void doServiceAction() {
        try {
            Thread.sleep(2000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        dao.doDaoAction();
    }
}

package com.demien.aoplogging;

public class TestDao {

    public void doDaoAction(){
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        System.out.println("done!");
    }

}

package com.demien.aoplogging;

import org.springframework.context.support.ClassPathXmlApplicationContext;

public class App {
    public static void main(String[] args) {

        ClassPathXmlApplicationContext context=new ClassPathXmlApplicationContext("/application-context.xml");
        TestUIController controller=(TestUIController)context.getBean("controller");
        controller.doSomeAction();
    }
}

7. Results of execution.

All our executions were logged with timings values:

Started : [com.demien.aoplogging.TestUIController] : doSomeAction
Started : [com.demien.aoplogging.TestService] : doServiceAction
Started : [com.demien.aoplogging.TestDao] : doDaoAction
done!
Finished : [com.demien.aoplogging.TestDao] : doDaoAction ExecutionTime is: 1sec
Finished : [com.demien.aoplogging.TestService] : doServiceAction ExecutionTime is: 3sec

Finished : [com.demien.aoplogging.TestUIController] : doSomeAction ExecutionTime is: 3sec

8.The end. 

Goal is reached. We have a logging without any changes in our business-logic classes - but just by adding AOP logger into application. Source code can be downloaded from here.