为什么我的接口响应时间这么长？记一次接口响应时间过长问题排查

一、情况描述

某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"))){
        //如果审核通过  刷新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的时间，那么问题到底出在哪呢？

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;
}

这里的aop，我们使用的是同步的方法，只有在aop执行完，接口才会返回

经过日志排查，发现@Log日志入库的时间，耗时2秒多，问题出现在系统日志入库这一步，进一步排查数据库问题

4. 排查数据库问题

mysql自带的库information schema中有张表processlist，可以查看所有的进程

通过查看这张表的数据，发现有一个进程一直在定时执行，经过和同事的咨询沟通，有人写了个定时任务，定时入库数据，占用了数据库资源

最后联系了负责paas资源相关的负责人，对数据库进行了相应的优化，解决了问题