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

ruanjianershu

背景:
客户端请求服务端域名,进行查询操作,偶尔出现200ms+延迟,且对于该请求服务端执行速度4ms左右,此问题非常诡异,决定对此进行研究. 下面记录下当时详细的定位&解决流程
问题定位:
1、分析代码
服务端系统是一个常见的spring-boot web工程,使用了集成的tomcat。分析了代码之后,发现并没有特殊的地方,没有特殊的过滤器或者拦截器,所以初步排除业务代码问题.
2、确定调用链路
image.png
3、问题排查分析
3.1、网络层问题,抓包 (20210701)
确定耗时位置是 客户端调用F5,还是 F5 调用 服务端 ?
3.1.1 服务端ack出现大量 RST
image.png
通过跟踪RST的HTTP 流 发现:在FIN最后一次关闭之后 , 服务端向客户端发送了 FIN 关闭连接的请求,然后服务端又向客户端发了报文导致RST. 抓包如下:
image.png

怀疑是连接不能复用导致的建联耗时,经排查代码发现,客户端未使用连接池,因此 客户端增加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 观察日志:
image.png
客户端发起请求: 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)

image.png

出现大量乱序重传,暂时怀疑是抓包工具镜像延迟导致, 此问题待 使用 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服务器,进入观察
image.png

本次调用 耗时 137ms
抓包:
客户端发送请求 : 2021-07-16 14:10:11.600

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

image.png

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

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

![上传中...]()

之后,我们定位源代码,找到了OrderedRequestContextFilter。
我们查阅了网上的资料后image.png(https://segmentfault.com/a/11...
image.png

在仔细研读了以上问题后,我们开始对我们的服务进行了“监视”:

对客户端进行arthas 的 trace 之后image.png![上传中...]()

这行代码加载了 31 次,一共耗时 140ms. 这里的现象几乎和帖子上的一致
后续我们分析了服务端的包结构,果真存在如下jar包
image.png

到这里,我们决定不再进行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 观察日志如下:
image.png

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

本次耗时不在容器层,为网络波动正常导致.

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、感谢把经验分享出来的大拿们
谢谢大家的帮助

阅读 508

人行天地间 忽如远行客

9 声望
1 粉丝
0 条评论
你知道吗?

人行天地间 忽如远行客

9 声望
1 粉丝
宣传栏