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

背景

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