一、情况描述
某saas应用,在请求一个接口的时候,发现响应时间非常的慢,利用前台google浏览器的F12调试,发现响应时间超过2秒
二、问题排查
项目整体采用前后端分离,前端通过nginx实现负载转发,请求后端接口,所以首先排查是不是前台的问题,发生了某些很耗时的操作。
- 查看nginx的响应时间
通过查看nginx的日志信息,发现nginx对接口的响应时间,差不多也在2.4秒,排除了前台的问题
因为nginx的性能非常高,所以一般情况下,从nginx到后端,不太可能会耗时这么久
-
查看后端接口代码
@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”))){
//如果审核通过 刷新session
HttpSession 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的时间,那么问题到底出在哪呢? -
分析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;
}
这里的aop,我们使用的是同步的方法,只有在aop执行完,接口才会返回
经过日志排查,发现@Log日志入库的时间,耗时2秒多,问题出现在系统日志入库这一步,进一步排查数据库问题
- 排查数据库问题
mysql自带的库information schema中有张表processlist,可以查看所有的进程
通过查看这张表的数据,发现有一个进程一直在定时执行,经过和同事的咨询沟通,有人写了个定时任务,定时入库数据,占用了数据库资源
最后联系了负责paas资源相关的负责人,对数据库进行了相应的优化,解决了问题