一个注解解决接口耗时日志的打印

在日常开发中，常常需要统计方法的耗时情况，一般的写法是在进入方法之前，记录一下当前时间戳，在方法最后再用当前时间戳减去进入时候的时间戳就是耗时情况，方法很简单，但不够优雅。
接下来我们用一个注解+AOP的方式来实现这个需求

首先，自定义一个注解 @StopWatch

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * 方法耗时日志
 *
 * @author 敖癸
 * @formatter:on
 * @since 2023/11/29
 */
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface StopWatch {

    /** 日志内容模板, ex: "topic: {}" */
    String value() default "";

    /** 模板参数,支持SpEL表达式, ex: {"#serialNo", "第二个参数"} */
    String[] args() default {};
}

然后再实现一个切面


import cn.hutool.core.lang.Opt;
import com.dmjy.pub.common.StopWatch;
import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.MDC;

/**
 * 耗时日志注解切面
 *
 * @author 敖癸
 * @formatter:on
 * @since 2023/11/29
 */
@Slf4j
@Aspect
@RequiredArgsConstructor
public class StopWatchAspect {

    private static final SpelExpressionParser PARSER = new SpelExpressionParser();
    
    @Around("@annotation(stopWatch)")
    public Object around(ProceedingJoinPoint joinPoint, StopWatch stopWatch) throws Throwable {
        long startTime = System.currentTimeMillis();
        try {
            return joinPoint.proceed();
        } finally {
            long totalMs = System.currentTimeMillis() - startTime;
            MDC.put("costTime", String.valueOf(totalMs));
            String content = buildTemplate(joinPoint, stopWatch);
            content = Opt.ofBlankAble(content).orElseGet(() -> joinPoint.getSignature().toShortString());
            if (log.isDebugEnabled()) {
                log.debug("{}, 执行耗时 {} ms", content, totalMs);
            } else {
                log.info("{}, 执行耗时 {} ms", content, totalMs);
            }
        }
    }


    /**
     * SpEL模板解析
     *
     * @param context     切点的上下文对象
     * @param template    字符串模板
     * @param expressions SpEL参数
     * @return java.lang.String
     * @author 敖癸
     * @since 2024/3/5 - 17:03
     */
    private static String buildTemplate(ProceedingJoinPoint joinPoint, StopWatch stopWatch) {
        String template = stopWatch.value();
        String[] expressions = stopWatch.args();
        if (StrUtil.isNotBlank(template) && expressions != null) {
            EvaluationContext context = buildEvaluationContext(joinPoint)
            Object[] args = Arrays.stream(expressions).map(expression -> {
                if (StrUtil.startWith(expression, "#")) {
                    return PARSER.parseExpression(expression).getValue(context);
                }
                return expression;
            }).toArray();
            template = StrUtil.format(template, args);
        }
        return template;
    }
    
    /**
     * 解析切点的上下文对象
     *
     * @param joinPoint aop切点
     * @return org.springframework.expression.EvaluationContext
     * @author 敖癸
     * @since 2024/3/5 - 17:05
     */
    private static EvaluationContext buildEvaluationContext(ProceedingJoinPoint joinPoint) {
        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        String[] argNames = signature.getParameterNames();
        EvaluationContext context = new StandardEvaluationContext();

        Object[] methodArgs = joinPoint.getArgs();
        for (int i = 0; i < methodArgs.length; i++) {
            context.setVariable(argNames[i], methodArgs[i]);
        }
        return context;
    }
}

使用示例：

    @StopWatch(value = "whatsappUser回调: phone: {}, {}", args = {"#dto.vcPhone", "#dto.isMatch()?\"匹配成功\":\"匹配失败\""})
    public void consumerFunc(WSUserInfoDTO dto) {
        ThreadUtil.sleep(345);
    }