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

作者：Gausst松鼠会 | 2024-03-07 00:50:59

踩

apache tomcat/9.0.62 个别时间接口时间长

点击上方“Java基基”，选择“设为星标”

做积极的人，而不是积极废人！

每天 14:00 更新文章，每天掉亿点点头发...

源码精品专栏

来源：blog.csdn.net/w139074301/

article/details/116498285

一、情况描述

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

基于 Spring Boot + MyBatis Plus + Vue & Element 实现的后台管理系统 + 用户小程序，支持 RBAC 动态权限、多租户、数据权限、工作流、三方登录、支付、短信、商城等功能

项目地址：https://github.com/YunaiV/ruoyi-vue-pro
视频教程：https://doc.iocoder.cn/video/

二、问题排查

项目整体采用前后端分离，前端通过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资源相关的负责人，对数据库进行了相应的优化，解决了问题

欢迎加入我的知识星球，一起探讨架构，交流源码。加入方式，长按下方二维码噢：

已在知识星球更新源码解析如下：

最近更新《芋道 SpringBoot 2.X 入门》系列，已经 101 余篇，覆盖了 MyBatis、Redis、MongoDB、ES、分库分表、读写分离、SpringMVC、Webflux、权限、WebSocket、Dubbo、RabbitMQ、RocketMQ、Kafka、性能测试等等内容。

提供近 3W 行代码的 SpringBoot 示例，以及超 6W 行代码的电商微服务项目。

获取方式：点“在看”，关注公众号并回复 666 领取，更多内容陆续奉上。


文章有帮助的话，在看，转发吧。
谢谢支持哟 (*^__^*）

声明：本文内容由网友自发贡献，不代表【wpsshop博客】立场，版权归原作者所有，本站不承担相应法律责任。如您发现有侵权的内容，请联系我们。转载请注明出处：https://www.wpsshop.cn/w/Gausst松鼠会/article/detail/202565?site