优雅打印接口调用时长-低调大师

优雅打印接口调用时长

2021-01-12 540

引言

优雅的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[], long, string>&gt; threadLocal = new ThreadLocal&lt;&gt;();

再改造通知部分

    @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源码地址 </string></string></tuple6<string,></string></string>

微信关注我们

原文链接：https://my.oschina.net/chenyunxuan/blog/4892141

转载内容版权归作者及来源网站所有！

低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。

新来的运维这样用HDFS，CIO都懵了···

摘要：本文主要研究了HDFS文件系统的读写流程以及基于MRS在windows客户端下读写HDFS文件的实现。 HDFS（Hadoop分布式文件系统）是Apache Hadoop项目的一个子项目。 HDFS支持海量数据的存储，允许用户把成百上千的计算机组成存储集群，其中的每一台计算机称为一个节点。用户通过HDFS的终端命令可以操作其中的文件和目录，如同操作本地文件系统（如Linux）中的文件一样。用户也可以通过HDFS API或MapReduce来编程访问其中的文件数据。本文主要研究了HDFS文件系统的读写流程以及基于MRS在windows客户端下读写HDFS文件的实现。 1. HDFS的架构和元数据 1.1 HDFS采用master/slaves主从结构模型管理数据，结构模型图如下 1.2 元数据的相关概念 Fsimage：文件系统映射文件，也是元数据的镜像文件（磁盘中），存储某段时间namenode内存元数据信息 Edits log：操作日志文件 1.3 元数据的工作特点 (1) namenode始终在内存中存储元数据,使得“读操作”更加快 (2)写请求时,向edits文件写入日志...

2021-01-12

532

摘要：下面就为大家带来个人认为的常见的烂注释风格。相信作为程序员的大家，只要写代码，就会自己写及看到别人写的代码注释。所以，我们往往会遇到“百花齐放，百家争鸣”般的注释。程序员最讨厌的10件事，0:写注释，1:别人不写注释。作为一个老IT人，看了那么多年代码，也就看了那么多年注释。可以说，好代码不一定有好注释，但烂代码基本和烂注释共存。下面就为大家带来个人认为的常见的烂注释风格，希望能对大家在日后的工作中，带来一丝丝的帮助。排名不分先后： 1. 注释上带联系方式，TODO事项，问题单需求链接等。这种风格其实体现了工程师没有意识去利用好现代的平台技术，还停留在90年代的编码习惯。2020年了，git类软件已经是软件开发的首选代码托管平台了，问题单需求链接和联系方式的最佳位置应该是Git的提交日志上，TODO事项应该使用Git的issue管理。这种注释看到就应该删掉。例如以下两种注释 2. 注释上带有一部分设计内容。这些内容最大的问题是，没人知道它是真是假，更没人知道它是否完整，删掉了吧，又有点可惜，万一有点用呢？不删吧，又看着不舒服。出现这种问题的最大原因是，团队内没有太好的地方承载...

2021-01-12

490

资源下载

更多资源

优质分享App

近一个月的开发和优化，本站点的第一个app全新上线。该app采用极致压缩，本体才4.36MB。系统里面做了大量数据访问、缓存优化。方便用户在手机上查看文章。后续会推出HarmonyOS的适配版本。

Mario

马里奥是站在游戏界顶峰的超人气多面角色。马里奥靠吃蘑菇成长，特征是大鼻子、头戴帽子、身穿背带裤，还留着胡子。与他的双胞胎兄弟路易基一起，长年担任任天堂的招牌角色。

Rocky Linux

Rocky Linux（中文名：洛基）是由Gregory Kurtzer于2020年12月发起的企业级Linux发行版，作为CentOS稳定版停止维护后与RHEL（Red Hat Enterprise Linux）完全兼容的开源替代方案，由社区拥有并管理，支持x86_64、aarch64等架构。其通过重新编译RHEL源代码提供长期稳定性，采用模块化包装和SELinux安全架构，默认包含GNOME桌面环境及XFS文件系统，支持十年生命周期更新。

Sublime Text

Sublime Text具有漂亮的用户界面和强大的功能，例如代码缩略图，Python的插件，代码段等。还可自定义键绑定，菜单和工具栏。Sublime Text 的主要功能包括：拼写检查，书签，完整的 Python API ， Goto 功能，即时项目切换，多选择，多窗口等等。Sublime Text 是一个跨平台的编辑器，同时支持Windows、Linux、Mac OS X等操作系统。