Spring AOP 切面编程记录日志和接口执行时间

最近客户现在提出系统访问非常慢，需要优化提升访问速度，在排查了nginx、tomcat内存和服务器负载之后，判断是数据库查询速度慢，进一步排查发现是因为部分视图和表查询特别慢导致了整个系统的响应时间特别长。知道了问题之后，就需要对查询比较慢的接口进行优化，但哪些接口需要优化、哪些不需要呢？只能通过日志里的执行时间来判断，那么如何才能知道每一个接口的执行时间呢？

对于这个问题，想到了使用动态代理的方式统一记录方法的执行时间并打印日志，这样就能很直观、方便的看到每个接口的执行时间了。

由于使用的是spring框架，对象都是由spring统一管理的，所以最后使用的是 Spring AOP 切面编程来统一记录接口的执行时间，具体代码如下（基于注解的方式）：

@Component
@Aspect
public class AopLoggerAspect {

    private static final Logger logger = Logger.getLogger(AopLoggerAspect.class);

    @Pointcut("execution(public * com.iflytek.credit.platform.*.service.impl.*Impl.*(..)) || execution(public * com.iflytek.credit.platform.*.controller.*Controller.*(..))")
    public void pointCut() {

    }

    @Before("pointCut()")
    public void boBefore(JoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP before ");
    }

    @After("pointCut()")
    public void doAfter(JoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP after ");
    }

    @AfterReturning(pointcut = "pointCut()",returning = "result")
    public void afterReturn(JoinPoint joinPoint, Object result) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP after return ,and result is : " + result.toString());
    }

    @AfterThrowing(pointcut = "pointCut()",throwing = "throwable")
    public void afterThrowing(JoinPoint joinPoint, Throwable throwable) {
        String methodName = joinPoint.getSignature().getName();
        logger.info("Method Name : [" + methodName + "] ---> AOP after throwing ,and throwable message is : " + throwable.getMessage());
    }

    @Around("pointCut()")
    public Object around(ProceedingJoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        try {
            logger.info("Method Name : [" + methodName + "] ---> AOP around start");
            long startTimeMillis = System.currentTimeMillis();
            //调用 proceed() 方法才会真正的执行实际被代理的方法
            Object result = joinPoint.proceed();
            long execTimeMillis = System.currentTimeMillis() - startTimeMillis;
            logger.info("Method Name : [" + methodName + "] ---> AOP method exec time millis : " + execTimeMillis);
            logger.info("Method Name : [" + methodName + "] ---> AOP around end , and result is : " + result.toString());
            return result;
        } catch (Throwable te) {
            logger.error(te.getMessage(),te);
            throw new RuntimeException(te.getMessage());
        }
    }

}

 

首先，需要创建一个类，然后在类名上加上两个注解

@Component
@Aspect

@Component 注解是让这个类被spring当作一个bean管理，@Aspect 注解是标明这个类是一个切面对象

类里面每个方法的注解含义如下：

@Pointcut  用于定义切面的匹配规则，如果想要同事匹配多个的话，可以使用 || 把两个规则连接起来，具体可以参照上面的代码

@Before  目标方法执行前调用

@After  目标方法执行后调用

@AfterReturning  目标方法执行后调用，可以拿到返回结果，执行顺序在 @After 之后

@AfterThrowing  目标方法执行异常时调用

@Around  调用实际的目标方法，可以在目标方法调用前做一些操作，也可以在目标方法调用后做一些操作。使用场景有：事物管理、权限控制，日志打印、性能分析等等

以上就是各个注解的含义和作用，重点的两个注解就是 @Pointcut 和 @Around 注解，@Pointcut用来指定切面规则，决定哪些地方使用这个切面；@Around 会实际的去调用目标方法，这样就可以在目标方法的调用前后做一些处理，例如事物、权限、日志等等。

需要注意的是，这些方法的执行顺序：

执行目标方法前： 先进入 around ，再进入 before 
目标方法执行完成后： 先进入 around ，再进入 after ，最后进入 afterreturning 

实际的日志信息如下，可以看出各个方法的执行顺序：

 

另外，使用spring aop 需要在spring的配置文件加上以下这行配置，以开启aop ：

<aop:aspectj-autoproxy/>

同时，maven中需要加入依赖的jar包：

<dependency>
   <groupId>org.aspectj</groupId>
   <artifactId>aspectjrt</artifactId>
   <version>1.6.12</version>
</dependency>
<dependency>
   <groupId>org.aspectj</groupId>
   <artifactId>aspectjweaver</artifactId>
   <version>1.6.12</version>
</dependency>

总结一下，Spring AOP 其实就是使用动态代理来对切面层进行统一的处理，动态代理的方式有：JDK动态代理和 cglib 动态代理，JDK动态代理基于接口实现， cglib 动态代理基于子类实现。spring默认使用的是JDK动态代理，如果没有接口，spring会自动的使用cglib动态代理。