TCPRT 案例

TCPRT 案例 – rtt、丢包率、rt、qps之间的关系

在分布式、微服务场景下如果rt出现问题一般都有pinpoint、Dapper、鹰眼之类的工具能帮忙分析是哪个服务慢了,但是如果是网络慢了这些工具就没有办法区分了。

TCPRT是从网络层面把整个服务的响应时间分成:网络传输时间+服务处理时间,这样一旦响应时间慢了很容易看到是网络慢了、丢包、抖动了,还是就是服务处理慢了。

如下案例都有tcpdump抓包来证明TCPRT的正确性,实际上在没有TCPRT之前处理类似问题只能抓包+等待重现,来排查问题。开启TCPRT之后会实时记录每一个请求响应的网络传输时间、服务处理时间、网络丢包率等各种数据,而对性能的影响非常非常小,控制在1%以内。

总的来说TCPRT区分了网络传输时间和服务处理时间,并记录了丢包、重传等各种数据,从此天下无包可抓。

可以在任何节点上部署tcprt,下面案例都只是在tomcat节点上部署了tcprt服务,来监控client到tomcat以及tomcat到后面RDS的响应时间:

image.png

图形化监控数据

捞取同一段时间内同样压力下tcprt监控数据后展示出来的图形:

  1. 最开始正常网络情况下QPS 40K,总RT 4.1ms(含网络),业务处理时间3.9ms,两者差就是网络传输时间;
  2. 突然网络变差,rtt从0.2ms降到了17ms,相应地QPS降到了8200,总RT 19.9ms(含网络),业务处理时间2.8ms(因为压力变小了,实际业务处理时间也快了);
  3. 接着rtt回到7ms,QPS回升到16400,总RT 9.9ms(含网络),业务处理时间2.82ms;
  4. rtt恢复到0.2ms,同时client到tomcat丢包率为0.1%,QPS 39.5K,总RT 4.1ms(含网络),业务处理时间3.7ms. 对QPS的影响基本可以忽略;
  5. client到tomcat丢包率为1%,QPS 31.8K,总RT 5.08ms(含网络),业务处理时间2.87ms;
  6. tomcat到client和RDS丢包率都为1%,QPS 23.2K,总RT 7.03ms(含网络),业务处理时间4.88ms,tomcat调用RDS的rt也从2.6ms上升到了4.6ms。

QPS随着上述6个阶段的变化图(以下所有图形都是在同一时间段所取得):

image.png

响应时间和丢包率在上述6个阶段的变化图:

image.png

应用到tomcat之间的网络消耗展示(逻辑响应时间-逻辑服务时间=网络传输时间):

image.png

tomcat到RDS之间的时间消耗:

image.png

物理响应时间(RDS响应时间)上升部分是因为RDS的丢包率为1%,tomcat的TCPRT监控上能看到的只是RDS总的响应时间上升了。

通过wireshark看到对应的tomcat和RDS之间的RTT数据:

image.png

上面都是对所有数据做平均后分析所得,接下来会通过具体的一个请求来分析,同时通过tcpdump抓包来分析对应的数据(对比验证tcprt的可靠性)

深圳盒子慢查询定位

这个实例没有上线manager,只能人肉分析tcprt日志,先看慢查询日志:

1
2
$tail -10 slow.log
2020-08-13 14:39:46.289 - [user=zhoubingbing,host=172.30.52.43,port=54754,schema=goodarights_base] [TDDL] select * from tbl_wm_mcht_invoice_record where mcht_no='323967' ORDER BY CREATE_TIME desc;#1070#392#111413ba1b1a2000, tddl version: 5.4.3-15844389

慢查询对应的tcprt记录,rtt高达35ms(正常都是2ms,而且重传了3次才把response传完),所以最终SQL执行花了差不多1.3秒(慢查询中有记录,1秒多,查询结果390行数据):

image.png

从60秒汇总统计日只看,慢查询发生的时间点 丢包率确实到了 0.1%:

image.png

总的平均时间统计,绿框是DRDS处理时间,红框是DRDS处理时间+网络传输时间,这个gap有点大(网络消耗比较高):

image.png

丢包造成rt过高

如下数据中每一行代表一个请求、响应数据,第三行和第八行总rt都比较高,超过200ms(第6列),但是server处理时间在3ms以内(最后一列)

1
2
3
4
5
6
7
8
9
10
                                                         总rt    重传       处理时间
1593677820 311182 10.0.186.70:32610 10.0.186.97:3306 142 5885 113 0 36314730 2758
1593677820 317068 10.0.186.70:32610 10.0.186.97:3306 142 214047 113 1 36314731 2791 <?
1593677820 533814 10.0.186.70:32610 10.0.186.97:3306 142 5905 113 0 36314732 2771
1593677820 539722 10.0.186.70:32610 10.0.186.97:3306 142 5842 113 0 36314733 2714
1593677820 545565 10.0.186.70:32610 10.0.186.97:3306 142 5898 113 0 36314734 2751
1593677820 551464 10.0.186.70:32610 10.0.186.97:3306 142 5866 113 0 36314735 2746
1593677820 557331 10.0.186.70:32610 10.0.186.97:3306 142 213762 113 1 36314736 2627 <?
1593677820 772815 10.0.186.70:32610 10.0.186.97:3306 142 5845 113 0 36314737 2731
1593677820 778677 10.0.186.70:32610 10.0.186.97:3306 142 5868 113 0 36314738 2744

对应这个时间点的抓包,可以看到这两个慢的查询都是因为第一个response发给client后没有收到ack(网络丢包?网络延时高?) 200ms后再发一次response就收到ack。所以总的rt都超过了200ms,其它没丢包的rt都很快。另外抓包的请求和和上面tcprt记录都是全对应的,时间精度都在微秒级。

image.png

丢包重传的分析

image.png

丢包率对性能影响

在client端设置:

tc qdisc add dev eth0 root netem loss 3% delay 3ms

这时可以看到tcprt stats统计到的网络丢包率基本在3%左右,第6列是丢包率千分数,可以看到tcprt吐出来的丢包率和我们用tc构造的基本一致:

1
2
3
4
5
6
7
8
9
10
11
12
$cat tcp-rt/rt-network-stats | awk '{ if($6!=0) print $0 }'
丢包率
1593677850 all 3306 10749 3217 23 915 0 141 0 45 882895
1593677911 all 3306 11938 2789 28 1102 0 141 0 45 795169
1593677972 all 3306 12001 2798 29 1104 0 141 0 45 789972
1593678034 all 3306 11919 2778 28 1103 0 141 0 45 796126
1593678095 all 3306 12049 2832 29 1714 0 141 0 45 786661
1593678157 all 3306 11893 2773 28 3000 0 141 0 45 797950
1593678218 all 3306 11956 2769 29 3000 0 141 0 45 793544
1593678280 all 3306 12032 2800 29 3000 0 141 0 45 789403
1593678341 all 3306 11973 2761 29 3000 0 141 0 45 791959
1593678403 all 3306 7733 3376 13 1442 0 141 0 45 1237712

时延增加对数据的影响

在Server上增加了网络17ms delay,可以看到平均rt增加了34ms,因为Server到P4192增加17,到client增加17,所以总共增加了34ms。另外QPS(最后一列)从200万/60秒降到了26万/60秒

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
$sudo tc qdisc add dev eth0 root netem  delay 17ms
$tail -40 tcp-rt/rt-network-stats
1593684362 all 3306 4860 4702 0 97 0 141 0 45 2022008
1593684362 all P4192 2596 2597 0 2359 0 139 0 139 2022289
1593684424 all 3306 4652 4493 0 97 0 141 0 45 2112538
1593684424 all P4192 2596 2597 0 2357 0 139 0 139 2112834
1593684485 all 3306 4858 4699 0 97 0 141 0 45 2023052
1593684485 all P4192 2598 2599 0 2358 0 139 0 139 2023316
---------------这里增加网络 rt 17ms---------
1593684547 all 3306 7188 4395 0 97 0 141 0 45 1367174
1593684547 all P4192 2593 2593 0 2355 0 139 0 139 1367466
1593684608 all 3306 19969 2838 0 97 0 141 0 45 492234
1593684608 all P4192 2592 2592 0 2357 0 139 0 139 492587
1593684669 all 3306 19935 2800 0 97 0 141 0 45 493045
1593684669 all P4192 2595 2595 0 2354 0 139 0 139 493383
1593684731 all 3306 20020 2885 0 97 0 141 0 45 491010
1593684731 all P4192 2674 2674 0 2362 0 139 0 139 491305
1593684792 all 3306 10362 4319 0 114 0 141 0 45 948355
1593684792 all P4192 3379 3379 0 2356 0 139 0 139 948710
1593684854 all 3306 37006 19866 0 317 0 141 0 45 265711
1593684854 all P4192 19610 19610 0 2359 0 139 0 139 265963
1593684915 all 3306 37088 19947 0 317 0 141 0 45 264957
1593684915 all P4192 19618 19617 0 2360 0 139 0 139 265226
1593684977 all 3306 37008 19869 0 317 0 141 0 45 265688
1593684977 all P4192 19625 19625 0 2356 0 139 0 139 265962
1593685038 all 3306 36968 19830 0 317 0 141 0 45 265864
1593685038 all P4192 19618 19618 0 2360 0 139 0 139 266145
1593685099 all 3306 37308 20166 0 317 0 141 0 45 263501
1593685099 all P4192 19869 19869 0 2361 0 139 0 139 263799

delay ack + client卡顿导致server rt偏高

如下tcprt日志中,问题行显示执行SQL花了14357微秒(最后一列),到结果发送给client并收到client ack花了32811微秒(第6列)

1
2
3
4
5
6
7
8
                                                         总RT             业务处理时间
1592470141 263882 10.0.186.79:31910 10.0.186.97:3306 142 32811 98 0 5361894 14357 << ?
1592470141 296695 10.0.186.79:31910 10.0.186.97:3306 142 13530 98 0 5361895 13389
1592470141 310226 10.0.186.79:31910 10.0.186.97:3306 142 13419 98 0 5361896 13253
1592470141 266860 10.0.186.79:32078 10.0.186.97:3306 142 5163 100 0 5470897 4953
1592470141 272024 10.0.186.79:32078 10.0.186.97:3306 142 24644 100 0 5470898 6024 << ?
1592470141 296669 10.0.186.79:32078 10.0.186.97:3306 142 10371 100 0 5470899 10249
1592470141 307041 10.0.186.79:32078 10.0.186.97:3306 142 11951 100 0 5470900 11766

Delay ACK 原理解析

image.png

从tcpdump抓包来分析原因

从实际抓包来看,32811等于:14358+18454 (红框+绿框),因为server只有收到ack后才会认为这个SQL执行完毕,但是可能由于delay ack导致client发下一个请求才将ack带回server,而client明显此时卡住了,发请求慢

image.png

image.png

同一时间点一批SQL都是ack慢了,跑了几个小时才抓到这么一点点ack慢导致SQL总rt偏高,统计曲线被平均掉了:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
$grep " R " tcp-rt/rt-network-log | awk '{ if(($8-$12)>10000) print $0 }' | sort -k3n,4n
1592470141 263882 10.0.186.79:31910 10.0.186.97:3306 142 32811 98 0 5361894 14357 0 45
1592470141 270617 10.0.186.79:32144 10.0.186.97:3306 142 25933 98 0 5339208 6317 0 45
1592470141 270675 10.0.186.79:32056 10.0.186.97:3306 142 26154 103 0 5511828 15901 0 45
1592470141 270687 10.0.186.79:31828 10.0.186.97:3306 142 25939 98 0 5399141 6850 0 45
1592470141 270701 10.0.186.79:32106 10.0.186.97:3306 142 25990 95 0 5432836 7551 0 45
1592470141 270728 10.0.186.79:32080 10.0.186.97:3306 142 25888 98 0 5303145 6811 0 45
1592470141 270732 10.0.186.79:31966 10.0.186.97:3306 142 26101 98 0 5529183 15906 0 45
1592470141 270781 10.0.186.79:31942 10.0.186.97:3306 142 26039 98 0 5478295 15603 0 45
1592470141 270786 10.0.186.79:32136 10.0.186.97:3306 142 25826 94 0 5375531 6743 0 45
1592470141 270803 10.0.186.79:32008 10.0.186.97:3306 142 25884 102 0 5411914 7446 0 45
1592470141 270815 10.0.186.79:31868 10.0.186.97:3306 142 25793 98 0 5378825 6711 0 45
1592470141 270856 10.0.186.79:31836 10.0.186.97:3306 142 25762 97 0 5324126 6677 0 45
1592470141 270889 10.0.186.79:32048 10.0.186.97:3306 142 25934 102 0 5462899 15559 0 45
1592470141 270911 10.0.186.79:32024 10.0.186.97:3306 142 25901 96 0 5441077 15340 0 45
1592470141 270915 10.0.186.79:32036 10.0.186.97:3306 142 25901 98 0 5455513 15399 0 45
1592470141 270918 10.0.186.79:31892 10.0.186.97:3306 142 25713 96 0 5312555 6624 0 45
1592470141 270921 10.0.186.79:32058 10.0.186.97:3306 142 25905 98 0 5499044 15596 0 45
1592470141 270927 10.0.186.79:31962 10.0.186.97:3306 142 25758 97 0 5417673 7319 0 45
1592470141 271894 10.0.186.79:31922 10.0.186.97:3306 142 24768 98 0 5523611 6160 0 45
1592470141 271897 10.0.186.79:32026 10.0.186.97:3306 142 24762 98 0 5390495 6148 0 45
1592470141 271904 10.0.186.79:31850 10.0.186.97:3306 142 24761 98 0 5505279 6147 0 45
1592470141 272024 10.0.186.79:32078 10.0.186.97:3306 142 24644 100 0 5470898 6024 0 45

原因总结

这个时间点发送压力的sysbench卡顿了20ms左右,导致一批请求发送慢,同时这个时候因为delay ack,server收到的ack慢了。

delay ack拉高实际rt的case

如下业务监控图:实际处理时间(逻辑服务时间1ms,rtt2.4ms,加起来3.5ms),但是系统监控到的rt(蓝线)是6ms,如果一个请求分很多响应包串行发给client,这个6ms是正常的(1+2.4*N),但实际上如果send buffer足够的话,按我们前面的理解多个响应包会并发发出去,所以如果整个rt是3.5ms才是正常的。

image.png

抓包来分析原因:

image.png

实际看到大量的response都是3.5ms左右,符合我们的预期,但是有少量rt被delay ack严重影响了

从下图也可以看到有很多rtt超过3ms的,这些超长时间的rtt会最终影响到整个服务rt

image.png

最后一个数据发送慢导致计时显示网络rt偏高

server 收到请求到查到结果后开始发送成为server-rt,从开始发送结果到client ack所有结果成为总rt(server-rt+网络传输时间)

如果 limit 164567, 1 的时候只有一个response,得到所有分片都返回来才开始发数据给client;但是当 limit 164567,5 的时候因为这个SQL下推到多个分片,第一个response很快发出来,但是最后一个response需要等很久。在tcprt眼中,这里传输花了很久(一旦开始response,所有时间都是传输时间),但实际这里response卡顿了。

image.png

从 jstack 抓的堆栈看到返回最后一个包之前,应用 在做 result.close(),因为关闭流模式结果集太耗时所以卡了。可以做的一个优化是提前发出 sendPacketEnd,然后异步去做物理连接的 result.close() 和 conn.close() 。

这是因为close的时候要挨个把所有记录处理掉,但是这里还在挨个做对象转换并抛弃。

这可以算是通过tcprt发现了程序的bug或者说可以优化的地方。

重传内核监控

TCP 重传率是通过解析 /proc/net/snmp 这个文件里的指标计算出来的,这个文件里面和 TCP 有关的关键指标如下:

image.png

为了让 Linux 用户更方便地观察 TCP 重传事件,4.16 内核版本中专门添加了TCP tracepoint来解析 TCP 重传事件。如果你使用的操作系统是 CentOS-7 以及更老的版本,就无法使用该 Tracepoint 来观察了;如果你的版本是 CentOS-8 以及后续更新的版本,那你可以直接使用这个 Tracepoint 来追踪 TCP 重传,可以使用如下命令:

1
2
3
4
5
6
7
8
9
10
11
12
13
$ cat /sys/kernel/debug/tracing/tracing_on
1
$ cd /sys/kernel/debug/tracing/
$ echo 1 > events/tcp/tcp_retransmit_skb/enable

$ cat trace_pipe
<idle>-0 [007] ..s. 265119.290232: tcp_retransmit_skb: sport=22 dport=62264 saddr=172.23.245.8 daddr=172.30.18.225 saddrv6=::ffff:172.23.245.8 daddrv6=::ffff:172.30.18.225 state=TCP_ESTABLISHED

<idle>-0 [001] ..s. 8898413.028276: tcp_retransmit_skb: sport=3306 dport=62460 saddr=10.0.186.140 daddr=10.0.186.70 saddrv6=::ffff:10.0.186.140 daddrv6=::ffff:10.0.186.70
<idle>-0 [000] ..s. 8898414.216218: tcp_retransmit_skb: sport=11236 dport=80 saddr=10.0.186.140 daddr=100.100.30.25 saddrv6=::ffff:10.0.186.140 daddrv6=::ffff:100.100.30.25

//关闭
$ echo 0 > events/tcp/tcp_retransmit_skb/enable

可以看到,当 TCP 重传发生时,该事件的基本信息就会被打印出来。

由于 Kprobe 是通过异常(Exception)这种方式来工作的,所以它还是有一些性能开销的,在 TCP 发包快速路径上还是要避免使用 Kprobe。不过,由于重传路径是慢速路径,所以在重传路径上添加 Kprobe 也无需担心性能开销。

参考资料

https://zhuanlan.zhihu.com/p/37112986