优雅打印接口调用时长 | 七日打卡

引言

优雅的API设计不仅仅是代码层面的书写规范.几乎不可能API开发完毕就能正常投入使用,更多的是对细节的打磨.例如接口的每次执行时间,入参都会在API测试中反复的推敲

思考

如何设计一个方案使开发者能一目了然的可视化接口的处理时间以及入参是否正确呢?

思路

首先想到的是Spring的AOP切面,现在我们编写API接口,一般都会把接口写在controller控制层里,按照不同的业务,分为写在不同业务包下的controller类中.大致的架构如下: 按照这种控制层的编写规范,只需要用切面找到每个业务包下的controller类,监控类下面的每个方法的入参和执行时间,打印在log日志中便可以在控制台中可视化每个接口的实时状态了.

实践

导包

<dependency>
    <!--spring启动包-->
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
     <!--spring aop核心包-->
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

AOP核心

aop的核心在于切点和通知类型.结合我们所需要实现的方案,我们所关注的切点就是每个业务下控制层包的每个类方法. 通知的主要类型分为:

前置通知[Before advice]：在连接点前面执行，前置通知不会影响连接点的执行，除非此处抛出异常。
正常返回通知[After returning advice]：在连接点正常执行完成后执行，如果连接点抛出异常，则不会执行。
异常返回通知[After throwing advice]：在连接点抛出异常后执行。
返回通知[After (finally) advice]：在连接点执行完成后执行，不管是正常执行完成，还是抛出异常，都会执行返回通知中的内容。
环绕通知[Around advice]：环绕通知围绕在连接点前后，比如一个方法调用的前后。这是最强大的通知类型，能在方法调用前后自定义一些操作。环绕通知还需要负责决定是继续处理join point(调用ProceedingJoinPoint的proceed方法)还是中断执行。

这里因为我们需要记录入参和接口处理时间,选用Before 前置通知和Around 环绕通知

定义切点

切面第一步,我们需要找准切点新建RuntimeMethod类,用@Aspect @Component修饰定义这是由spring管理的切面入口类,@Log4j2 注释方便后续打印日志

@Aspect
@Component
@Log4j2
public class RuntimeMethod {
    //定义aopPoint私有方法,用@Pointcut修饰并标识该切面的切点
    //以execution(* com.staging.business.*.controller.*.*(..))为例
    //execution()是切面的主体
    //第一个" * "符号,表示返回值的类型任意
    //com.staging.business表示AOP所切的服务的包名,即需要进行横切的业务类
    //包名后面的" .. ",表示当前包及子包
    //之后的" * ",表示类名，*即所有类
    // .*(..) 表示任何方法名,括号内表示参数,两个点表示匹配任何参数类型
    @Pointcut("execution(* com.staging.business.*.controller.*.*(..))")
    private void aopPoint() {
    } 
}

切面第二步,定义前置和环绕通知,并声明通知的切点为aopPoint()

    /**
     * 功能描述: 前置通知
     */
    @Before("aopPoint()")
    public void before(JoinPoint joinPoint) throws Throwable {
        //在调用切面管理的接口前会进入这里
    }

    /**
     * 功能描述: 环绕通知
     */
    @Around("aopPoint()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {  
        //在before通知后会走入这里,直到返回result对象后,客户端才可以拿到回参
        Object result = joinPoint.proceed();
        return result;
    }

前面两步实现了两个需要用到的通知并简要说明了他的作用.接下来还需要使用到spring包中的ServletRequestAttributes对象用于获取HttpServletRequest对象,获取到我们想要的一些打印参数.

    public void before(JoinPoint joinPoint) throws Throwable {
        //在调用切面管理的接口前会进入这里
        ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = requestAttributes.getRequest();
        Enumeration<String> e = request.getHeaderNames();
        JSONObject headers = new JSONObject();
        if (null != e) {
            while (e.hasMoreElements()) {
                String headerName = e.nextElement();
                Enumeration<String> headerValues = request.getHeaders(headerName);
                while (headerValues.hasMoreElements()) {
                    headers.put(headerName, headerValues.nextElement());
                }
            }
        }
        //参数依次代表请求方法,请求地址,参数,头参数,调用时间
        log.info("-in- {} {} -{}{}",request.getMethod(),request.getRequestURI(),joinPoint.getArgs(),headers.toJSONString()}
    }

接口调用时间也能很轻松的在环绕通知中打印

    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {  
        long begin=System.currentTimeMillis();
        //在before通知后会走入这里,直到返回result对象后,客户端才可以拿到回参
        Object result = joinPoint.proceed();
        long end= System.currentTimeMillis();
        log.info("-out -time:{}ms", end - begin}
        return result;
    }

运行起来,调用API接口,我们都会输出以下日志

    -in- GET /user/info -id=123  header:{"content-length":"0",......}
    -out- -time:91ms
    ......

测试完全没有问题,当然这不是最终版本,尝试放在测试环境,调用的人多起来,就会非常混乱,类似下面的画风

    -in- GET /user/info -id=123  header:{"content-length":"0",......}
    -in- GET /teacher/info -id=123  header:{"content-length":"0",......}
    -out- -time:91ms
    -in- GET /user/info -id=321  header:{"content-length":"0",......}
    -out- -time:191ms
    ......

可以看到问题出现在并发操作上,在同一时间调用多个接口时,日志会乱掉,这可不是我想要的结果.必须想办法解决这个问题.翻阅资料,想到用ThreadLocal线程局部变量以及Tuple元组对象解决这个问题.接下来改造代码. 在RuntimeMethod类中定义一个私有变量ThreadLocal.

    private ThreadLocal<Tuple6<String, String, Object[], String, Long, String>> threadLocal = new ThreadLocal<>();

再改造通知部分

    @Before("aopPoint()")
    public void before(JoinPoint joinPoint) throws Throwable {
        //打印请求体
        ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if (null != requestAttributes) {
            //在loadingThreadLocal用ThreadLocal和Tuple对象存储参数.这样就可以方便的取出接口的必要参数
            loadingThreadLocal(requestAttributes, joinPoint.getArgs());
                log.info("-in- {} {} -{}",
                        threadLocal.get().getT1(),
                        threadLocal.get().getT2(),
                        threadLocal.get().getT6());
                log.info("Method arguments:{} -{}",
                        threadLocal.get().getT3(),
                        threadLocal.get().getT6());
                log.info("Request header:{} -{}",
                        threadLocal.get().getT4(),
                        threadLocal.get().getT6());
        }
    }
    
    @Around("aopPoint()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
         // 调用目标方法
        Object result = joinPoint.proceed();
        String requestUrl = threadLocal.get().getT2();
        // 注意在out的时候,取出调用的接口名称,这样可以用接口名称去方便过滤,就不用害怕日志错乱的问题了.return回参在生产环境中尽量不要加进去,因为是测试阶段排查问题打的日志所以越详细越好.
        log.info("-out- {} return:{} -time:{}ms -{}", requestUrl, JSONObject.toJSONString(result), System.currentTimeMillis() - threadLocal.get().getT5(), threadLocal.get().getT6());
        //接口出参处理
        return delReturnData(result);
    }
    
    private void loadingThreadLocal(ServletRequestAttributes requestAttributes, Object[] args) {
        HttpServletRequest request = requestAttributes.getRequest();
        Enumeration<String> e = request.getHeaderNames();
        JSONObject headers = new JSONObject();
        if (null != e) {
            while (e.hasMoreElements()) {
                String headerName = e.nextElement();
                Enumeration<String> headerValues = request.getHeaders(headerName);
                while (headerValues.hasMoreElements()) {
                    headers.put(headerName, headerValues.nextElement());
                }
            }
        }
        //此处追加了一个调用链的id,可返回客户端,让客户端在下一次请求中带入这个id,方法统计一个业务闭环.
        String businessId = IdUtil.getSnowflake(1, 1).nextIdStr();
        //请求方法,请求地址,参数,头参数,调用时间,调用链id
        threadLocal.set(Tuples.of(request.getMethod(), request.getRequestURI(), args, headers.toJSONString(), System.currentTimeMillis(), businessId));
    }

再看看使用此方案后的接口调用日志

2021-01-11 20:16:39.565 [http-nio-8080-exec-7] INFO  cn.mc.apd[86] - -in- GET /activityArea/getUserPrize -1348604735921459200
2021-01-11 20:16:39.565 [http-nio-8080-exec-7] INFO  cn.mc.appod[90] - Method arguments:[1] -1348604735921459200
2021-01-11 20:16:39.566 [http-nio-8080-exec-7] INFO  cn.mc.app.tood[93] - Request header:{"content-length":"0","idfa":"00000",x-nondec-sign":"d93207ba","host":"80""} -1348604735921459200
2021-01-11 20:16:39.593 [http-nio-8080-exec-7] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[126] - -out- /activityArea/getUserPrize return:{"code":0,"data":{"userActivePrizeRec":"0","message":"成功"} -time:28ms

后记

至此一套简化版的接口入参和接口时长统计方案齐活.大家需要注意的是,此方法会导致冗余日志过多尽量规避在生产环境中使用,可在类头部加入@Profile({"dev", "test"})指定环境.在生产环境中排查可使用阿里爸爸的Arthas或者zipkin链路追踪解决.切记,此方案只是方便排查测试时期错误入参和接口时间过长问题.github源码地址