记一次接口执行时间和响应时间相差大的排查过程

旧城等待， 2023-10-12 17:02 2阅读 0赞

### 一、背景 ###

因为项目需要进行私有化部署，对系统关键业务的接口tps、qps都有要求，目标值为单台4C\*8G机器qps需要达到250、tps达到200，且响应时间tp99低于300ms。因此利用jmeter对关键接口进行性能测试。

### 二、测试过程 ###

机器配置：4C\*8G(阿里云sae通用型6)

jvm参数配置为

ruby复制代码-Xms5734M -Xmx5734M -Xmn4300M -Xss512k -XX:MetaspaceSize=200M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=85 -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintReferenceGC -XX:+ParallelRefProcEnabled -XX:+HeapDumpOnOutOfMemoryError

jmeter参数配置：

yaml复制代码thread: 200
    Ram-up period: 1
    Loop count: 30

# 三、测试结果 #

通过配置的监控可看到实际qps为15，接口平均响应时间为1.8s，这跟目标要求相差甚远，且与我的估算值也相差很大，因为这个接口我们做了大量的优化，基本不存在直接查询数据库的情况，对数据做了二级缓存(本地缓存+分布式缓存)，并且浏览器接口单次请求响应基本在30ms上下，这30ms包含了从接口返回到页面接收到数据的时间，也就是说服务器接口时间还会比30ms小的多。而实际情况压测情况来看比理论值相差了50倍

![format_png][]

### 四、排查过程 ###

1.查看jvm监控，判断是否jvm参数配置不合理，导致大量的时间在gc。通过监控发现整个过程只有14次youngGC,且没有一次full gc。平均每次youngGC耗时400ms(由于年轻代配置的堆内存较大，也没有细致的对jvm参数调优，这个时间还算正常)。所以基本排除了gc导致接口响应时间长的问题

![format_png 1][]

2.查看cpu监控情况，发现cpu平均使用率为50%左右，最大值为71%，且系统负载也较低，因此也排除cpu的情况

![format_png 2][]

![format_png 3][]

3.根据日志链路追踪查看方法栈调用情况，发现整个接口耗时3s，实际接口处理逻辑只有2ms，并且通过接口日志打印的时间发现也是2ms。

![format_png 4][]

通过调用栈看到整个耗时是在FrameworkServlet.doPost方法上，因此点开源码进行分析，doPost实际执行processRequest方法，通过分析猜测可能finally执行的代码块存在耗时操作(日志打印，日志文件写入等操作？)，而且finally里面最后发布一个RequestHandleEvent事件，表示着这个接口处理完成。所以我订阅了一下这个事件，并event.getProcessingTimeMillis()输出耗时时间，结果发现耗时也是毫秒级，说明finally代码块并不存在耗时逻辑。并且还排除自定义filter的拦截器耗时操作的可能性。

![format_png 5][]

![format_png 6][]

4.怀疑是否是带宽限制导致接口处理慢，由于网络问题无法及时返回，但是通过对此排查，发现网络带宽已经调整到最大，且带宽并未打满，因此不可能是网络的问题，同时通过监控也排除了磁盘io问题

5.到此初步能想到的问题都排查了一遍，于是按照生产jvm的配置在本地启动项目进行压测，发现整个qps要比线上高很多，同时通过任务管理器发现此时电脑cpu已经达到100%

![format_png 7][]

这不禁让我感到疑惑，因为在第二步的时候我就通过阿里云监控排查了机器cpu负载发现并不高，难道是监控的值不准确吗？于是我直接进入线上容器同时进行压测，通过命令查看机器cpu负载情况，结果果真如猜想一样，此时cpu负载持续超过200%，而监控上的负载却只有46%。

![format_png 8][]

到这基本上就已经确认是因为cpu负载高导致的接口响应时间慢，前面说过，压测的这几个接口都属于cpu密集型，而且接口耗时也比较短，所以推断是因为tomcat线程数大(springboot默认线程数为200)，线程之间频繁切换导致的。调整tomcat配置调整为如下，

再重启服务进行压测。

yaml复制代码server:
      tomcat:
        max-threads: 8
        accept-count: 1000
        max-connections: 10000
        min-spare-threads: 8

测试结果为qps正常达到200，平均响应时间为72ms，最大响应时间为151ms；且通过后续压测，qps能够在1000控制平均响应时间为85ms左右

![format_png 9][]

![format_png 10][]

### 四、复盘 ###

其实问题原因并不复杂，也还是常见的那些情况之一，在排查的第二步就已经接近真相，只是被阿里云sae监控误导了。

[format_png]: https://img-blog.csdnimg.cn/img_convert/65b0dc92de4012f8ee0c8b782344d569.webp?x-oss-process=image/format,png
[format_png 1]: https://img-blog.csdnimg.cn/img_convert/f0fb43a5740fa82d02af384fcc573af4.webp?x-oss-process=image/format,png
[format_png 2]: https://img-blog.csdnimg.cn/img_convert/e8255a1bf0b5b07fd692d4132ed8a51b.webp?x-oss-process=image/format,png
[format_png 3]: https://img-blog.csdnimg.cn/img_convert/faac85741fcc64f7dedfad63b077eb8e.webp?x-oss-process=image/format,png
[format_png 4]: https://img-blog.csdnimg.cn/img_convert/f5acdfa0033dc4cbd9411592f29d36e8.webp?x-oss-process=image/format,png
[format_png 5]: https://img-blog.csdnimg.cn/img_convert/0927eb2e5cefa6e8979f2da205707d0d.webp?x-oss-process=image/format,png
[format_png 6]: https://img-blog.csdnimg.cn/img_convert/de9643b50907e2c97e0795406488908b.webp?x-oss-process=image/format,png
[format_png 7]: https://img-blog.csdnimg.cn/img_convert/ca1a6e850ab64510f5945c0a76e9caf9.webp?x-oss-process=image/format,png
[format_png 8]: https://img-blog.csdnimg.cn/img_convert/2d7027d614a560cf5abb6ead4c523dca.webp?x-oss-process=image/format,png
[format_png 9]: https://img-blog.csdnimg.cn/img_convert/2ef2bab2257887ba499a5b2b1d33ad07.webp?x-oss-process=image/format,png
[format_png 10]: https://img-blog.csdnimg.cn/img_convert/92ef0748190e5faa30929a4ea7b12133.webp?x-oss-process=image/format,png