客户端请求服务端莫名出现超时客户端请求服务端莫名出现超

背景：
客户端请求服务端域名，进行查询操作，偶尔出现200ms+延迟，且对于该请求服务端执行速度4ms左右，此问题非常诡异，决定对此进行研究. 下面记录下当时详细的定位&解决流程
问题定位：
1、分析代码
服务端系统是一个常见的spring-boot web工程，使用了集成的tomcat。分析了代码之后，发现并没有特殊的地方，没有特殊的过滤器或者拦截器，所以初步排除业务代码问题.
2、确定调用链路

文章图片

3、问题排查分析
3.1、网络层问题，抓包 (20210701)
确定耗时位置是客户端调用F5，还是 F5 调用服务端？
3.1.1 服务端ack出现大量 RST

文章图片

通过跟踪RST的HTTP 流发现：在FIN最后一次关闭之后 , 服务端向客户端发送了 FIN 关闭连接的请求，然后服务端又向客户端发了报文导致RST. 抓包如下:

文章图片

怀疑是连接不能复用导致的建联耗时，经排查代码发现，客户端未使用连接池，因此客户端增加HTTP 连接池来解决此类问题 .
3.1.2 网络耗时长，抓包
经过2.1.1 的优化之后，还是存在调用超时的现象，现在我们通过wireshark 抓包观察，发现客户端与F5之间无超时情况，客户端发出请求后，随机收到了F5的ACK；F5 发出请求后，间隔40ms 收到服务端的ack , 此处就引出了另外一个问题，就是 TCP 神奇的40 ms (https://cloud.tencent.com/dev... 大家可以自行去备注的链接去研读，这里篇幅时间有限，不在进行赘述 .
3.2、网络层无波动，考虑应用层
开始考虑服务端 socket 连接和服务端容器方向
3.2.1. 服务器socket连接
跳过F5 负载，直接使用IP:port 的方式请求服务端（20210713）
20210714 观察日志:

文章图片

客户端发起请求: 2021-07-14 14:05:02.670
服务端收到请求: 2021-07-14 14:05:02.939
服务端返回结果: 2021-07-14 14:05:03.280
客户端收到返回: 2021-07-14 14:05:03.280
客户端整体请求耗时: 610ms 服务端程序耗时: 546ms
对服务请求抓包进行分析(d1134184-2a52-4915-8e63-7f32ed6d274d)

文章图片

出现大量乱序重传，暂时怀疑是抓包工具镜像延迟导致, 此问题待使用 tcpdump 抓包后给出结论.
20210716 tcpdump 抓包
确认了以上问题是抓包工具导致 .
3.2.2. 服务端容器
服务端使用的容器是 tomcat 8.5, 内存是NIO 模型，不存在阻塞情况。对于 tomcat NIO 来说，是由一系列框架类和数据读写类来组成的，同时这些类运行在不同的线程中，共同维持整个 tomcat NIO 架构。包括原始 socket 监听的acceptor 线程，监测注册在原始 scoket 上的事件是否发生的 poller thread 事件线程，进行数据读写和运行 servlet API 的 tomcat io 线程。当数据需要多次读写的时候，监测注册在原始 scoket 上的读写事件的 block poller 事件线程。即 NIO 整体架构运行着4种线程：
Acceptor 线程
Poller 线程
Tomcat IO 线程
BlockPoller 线程
这里要注意:
tomcat有一个acceptor线程来accept socket连接，然后有工作线程来进行业务处理。对于client端的一个请求进来，流程是这样的：tcp的三次握手建立连接，建立连接的过程中，OS维护了半连接队列(syn队列)以及完全连接队列(accept队列)，在第三次握手之后，server收到了client的ack，则进入establish的状态，然后该连接由syn队列移动到accept队列。tomcat的acceptor线程则负责从accept队列中取出该connection，接受该connection，然后交给工作线程去处理(读取请求参数、处理逻辑、返回响应等等；如果该连接不是keep alived的话，则关闭该连接，然后该工作线程释放回线程池，如果是keep alived的话，则等待下一个数据包的到来直到keepAliveTimeout，然后关闭该连接释放回线程池)，然后自己接着去accept队列取connection(当当前socket连接超过maxConnections的时候，acceptor线程自己会阻塞等待，等连接降下去之后，才去处理accept队列的下一个连接)。acceptCount指的就是这个accept队列的大小。
具体tomcat的线程的介绍: https://segmentfault.com/a/11...
经过对服务端代码审查发现，未曾配置过tomcat线程相关参数，即一直使用默认值
3.2.2.1 调整原服务容器参数(20210708)
这里怀疑服务端线程设置过小，一直在创建新的线程上消耗时间，所以对服务端配置进行调整，调整如下：
server:
port: ${port:8080}
tomcat:

max-threads: 1000 min-spare-threads: 500 accept-count: 1000 max-connections: 10000

connection-timeout: 300000
投产后发现，客户端仍存在原来的情况，此次调整失败.
3.2.2.2 下线服务端A服务器仅供客户端IP调用 (20210716)
怀疑accept-count 设置过大，导致请求一直在队列中，但是还未满1000，不会创建新的线程导致。20210716 摘除服务端的A服务器，进入观察

文章图片

本次调用耗时 137ms
抓包:
客户端发送请求 : 2021-07-16 14:10:11.600
【客户端请求服务端莫名出现超时】

文章图片

服务端接收请求在 14:10:11.602897

文章图片

请求在服务端容器耗时
为了验证上述判断，我们打印一下tomcat的access_log日志，并保持服务端A服务器对外下线状态(20210720)
20210721 观察发现，
tomcat 容器收到请求: 2021-07-21 14:18:14.872
servlet 开始执行: 2021-07-21 14:18:15.014

3.2.2.3 看见光明，升级 tomcat 容器
本次定位问题为 tomcat 容器导致. 但是究竟问题是在tomcat的什么地方呢？我们继续往下找
首先这里我们查了下客户端的请求量，每分钟不到1000，暂时不考虑tomcat队列积压的问题
然后，这里打算寄出我们的神器了，打开debug日志, 进行观察，看看会不会有惊喜(其实这里已经怀疑springBoot 对 tomcat 的支持不是那么的友好)
过不期然，再打开了debug日志之后，我们发现了这样的一个问题
![上传中...]()
之后，我们定位源代码，找到了OrderedRequestContextFilter。
我们查阅了网上的资料后

文章图片
(https://segmentfault.com/a/11...

文章图片

在仔细研读了以上问题后，我们开始对我们的服务进行了“监视”：
对客户端进行arthas 的 trace 之后![上传中...]()
这行代码加载了 31 次，一共耗时 140ms. 这里的现象几乎和帖子上的一致
后续我们分析了服务端的包结构，果真存在如下jar包

文章图片

到这里，我们决定不再进行trace, 直接升级tomcat版本到 8.5.40
升级方法如下:
compile('org.springframework.boot:spring-boot-starter-web') {

exclude module: "spring-boot-starter-tomcat" } compile 'org.apache.tomcat.embed:tomcat-embed-core:8.5.40' compile 'org.apache.tomcat.embed:tomcat-embed-el:8.5.40'

// compile 'org.apache.tomcat.embed:tomcat-embed-logging-juli:+'

compile 'org.apache.tomcat.embed:tomcat-embed-logging-juli:8.0.37' compile 'org.apache.tomcat.embed:tomcat-embed-websocket:8.5.40'

升级于20210722 上线部署
20210723 观察日志如下:

文章图片

观察一天，调用耗时均有明显降低，但仍然偶有时间长(超过10ms)现象 , 日志分析如下:

文章图片

本次耗时不在容器层，为网络波动正常导致.
3.2.2.4 更换容器为undertow 容器
3.3 最终定位为Tomcat embed Bug(以下摘自 https://segmentfault.com/a/11...
3.3.1 为什么每次请求会加载Jar包内的静态资源
关键在于org.apache.catalina.mapper.Mapper#internalMapWrapper这个方法，该版本下处理请求的方式有问题，导致每次都校验静态资源。
3.3.2 为什么连续请求不会出现问题
因为Tomcat对于这种静态资源的解析是有缓存的，优先从缓存查找，缓存过期后再重新解析。具体参考org.apache.catalina.webresources.Cache，默认过期时间ttl是5000ms。
3.3.3 为什么本地不会复现
其实确切的说，是通过spring-boot打包插件后不能复现。由于启动方式的不同，tomcat使用了不同的类去处理静态资源，所以没问题
解决方案：
1、升级tomcat-embed版本即可，出现bug的版本为
springBoot:1.5.9 tomcat: Apache Tomcat/8.5.23
升级tomcat embed版本至8.5.40+即可解决此问题，新版本已经修复了
2、升级spring boot版本
springboot 2.1.0.RELEASE中的tomcat embed版本已经大于8.5.31了，所以直接将springboot升级至该版本及以上版本就可以解决此问题
致谢
1、感谢为解决此次问题提供帮助的同事们
2、感谢把经验分享出来的大拿们
谢谢大家的帮助