问题背景
沿用之前文章的开头说明,应用传输慢是一种比较常见的问题,慢在哪,为什么慢,有时候光从网络数据包分析方面很难回答的一清二楚,毕竟不同的技术方向专业性太强,全栈大佬只能仰望,而我们能做到的是在专注于自身的专业方向之外,尽量扩展知识面,学会找出问题的规律,并提出可能的解决建议。
本篇案例是一个应用开发团队提出的“缓慢”问题,分别在发送和接收端抓取了相关数据包,“SendSideFinal.pcap” 以及 “RcvSideFinal.pcap”,实际上部分场景下的数据包分析确实需要在多点捕获,包括发送端或者接收端,甚至于中间路径的多个节点,这样更有助于网络问题分析。
案例取自 SharkFest 2010《Wireshark in the Large Enterprise》
问题信息
跟踪文件基本信息如下:
λ capinfos SendSideFinal.pcap RcvSideFinal.pcap
File name: SendSideFinal.pcap
File type: Wireshark/tcpdump/... - pcap
File encapsulation: Ethernet
File timestamp precision: microseconds (6)
Packet size limit: file hdr: 65535 bytes
Packet size limit: inferred: 70 bytes
Number of packets: 220
File size: 18 kB
Data size: 46 kB
Capture duration: 95.639823 seconds
First packet time: 2009-09-11 05:24:51.255133
Last packet time: 2009-09-11 05:26:26.894956
Data byte rate: 485 bytes/s
Data bit rate: 3885 bits/s
Average packet size: 211.14 bytes
Average packet rate: 2 packets/s
SHA256: 104aeea149181060e3d3c744bb9ea4aea13c0be832e92e0852abf173df253f77
RIPEMD160: 3d5d768f175a949e818c9f1160688c8854234b59
SHA1: 1e117af53e4bbdd9b0cb3636117374a191c4ebf3
Strict time order: True
Number of interfaces in file: 1
Interface #0 info:
Encapsulation = Ethernet (1 - ether)
Capture length = 65535
Time precision = microseconds (6)
Time ticks per second = 1000000
Number of stat entries = 0
Number of packets = 220
File name: RcvSideFinal.pcap
File type: Wireshark/tcpdump/... - pcap
File encapsulation: Ethernet
File timestamp precision: microseconds (6)
Packet size limit: file hdr: 65535 bytes
Packet size limit: inferred: 70 bytes
Number of packets: 213
File size: 18 kB
Data size: 45 kB
Capture duration: 91.744055 seconds
First packet time: 2009-09-11 05:24:55.248731
Last packet time: 2009-09-11 05:26:26.992786
Data byte rate: 492 bytes/s
Data bit rate: 3936 bits/s
Average packet size: 211.94 bytes
Average packet rate: 2 packets/s
SHA256: 15731bbc644d0e2c1a304ef955ec62052d7fae377d3d8a420fc566e5be819404
RIPEMD160: d28207f0689fb74106d4d206c94cd305dd30cb2a
SHA1: bf129e7e359676a3d2cb496a8fa7169344356c7d
Strict time order: True
Number of interfaces in file: 1
Interface #0 info:
Encapsulation = Ethernet (1 - ether)
Capture length = 65535
Time precision = microseconds (6)
Time ticks per second = 1000000
Number of stat entries = 0
Number of packets = 213
数据包跟踪文件在 linux 上通过 tcpdump 所捕获,两端数据包数量分别为 220 和 213 个,长度截断为 70 字节。发送端文件数据大小 46k 字节,捕获时长 95.64 秒,平均速率 3885 bps,而接收端文件数据大小 45k 字节,捕获时长 91.74 秒,平均速率 3936 bps,总体来说两端信息基本匹配,确实速率很低。
专家信息如下,可以看到异常的简洁,没有 Warning 相关信息,可见传输缓慢的问题并不是常见的丢包导致重传所引起。
问题分析
首先从发送端 “SendSideFinal.pcap” 跟踪文件开始,展开数据包信息如下,可以看到数据包文件缺失 TCP 三次握手阶段的数据包,仅有数据传输 PSH/ACK 相关,最后以 RST 数据包结束。
其中 TCP 会话完整性分析中 tcp.completeness == 44
也说明了相关情况,44 = 4 + 8 + 32,其中 4 为 ACK,8 为 DATA,32 为 RST。
TCP 会话完整性分析说明详见《 Wieshark 提示和技巧 | TCP 会话完整性分析》
另从上面数据包交互来看,两端实际都有数据分段在传输,如果不是数据包文件的名字 “SendSideFinal.pcap” 以及 “RcvSideFinal.pcap”,也确实不好辨别哪个是发送端,哪个是接收端。从我个人的角度来说,定义出哪个是客户端,哪个是服务器端,以及两个文件的捕获点,可能会更加简单些。
首先因为是 TCP 传输,所以 TCP 端口 60301 和 7609 一般就可以分辨出,客户端 10.10.10.10,服务器 192.168.1.1。
其次如何判断这两个数据包跟踪文件分别是在哪里捕获的呢 ?可以通过两个字段值分析,一个 TTL,一个 ACK 间隔时间。
- “SendSideFinal.pcap” 中 192.168.1.1 TTL 为 64,64 一般为 linux 系统的默认值,逐跳减 1 ,既然为 64,说明捕获点是在本地或是靠近本地侧(譬如上连接入交换机上),也就是在 192.168.1.1 ;
- “SendSideFinal.pcap” 中 ACK 间隔时间,ACK 对于数据分段的确认,譬如 No.5 确认 No.4 ,以及 No.2 确认 No.1,No.11 确认 No.10,间隔时间都极短,0.1-0.2ms,相对于中间网络传输的时间很小,而如果反过来判断,很多数据包交互时间都无法说通,所以也可判断捕获点是在本地或是靠近本地侧,也就是 192.168.1.1。
也有同学也会注意 No.7 以及 No.9 的间隔时间,为什么同样是 192.168.1.1 也是 ACK,而不考虑在内?首先简单来说,就是上面提到的,如果反过来判断,现象不匹配;其次细想下,No.7 只是发送端发送数据间隔的时间,譬如像浏览网页,停顿几秒再去点击一次的间隔,综合判断下来的结论就是 “SendSideFinal.pcap” 是在服务器端 192.168.1.1 所捕获,而 “RcvSideFinal.pcap” 是在客户端 10.10.10.10 所捕获。而剩下来的一个 No.9 ,不同于绝大部分的正常传输规律,那么它就真的是属于有问题的那一个了。
“SendSideFinal.pcap” 中数据交互规律如下图,总结一番:
- 服务器端 192.168.1.1,连续发送三次 Length 为 179 的数据帧后,再发送一个 Length 为162 的数据帧后,最后一个 ACK;(第一组未抓全)
- 客户端 10.10.10.10,发送一次 Length 为 152 的数据帧后发送一个 ACK,连续三次后 ,再发送一个 Length 为 189 的数据帧;
- 汇总以上,以客户端 10.10.10.10 发起,Length 为 152、179、66 的一组数据帧,连续交互三次后, 再以服务器端 192.168.1.1 所发起的 Length 162、189、66 的一组数据帧做为结束。(当然由于未捕获到最起初的数据包,此一组数据帧也可能为起始)
找到 “SendSideFinal.pcap” 数据包传输的规律后,同时再结合“RcvSideFinal.pcap”对比分析,就比较容易识别出缓慢的问题所在,慢在哪。
- 通过数据包的 ip.id 字段,可以找到两个数据包跟踪文件中的数据包对应关系,如下;
- 左图 No.7 请求和 No.8 响应间隔 200ms,一部分来自于 RTT,一部分来自于响应,具体是多少?通过右图对比,可以得知响应时长极短,不到 1ms,而 RTT 近乎 200ms;此后服务器端 192.168.1.1 No.9 带来第一个慢的地方,ACK 的时长为 106ms,初步判断可能是延迟确认的时间,略长。
以下仍以之前总结的数据交互规律,说明如下:
- 以客户端 10.10.10.10 发起,Length 为 152、179、66 的一组数据帧,连续交互三次后, 再以服务器端 192.168.1.1 所发起的 Length 162、189、66 的一组数据帧做为结束;
- 右图客户端 No.4 发起第一组 Length 为 152 的数据帧,经 RTT 后得到了服务器端 No.5 的 ACK 确认,但同样 No.6 约有 100ms 的 ACK 确认间隔,初步判断可能是延迟确认的时间,同样略长;
- 之后第二组 Length 为 152 的 No.7 数据帧,就带来一次很大的间隔发送延迟,约 1.91s,之后同样有一个约 109ms 的 ACK 确认间隔;
- 之后第三组 Length 为 152 的 No.10 数据帧,就又带来一次很大的间隔发送延迟,约 1.90s,之后同样有一个约 105ms 的 ACK 确认间隔;
- 左图服务器端 No.19 最后发起 Length 为 162 的数据帧,经 RTT 后客户端收到后立马响应带有数据分段的数据帧,最后服务器端 No.21 约有 92ms 的 ACK 确认间隔。
问题总结
总结两个数据包跟踪文件的数据包交互规律以及时间分析,应用缓慢的问题主要出现在客户端 10.10.10.10 的数据请求阶段,每一次间隔基本都在 1.9s 左右,相对于如此大的延迟时间,两端基本都存在的延迟确认 100ms 左右的时间几乎都可以忽略不计了。