问题描述
又是来自于呼叫中心的一起案例,感觉全年技术支持最多的就是呼叫中心了,问题一个接一个 🤣 。
具体业务场景及问题:在线坐席 HTTP 访问 IM 服务端 NAS 中图片时,偶现超时。测试方法是从压力机循环访问图片服务端 HTTP 接口时,请求间隔 1s 以上,循环 1000 次大概会抓到 1 次超时,因此又怀疑内部网络问题导致。
咋能又这样怀疑呢?🤔
问题梳理
网络拓扑
大概也是配合多次的缘故,技术负责人在抛出问题的同时,也提供了在图片服务器端的抓包文件,大概梳理了访问过程如下: 客户端 192.168.0.1 循环POST 请求服务器 192.168.0.10 的图片链接,服务器 192.168.0.10 再去访问存储在 NAS 服务器 10.0.0.1 上的图片资源。
数据流:压测客户端 192.168.0.1 <—> HTTP 图片服务器 192.168.0.10 <—> NAS 服务器 10.0.0.1。
数据包过滤
图片服务器 192.168.0.10 上的抓包文件,由于压测以及部分业务运行的缘故,数据包文件较大,因此例行进行数据包过滤。
考虑到数据包交互对象清晰,通过 IPv4 会话过滤即可,然后导出特定分组,仅保存显示过滤后的数据包文件。
(ip.addr eq 192.168.0.1 and ip.addr eq 192.168.0.10) or (ip.addr eq 192.168.0.10 and ip.addr eq 10.0.0.1)
数据包文件部分统计信息如下,可看出通过合理的过滤方式,数据包大小和数量明显减少,利于之后 Wireshark 加载并分析 。
$ capinfos -csdl 1230.cap
File name: 1230.cap
Packet size limit: file hdr: 262144 bytes
Number of packets: 257 k
File size: 179 MB
Data size: 171 MB
$ capinfos -csdl 1230-01.pcap
File name: 1230-01.pcap
Packet size limit: file hdr: 262144 bytes
Number of packets: 5250
File size: 11 MB
Data size: 11 MB
会话统计信息
通过 Statistics
-> Conversations
查看数据包文件信息,图片文件大致的传输方向和大小如下:
TCP 会话中,由于压测程序,客户端 192.168.0.1 产生多条 TCP 流与服务器 192.168.0.10 进行交互,而 192.168.0.10 与 NAS 10.0.0.1 仅存在一条 TCP 会话流。
问题分析
192.168.0.1 <-> 192.168.0.10 正常交互
简要遍历 192.168.0.1 与 192.168.0.10 各条流内容后,行为和现象基本一致,正常情况下的交互过程如下:
192.168.0.1 HTTP POST 请求 JPG 文件,192.168.0.10 响应 200 OK 后进行传输数据,之后正常完成 TCP 四次挥手,完成一次交互。
192.168.0.1 <-> 192.168.0.10 异常交互
那么如何找出请求超时问题呢,所谓超时超时,肯定是落在时间上。同样利用 Delta Time 列,表达式含义为 frame.time_delta_displayed
, 并进行大小排序。可以明显看到 TCP Stream 13 存在一个 15s 的大延时,匹配业务日志上反馈的响应延时现象,而其它延时只是 FIN 会话关闭连接时的正常等待时间。
展开 TCP Stream 13 中的数据包,可以看到服务器 192.168.0.10 在客户端 POST 请求之后仅回复了网络 TCP 层面的 ACK,在间隔 15s 之后才发送 HTTP 200 OK 响应的 No. 1190 数据包,远远超过正常传输交互过程中 1ms 的延时。
如果仅从 192.168.0.1 <-> 192.168.0.10 交互的情况来说,15s 大延时明显来自于服务器端响应数据过长的问题,但在上面章节曾分析数据流的完整交互过程为:压测客户端 192.168.0.1 <—> HTTP 图片服务器 192.168.0.10 <—> NAS 服务器 10.0.0.1。那么具体服务器 192.168.0.10 的响应过慢,是本身的问题,还是与 10.0.0.1 的交互引发的问题呢?
192.168.0.1 <-> 192.168.0.10 <-> 10.0.0.1 正常交互
以 192.168.0.1 <-> 192.168.0.10 <-> 10.0.0.1 来看,192.168.0.1 HTTP POST 请求 JPG 文件,192.168.0.10 会进行响应,根据本地是否有图片资源缓存的不同,分为以下两种情况:
- 如本地有缓存,192.168.0.10 仅向 NAS 服务器 10.0.0.1 查询图片资源属性(是否有变化之类)等,因压测重复请求同一资源,资源实际无变化,因此 192.168.0.10 <-> 10.0.0.1 短暂交互完成后,192.168.0.10 再向 192.168.0.1 传输图片。
- 如本地没有缓存,192.168.0.10 会向 NAS 服务器 10.0.0.1 请求图片资源,之后经查找目录、权限检查、读操作等请求后, 10.0.0.1 向 192.168.0.10 传输图片资源,完成之后 192.168.0.10 才会继续向 192.168.0.1 传输图片。
有缓存情况下的数据包交互
中间会穿插有 192.168.0.10 <-> 10.0.0.1 NFS 协议交互的过程,包括 V4 版本下的 Call GETATTR 和 Reply GETATTR ,在 HTTP POST 和 Response 200 OK 之间、以及 HTTP Response 200 OK 和 Continuation 正式开始传输图片数据之间各有一次。
无缓存情况下的数据包交互
相较于有缓存的情况,多了 ACCESS 的操作,同时在 HTTP POST 和 Response 200 OK 之后,NFS 10.0.0.1 向 192.168.0.10 传输图片资源,大小为 180938
,在两者完成传输之后,服务器 192.168.0.10 才会继续向 192.168.0.1 传输图片,直至完成。
192.168.0.1 <-> 192.168.0.10 <-> 10.0.0.1 异常交互
那么展开上面 192.168.0.1 <-> 192.168.0.10 异常交互分析中提到的 TCP Stream 13
15s 大延时的前后完整数据包,看看发生了什么
可以明显看到在客户端 192.168.0.1 HTTP POST 请求之后,图片服务器 192.168.0.10 与 NAS 服务器 10.0.0.1 之间的交互报文明显增多,存在几个问题:
- 192.168.0.10 频繁进行 GETATTR 操作,而且文件句柄发生了变化,由之前的** 0xde** 开头变成了 **0x91 **开头;
- 在 Call 和 Reply 的交互中,服务器 192.168.0.10 发生了 Call 请求间隔时长过大的问题,分别为 4.97s、2.47s、7.42s ,加起来约 14.86s , 正好和 15s 大延时匹配,可见真正的问题出现在 HTTP 图片服务器 192.168.0.10 本身。
后续过程
- 192.168.0.1 <-> 192.168.0.10 一直进行
ACCESS、GETATTR、LOOKUP
等操作,直至最后请求到 **0xde **文件后,才开始恢复正常; - 从 No.988 HTTP POST 请求之后,直到 No.1190 才完成 HTTP 200 OK 。
问题总结
之后与呼叫中心技术负责人进一步沟通后,得知该服务器 192.168.0.10 在压测的同时还存在部分生产业务,至此怀疑服务器 192.168.0.10 在前端收到不同客户端的请求之后,再往后请求 NAS 服务器资源时,会产生请求不同挂载文件目录下的文件需求。
考虑到 NFS 协议自身的设计(单条流),需求响应交互,服务器 192.168.0.10 在发起下一个请求时产生了个别延时,造成响应超时,因此需进一步排查服务器系统和 NFS 日志。
排查故障过程中,简单看了下 NFSv4 RFC 7530 。。。323 页,看的脑壳疼,对于 NFS 协议的了解和交互过程还有很多不清楚的地方,之后有空需要进一步研究。