Spring AOP在函数接口调用性能分析及其日志处理方面的应用

面向切面编程可以实现在不修改原来代码的情况下，增加我们所需的业务处理逻辑，比如：添加日志。本文AOP实例是基于Aspect Around注解实现的，我们需要在调用API函数的时候，统计函数调用的具体信息，包括：函数签名，传入参数，函数处理时间，异常信息拦截等, @Around是可以同时在所拦截方法的前后执行一段逻辑，可以满足我们的需求。

目标对象

目标对象是一个客户管理服务，下面分别是其服务接口定义和具体业务逻辑实现。

API

public interface CustomerManagerService {
    void addCustomer(String customer) throws CustomeExistException;
}

Implementation

public class customerManager implements CustomerManagerService {

    private List<String> list = Lists.newArrayList();

    public void addCustomer(String customer) throws CustomeExistException {
        if (list.contains(customer)) {
            throw new CustomeExistException("Customer exists, repeat operation");
         }
        list.add(customer);
    }
    @Override
    public String toString() {
        return "customerManager{" +
            "list=" + list +
            '}';
    }
}

切面类代理

切面代理可以实现对客户管理服务的控制，在切面类中定义Advice函数，设定切面要增加的业务逻辑。APIProxy定义了一个简单的切面类around advice，作用范围为com.mj.spring.aop.api包下面所有的函数, 当作用域内的函数被调用时会执行aroundAdvice中的业务逻辑。

@Aspect
public class APIProxy {

    private final static Log LOGGER = LogFactory.getLog(APIProxy.class);

    //切面应用范围是在com.mj.spring.aop.api下面所有的接口函数
    @Around("execution(* com.mj.spring.aop.api..*.*(..))")
    public void aroundAdvice(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {

        Signature signature = proceedingJoinPoint.getSignature();
        String args = Arrays.toString(proceedingJoinPoint.getArgs());

        long start = System.currentTimeMillis();
        try {
            proceedingJoinPoint.proceed();
        } catch (Exception e) {
            if (e instanceof CustomeExistException) {
                LOGGER.warn(e.getMessage());
            }
            LOGGER.error(String.format("Method:%s call failed  parameter input:%s",
                    signature,
                    args), e);
        } finally {
            LOGGER.info(String.format("method:%s  parameter input:%s carry_out_time:%s ms",
                    signature, args, System.currentTimeMillis() - start));
        }
    }
}

ProceedingJoinPoint接口

ProceedingJoinPoint接口提供了很多实用的函数，便于用户获取应用切面点函数具体的信息。下面四个接口是我们用的比较多的：

1. Object proceed() throws Throwable; 调用要拦截的方法
2. Object proceed(Object[] var1) throws Throwable;调用要拦截的方法，可以自定义传入参数
3. Object[] getArgs();获取拦截方法的传入参数
4. Signature getSignature();获取拦截方法的方法签名

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:aop="http://www.springframework.org/schema/aop"
	   xsi:schemaLocation="http://www.springframework.org/schema/beans
			http://www.springframework.org/schema/beans/spring-beans-3.1.xsd
			http://www.springframework.org/schema/aop
			http://www.springframework.org/schema/aop/spring-aop-3.1.xsd">
    <!-- 使能AOP-->
    <aop:aspectj-autoproxy/>


    <!--声明切面类 -->
    <bean id="apiProxy" class="com.mj.spring.aop.aspect.APIProxy"></bean>
    <!-- 声明customerManager bean-->
    <bean id="customerManagerService" class="com.mj.spring.aop.impl.customerManager"></bean>
	
</beans>

测试类

public class customerManagerTest {
    private ApplicationContext applicationContext = null;

    @Before
    public void setUp() throws Exception {
        applicationContext = new ClassPathXmlApplicationContext("ApplicationContext.xml");
    }

    @Test
    public void should_print_normal_log_info_when_add_a_customer() throws Exception {
        CustomerManagerService customerManagerService = (CustomerManagerService) applicationContext.getBean("customerManagerService");
        customerManagerService.addCustomer("Mengya");
    }

    @Test
    public void should_print_warn_log_info_when_add_a_same_customer_twice() throws Exception {
        CustomerManagerService customerManagerService = (CustomerManagerService) applicationContext.getBean("customerManagerService");
        customerManagerService.addCustomer("Mengya");
        customerManagerService.addCustomer("Mengya");
    }
}

运行第一个Test，接口调用信息：

2015-09-24 18:25:42,000 INFO [com.mj.spring.aop.aspect.APIProxy] - method:void com.mj.spring.aop.api.CustomerManagerService.addCustomer(String)  parameter input:[Mengya] carry_out_time:0 ms

运行第二个Test，异常报错信息会被拦截下来：

2015-09-24 18:26:58,885 INFO [com.mj.spring.aop.aspect.APIProxy] - method:void com.mj.spring.aop.api.CustomerManagerService.addCustomer(String)  parameter input:[Mengya] carry_out_time:0 ms
2015-09-24 18:26:58,886 WARN [com.mj.spring.aop.aspect.APIProxy] - Customer exists, repeat operation
2015-09-24 18:26:58,888 ERROR [com.mj.spring.aop.aspect.APIProxy] - Method:void com.mj.spring.aop.api.CustomerManagerService.addCustomer(String) call failed  parameter input:[Mengya]
com.mj.spring.aop.impl.CustomeExistException: Customer exists, repeat operation
	at com.mj.spring.aop.impl.customerManager.addCustomer(customerManager.java:16)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
	at com.mj.spring.aop.aspect.APIProxy.aroundAdvice(APIProxy.java:30)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:68)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
	at com.sun.proxy.$Proxy12.addCustomer(Unknown Source)
	at com.mj.spring.aop.impl.customerManagerTest.should_print_normal_log_info_when_add_a_same_customer_twice(customerManagerTest.java:30)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:157)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:78)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:212)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:68)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:140)
2015-09-24 18:26:58,905 INFO [com.mj.spring.aop.aspect.APIProxy] - method:void com.mj.spring.aop.api.CustomerManagerService.addCustomer(String)  parameter input:[Mengya] carry_out_time:20 ms

Console窗口日志无法打印问题

使用log4j有时候我们会遇到日志无法在concole窗口打印的问题，console窗口提示日志配置异常。

log4j:WARN No appenders could be found for logger (org.springframework.core.env.StandardEnvironment).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

解决这个问题很简单，和src平级目录创建log4j.properties文件，输入下面内容，就可以解决这个问题了

log4j.rootLogger=INFO,stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %m%n

Conslusion

本文讲解了Spring AOP在函数接口调用性能分析及其日志处理方面的应用，希望能够给大家带来一些帮助和启发。