背景

在做性能分析时，API的执行时间是一个显著的指标，这里使用SpringBoot AOP的方式，通过对接口添加简单注解的方式来打印API的执行时间，进而对API性能加以评估。关于Spring AOP的配置，详见Spring Boot AOP 配置。

步骤

声明注解 Time.java

/**
 * 时间记录annotation
 * 标注需要记录时间消耗的方法
 */
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface Timer {
}

声明切面 TimeAspect.java

/**
 * 时间记录切面，收集接口的运行时间
 */
@Aspect
@Component
public class TimeAspect {

    // 修正Timer注解的全局唯一限定符
    @Pointcut("@annotation(com.rainlf.aop.timer.Timer)")
    private void pointcut() {}

    @Around("pointcut()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        // 获取目标Logger
        Logger logger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());

        // 获取目标类名称
        String clazzName = joinPoint.getTarget().getClass().getName();

        // 获取目标类方法名称
        String methodName = joinPoint.getSignature().getName();

        long start = System.currentTimeMillis();
        logger.info( "{}: {}: start...", clazzName, methodName);

        // 调用目标方法
        Object result = joinPoint.proceed();

        long time = System.currentTimeMillis() - start;
        logger.info( "{}: {}: : end... cost time: {} ms", clazzName, methodName, time);

        return result;
    }
}

使用时，在目标方式上加上@Timer即可。

@Timer
public void test() {
    // do something ...
}

备注

如果不使用AOP，可简单添加如下代码。

// 获取毫秒数
long startTime = System.currentTimeMillis();   //获取开始时间
System.out.println("Start...");
doSomeThing();  //测试的代码段
long endTime = System.currentTimeMillis();   //获取结束时间
System.out.println("End... Time cost: " + (endTime - startTime) + "ms");
 
// 获取纳秒数
long startTime = System.nanoTime();   //获取开始时间
System.out.println("Start...");
doSomeThing();  //测试的代码段
long endTime = System.nanoTime();   //获取结束时间
System.out.println("End... Time cost: " + (endTime - startTime) + "ns");


上面是采用注解的方案，不过有人觉得注解不太好，可以换成以下方案：

import org.apache.commons.lang.time.StopWatch;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;
import javax.servlet.http.HttpServletRequest;
/**
 * 声明一个切面,记录每个Action的执行时间
 * @author administrator
 */
@Aspect
@Component
public class LogAspect {

    private static final Logger logger=LoggerFactory.getLogger(LogAspect.class);
    /**
     * 切入点：表示在哪个类的哪个方法进行切入。配置有切入点表达式
     */
    @Pointcut("execution(* com.Xx.xxx..controller.*.*(..))")
    public void pointcutExpression() {
        logger.debug("配置切入点");
    }
    /**
     * 1 前置通知
     * @param joinPoint
     */
    @Before("pointcutExpression()")
    public void beforeMethod(JoinPoint joinPoint) {

        // 开始打印请求日志
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();

        // 打印请求相关参数
        logger.info("===== Start ======");
        // 打印请求 url
        logger.info("URL:{}", request.getRequestURL().toString());
        // 打印 Http method
        logger.info("HTTP Method:{}", request.getMethod());
        // 打印调用 controller 的全路径以及执行方法
        logger.info("Class Method:{}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
        // 打印请求的 IP
        logger.info("IP:{}", request.getRemoteAddr());
        //获取传入目标方法的参数
        logger.info("args={}",joinPoint.getArgs());
    }
    
    /**
     * 2 后置通知
     * 在方法执行之后执行的代码. 无论该方法是否出现异常
     */
    @After("pointcutExpression()") 
    public void afterMethod(JoinPoint joinPoint) {
        logger.debug("后置通知执行了，有异常也会执行");
    }
    
    /**
     * 3 返回通知
     * 在方法法正常结束受执行的代码
     * 返回通知是可以访问到方法的返回值的!
     * @param joinPoint
     * @param returnValue
     */
    @AfterReturning(value = "pointcutExpression()", returning = "returnValue")
    public void afterRunningMethod(JoinPoint joinPoint, Object returnValue) {
        logger.debug("返回通知执行，执行结果：" + returnValue);
    }
    /**
     * 4 异常通知
     * 在目标方法出现异常时会执行的代码.
     * 可以访问到异常对象; 且可以指定在出现特定异常时在执行通知代码
     * @param joinPoint
     * @param e
     */
    @AfterThrowing(value = "pointcutExpression()", throwing = "e")
    public void afterThrowingMethod(JoinPoint joinPoint, Exception e)
    {
        logger.debug("异常通知, 出现异常 " + e);
    }
    
    /**
     * 环绕通知需要携带 ProceedingJoinPoint 类型的参数. 
     * 环绕通知类似于动态代理的全过程: ProceedingJoinPoint 类型的参数可以决定是否执行目标方法.
     * 且环绕通知必须有返回值, 返回值即为目标方法的返回值
     */
    @Around("pointcutExpression()")
    public Object aroundMethod(ProceedingJoinPoint pjd)
    {
        StopWatch clock = new StopWatch();
        //返回的结果
        Object result = null;
        //方法名称
        String className=pjd.getTarget().getClass().getName();
        
        String methodName = pjd.getSignature().getName();
        
        try 
        {
            // 计时开始
            clock.start(); 
            //前置通知
            //执行目标方法
            result = pjd.proceed();
            //返回通知
            clock.stop();
        } catch (Throwable e) 
        {
            //异常通知
            e.printStackTrace();
        }
        //后置通知
        if(!methodName.equalsIgnoreCase("initBinder"))
        {
            long constTime=clock.getTime();
            
            logger.info("["+className+"]"+"-" +"["+methodName+"]"+" 花费时间： " +constTime+"ms");
            
            if(constTime>500)
            {
                logger.error("["+className+"]"+"-" +"["+methodName+"]"+" 花费时间过长，请检查: " +constTime+"ms");
            }
        }
        return result;
    }
}