结合 tcprstat 和tcpdump、wireshark 工具定位Redis响应慢的原因

一、背景说明

之前使用过 tcpdump / wireshark，线上也有时延探测工具 tcprstat，但是一直感觉差点意思，每次抓包或者看响应时间，都对不上号，不能较好的定位问题。

知道机缘巧合发现了这个改良后的 tcprstat，如获至宝，经验证后效果不错，故写此博文。

二、工具说明

2.1 tcprstat

tcprstat 是一个免费、开源的 TCP 分析工具，可以用来观测网络通信状态以及计算 request 和 response 之间的延迟。通过它可以获得应答时间统计信息并将其显示输出。输出格式类似于 Unix 中各种 -stat 工具的模式，如 vmstat、iostat、mpstat 。

该工具可以选择观测指定 port 上的通信负载，这种方式使其在针对单实例 daemon 进程 request-response 时间测量上具有实际意义，例如针对 mysqld、httpd、memcached 等。

(不过 tcprstat源码 已经不怎么维护了，大家可以参考本人根据 y123456yz 大佬改进版本进行整理的github项目，进行tcprstat的安装和使用。)

y123456yz 大佬添加了 记录响应时间超过阈值的时间戳 的功能，对报文的分析有很大的帮助。

2.2 tcpdump

Tcpdump工具是Unix和Linux系统抓网络数据库包最有效的工具。

tcpdump可以将网络中传送的数据包的“头”完全截获下来提供分析。它支持针对网络层、协议、主机、网络或端口的过滤，并提供and、or、not等逻辑语句来帮助你去掉无用的信息。另外tcpdump可以导入的文件中，可以进一步使用wireshark和Java代码进一步统计过滤分析。

网上有很多的使用教程，就不一一例举了。

2.3 Wireshark

Wireshark（前称Ethereal）是一个网络封包分析软件。网络封包分析软件的功能是撷取网络封包，并尽可能显示出最为详细的网络封包资料。Wireshark使用WinPCAP作为接口，直接与网卡进行数据报文交换。

wireshark是强大的网络报文分析工具，可以帮助我们在windows或者MAC上方便的分析在Linux上用tcpdump抓取到的包，帮助我们快速有效的定位网络问题。

三、使用步骤

根据上面的介绍，可以知道：

• tcprstat 可以获取到响应时间最长的报文的时间戳
• tcpdump 可以在服务器上抓取某个服务的网络数据报文
• Wireshark 可以帮我们可视化的分析tcpdump抓取到的网络报文

根据以下的操作，来学习下这三个工具的使用流程和方法。

3.1 使用 tcpdump 进行抓包

抓取 eth0网卡上 xxx 端口Redis服务的所有网络数据报文，并保存到 xxx.pcap文件。

tcpdump -i eth0 port xxx -w xxx.pcap

因为 tcpdump 抓取到的是二进制文件，所以我们不能直接打开进行查看；(虽然也可以使用 tcpdump -r 进行查看，不过格式和内容比较单一，不利于我们分析)

注：因为要对同一时刻的数据进行分析，所以得开两个终端，同时进行 tcpdump 和 tcprstat 工具的操作。

3.2 使用 tcprstat 进行时延探测记录

• -l 表示统计 xx.xx.xx.xx 服务器上面
• -p 表示统计端口为 xxx
• -t 1 表示每隔1s统计一次，也就是每行的打印时间间隔
• -T 1 表示时延超过1ms的请求将进行记录
• -o tcprstat.log 把时延超过-T设置的1ms的数据包时间戳记录到该文件，并记录该包的响应时间，见后面的时延tcprstat.log内容

[root@xxx delay_test]# tcprstat -l xx.xx.xx.xx -p xxx -n 1000 -t 1 -T 1 -o tcprstat.log

timestamp       count   max     min     avg     med     stddev  tc      95_max  95_avg  95_std  99_max  99_avg  99_std
1619774295      40      16451   7       532     37      2555    1       704     107     150     760     124     180
1619774296      29      140866  2       4942    69      25687   1       325     79      90      329     88      99
1619774297      16      31528   1       2203    228     7578    2       1284    248     339     1284    248     339
1619774298      28      40989   5       1556    62      7590    1       266     72      71      714     96      140
1619774299      31      290226  9       9537    62      51247   1       804     157     211     862     181     243
1619774300      50      445072  1       8984    21      62298   1       502     62      109     672     84      150
1619774301      35      281037  1       8144    24      46801   2       970     85      190     1188    118     264
1619774302      46      192983  8       4308    49      28126   2       351     77      82      1236    115     205
1619774303      64      216234  5       3477    33      26805   2       446     69      96      1145    100     179
1619774304      41      323947  3       8180    30      49947   2       144     42      42      9195    286     1430
1619774305      18      213248  3       12633   13      48753   2       13485   832     3163    13485   832     3163
1619774306      16      514698  0       32295   17      124556  2       1292    135     320     1292    135     320
1619774307      37      28758   3       854     58      4651    1       246     68      61      454     79      87
1619774308      24      46614   2       2061    95      9291    1       507     107     126     509     124     149
1619774309      40      225787  2       5786    31      35230   2       698     89      138     2290    145     373

tcprstat.log 记录的内容如下：

[root@xxx delay_test]# cat tcprstat.log 
timestamp:1619774294.779693     delay_time:16451
timestamp:1619774295.775643     delay_time:140866
timestamp:1619774296.676406     delay_time:1284
timestamp:1619774296.771553     delay_time:31528
timestamp:1619774297.769542     delay_time:40989
timestamp:1619774298.767789     delay_time:290226
timestamp:1619774299.765110     delay_time:445072
timestamp:1619774300.761624     delay_time:281037
timestamp:1619774301.65521     delay_time:1188
timestamp:1619774301.513685     delay_time:1236
timestamp:1619774301.757251     delay_time:192983
timestamp:1619774302.591191     delay_time:1145
timestamp:1619774302.752262     delay_time:216234
timestamp:1619774303.749226     delay_time:323947
timestamp:1619774304.73682     delay_time:9195
timestamp:1619774304.745029     delay_time:213248
timestamp:1619774304.959391     delay_time:13485
timestamp:1619774305.740336     delay_time:514698
timestamp:1619774306.257507     delay_time:1292
timestamp:1619774306.735689     delay_time:28758
timestamp:1619774307.731100     delay_time:46614
timestamp:1619774308.727788     delay_time:225787
timestamp:1619774309.242648     delay_time:2290
timestamp:1619774309.722615     delay_time:48644

3.3 使用 Wireshark 对包进行分析

将刚才 tcpdump抓取到的包xxx.pcap，传到自己的电脑上，并使用 Wireshark 打开，可以看到如下信息：

不过数据量太多了，人工一条条找是不现实的。我们已经通过 tcprstat.log文件知道响应时延大的时间点了，就可以直接搜索时间戳，定位到具体的响应数据。

比如 tcprstat.log文件中响应时间最大的一条

timestamp:1619774305.740336     delay_time:514698

时间戳为 1619774305.740336，耗时为514698us。

在 Wireshark 上直接ctrl + f或者点击“放大镜” 进行搜索：

可以看到，该时间戳执行的命令是一个 REPLCONF ACK命令。

四、总结

通过上述步骤，我们就快速的找到了耗时最长的命令为REPLCONF ACK，然后再结合实际的情况，就可以更好的分析Redis响应慢的原因了。

改进的tcprstat https://github.com/Damanchen/tcprstat