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

一、布景

由于项目需求进行私有化部署，对体系要害事务的接口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监控误导了。