一、情况描述

某saas应用，在请求一个接口的时候，发现响应时间非常的慢，利用前台google浏览器的F12调试，发现响应时间超过2秒

二、问题排查

项目整体采用前后端分离，前端通过nginx实现负载转发，请求后端接口，所以首先排查是不是前台的问题，发生了某些很耗时的操作。

1. 查看nginx的响应时间

通过查看nginx的日志信息，发现nginx对接口的响应时间，差不多也在2.4秒，排除了前台的问题

因为nginx的性能非常高，所以一般情况下，从nginx到后端，不太可能会耗时这么久

2. 查看后端接口代码

@ApiOperation(value = "获取用户状态", httpMethod = "GET")
@Log("获取用户状态")
@GetMapping("/getUserStatus")
public RetInfo getUserStatus(HttpServletRequest request) {log.info("===============获取用户状态 开始===============");long s = System.currentTimeMillis();RetInfo retInfo = RetInfoUtils.getRetInfoBySuccess();Map<String, String> loginMap = RequestUtils.getLoginMap(request);if(loginMap == null){return RetInfoUtils.getRetInfoByError(CommonConstant.BUS_EXCEPTION_RESULT,"用户未登录");}long start = System.currentTimeMillis();Map<String, String> userInfo = userInfoSrv.getUserInfo(loginMap.get("phone"));log.info("获取用户信息 耗时：" + (System.currentTimeMillis() - start));start = System.currentTimeMillis();if("1".equals(userInfo.get("is_enabled")) && StringUtils.isEmpty(loginMap.get("co_code"))){//如果审核通过  刷新sessionHttpSession session = request.getSession();session.setAttribute("open_session_userinfo", userInfo);session.setMaxInactiveInterval(time);}log.info("刷新session 耗时：" + (System.currentTimeMillis() - start));retInfo.setObject(userInfo.get("is_enabled"));retInfo.setResult(userInfo.get("feed_back"));log.info("===============获取用户状态 结束============耗时： " + (System.currentTimeMillis() - s));return retInfo;
}

后端代码其实也很简单，就是从session里面获取用户登录状态，通过打日志等一些方法，发现这个接口的实际执行时间，在4ms左右，完全达不到2.4s的时间，那么问题到底出在哪呢？

3. 分析aop注解

发现在接口加了一个自定义注解 @Log，这是我们自定义的注解，用于记录接口的调用日志

@Pointcut("@annotation(com.test.annotation.Log)")
public void pointcut() {
}@Around("pointcut()")
public Object around(ProceedingJoinPoint point) {Object result = null;long beginTime = System.currentTimeMillis();try {// 执行方法result = point.proceed();} catch (Throwable e) {log.error("方法执行错误::::{}", e.getMessage());}// 执行时长(毫秒)long time = System.currentTimeMillis() - beginTime;// 保存日志saveLog(point, time, result);return result;
}