TCPRT 案例 – rtt、丢包率、rt、qps之间的关系
在分布式、微服务场景下如果rt出现问题一般都有pinpoint、Dapper、鹰眼之类的工具能帮忙分析是哪个服务慢了，但是如果是网络慢了这些工具就没有办法区分了。
TCPRT是从网络层面把整个服务的响应时间分成：网络传输时间+服务处理时间，这样一旦响应时间慢了很容易看到是网络慢了、丢包、抖动了，还是就是服务处理慢了。
如下案例都有tcpdump抓包来证明TCPRT的正确性，实际上在没有TCPRT之前处理类似问题只能抓包+等待重现，来排查问题。开启TCPRT之后会实时记录每一个请求响应的网络传输时间、服务处理时间、网络丢包率等各种数据，而对性能的影响非常非常小，控制在1%以内。
总的来说TCPRT区分了网络传输时间和服务处理时间，并记录了丢包、重传等各种数据，从此天下无包可抓。
可以在任何节点上部署tcprt，下面案例都只是在tomcat节点上部署了tcprt服务，来监控client到tomcat以及tomcat到后面RDS的响应时间：
图形化监控数据
捞取同一段时间内同样压力下tcprt监控数据后展示出来的图形：
- 最开始正常网络情况下QPS 40K，总RT 4.1ms（含网络），业务处理时间3.9ms，两者差就是网络传输时间；
- 突然网络变差，rtt从0.2ms降到了17ms，相应地QPS降到了8200，总RT 19.9ms（含网络），业务处理时间2.8ms（因为压力变小了，实际业务处理时间也快了）；
- 接着rtt回到7ms，QPS回升到16400，总RT 9.9ms（含网络），业务处理时间2.82ms；
- rtt恢复到0.2ms，同时client到tomcat丢包率为0.1%，QPS 39.5K，总RT 4.1ms（含网络），业务处理时间3.7ms. 对QPS的影响基本可以忽略；
- client到tomcat丢包率为1%，QPS 31.8K，总RT 5.08ms（含网络），业务处理时间2.87ms；
- tomcat到client和RDS丢包率都为1%，QPS 23.2K，总RT 7.03ms（含网络），业务处理时间4.88ms，tomcat调用RDS的rt也从2.6ms上升到了4.6ms。
QPS随着上述6个阶段的变化图（以下所有图形都是在同一时间段所取得）：
响应时间和丢包率在上述6个阶段的变化图：
应用到tomcat之间的网络消耗展示（逻辑响应时间-逻辑服务时间=网络传输时间）：
tomcat到RDS之间的时间消耗：
物理响应时间（RDS响应时间）上升部分是因为RDS的丢包率为1%，tomcat的TCPRT监控上能看到的只是RDS总的响应时间上升了。
通过wireshark看到对应的tomcat和RDS之间的RTT数据：
上面都是对所有数据做平均后分析所得，接下来会通过具体的一个请求来分析，同时通过tcpdump抓包来分析对应的数据（对比验证tcprt的可靠性）
深圳盒子慢查询定位
这个实例没有上线manager，只能人肉分析tcprt日志，先看慢查询日志：
1 | $tail -10 slow.log |
慢查询对应的tcprt记录，rtt高达35ms（正常都是2ms，而且重传了3次才把response传完），所以最终SQL执行花了差不多1.3秒（慢查询中有记录，1秒多，查询结果390行数据）：
从60秒汇总统计日只看，慢查询发生的时间点 丢包率确实到了 0.1%：
总的平均时间统计，绿框是DRDS处理时间，红框是DRDS处理时间+网络传输时间，这个gap有点大（网络消耗比较高）：
丢包造成rt过高
如下数据中每一行代表一个请求、响应数据，第三行和第八行总rt都比较高，超过200ms（第6列），但是server处理时间在3ms以内（最后一列）
1 | 总rt 重传 处理时间 |
对应这个时间点的抓包，可以看到这两个慢的查询都是因为第一个response发给client后没有收到ack（网络丢包？网络延时高？） 200ms后再发一次response就收到ack。所以总的rt都超过了200ms，其它没丢包的rt都很快。另外抓包的请求和和上面tcprt记录都是全对应的，时间精度都在微秒级。
丢包重传的分析
丢包率对性能影响
在client端设置：
tc qdisc add dev eth0 root netem loss 3% delay 3ms
这时可以看到tcprt stats统计到的网络丢包率基本在3%左右，第6列是丢包率千分数，可以看到tcprt吐出来的丢包率和我们用tc构造的基本一致：
1 | $cat tcp-rt/rt-network-stats | awk '{ if($6!=0) print $0 }' |
时延增加对数据的影响
在Server上增加了网络17ms delay，可以看到平均rt增加了34ms，因为Server到P4192增加17，到client增加17，所以总共增加了34ms。另外QPS（最后一列）从200万/60秒降到了26万/60秒
1 | $sudo tc qdisc add dev eth0 root netem delay 17ms |
delay ack + client卡顿导致server rt偏高
如下tcprt日志中，问题行显示执行SQL花了14357微秒（最后一列），到结果发送给client并收到client ack花了32811微秒（第6列）
1 | 总RT 业务处理时间 |
Delay ACK 原理解析
从tcpdump抓包来分析原因
从实际抓包来看，32811等于：14358+18454 （红框+绿框），因为server只有收到ack后才会认为这个SQL执行完毕，但是可能由于delay ack导致client发下一个请求才将ack带回server，而client明显此时卡住了，发请求慢
同一时间点一批SQL都是ack慢了，跑了几个小时才抓到这么一点点ack慢导致SQL总rt偏高，统计曲线被平均掉了：
1 | $grep " R " tcp-rt/rt-network-log | awk '{ if(($8-$12)>10000) print $0 }' | sort -k3n,4n |
原因总结
这个时间点发送压力的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才是正常的。
抓包来分析原因：
实际看到大量的response都是3.5ms左右，符合我们的预期，但是有少量rt被delay ack严重影响了
从下图也可以看到有很多rtt超过3ms的，这些超长时间的rtt会最终影响到整个服务rt
最后一个数据发送慢导致计时显示网络rt偏高
server 收到请求到查到结果后开始发送成为server-rt，从开始发送结果到client ack所有结果成为总rt（server-rt+网络传输时间）
如果 limit 164567, 1 的时候只有一个response，得到所有分片都返回来才开始发数据给client；但是当 limit 164567,5 的时候因为这个SQL下推到多个分片，第一个response很快发出来，但是最后一个response需要等很久。在tcprt眼中，这里传输花了很久（一旦开始response，所有时间都是传输时间），但实际这里response卡顿了。
从 jstack 抓的堆栈看到返回最后一个包之前，应用 在做 result.close()，因为关闭流模式结果集太耗时所以卡了。可以做的一个优化是提前发出 sendPacketEnd，然后异步去做物理连接的 result.close() 和 conn.close() 。
这是因为close的时候要挨个把所有记录处理掉，但是这里还在挨个做对象转换并抛弃。
这可以算是通过tcprt发现了程序的bug或者说可以优化的地方。
重传内核监控
TCP 重传率是通过解析 /proc/net/snmp 这个文件里的指标计算出来的，这个文件里面和 TCP 有关的关键指标如下：
为了让 Linux 用户更方便地观察 TCP 重传事件，4.16 内核版本中专门添加了TCP tracepoint来解析 TCP 重传事件。如果你使用的操作系统是 CentOS-7 以及更老的版本，就无法使用该 Tracepoint 来观察了；如果你的版本是 CentOS-8 以及后续更新的版本，那你可以直接使用这个 Tracepoint 来追踪 TCP 重传，可以使用如下命令：
1 | $ cat /sys/kernel/debug/tracing/tracing_on |
可以看到，当 TCP 重传发生时，该事件的基本信息就会被打印出来。
由于 Kprobe 是通过异常（Exception）这种方式来工作的，所以它还是有一些性能开销的，在 TCP 发包快速路径上还是要避免使用 Kprobe。不过，由于重传路径是慢速路径，所以在重传路径上添加 Kprobe 也无需担心性能开销。