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