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

一、背景

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

二、测试过程

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

jvm参数配置为

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

jmeter参数配置：

thread: 200
Ram-up period: 1
Loop count: 30

三、测试结果

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

四、排查过程

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

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

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

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

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

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

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

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

server:
  tomcat:
    max-threads: 8
    accept-count: 1000
    max-connections: 10000
    min-spare-threads: 8

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

四、复盘

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