本文已参与「新人创造礼」活动,一同开启创造之路。
问题描述
又是来自于呼叫中心的一同案例,感觉全年技能支持最多的就是呼叫中心了,问题一个接一个 。
具体事务场景及问题:在线坐席 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 协议的了解和交互进程还有很多不清楚的当地,之后有空需求进一步研究。