在我感叹Wireshark图形界面的强大时候,有时候也抱怨有点慢,或者感叹下要是有命令行界面版该多好啊,实际上TShark就是WireShark的命令行版,WireShark的功能基本都有,还能组合grep/awk等编程处理分析抓包文件。
下面让我们通过一些例子来学习TShark的常用功能,所有用到的.cap/.pcap等都是通过tcpdump抓到的包。请收藏好,下次碰到类似问题直接用文章中的命令跑一下。
wireshark问题
不再展示协议内容
比如,info列不再显示mysql 的request、response,但是下方的二进制解析能看到select等语句,这种一般是配置文件中 disable 了mysql协议。
配置文件名:C:\Users\xijun.rxj\AppData\Roaming\Wireshark\disabled_protos
如果抓包缺失很大(比如进出走两个网卡,实际只抓了一个网卡),那么协议解析后也不会正确显示。
IO graph图表无法展示数据
一般是缺数据,先把IO graph关掉再重新打开就可以了,注意图表title显示
tcp segment of a reassembled pdu
这个提示是指,wireshark需要将多个tcp协议包重新组合成特定协议内容(比如MySQL,HTTP),但是因为包缺失(或者每个包大小截断了)导致reassembled失败。实际上wireshark已经成功检测到该协议,只是在解析这个协议的时候缺失包导致解析不好。
这个时候可以试试将指定协议的reassembled属性关掉.
If the reassembly is successful, the TCP segment containing the last part of the packet will show the packet.
The reassembly might fail if some TCP segments are missing.
TCP segment of a reassembled PDU means that:
- Wireshark/TShark thinks it knows what protocol is running atop TCP in that TCP segment;
- that TCP segment doesn’t contain all of a “protocol data unit” (PDU) for that higher-level protocol, i.e. a packet or protocol message for that higher-level protocol, and doesn’t contain the last part of that PDU, so it’s trying to reassemble the multiple TCP segments containing that higher-level PDU.
常用命令
|
分析mysql的每个SQL响应时间
应用有输出的日志显示DB慢,DB监控到的日志显示自己很快,经常扯皮,如果直接在应用机器的网卡抓包,然后分析到每个SQL的响应时间,那么DB、网络都可以甩锅了(有时候应用统计的时间包含了应用自身的时间、取连接的时间等)
tshark -r 213_php.cap -Y "mysql.query or ( tcp.srcport==3306)" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e mysql.query |sort -nk9 -nk1
|
或者:
tshark -r gege_drds.pcap -Y “ ((tcp.srcport eq 3306 ) and
tcp.len>0 )” -o tcp.calculate_timestamps:true -T fields -e
frame.number -e frame.time_epoch -e frame.time_delta_displayed -e
ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e
tcp.stream -e tcp.len -e tcp.analysis.ack_rtt
这个命令跑出来,倒数第四列基本就是rt
967 1548148159.346612000 0.000442000 192.168.4.18 3306 44026 192.168.100.30 0.005255000 17 1576 0.005255000
969 1548148159.346826000 0.000214000 192.168.4.18 3306 44090 192.168.100.30 0.005425000 15 1576 0.005425000
973 1548148159.347428000 0.000602000 192.168.4.18 3306 44070 192.168.100.30 0.005517000 8 2500 0.005517000
979 1548148159.348640000 0.001212000 192.168.4.18 3306 44048 192.168.100.30 0.005517000 22 2462 0.005517000
981 1548148159.348751000 0.000111000 192.168.4.18 3306 44066 192.168.100.30 0.005855000 21 2692 0.005855000
983 1548148159.348844000 0.000093000 192.168.4.18 3306 44046 192.168.100.30 0.004589000 3 2692 0.004589000
985 1548148159.348981000 0.000137000 192.168.4.18 3306 44012 192.168.100.30 0.004885000 19 2443 0.004885000
990 1548148159.349293000 0.000312000 192.168.4.18 3306 44074 192.168.100.30 0.005923000 5 2692 0.005923000
994 1548148159.349671000 0.000378000 192.168.4.18 3306 44080 192.168.100.30 0.004889000 4 2730 0.004889000
1009 1548148159.350591000 0.000920000 192.168.4.18 3306 44022 192.168.100.30 0.004187000 14 1448 0.004187000
1010 1548148159.350592000 0.000001000 192.168.4.18 3306 44022 192.168.100.30 0.000001000 14 1052
1013 1548148159.350790000 0.000198000 192.168.4.18 3306 44002 192.168.100.30 0.005998000 0 1576 0.005998000
1026 1548148159.352207000 0.001417000 192.168.4.18 3306 44026 192.168.100.30 0.005348000 17 1448 0.005348000
1027 1548148159.352217000 0.000010000 192.168.4.18 3306 44026 192.168.100.30 0.000010000 17 1052
1036 1548148159.352973000 0.000756000 192.168.4.18 3306 44090 192.168.100.30 0.005940000 15 2500 0.005940000
1041 1548148159.353683000 0.000710000 192.168.4.18 3306 44070 192.168.100.30 0.005190000 8 2692 0.005190000
1043 1548148159.353737000 0.000054000 192.168.4.18 3306 44066 192.168.100.30 0.004635000 21 1448 0.004635000
1044 1548148159.353749000 0.000012000 192.168.4.18 3306 44066 192.168.100.30 0.000012000 21 128
1051 1548148159.354289000 0.000540000 192.168.4.18 3306 44046 192.168.100.30 0.004911000 3 1576 0.004911000
1054 1548148159.354511000 0.000222000 192.168.4.18 3306 44080 192.168.100.30 0.004515000 4 1576 0.004515000
1055 1548148159.354530000 0.000019000 192.168.4.18 3306 44074 192.168.100.30 0.004909000 5 1576 0.004909000
1065 1548148159.355412000 0.000882000 192.168.4.18 3306 44012 192.168.100.30 0.005217000 19 2692 0.005217000
1067 1548148159.355496000 0.000084000 192.168.4.18 3306 44048 192.168.100.30 0.005231000 22 2610 0.005231000
1072 1548148159.356111000 0.000615000 192.168.4.18 3306 44052 192.168.100.30 0.005830000 24 2730 0.005830000
1076 1548148159.356545000 0.000434000 192.168.4.18 3306 44022 192.168.100.30 0.005615000 14 2692 0.005615000
1079 1548148159.357012000 0.000467000 192.168.4.18 3306 44002 192.168.100.30 0.005966000 0 2462 0.005966000
1082 1548148159.357235000 0.000223000 192.168.4.18 3306 44072 192.168.100.30 0.004817000 23 2692 0.004817000
1093 1548148159.359244000 0.002009000 192.168.4.18 3306 44070 192.168.100.30 0.005188000 8 1576 0.005188000
MySQL响应时间直方图【第八列的含义– Time since previous frame in this TCP stream: seconds】
tshark -r gege_drds.pcap -Y "mysql.query or (tcp.srcport==3306 and tcp.len>60)" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len | awk 'BEGIN {sum0=0;sum3=0;sum10=0;sum30=0;sum50=0;sum100=0;sum300=0;sum500=0;sum1000=0;sumo=0;count=0;sum=0} {rt=$8; if(rt>=0.000) sum=sum+rt; count=count+1; if(rt<=0.000) sum0=sum0+1; else if(rt<0.003) sum3=sum3+1 ; else if(rt<0.01) sum10=sum10+1; else if(rt<0.03) sum30=sum30+1; else if(rt<0.05) sum50=sum50+1; else if(rt < 0.1) sum100=sum100+1; else if(rt < 0.3) sum300=sum300+1; else if(rt < 0.5) sum500=sum500+1; else if(rt < 1) sum1000=sum1000+1; else sum=sum+1 ;} END{printf "-------------\n3ms:\t%s \n10ms:\t%s \n30ms:\t%s \n50ms:\t%s \n100ms:\t%s \n300ms:\t%s \n500ms:\t%s \n1000ms:\t%s \n>1s:\t %s\n-------------\navg: %.6f \n" , sum3,sum10,sum30,sum50,sum100,sum300,sum500,sum1000,sumo,sum/count;}'
-------------
3ms: 145037
10ms: 78811
30ms: 7032
50ms: 2172
100ms: 1219
300ms: 856
500ms: 449
1000ms:118
>1s: 0
-------------
avg: 0.005937
对于rt分析,要注意一个query多个response情况(response结果多,分包了),分析这种rt的时候只看query之后的第一个response,其它连续response需要忽略掉。
有时候应用说修改库存的代码都加了事务,但是数据库里库存对不上,这锅压力好大,抓个包看看应用发过来的SQL是啥
开发测试环境上通过如下命令也可以直接用tshark抓包分析SQL语句:
sudo tshark -i eth0 -d tcp.port==3306,mysql -T fields -e mysql.query 'port 3306'
这样就直接看到发出的SQL是否是autocommit=1了
HTTP响应时间分析
|
按http response分析响应时间
第三列是RT,倒数第二列是stream,同一个stream是一个连接。对应http response 200的是请求响应结果的RT
|
改进版本,每10秒钟统计http response耗时,最后按时间排序输出:
|
分析包的总概览:
|
分析每两个IP之间的流量:
|
分析每个会话的流量:
|
分析每个包的response time:
$ tshark -r rsb2.cap -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e ip.src -e ip.dst -e tcp.stream -e tcp.len -e tcp.analysis.initial_rtt -e tcp.time_delta
|
分析有问题的包、概览:
|
分析rtt、丢包、deplicate等等:
$ tshark -r retrans.cap -q -z io,stat,1,”AVG(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”,”COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission”,”COUNT(tcp.analysis.fast_retransmission) tcp.analysis.fast_retransmission”,”COUNT(tcp.analysis.duplicate_ack) tcp.analysis.duplicate_ack”,”COUNT(tcp.analysis.lost_segment) tcp.analysis.lost_segment”,”MIN(tcp.window_size)tcp.window_size”
|
分析丢包、duplicate ack:
$ tshark -r retrans.cap -q -z io,stat,5,”COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission”,”COUNT(tcp.analysis.fast_retransmission) tcp.analysis.fast_retransmission”,”COUNT(tcp.analysis.duplicate_ack) tcp.analysis.duplicate_ack”,”COUNT(tcp.analysis.lost_segment) tcp.analysis.lost_segment”
|
分析rtt 时间:
$ tshark -r ~/ali/metrics/tcpdump/rsb2.cap -q -z io,stat,1,”MIN(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”,”MAX(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”,”AVG(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”
|
计算window size:
$ tshark -r rsb-single2.cap -q -z io,stat,5,”COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission”,”AVG(tcp.window_size) tcp.window_size”,”MAX(tcp.window_size) tcp.window_size”,”MIN(tcp.window_size) tcp.window_size”
|
有用的命令(这些命令也都是安装WireShark就装好了的):
capinfos rsb2.cap
tshark -q -n -r rsb2.cap -z “conv,ip” 分析流量总况
tshark -q -n -r rsb2.cap -z “conv,tcp” 分析每一个连接的流量、rtt、响应时间、丢包率、重传率等等
editcap -c 100000 ./rsb2.cap rsb00.cap //把大文件rsb2.cap按每个文件100000个package切成小文件
常用排错过滤条件:
对于排查网络延时/应用问题有一些过滤条件是非常有用的:
- tcp.analysis.lost_segment:表明已经在抓包中看到不连续的序列号。报文丢失会造成重复的ACK,这会导致重传。
- tcp.analysis.duplicate_ack:显示被确认过不止一次的报文。大量的重复ACK是TCP端点之间高延时的迹象。
- tcp.analysis.retransmission:显示抓包中的所有重传。如果重传次数不多的话还是正常的,过多重传可能有问题。这通常意味着应用性能缓慢和/或用户报文丢失。
- tcp.analysis.window_update:将传输过程中的TCP window大小图形化。如果看到窗口大小下降为零,这意味着发送方已经退出了,并等待接收方确认所有已传送数据。这可能表明接收端已经不堪重负了。
- tcp.analysis.bytes_in_flight:某一时间点网络上未确认字节数。未确认字节数不能超过你的TCP窗口大小(定义于最初3此TCP握手),为了最大化吞吐量你想要获得尽可能接近TCP窗口大小。如果看到连续低于TCP窗口大小,可能意味着报文丢失或路径上其他影响吞吐量的问题。
- tcp.analysis.ack_rtt:衡量抓取的TCP报文与相应的ACK。如果这一时间间隔比较长那可能表示某种类型的网络延时(报文丢失,拥塞,等等)。
抓包常用命令:
|
Wireshark 插件安装:
|
一个案例
问题:客户现场不管怎么样增加应用机器,tps就是上不去,同时增加机器后,增加的机器CPU还都能被用完,但是tps没有变化(这点比较奇怪) 整体服务调用慢,数据库没有慢查询,不知道到具体时间花在哪里,各个环节都尝试过增加服务器(或提升配置),但是问题一直得不到解决
tshark分析抓包文件数据库服务器网卡中断瓶颈导致rtt非常高,进一步导致每个Query的ResponseTime非常高(图中左边都是出问题、右边都是问题解决后的响应时间)
下面两个图是吧tshark解析结果丢到了数据库中好用SQL可以进一步分析
问题修复后数据库每个查询的平均响应时间从47毫秒下降到了4.5毫秒
从wireshark中也可以看到类似的rtt不正常(超过150ms的比较多)
从wireshark中也可以看到类似的rtt正常(99%都在10ms以内)
tcprstat
推荐一个快速统计rt的工具tcprstat,实测在CPU打满的高压力情况下会丢失大量请求数据,但是作为统计平均值这问题不大。支持http、mysql协议等。实际测试在每秒2万个SQL的时候,对于一台4C的机器,只能采集到70%的请求。
或者看这个支持设置RT阈值的统计改进版
tcprstat 统计抓包离线文件
|
其它工具
https://github.com/google/packetdrill
https://mp.weixin.qq.com/s/CcM3rINPn54Oean144kvMw
http://beta.computer-networking.info/syllabus/default/exercises/tcp-2.html
No comments:
Post a Comment