如何调试Kubernetes集群中的网络延迟问题

就在不久前我也遇到了类似的问题，看似是玄学事件，刚开始归结于网络链路抖动，一段时间后依然存在，虽然影响都是 P99.99 以后的数据，但是扰人心智，最后通过多方面定位，解决了该问题。最后发现跟业务、网络都没有什么关系，而是基础设施自身出了问题，如下文给了一个具体排查方案，并从一定程度上解释了容器、cgroup、CPU 会给网络延迟带来怎样的影响。 随着 Kubernetes 集群规模不断增长，我们对于服务延迟的要求越来越严苛。我们开始观察到一些运行在我们 Kubernetes 平台上的服务正在面临偶发的延迟问题，这些断断续续的问题并不是由于应用本身的性能问题导致的。 我们发现，Kubernetes 集群上的应用产生的延迟问题看上去似乎是随机的，对于某些网络连接的建立可能会超过 100ms，从而使得下游的服务产生超时或者重试。这些服务本身处理业务的响应时间都能够很好地保持在 100ms 以内，而建立连接就需要花费 100ms 以上对我们来说是不可忍受的。另外，我们也发现对于一些应该执行非常快的 SQL 查询（毫秒量级），从应用的角度看居然超过 100ms，但是在 MySQL 数据库的角度看又是完全正常的，并没有发现可能出现的慢查询问题。 通过排查，我们将问题缩小到与 Kubernetes 节点建立连接的这个环节，包括集群内部的请求或者是涉及到外部的资源和外部的访问者的请求。最简单的重现这个问题的方法是：在任意的内部节点使用 Vegeta 对一个以 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(): …;dosyscall_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）的性能对于在其之上构建的所有服务的可靠性和速度都至关重要。当我们为此作出大量的技术”投资”并提高性能时，我们运行的每个系统都会从这些改进中受益。