使用stopwatch实现接口的耗时日志输出

待我称王封你为后i 2022-12-09 01:51 273阅读 0赞

### 背景 ###

对接业务逻辑的耗时计算，以前都是使用`System.currentTimeMillis();`,分被获取开始时间和结束时间，最后算出差值来显示执行的耗时。  
spring框架中提供了一个秒表功能——stopwatch，我们可以直接实例化一个stopwatch的对象，调用start和stop方法即可完成时间的差值计算。

### stopWatch的基本使用 ###

*  用法

public static void main(String[] args) throws InterruptedException { 
            // TODO Auto-generated method stub
            StopWatch sw = new StopWatch();
            sw .start("TaskOneName");
            Thread.sleep(1000 * 3);// 任务一模拟休眠3秒钟
            sw .stop();
            sw .start("TaskTwoName");
            Thread.sleep(1000 * 10);// 任务一模拟休眠10秒钟
            sw .stop();
            sw .start("TaskThreeName");
            Thread.sleep(1000 * 10);// 任务一模拟休眠10秒钟
            sw .stop();
     
            System.out.println(sw .prettyPrint());
        }

控制台输出：

StopWatch '': running time (millis) = 22926
    -----------------------------------------
    ms     %     Task name
    -----------------------------------------
    02990  013%  TaskOneName
    09968  043%  TaskTwoName
    09968  043%  TaskThreeName

*  优缺点：
    
     *  优点：
        
         *  spring自带的工具 ，可以直接使用（spring体系均可直接使用）
         *  相比于`System.currentTimeMillis();`更加简洁，方便
         *  可以很直观的展示业务逻辑中不同部分的耗时比例，便于做耗时分析的排查优化
         *  可以指定任务的名称，直观的得到结果
     *  缺点
        
         *  不能同时开启多个task，只有等上一个task结束之后才能调用下一个task的start方法
         *  具有侵入性，如果在接口中调用需要更改多处代码

### 系统日志中引入stopwatch ###

*  上述的基本方式介绍完之后，如果在每个接口中都添加stopwatch组件，显得相当的笨拙，而且如果是放到项目的优化阶段来实现的话，同样会有相当大的工作量，那我们能不能全局的实现接口计时功能呢，下面就来就来介绍一下。
 *  首先，定义切点  
    将你想进行计时统计或者日志输出的内容，定义一个切点，aop可以拦截这些接口的请求，如：

/** * AOP 拦截所有controller */
        @Pointcut("execution(public * cn.buyforyou.aipc.small.api.controller..*.*(..))")
        public void pointCut() { 
        }

我们项目中就拦截了所有的controller方法，将耗时统计放到最外面的请求响应层

*  在日志输出文件中，我们希望在请求前打印出请求参数，并且在响应之后打印输出响应参数，所以这里很明显我们应该使用around注解实现。

@Around("pointCut()")
        public Object parameterCalibration(ProceedingJoinPoint pjp) throws Throwable { 
    
            HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();
            String ip = IpUtil.getIpAddr(request);
    		//计时开始
            StopWatch stopwatch = new StopWatch("pjp");
            stopwatch.start();
            //中间省略若干参数获取的逻辑代码
    		//如果请求参数不为空，则是request日志输出，否则是response日志输出
    		if (!Assert.isEmpty(params)) { 
    		  logger.info("{}||{}||{}||Request ||{}||{}||{}", userInfo.getAppId(), ip, logId, interfaceName,userInfo.getUserId(), JsonUtil.formatJson(reqMap));
    		}else{ 
    		Object rspBody = pjp.proceed();
    		//计时结束
    		stopwatch.stop();
    		//调用stopwatch.getTotalTimeMillis()获取接口响应的耗时
            logger.info("{}||{}||{}||Response||{}||{}||{}||{}ms", userInfo.getAppId(), ip, logId, interfaceName,userInfo.getUserId(), JsonUtil.formatJson(rsp),stopwatch.getTotalTimeMillis());
            return rsp;
    }

日志输出的样例如下：

请求日志输出：

wxd8075440765922db||175.24.19.51||757414972094676992||Request ||CL139||未知用户||{ "deviceType":"ios","tradeTime":"1600623401262","appid":"wxd8075440765922db","token":null,"openid":"1212121"}

响应日志输出：

wxd8075440765922db||175.24.19.51||757414972094676992||Response||CL139||未知用户||{ "rspHead":{ "status":"PR0000","message":null,"rspTime":1600623401606},"rspBody":{ "falg":"0","mobile":null}}||169ms

### 总结 ###

stopwatch在平时的开发中使用并不是很多，当出现效率问题的时候，我们才会去添加秒表监控用于性能分析，但是如果在系统日志中添加耗时显示，那么就能从日志层面直接筛选出耗时比较长的接口信息。缺点就是这种方式的耗时评估颗粒度比较粗，因为一个请求接口后面可能跟着若干个业务方法，这些业务方法的耗时并没有更加直观的展示出来，但是我们还是可以从整体上去筛选的。