调试Kubernetes集群中的网络停顿问题

我们曾经在这里中聊起过Kubernetes ( Kubernetes at GitHub : https://github.blog/2017-08-16 ... ithub /)，在过去几年，Kubernetes在Github已经成为标准的部署模式。目前在Github，我们在Kubernetes上运行着海量的面向内部团队以及面向C端的服务。

随着Kubernetes集群规模不断增长，我们对于服务延迟的要求越来越严苛。我们开始观察到一些运行在我们Kubernetes平台上的服务正在面临偶发的延迟问题，这些断断续续的问题并不是由于应用本身的性能问题导致的。

我们发现，Kubernetes集群上的应用产生的延迟问题看上去似乎是随机的，对于某些网络连接的建立可能会超过100ms，从而使得下游的服务产生超时或者重试。这些服务本身处理业务的响应时间都能够很好地保持在100ms以内，而建立连接就需要花费100ms以上对我们来说是不可忍受的。另外，我们也发现对于一些应该执行地非常快的 SQL 查询（毫秒量级），从应用的角度看居然超过100ms，但是在 MySQL 数据库的角度看又是完全正常的，并没有发现可能出现的慢查询问题。

通过排查，我们将问题缩小到与Kubernetes节点建立连接的这个环节，包括集群内部的请求或者是涉及到外部的资源和外部的访问者的请求。最简单的重现这个问题的方法是：在任意的内部节点使用Vegeta ( https://github.com/tsenart/veget a) 对一个以 NodePort 暴露的服务发起 HTTP 压测，我们就能观察到不时会产生一些高延迟请求。在这篇文章中，我们将聊一聊我们是如何追踪定位到这个问题的。

拨开迷雾找到问题的关键

我们想用一个简单的例子来复现问题，那么我们希望能够把问题的范围缩小，并移除不必要的复杂度。起初，数据在Vegeta和Kubernetes Pods之间的流转的过程中涉及了太多的组件，很难确定这是不是一个更深层次的网络问题，所以我们需要来做一个减法。

Vegeta客户端会向集群中的某个Kube节点发起TCP请求。在我们的数据中心的Kubernetes集群使用Overlay网络（运行在我们已有的数据中心网络之上），会把Overlay网络的IP包封装在数据中心的IP包内。当请求抵达第一个kube节点，它会进行NAT转换，从而把kube节点的IP和端口转换成Overlay的网络地址，具体来说就是运行着应用的Pod的IP和端口。再请求响应的时候，则会发生相应的逆变换（SNAT/DNAT）。这是一个非常复杂的系统，其中维持着大量可变的状态，会随着服务的部署而不断更新。

在最开始利用Vegeta进行进行压测的时候，我们发现在TCP握手的阶段（SYN和SYN-ACK之间）存在延迟。为了简化HTTP和Vegeta带来的复杂度，我们使用hping3来发送SYN包，并观测响应的包是否存在延迟的情况，然后把连接关闭。我们能够过滤出那些延迟超过100ms的包，来简单地重现Vegeta的7层压力测试或是模拟一个服务暴露在SYN攻击中。以下的一段日志显示的是以10ms间隔向kube-node的30927端口发送TCP SYN/SYN-ACK包并过滤出慢请求的结果，

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的NAT规则吗，毕竟它们有几百行之多？还是IPIP隧道或类似的网络组件的性能比较差？排查的一种方式是去测试系统中的每一个步骤。如果我们把NAT规则和防火墙逻辑删除，仅仅使用IPIP隧道会发生什么？

如果你同样也在一个kube节点上，那么 Linux 允许你直接和Pod进行通讯，非常简单：

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请求会发生什么，

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

结果显示ICMP仍然能够复现问题。那是不是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。如果这个目标节点是“异常的”（某些节点会比另一些更糟糕，比如延迟更高，问题出现的频率更高），那么当问题发生时，我们仍然能看到类似的延迟。

那么现在的问题是，我们显然没有在所有的机器上发现这个问题，为什么这个问题只出现在那些kube节点的服务器上？是在kube节点作为请求发送方还是请求接收方时会出现呢？幸运的是，我们能够轻易地把问题的范围缩小：我们可以用一台集群外的机器作为发送方，而使用相同的"已知故障"的机器作为请求的目标。我们发现在这个方向上的请求仍然存在问题，

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节点发送请求到外部节点，

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

通过查看抓包中的延迟数据, 我们获得了更多的信息。具体来说，从发送端观察到了延迟（下图），然而接收端的服务器没有看到延迟（上图）-- 注意图中的Delta列（单位是秒）:

另外，通过查看接收端的TCP以及ICMP网络包的顺序的区别 (基于序列ID)， 我们发现ICMP包总是按照他们发送的顺序抵达接收端，但是送达时间不规律，而TCP包的序列ID有时会交错，其中的一部分会停顿。尤其是，如果你去数SYN包发送/接收的端口，这些端口在接收端并不是顺序的，而他们在发送端是有序的。

目前我们服务器所使用的网卡，比如我们在自己的数据中心里面使用的那些硬件，在处理TCP和ICMP网络报文时有一些微妙的区别。当一个数据报抵达的时候，网卡会对每个连接上传递的报文进行哈希，并且试图将不同的连接分配给不同的接收队列，并为每个队列 (大概) 分配一个CPU核心。对于TCP报文来说，这个哈希值同时包含了源IP、端口和目标IP、端口。换而言之，每个连接的哈希值都很有可能是不同的。对于ICMP包，哈希值仅包含源IP和目标IP，因为没有端口之说。这也就解释了上面的那个发现。

另一个新的发现是一段时间内两台主机之间的ICMP包都发现了停顿，然而在同一段时间内TCP包却没有问题。这似乎在告诉我们，是接收的网卡队列的哈希在"开玩笑"，我们几乎确定停顿是发生在接收端处理RX包的过程中，而不是发送端的问题。

这排除了kube节点之间的传输问题，所以我们现在知道了这是在处理包的阶段发生了停顿，并且是一些作为接收端的kube节点。

深入挖掘 Linux 内核的网络包处理过程

为了理解为什么问题会出现在kube节点服务的接收端，我们来看下Linux是如何处理网络包的。

在最简单原始的实现中，网卡接收到一个网络包以后会向Linux内核发送一个中断，告知有一个网络包需要被处理。内核会停下它当前正在进行的其他工作，将上下文切换到中断处理器，处理网络报文然后再切换回到之前的工作任务。

上下文切换会非常慢，对于上世纪90年代10Mbit的网卡可能这个方式没什么问题，但现在许多服务器都是万兆网卡，最大的包处理速度可能能够达到1500万包每秒：在一个小型的8核心服务器上这意味着每秒会产生数以百万计的中断。

许多年前，Linux新增了一个NAPI，Networking API用于代替过去的传统方式，现代的网卡驱动使用这个新的API可以显著提升高速率下包处理的性能。在低速率下，内核仍然按照如前所述的方式从网卡接受中断。一旦有超过阈值的包抵达，内核便会禁用中断，然后开始轮询网卡，通过批处理的方式来抓取网络包。这个过程是在"softirq"中完成的，或者也可以称为软件中断上下文(software interrupt context)。这发生在系统调用的最后阶段，此时程序运行已经进入到内核空间，而不是在用户空间。

这种方式比传统的方式快得多，但也会带来另一个问题。如果包的数量特别大，以至于我们将所有的CPU时间花费在处理从网卡中收到的包，但这样我们就无法让用户态的程序去实际处理这些处于队列中的网络请求（比如从TCP连接中获取数据等）。最终，队列会堆满，我们会开始丢弃包。为了权衡用户态和内核态运行的时间，内核会限制给定软件中断上下文处理包的数量，安排一个"预算"。一旦超过这个"预算"值，它会唤醒另一个线程，称为"ksoftiqrd"（或者你会在ps命令中看到过这个线程），它会在正常的系统调用路径之外继续处理这些软件中断上下文。这个线程会使用标准的进程调度器，从而能够实现公平的调度。

通过整理Linux内核处理网络包的路径，我们发现这个处理过程确实有可能发生停顿。如果softirq处理调用之间的间隔变长，那么网络包就有可能处于网卡的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包会被散列到某一个特定的网卡RX队列，然后被某个CPU核心处理。如果我们想要理解内核正在做什么，那么我们首先要知道到底是哪一个CPU核心以及softirq和ksoftiqrd是如何处理这些包的，这对我们定位问题会十分有帮助。

现在我们可以使用一些 工具 来帮助我们实时追踪Linux内核的运行状态，为此我可以可以使用bcc。bcc允许你写一小段C的程序，并挂载到内核的任意函数上，然后它可以把缓存事件并将其传送给一个用户态的 Python 程序，而这个Python程序对这些事件进行一些汇总分析然后把结果返回给你。以上所说的"挂载到内核的任意函数上"实际上是一个难点，但它已经尽可能地做到被安全使用，因为它本身就是设计来为了追踪这类生产环境的问题，这些问题普遍无法简单地在测试环境或者开发环境中重现。

我们的想法非常简单：我们知道内核正在处理那些IMCP的Ping包，那么我们就来拦截一下内核的icmp_echo方法，这个方法会接受一个入站方向的ICMP的"echo请求"包，并发起一个ICMP的回复"echo response"。我们可以通过hping3中显示的icmp_seq序列号来识别这些包。

这个bcc脚本的代码看起来似乎很复杂，但将其分解以后听起来并没有那么可怕。 icmp_echo函数传递了一个结构体的指针sk_buff * skb，它是包含ICMP echo请求的数据包。 我们可以做一些深入的研究，提取出echo.sequence（对应于上面hping3所示的icmp_seq），然后将其发送回用户空间。 同时我们也可以方便地获取到当前的进程名称或是进程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这个发生在系统调用后的上下文中，你能看到发起这个系统调用的进程显示为"process"，即使这是内核在内核的上下文中处理它。

通过运行，我们现在可以将hping3观察到的停顿数据包与处理它的进程相关联。 对捕获的icmp_seq值进行简单grep操作，通过这些上下文能够看出在处理这些数据包之前发生的情况。 符合以上hping3中显示的icmp_seq值的数据包已被标记出来，同时也显示了我们观察到的rtt数值（括号内是我们假设RTT<50ms的请求没有被过滤掉）：

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数据包散列到接收方的CPU核心11上。 我们还可以看到，每次看到停顿时，我们总是会看到在cadvisor的系统调用softirq上下文中处理了一些数据包，然后ksoftirqd接管并处理了积压，而这恰好就对应于我们发现的那些停顿的数据包。

cadvisor始终在紧接卡顿的请求之前运行的事实也表明这可能与我们排查的问题相关。具有讽刺意味的是，正如cadvisor的主页中描述的那样，我们使用cadvisor正是为了"分析正在运行的容器的资源使用情况和性能特征"，但它却引发了这一性能问题。与许多与容器相关的事情一样，这些都是相对前沿的工具，是存在导致某些预想不到的性能下降的情况。

cadvisor做了什么会导致停顿?

了解了停顿如何发生，导致停顿的进程以及发生停顿的CPU内核以后，我们现在对它有了一个很好的了解。为了让内核能够硬阻塞而不是提前调度ksoftirqd，并且我们也看到了在cadvisor的softirq上下文中处理的数据包，我们认为cadvisor调用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_r

日志有很多，但细心的你可能已经发现了其中固定的模式：cadvisor然后ksoftirqd。那这意味着什么？

其中每一行都是在某一时刻的追踪记录。每个调用的方法栈中的方法用分号来分割。在行的中间我们可以看到被调用的syscall是read(): ...; do_syscall_64;sys_read;... 所以cadvisor花费了大量的时间来调用read()系统调用，这个调用和mem_cgroup_*函数有关，因为它是方法栈中处于栈底的方法）。

方法栈的追踪并不能方便地显示出read的具体内容，那么我们可以使用strace来查看cadvisor到底在做什么，并找到那些超过100ms的系统调用。

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()系统调用是很慢的。从read读取的内容和mem_cgroup这个上下文来看，那些read()调用是在读取memory.state文件，这些文件用于描述系统的内存使用以及cgroup的限制。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的使用情况进行调查。

纵观这个问题，它主要是关于内存的cgroup，它负责管理与统计命名空间（容器）内的内存使用情况。当该cgroup中的所有进程退出时，内存cgroup会被 Docker 释放。 但是，“内存”不仅是进程的内存，而且虽然进程内存的使用量已经消失，但事实证明，内核还为缓存空间分配了内存，例如dentries和inode（目录和文件元数据），这些内容被缓存到内存cgroup中。从这个问题可以看出：

”僵尸“cgroups：那些没有进程运行并被删除得cgroups仍然持有一定得内存空间（在我们的案例中，这些缓存对象是目录数据，但也有可能是页缓存或是tmpfs）。

与其在cgroup释放的时候遍历所有的缓存页，而这也可能很慢，内核会惰性地等待这些内存需要用到的时候再去回收它们，当所有的内存页被清理以后，相应的cgroup才会最后被回收。与此同时，这些cgroup仍然会被计入统计信息中。

从性能的角度来看，他们通过分期回收每个页面来摊销直接整体回收的巨大耗时，选择快速地进行初始的清理，但这种方式会保留一些缓存在内存中。但这也没什么问题，当内核回收缓存中的最后一页内存时，cgroup最终会被清理，因此这并不是一个“泄漏”。 不幸的是，问题在于memory.stat执行搜索的方式，比如在我们的某些服务器上内核仍然是4.9版本，这个版本的实现是有问题的，再加上我们服务器一般都有大量的内存空间，这意味着最后一次内存缓存回收并清理僵尸cgroup可能要花很长时间。

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

这个cadvisor问题的临时解决方法是，立即释放系统范围内的目录/inode节点缓存，这能够立即消除读取延迟，同时网络延迟也得到解决，这是因为缓存的删除包括了那些”僵尸” cgroup占用的缓存页面，他们同时也被释放了。这并不是最终的解决方案，但可以验证问题的原因。

事实证明，较新的内核版本（4.19+）改进了memory.stat调用的性能，因此在更新到这个版本的内核以后这不再是一个问题。 在此期间，我们使用现有的工具来检测Kubernetes集群中节点出现的问题并优雅地移除并重新启动它们：我们正是利用这些工具来检测延迟的情况，当发现延迟高到会触发问题的时候，我们随即会通过正常重新启动来对其进行处理 。这为我们提供了喘息的机会，再次期间我们能够升级剩余的服务器的系统和内核。

总结一下

由于此问题表现为NIC RX队列停顿几百毫秒，它导致了短连接上的高延迟以及在连接中间（例如MySQL查询和响应数据包之间）出现的延迟。理解和维护我们最基础的系统（如Kubernetes）的性能对于在其之上构建的所有服务的可靠性和速度都至关重要。 当我们为此作出大量的技术"投资"并提高性能时，我们运行的每个系统都会从这些改进中受益。