问题描述

又是来自于呼叫中心的一起案例,感觉全年技术支持最多的就是呼叫中心了,问题一个接一个 🤣 。

具体业务场景及问题:在线坐席 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。

Wireshark网络分析 pdf wireshark网络分析器未响应_网络协议

数据包过滤

图片服务器 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 查看数据包文件信息,图片文件大致的传输方向和大小如下:

Wireshark网络分析 pdf wireshark网络分析器未响应_网络协议_02

TCP 会话中,由于压测程序,客户端 192.168.0.1 产生多条 TCP 流与服务器 192.168.0.10 进行交互,而 192.168.0.10 与 NAS 10.0.0.1 仅存在一条 TCP 会话流。

Wireshark网络分析 pdf wireshark网络分析器未响应_Wireshark网络分析 pdf_03


问题分析

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 四次挥手,完成一次交互。

Wireshark网络分析 pdf wireshark网络分析器未响应_wireshark_04


Wireshark网络分析 pdf wireshark网络分析器未响应_wireshark_05

192.168.0.1 <-> 192.168.0.10 异常交互

那么如何找出请求超时问题呢,所谓超时超时,肯定是落在时间上。同样利用 Delta Time 列,表达式含义为 frame.time_delta_displayed , 并进行大小排序。可以明显看到 TCP Stream 13 存在一个 15s 的大延时,匹配业务日志上反馈的响应延时现象,而其它延时只是 FIN 会话关闭连接时的正常等待时间。

Wireshark网络分析 pdf wireshark网络分析器未响应_网络协议_06

展开 TCP Stream 13 中的数据包,可以看到服务器 192.168.0.10 在客户端 POST 请求之后仅回复了网络 TCP 层面的 ACK,在间隔 15s 之后才发送 HTTP 200 OK 响应的 No. 1190 数据包,远远超过正常传输交互过程中 1ms 的延时。

Wireshark网络分析 pdf wireshark网络分析器未响应_wireshark_07


如果仅从 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 会进行响应,根据本地是否有图片资源缓存的不同,分为以下两种情况:

  1. 如本地有缓存,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 传输图片。
  2. 如本地没有缓存,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 传输图片。

有缓存情况下的数据包交互

Wireshark网络分析 pdf wireshark网络分析器未响应_wireshark_08


中间会穿插有 192.168.0.10 <-> 10.0.0.1 NFS 协议交互的过程,包括 V4 版本下的 Call GETATTR 和 Reply GETATTR ,在 HTTP POST 和 Response 200 OK 之间、以及 HTTP Response 200 OK 和 Continuation 正式开始传输图片数据之间各有一次。


无缓存情况下的数据包交互

Wireshark网络分析 pdf wireshark网络分析器未响应_wireshark_09


相较于有缓存的情况,多了 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 大延时的前后完整数据包,看看发生了什么

Wireshark网络分析 pdf wireshark网络分析器未响应_wireshark_10


可以明显看到在客户端 192.168.0.1 HTTP POST 请求之后,图片服务器 192.168.0.10 与 NAS 服务器 10.0.0.1 之间的交互报文明显增多,存在几个问题:

  1. 192.168.0.10 频繁进行 GETATTR 操作,而且文件句柄发生了变化,由之前的** 0xde** 开头变成了 **0x91 **开头;
  2. 在 Call 和 Reply 的交互中,服务器 192.168.0.10 发生了 Call 请求间隔时长过大的问题,分别为 4.97s、2.47s、7.42s ,加起来约 14.86s , 正好和 15s 大延时匹配,可见真正的问题出现在 HTTP 图片服务器 192.168.0.10 本身

后续过程

Wireshark网络分析 pdf wireshark网络分析器未响应_网络_11

  1. 192.168.0.1 <-> 192.168.0.10 一直进行 ACCESS、GETATTR、LOOKUP 等操作,直至最后请求到 **0xde **文件后,才开始恢复正常;
  2. 从 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 协议的了解和交互过程还有很多不清楚的地方,之后有空需要进一步研究。