阅读全文

⭐⭐⭐ Spring Boot 项目实战	⭐⭐⭐ Spring Cloud 项目实战
《Dubbo 实现原理与源码解析 —— 精品合集》	《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》	《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》	《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》	《Java 面试题 + Java 学习指南》

摘要: 原创出处 blog.csdn.net/w139074301/article/details/116498285 「逍遥大俠」欢迎转载，保留摘要，谢谢！

• 一、情况描述
• 二、问题排查

---

🙂🙂🙂关注**微信公众号：【芋道源码】**有福利：

1. RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表
2. RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址
3. 您对于源码的疑问每条留言都将得到认真回复。甚至不知道如何读源码也可以请教噢。
4. 新的源码解析文章实时收到通知。每周更新一篇左右。
5. 认真的源码交流微信群。

---

一、情况描述

某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资源相关的负责人，对数据库进行了相应的优化，解决了问题