一位客户报告我们的CloudFlare CDN出现了一个异常问题：我们的服务器对某些HTTP请求的响应速度很慢。非常慢。慢30秒。这种情况很少发生，而且不容易重现。更糟糕的是，我们平时的监控都没有发现问题。在应用层一切正常：我们的NGINX服务器没有报告任何长时间运行的请求。是时候让狼进来了。他解决问题。跟踪证据首先，我们试图重现客户报告的长HTTP响应。以下是根据CDN测量的测试HTTP请求时间的图表：我们在几个小时内对一台服务器运行了数千个HTTP查询。几乎所有的请求都在毫秒内完成，但是，正如您可以清楚地看到的那样，数千个请求中有5个请求需要长达1000毫秒才能完成。在调试网络问题时，1s、30s的延迟是非常典型的。由于SYN分组通常在1s、3s、7s、15、31s被重传，因此它们可能指示分组丢失。责怪网络起初，我们认为HTTP加载时间的峰值可能表示某种网络问题。为了确保我们对两个IP运行了数小时的ICMP ping。第一次"ping"从外部测试机器发送到路由器，显示出约20ms的平坦延迟（除了两个峰值，约120ms，这是由于用于测试的VPS的速度慢）：---ping统计---发送114890包，接收114845包，0%丢包rtt最小值/平均值/最大值/最大值=10.432/11.025/122.768/4.114毫秒对于该网络来说，这~20ms是一个不错的往返时间（RTT），并确认网络连接实际上是稳定的。第二个"ping"会话是从我们的外部测试机器针对路由器后面的一个Linux服务器启动的：---ping统计---发送114931包，接收114805包，0%丢包rtt最小值/平均值/最大值/最大值=10.434/11.607/1868.110/22.703毫秒"ping"输出显示最大RTT为1.8s。巨大的延迟峰值在图表上也清晰可见。第一次实验表明路由器与外部网络之间的故障不是第一次测试。但是第二次测试，针对路由器后面的服务器，发现了可怕的峰值。这表明问题出在我们数据中心内部的路由器和服务器之间。tcpdump前往救援为了验证该问题，我们在受影响的服务器上运行了tcpdump，试图查明受峰值影响的特定ICMP数据包：$tcpdump-ttt-n-i eth2 icmp00:00.000000 IP x.x.x.a>x.x.x.b:ICMP回显请求，id 1928300:01.296841 IP x.x.x.b>x.x.x.a:ICMP回显回复，id 19283正如您从tcpdump输出中看到的，在时间0时确实从网络收到了一个特定的ICMP包，但由于某种原因，操作系统等待了1.3秒才应答。在Linux网络上，当中断发生时，数据包会被迅速处理；这种延迟的ICMP响应表明存在严重的内核问题。欢迎点击系统为了理解到底发生了什么，我们必须查看操作系统包处理的内部结构。现在Linux上有太多的调试工具，而且没有特别的原因，我们选择了systemtap（stap）。在火焰图的帮助下，我们确定了一个感兴趣的函数：net_rx_action。$/火焰核-全局.sh美元/堆叠倒塌-stap.pl公司离开.stap-堆叠|/火焰图.pl>斯塔普-内核.svg火焰图本身：net_rx_action函数负责在软IRQ模式下处理数据包。它将一次性处理多达netdev_预算包：$系统控制net.core.netdev_预算net.core.netdev_预算=300下面是stap脚本的运行，显示了此函数的延迟分布：$stap-v直方图-内核.stp'内核函数（"网络接收行动）"'30持续时间最小值：0毫秒平均值：0毫秒最大：23ms计数：3685271持续时间（毫秒）：值|--------------------------------------------------计数0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@36850111 | 2152 | 304 | 98 | 516 | 132 | 0在一个30秒的运行中，我们命中了360万次net_rx_action函数。在这些运行中，大多数在1毫秒内完成，但也有一些异常值。最重要的是，一次跑步需要惊人的23毫秒。在低层数据包处理中出现23毫秒的暂停是灾难性的。如果累积了一些这样的事件，完全有可能耗尽缓冲区空间并开始丢弃数据包。难怪ICMP包没有及时处理！深入兔子洞我们又重复了几次。即：我们制作了一个火焰图源。通过反复试验找出了net_rx_操作导致延迟峰值源。这个过程非常有效，运行了几次之后，我们发现了罪魁祸首：tcp峈collapse函数。以下是延迟测量的摘要：$stap-v直方图-内核.stp'内核函数（"tcp_崩溃"）'300持续时间最小值：0毫秒平均值：3毫秒最大：21ms计数：1552个在300多秒的时间里，只有大约1500次执行tcp\u collapse函数。在这些执行中，有一半在3毫秒内完成，但最长时间是21毫秒。让我们折叠TCPtcp_collapse函数很有趣。事实证明，它与bsdsocketsapi的工作方式有着很深的混合。为了充分理解这一点，让我们从一个酒吧问题开始：如果您在TCP套接字上设置了"接收缓冲区大小"，它实际上意味着什么？继续读手册，把你的史蒂文斯掸掉。我等一下。简单的答案是这样的：TCP receive buffer设置指示read（）系统调用在不阻塞的情况下可以检索的最大字节数。虽然这是目的，但这并不完全是它的工作方式。实际上，套接字上的接收缓冲区大小值是对操作系统的一个提示，它可以使用多少内存来处理接收到的数据。最重要的是，这不仅包括可以传递到应用程序的有效负载字节，还包括它周围的元数据。在正常情况下，TCP套接字结构包含sk_buff结构的双链接数据包列表。每个包不仅包含数据，而且还包含sk_buff元数据（据说sk_buff需要240个字节）。元数据大小不计入接收缓冲区大小计数器。在悲观的情况下，当数据包非常短时，接收缓冲区内存可能几乎全部被元数据使用。为元数据使用大量的接收缓冲区空间并不是程序员真正想要的。为了解决这个问题，当套接字处于内存压力下时，运行复杂逻辑的目的是释放一些空间。其中一个操作是tcp_collapse，它将把相邻的tcp包合并成一个更大的sk_buff。这种行为在很大程度上是一种垃圾收集（GC）——众所周知，当垃圾收集开始时，延迟必须达到峰值。调整rmemLinux上有两种控制TCP套接字接收缓冲区的方法：您可以显式设置setsockopt（SO\u RCVBUF）。或者，您可以将它留给操作系统，并允许它自动调整它，使用tcp-rmem-sysctl作为提示。在CloudFlare，我们使用后一种方法，接收缓冲区大小由sysctl控制：$系统控制网络ipv4.tcp协议网络ipv4.tcpμrmem=4096 5242880 33554432此设置告诉Linux自动调整套接字接收缓冲区，并在4KiB和32MiB之间分配，默认启动缓冲区为5MiB。由于接收缓冲区的大小相当大，垃圾回收可能需要很长时间。为了测试这一点，我们将最大rmem大小减小到2MiB，并重复了延迟测量：$系统控制网络ipv4.tcp协议网络ipv4.tcp附件=4096 1048576 2097152$stap-v直方图-内核.stp'内核函数（"tcp_崩溃"）'300持续时间最小值：0毫秒平均值：0毫秒最大：3ms计数：592个现在，这些数字好多了。改变了设置后，tcp峎u崩溃的时间不会超过3ms！我们验证了net_rx_动作延迟也得到了改善：$stap-v直方图-内核.stp'内核函数（"净收益行动"）'持续时间最小值：0毫秒平均值：0毫秒最大：3ms计数：3567235个持续时间（毫秒）：值|--------------------------------------------------计数0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@35671961 | 362 | 34 | 0随着rmem的改变，观察到的网络动作时间的最大延迟从23ms下降到3ms。摘要不建议将rmem sysctl设置为仅2MiB，因为这可能会影响高吞吐量、高延迟连接的性能。另一方面，减少rmem肯定有助于缓解观察到的延迟问题。我们使用4MiB max rmem值来解决这个问题，它提供了一个合理的GC时间的折衷方案，并且不会影响TCP层的吞吐量。但最重要的是，我们展示了如何使用系统抽头来调试延迟问题。使用我们的脚本来测量您系统上的net_rx_操作延迟！我们的简单Stap脚本在GitHub上提供。本文中提到的修复已经推出。我们所有的客户都应该感觉快一点：）如果进行这种类型的调试听起来很有趣。。。我们在伦敦、新加坡和旧金山招聘！