性能问题排查过程

项目场景：

记录一次性能问题排查

---

问题描述

前段时间，测试提出了一个性能问题，然后进行分析，这个接口是一个菜单接口，要求性能比较高，测试环境的请求时间是500并发，2.5s左右，但是实际要求是要1s内的，所以就要对这个问题进行分析。

---

原因分析：

1.代码主要逻辑

第一步我们先分析了该方法的代码，代码逻辑有好几部分，1.在redis获取用户信息 2、对菜单的访问量进行统计功能，并且用到了第一步的用户信息 3.从redis获取菜单信息 4.如果获取到了菜单信息，直接返回，如果获取不到信息，则从数据库查询菜单信息。

2.初步分析

大体看代码逻辑都没啥问题，首先进行了一些初步的日志打印，比如获取用户信息，统计功能，从redis获取菜单信息，都打印了耗时，然后在测试环境测试，发现从redis获取信息基本上都在500ms以上，如果是从数据库查询，时间就更久了基本上要7s左右。

3.初步优化

首先我们进行了能看到的问题进行优化，比如1，在redis获取用户信息，这个必须要做的，就不能省略，2. 访问量的统计，这个和获取菜单功能不是直接相关的，可以放到异步线程池去执行，没有必要也在主线程执行。3.从数据库获取菜单的时候，sql语句关联了一个应用表，有个应用名字需要获取，使用left join的方式，并且在后面有个in操作，in操作有可能是有性能问题的，所以优化了下sql，把where条件查的都是菜单表，所以把这些条件都放到菜单表里面去查，然后再以临时表的方式join应用表，去获取应用表的信息，这样驱动表就是最小集join，可以提高性能，并且检查了索引是否使用正确，是否建立索引。

4.再次测试

做了以上改动后，我们就再次进行测试了，然而结果却不太如意，结果好了一些，但是影响不大，后面我们也分析了，上面的改动能提高一点，但是测试环境本身数据量就不是很大，对于sql的改动是测不出来的，对于异步执行统计倒是节省了一些时间。

5.本地测试

既然环境上测试不出来，然后我们就直接本地测试算了，方便调试问题，本地启动测试500并发，时间是4.5s因为本机电脑是比不上服务器的可以理解，但是不影响调试性能。接着我怀疑是redis的问题，查看日志，发现在请求的过程中多次走了数据库，redis设置过期的时间是3分钟，但是似乎一秒就过期了，为了忽略这个问题的影响，把过期时间设置为不过期，再次测试。

6.再次测试

设置了过期时间后，不再频繁请求数据库了快了1s左右，3.5s,但是还是很慢，

7.分析

看了下载速率是950kb，一个请求的响应大概是2.5kb左右，500并发，也就是1M的数据，950kb是差不多了，带宽不是影响的原因，接着还是继续查看redis，我们用的是jedis，然后我对jedis连接池的参数进行了优化，把try(resource){}改成了使用jedispool.returnResource放回连接池中，连接池参数增加了

        poolConfig.setTimeBetweenEvictionRunsMillis(5000);
        poolConfig.setMinEvictableIdleTimeMillis(60000);

并且把原来只有100个连接改成了500个

    poolConfig.setMaxTotal(500);
    poolConfig.setMaxIdle(500);
    poolConfig.setMinIdle(10);
    poolConfig.setMaxWaitMillis(1000);    

8.测试

再次测试发现减少了1s为2.5s，有了一些优化,后面直接注释掉了获取用户信息，流量统计的代码，测试为1.4s少了1s。

9. 分析

然后怀疑是不是服务器的redis问题，我就本地装了redis去测试，连接我本地的redis，换成我本地的redis后，还是一样，就快到崩溃的边缘了。。。然后看了下redis的版本是3.1.200，怀疑是不是我版本太低了，然后去找了windows 6.0以上的版本安装，调试了一上午，结果windows上找到的安装版本基本都是用不了的，很容易就崩溃退出进程了，后面才发现，redis是不好在windows支持的，然后在本地安装了虚拟机，在虚拟机上安装了redis6.2.5版本，并且开启了多线程支持，了解过redis的应该知道6.0版本后可以开启多线程支持。
在redis.conf文件中把no改为yes，把线程改下，一般和cpu核数一致即可。

# io-threads-do-reads no
# io-threads 4

（后面发现redis版本和多线程的影响几乎为0，不是影响因素）

10.windows参数设置

上面第九步就花了半天多的时间，然后也对wiindows的参数进行了调整
一个是句柄数的设置，一个是tcp连接数的设置，调大些，不要因为这些影响到并发数，具体的参数我发调试连接出来，大家也可以自己找。
句柄数限制

1. https://www.lmlphp.com/user/16721/article/item/460591/
   tcp连接数限制
2. https://blog.imdst.com/windows-xia-dan-ji-zui-da-tcplian-jie-shu/
   （这个也不是问题原因，但是写出来也给大家一个思考的方向）

11. 测试

然后启动项目的时候使用java -jar的方式去启动，排查idea可能的影响，结果还是有优化的最终的结果是1.3s左右，看日志，redis请求花费时间是500ms，这个结果相对于刚开始是优化了很多，但是还是不对劲，才500并发，怎么可能从redis获取的时间这么长，redis不是这么差的，而且也不是bigkey，数据才2.5kb不是大key

12.分析

然后我就继续看日志了，请求一次，然后看完整的请求日志，然后发现日志中有去获取用户信息多次，然后我在代码中搜索该日志，发现之前多租户的代码，对redis连接池进行了一个aop拦截，也就是会拦截redis，对redis的key加上用户的信息，拦截了两次，两个方法都是@around，并且在@around里面又从redis获取了租户信息（redis操作），
也就是每次对redis进行操作，都会执行四次*2，8次操作，因为在切面方法里面又对redis进行了操作，around是前后都执行，这次找到了影响最大的问题了。我直接把这个类注释掉了，再测试

13.测试

再次测试快了非常多，500并发的情况下，redis请求耗时很短，有时候是0ms，可能是真的很快，机器都觉得不耗时了，总耗时100ms的时间，也就是从1.3s到100ms，这个切面花了1s多的时间。

---

解决方案：

最终的解决方案，就是删除掉了redis的切面操作，用其他方式实现了，找到了最终的根因就是对redispool的切面操作导致的，所以各位对切面操作的时候要谨慎啊，特别是对频繁使用的工具类切面。

总结

本次性能优化花费了近一周的时间，最终找到了问题的所在，总结就是性能优化需要对很多东西有了解，包括在测试过程中会对机器的性能进行查看，看看cpu，内存，带宽，磁盘的性能，是不是机器问题限制了并发，还是说是网络问题，还是说是代码问题，代码问题又涉及了刚刚的是否要全部同步操作，sql优化，索引优化，redis连接池优化等，要一个个去分析，看结果当然是很简单，找出来就不容易了。