记一次在Kubernetes上进行网络troubleshooting

作者 |祝祥 翻译

来源 | 新钛云服（ID：newtyun）

转载请联系授权（微信ID：zlm935177782）

在过去的几年中，Kubernetes已成为GitHub上的标准部署模式。现在，我们在Kubernetes上运行了大量内部和外部的服务。随着Kubernetes集群的增长以及我们对服务延迟时间的要求变得越来越严格，我们开始注意到我们环境中在Kubernetes上运行的某些服务正在经历的延迟，这不能归因于应用程序本身的性能特征。

从本质上讲，运行在Kubernetes集群上的应用程序在连接上我们观察到高达或超过100ms的随机延迟，这将导致下游超时或重试。我们预计服务能够在100毫秒内响应请求，但当连接本身花费了很长时间时，这明显是不可行的。另外，我们还观察到了非常快的MySQL查询，从查询应用程序的角度来看，我们预计这需要几毫秒的时间，而MySQL查询确实只用了几毫秒时间。

最初，问题被缩小到涉及Kubernetes节点的通信，即使连接的另一端不在Kubernetes之内。我们使用的是Vegeta基准测试工具，该工具可以在任何内部主机运行，以运行的Kubernetes服务端口为目标，测试过程中会偶尔出现高延迟。在这篇文章中，我们将逐步解决根本问题。

消除排障复杂性以快速找到网络故障的问题点
通过复制线上案例，我们希望缩小问题范围并消除排障的复杂性。最初，Vegeta和在Kubernetes上运行的Pod之间的流程中有太多的动态部分，无法确定这是否是更深层的网络问题，因此我们需要排除一些问题。

客户端Vegeta与群集中任何kube节点建立TCP连接。Kubernetes在我们的数据中心中使用overlay network（在我们现有数据中心网络之上运行的网络）网络模型，该网络使用IPIP（将覆盖网络的IP数据包封装在数据中心的IP数据包中）隧道协议。当与第一个kube节点建立连接时，它将执行网络地址转换（NAT），以将kube节点的IP和端口转换为overlay network（特别是运行该应用程序的Pod）上的IP和端口。数据包返回时，它将撤消所有这些步骤。这是一个复杂的过程，具有很多状态，涉及到多个组件，它们随着服务的部署和移动而不断更新和变化。

tcpdump是原始Vegeta基准上运行的一部分，我们观察了TCP握手（介于SYN和SYN-ACK之间）的延迟。为了简化HTTP和Vegeta的某些复杂性，我们可以使用hping3只对SYN数据包执行“ ping”操作，看看是否观察到响应数据包中的等待时间，然后放弃连接。我们可以对其进行过滤，使其仅包含超过100ms的数据包，并获得比完整的7层Vegeta基准测试或针对服务的攻击更为简单的重现案例。以下为服务（30927）使用“node port”上的TCP SYN / SYN-ACK以10ms的间隔ping一个kube节点，间隔为10ms，并过滤了慢响应：

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117.0 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms

我们获得的第一个观察结果是，这不是一次性的，而是经常分组出现的，就像最终处理的积压订单一样。

接下来，我们要缩小哪些组件可能存在故障。是数百条规则的kube-proxy iptables NAT规则吗？是IPIP隧道和网络上处理不佳的东西吗？一种验证方法是测试系统的每个步骤。如果我们删除NAT和防火墙逻辑而仅使用IPIP部分会发生什么：

幸运的是，在位于同一网络中的节点上直接与 overlay IP 对接，非常容易做到：

theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107.2 ms

根据我们的结果，问题仍然存在！那排除了iptables和NAT。这是TCP的问题吗？让我们看看执行普通的ICMP ping时会发生什么：

theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=28 ip=10.125.20.64 ttl=64 id=42594 icmp_seq=104 rtt=110.0 ms
len=28 ip=10.125.20.64 ttl=64 id=49448 icmp_seq=4022 rtt=141.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49449 icmp_seq=4023 rtt=131.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49450 icmp_seq=4024 rtt=121.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49451 icmp_seq=4025 rtt=111.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 ms
len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50024 icmp_seq=4344 rtt=116.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50025 icmp_seq=4345 rtt=106.8 ms
len=28 ip=10.125.20.64 ttl=64 id=59727 icmp_seq=9836 rtt=106.1 ms

我们的结果表明问题仍然存在。是引起问题的IPIP隧道吗？让我们进一步简化一下：

这是否是这两个主机之间的每个数据包？

theojulienne@kube-node-client ~ $ sudo hping3 172.16.47.27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=46 ip=172.16.47.27 ttl=61 id=41127 icmp_seq=12564 rtt=140.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41128 icmp_seq=12565 rtt=130.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41129 icmp_seq=12566 rtt=120.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41131 icmp_seq=12568 rtt=100.7 ms
len=46 ip=172.16.47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9064 icmp_seq=31445 rtt=114.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9065 icmp_seq=31446 rtt=104.2 ms

在复杂性的背后，它就像两台kube节点主机彼此之间发送任何数据包（甚至是ICMP ping）一样简单。如果目标主机是“不良”主机（某些主机比其他主机差），他们仍然会看到延迟。

现在还有最后一件事要问：我们显然没有在所有地方都观察到这一点，那么为什么只在kube节点服务器上观察到呢？当kube节点是发送方还是接收方时，会发生这种情况吗？幸运的是，通过使用Kubernetes外部的主机作为发送方，但具有相同的“已知不良”目标主机，也很容易缩小范围。我们可以观察到这仍然是一个问题：

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108.5 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119.4 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139.9 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131.2 ms

然后，从先前的源kube-node到staff shell主机（由于ping同时具有RX和TX组件而将其排除在外）执行相同的操作：

theojulienne@kube-node-client ~ $ sudo hping3 172.16.33.44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
^C
--- 172.16.33.44 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms

通过观察延迟数据包，我们可以获得更多信息。具体来说，“发送者”主机（下方第二幅图）观察到此超时，而“接收者”主机（下方第一幅图）观察不到此超时（请参见“增量”列（以秒为单位）：

此外，通过查看上述TCP和ICMP结果的接收方的数据包排序（基于序列号）之间的差异，我们可以观察到ICMP数据包始终以与发送时相同的顺序到达，但是时间不均匀，TCP数据包有时会交错，但其中一部分会停顿。值得注意的是，我们观察到，如果您对SYN数据包的端口进行计数，则这些端口在接收器端的顺序不正确，而在发送器端的顺序是正常的。

就像我们在数据中心中一样，现代服务器NIC处理包含TCP与ICMP的数据包之间存在细微的差异。当数据包到达时，NIC会“按连接”对数据包进行哈希处理，并尝试在接收队列之间划分连接，每个队列（大约）委托给给定的CPU内核。对于TCP，此哈希同时包括源IP和目标IP以及端口。换句话说，每个连接的散列（可能）都不同。对于ICMP，由于没有端口，因此仅对IP源和目标进行哈希处理。

另一个新发现是，我们可以从ICMP vs TCP中的序列号看出，ICMP在此期间观察到了两台主机之间所有通信的停顿，而TCP没有。这告诉我们，RX队列散列很可能在起作用，几乎可以肯定地表明，停顿是在处理RX数据包，而不是在发送响应。

这排除了kube-node的传输，因此我们现在知道它在处理数据包方面停滞不前，并且在某些kube-node服务器上位于接收端。

深入研究Linux内核的数据包处理
要了解为什么问题可能出现在某些kube节点服务器的接收端，让我们看一下Linux内核如何处理数据包。

回到最简单的传统实现，网卡接收到一个数据包，并向Linux内核发送一个中断，指出存在应该处理的数据包。内核停止其他工作，将上下文切换到中断处理程序，处理数据包，然后切换回其正在执行的操作。

这种上下文切换很慢，在90年代对10Mbit NIC来说可能还不错，但是在NIC为10G并且以最大speed运行的现代服务器上，每秒可以带来大约1500万个数据包，而在具有八核的小型服务器上这可能意味着每个内核每秒中断数百万次。

多年前，Linux 不再不断处理中断，而是添加了NAPI，这是现代驱动程序用来提高高数据包速率性能的网络API。在低速率下，内核仍然按照我们提到的方法接受来自NIC的中断。一旦有足够的数据包到达并超过阈值，它将禁用中断，而是开始轮询NIC并分批提取数据包。该处理在“ softirq”或软件中断上下文中完成。这发生在系统调用和硬件中断的末尾，这是内核（而不是用户空间）已经在运行的时候。

这快得多，但是带来了另一个问题。如果要处理的数据包如此之多，以至于我们花了所有的时间来处理来自NIC的数据包，但又没有时间让用户空间进程实际上耗尽那些队列（从TCP连接等读取），会发生什么？最终，队列将填满，我们将开始丢弃数据包。为了使公平起见，内核将在给定softirq上下文中处理的数据包数量限制为一定的预算。一旦超出预算，它就会唤醒一个单独的线程ksoftirqd（您将在ps每个内核中看到一个线程），该线程将在正常的系统调用/中断路径之外处理这些softirq。使用标准流程调度程序调度该线程，该进程已经尝试公平了。

纵观内核处理数据包的方式，我们可以肯定地有机会停止处理。如果两次softirq处理调用之间的时间增加，则在处理数据包之前，数据包可能会在NIC RX队列中停留一段时间。这可能是导致CPU内核死锁的原因，也可能是导致内核无法运行softirqs的缓慢原因。

将处理范围缩小到核心重点
在这一点上，这有可能发生是有道理的。下一步是确认这一理论，如果是，请理解造成这种情况的原因。

让我们回顾一下之前看到的延迟较大的往返数据包：

len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 ms
len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 ms
len=46 ip=172.16.53.32 ttl=61 id=29575 icmp_seq=1955 rtt=79.2 ms
len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 ms
len=46 ip=172.16.53.32 ttl=61 id=29577 icmp_seq=1957 rtt=59.1 ms
len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 ms
len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rtt=65.6 ms
len=46 ip=172.16.53.32 ttl=61 id=29792 icmp_seq=2072 rtt=55.5 ms

如前所述，这些ICMP数据包被散列到单个NIC RX队列，并由单个CPU内核进行处理。如果我们想了解内核在做什么，那么了解它们在哪里（cpu内核）以及如何处理这些数据包，这样我们就可以将它们付诸实践。

现在是时候使用允许实时跟踪正在运行的Linux内核的工具了——bcc。这样，您就可以编写可在内核中挂接任意函数的小型C程序，并将事件缓冲回到用户空间Python程序中，该程序可以对其进行汇总并将其返回给您。“在内核中挂钩任意函数”是困难的部分，但是实际上它尽其所能地变得尽可能安全，因为它旨在精确地跟踪您不能简单地在其中复制的这种生产问题。测试或开发环境。

这里的计划很简单：我们知道内核正在处理这些ICMP ping数据包，因此让我们挂接内核函数icmp_echo，该函数接收传入的ICMP“回声请求”数据包并启动发送ICMP“echo response”应答。我们可以使用hping3上面显示的icmp_seq增量来标识数据包。

该bcc脚本的代码看起来很复杂，但是将其分解后并没有听起来那么可怕。该icmp_echo函数传递给a struct sk_buff *skb，这是包含ICMP回显请求的数据包。我们可以深入研究此内容并拉出echo.sequence（映射到上面icmp_seq显示的内容hping3），然后将其发送回用户空间。方便地，我们也可以获取当前的进程name/ id。当内核处理这些数据包时，这将为我们提供如下结果：

TGID PID   PROCESS NAME ICMP_SEQ`
`0   0   swapper/11   770`
`0   0   swapper/11   771`
`0   0   swapper/11   772`
`0   0   swapper/11   773`
`0   0   swapper/11   774`
`20041 20086 prometheus   775`
`0   0   swapper/11   776`
`0   0   swapper/11   777`
`0   0   swapper/11   778`
`4512 4542 spokes-report-s 779

关于该进程名称，需要注意的一件事是，在系统调用后的softirq上下文中，您看到使syscall显示为“process”的进程，即使实际上是内核在内核上下文中安全地对其进行处理。

通过运行，我们现在可以将观察到的停顿数据包与hping3处理它的进程关联起来。grep在icmp_seq具有某些上下文的值的捕获中，一个简单的例子显示了在处理这些数据包之前发生的情况。与上面的hping3icmp_seq值对齐的数据包已经标记了我们在上面观察到的rtt（以及未过滤掉<50ms rtt的期望值）：

TGID PID   PROCESS NAME ICMP_SEQ ** RTT`
`--`
`10137 10436 cadvisor   1951`
`10137 10436 cadvisor   1952`
`76   76   ksoftirqd/11 1953 ** 99ms`
`76   76   ksoftirqd/11 1954 ** 89ms`
`76   76   ksoftirqd/11 1955 ** 79ms`
`76   76   ksoftirqd/11 1956 ** 69ms`
`76   76   ksoftirqd/11 1957 ** 59ms`
`76   76   ksoftirqd/11 1958 ** (49ms)`
`76   76   ksoftirqd/11 1959 ** (39ms)`
`76   76   ksoftirqd/11 1960 ** (29ms)`
`76   76   ksoftirqd/11 1961 ** (19ms)`
`76   76   ksoftirqd/11 1962 ** (9ms)`
`--`
`10137 10436 cadvisor   2068`
`10137 10436 cadvisor   2069`
`76   76   ksoftirqd/11 2070 ** 75ms`
`76   76   ksoftirqd/11 2071 ** 65ms`
`76   76   ksoftirqd/11 2072 ** 55ms`
`76   76   ksoftirqd/11 2073 ** (45ms)`
`76   76   ksoftirqd/11 2074 ** (35ms)`
`76   76   ksoftirqd/11 2075 ** (25ms)`
`76   76   ksoftirqd/11 2076 ** (15ms)`
`76   76   ksoftirqd/11 2077 ** (5ms)

结果告诉我们一些事情。首先，对这些数据包进行处理，ksoftirqd/11以方便地告诉我们这对特定的机器将其ICMP数据包散列到接收方的core 11。我们还可以看到，每次遇到停顿时，我们总是会看到在cadvisorsyscall softirq上下文中处理了一些数据包，然后ksoftirqd接管并处理了积压，恰好是我们希望通过积压工作的数量。

cadvisor总是在此之前立即运行的事实也将它牵连到问题中。具有讽刺意味的是，cadvisor “分析了正在运行的容器的资源使用情况和性能特征”，但却引发了这一性能问题。与许多与容器相关的事情一样，它们都是相对尖端的工具，可能会导致某些预料不到的性能下降情况。

cadvisor是如何影响的？
了解了停顿如何发生，导致停顿的过程以及发生的CPU内核之后，我们现在对它的外观有了一个很好的了解。为了使内核能够硬阻塞而不是ksoftirqd提前调度，并且鉴于我们看到了在cadvisorsoftirq上下文下处理的数据包，很可能cadvisor正在运行缓慢的syscall，该syscall会以正在处理的其余数据包结尾：

这是一个理论，但是我们如何验证呢？我们可以做的一件事是跟踪整个过程中CPU内核上正在运行的内容，找出数据包超出预算并由ksoftirqd处理的点，然后再回顾一下以查看CPU内核上正在运行的内容。可以将其想象为每隔几毫秒对CPU进行一次X射线检查。它看起来像这样：

这已得到大多数支持。该perf record工具以特定频率对给定的CPU内核进行采样，并且可以生成实时系统（包括用户空间和内核）的调用图。使用来自Brendan Gregg的FlameGraph的工具的快速叉子进行记录并对其进行操作，该工具保留了堆栈跟踪的顺序，我们可以为每个1ms样本获得单行堆栈跟踪，然后ksoftirqd在跟踪之前获得100ms的样本：

# record 999 times a second, or every 1ms with some offset so not to align exactly with timers`
`sudo perf record -C 11 -g -F 999`
`# take that recording and make a simpler stack trace.`
`sudo perf script 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl | grep ksoftir -B 100

结果如下：(hundreds of traces that look similar)

cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_iter cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;ixgbe_poll;ixgbe_clean_rx_irq;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;bond_handle_frame;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;ipip_tunnel_xmit;ip_tunnel_xmit;iptunnel_xmit;ip_local_out;dst_output;__ip_local_out;nf_hook_slow;nf_iterate;nf_conntrack_in;generic_packet;ipt_do_table;set_match_v4;ip_set_test;hash_net4_kadt;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;hash_net4_test ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;gro_cell_poll;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;dev_queue_xmit_nit;packet_rcv;tpacket_rcv;sch_direct_xmit;validate_xmit_skb_list;validate_xmit_skb;netif_skb_features;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;__dev_queue_xmit;dev_hard_start_xmit;__bpf_prog_run;__bpf_prog_run

输出有很多东西，您可以看到它是我们从上面的ICMP跟踪器看到的cadvisor-then-ksoftirqd模式。这是什么意思？

每行都是一个时间点上的CPU轨迹。堆栈中的每个调用都;在该行上以分隔。查看各行的中间，我们可以看到被调用的syscall是read(): .... ;do_syscall_64;sys_read; ...cadvisor在read()与mem_cgroup_*功能有关的syscall中花费了大量时间（调用堆栈的顶部/行尾）。

调用堆栈跟踪不方便查看正在读取的内容，因此让我们使用stracecadvisor进行操作并查找100ms或更慢的syscall：

theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0\.[1-9]'`
`[pid 10436] <... futex resumed> )   = 0 <0.156784>`
`[pid 10432] <... futex resumed> )   = 0 <0.258285>`
`[pid 10137] <... futex resumed> )   = 0 <0.678382>`
`[pid 10384] <... futex resumed> )   = 0 <0.762328>`
`[pid 10436] <... read resumed> "cache 154234880\nrss 507904\nrss_h"..., 4096) = 658 <0.179438>`
`[pid 10384] <... futex resumed> )   = 0 <0.104614>`
`[pid 10436] <... futex resumed> )   = 0 <0.175936>`
`[pid 10436] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 577 <0.228091>`
`[pid 10427] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 577 <0.207334>`
`[pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113>`
`[pid 10382] <... pselect6 resumed> )   = 0 (Timeout) <0.117717>`
`[pid 10436] <... read resumed> "cache 154234880\nrss 507904\nrss_h"..., 4096) = 660 <0.159891>`
`[pid 10417] <... futex resumed> )   = 0 <0.917495>`
`[pid 10436] <... futex resumed> )   = 0 <0.208172>`
`[pid 10417] <... futex resumed> )   = 0 <0.190763>`
`[pid 10417] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 576 <0.154442>

果然，我们看到了缓慢的read()calls。从mem_cgroup上面读取的内容和上下文来看，这些read()调用是指向一个memory.stat文件的，该文件显示了内存使用情况和cgroup（Docker使用的资源隔离技术）的限制。cadvisor正在轮询此文件以获取容器的资源利用率详细信息。让我们看看尝试自己读取的是内核还是Cadvisor做意外的事情：

theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null
real 0m0.153s`
`user 0m0.000s`
`sys 0m0.152s`
`theojulienne@kube-node-bad ~ $

既然我们可以重现它，则表明它是内核遇到了不正常的情况。

是什么原因导致读取速度如此之慢
在这一点上，查看其他人提交的类似问题要简单得多。事实证明，这已经报告给cadvisor，是由于CPU使用率过高而引起的，只是还没有发现网络堆栈中也随机引入了延迟。实际上，一些内部人员已经注意到cadvisor消耗的CPU超出了预期，但似乎没有引起异常问题，因为我们的服务器具有足够的CPU数目，因此尚未对CPU的使用情况进行调查。

问题的概述是，memory cgroup正在考虑namespace（container）内的内存使用情况。当该cgroup中的所有进程退出时，memory cgroup由Docker释放。但是，“memory”不仅仅是进程内存，尽管进程内存使用本身已消失，但事实证明，内核还分配了缓存到memory cgroup的缓存内容，例如dentries和inode（目录和文件元数据）。issue：

“僵尸” cgroup：没有进程且已删除但仍被占用的cgroup（在我的情况下，是从dentry高速缓存中进行的，但也可以从页面高速缓存或tmpfs中进行）。

内核不是选择在cgroup发布时对缓存中的每个页面进行迭代（这可能会很慢），而是选择等待这些页面被回收，然后在需要内存时懒惰地最终回收所有的cgroup，最后清理cgroup。同时，在统计信息收集期间仍需要对cgroup进行计数。

从性能的角度来看，他们是在一个缓慢的进程上交换时间，在每个页面的回收过程中分期偿还，并选择快速进行初始清理，以换取保留一些缓存的内存。很好，当内核回收缓存中的最后一个内存时，cgroup最终会被清除，因此这并不是真正的“泄漏”。不幸的是，memory.stat执行搜索的方式以及在某些服务器上运行的内核版本（4.9）的实现方式，再加上服务器上的大量内存，意味着最后一次缓存可能要花费很长时间要回收的数据以及要清理的僵尸cgroup。

事实证明，我们的节点具有大量的僵尸cgroup，有些节点的reads/stalls超过一秒钟。

解决该cadvisor问题的方法是，立即释放系统范围内的dentries/inodes缓存，立即停止读取延迟，并且主机上的网络延迟也停止了，因为缓存的删除包括了“僵尸” cgroup中的缓存页面，因此他们也被释放了。这不是解决方案，但可以验证问题的原因。

事实证明，较新的内核版本（4.19+）改进了memory.stat调用的性能，因此在移至该内核之后，这不再是问题。在此期间，我们拥有现有的工具，能够检测Kubernetes集群中节点的问题，并优雅地耗尽并重新启动它们，我们用来检测可能导致问题的足够高的延迟情况，并通过正常重启来处理。这为我们提供了改善的机会，而OS和内核升级则推广到了其余的机队中。

总结
因为未处理的数百毫秒的NIC RX队列积压，导致了短连接上的高延迟以及观察到的中间连接（例如MySQL查询和响应数据包之间）的延迟。理解和维护我们最基本的系统（如Kubernetes）的性能，对建立在它们之上的所有服务的可靠性和速度至关重要。当我们投入并改进这个性能时，我们运行的每个系统都会从这些改进中受益。