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

我不久前遇到了类似的问题。 这似乎是一个形而上学的事件。 最初认为是网络链路抖动造成的。 P99.99之后的数据受到影响，但一段时间后仍然存在。 但却扰乱了人们，最终通过多维定位解决了问题。 最后发现，这与业务或网络无关，而是与基础设施本身有关。 下面给出具体的故障排除方案。 它在一定程度上解释了容器、cgroup和CPU如何影响网络延迟。 。

随着 Kubernetes 集群规模不断增长，服务延迟要求变得越来越严格。 我们开始观察 Kubernetes 平台上运行的某些服务的零星延迟问题。 这些间歇性问题并不是由应用程序本身的性能问题引起的。

我们发现 Kubernetes 集群上的应用程序引起的延迟问题似乎是随机的。 某些网络连接可能需要超过 100 毫秒才能建立，导致下游服务超时或重试。 虽然这些服务自身处理任务的响应时间很好在100ms以内，但建立连接却需要100ms以上，这是无法忍受的。 另外，我们发现一些需要运行得非常快（毫秒级）的 SQL 查询从应用程序的角度来看实际上花费了 100 毫秒以上，但从 MySQL 数据库的角度来看，这是完全正常的，我无法想象它很慢。 查询发现。 问题。

通过调查，我们将问题范围缩小到与 Kubernetes 节点建立连接的过程，包括集群内部的请求以及外部资源和访问者的参与。 要求。 重现此问题的最简单方法是在任何内部节点上使用 Vegeta 对 NodePort 上公开的服务启动 HTTP 压力测试。 您会注意到，时不时会生成延迟较长的请求。 本文介绍了我们如何跟踪此问题。

拨开迷雾，找到问题的关键

我想用一个简单的例子重现这个问题，所以我想缩小问题的范围并消除不必要的复杂性。 最初，我们不得不进行减去，因为 Vegeta 和 Kubernetes Pod 之间的数据流涉及太多组件，因此很难确定这是否是更深层次的网络问题。

Vegeta 客户端请求 Kube 节点。 TCP 请求。 数据中心中的 Kubernetes 集群使用覆盖网络（在现有数据中心网络之上运行）将覆盖网络 IP 数据包封装在数据中心 IP 数据包中。 当请求到达第一个 kube 节点时，它会执行 NAT 转换，将 kube 节点的 IP 和端口转换为 Overlay 的网络地址，特别是运行应用程序的 pod 的 IP 和端口。 请求响应会导致相应的逆变换 (SNAT/DNAT)。 这是一个非常复杂的系统，维护大量可变状态，这些状态随着服务的部署而不断更新。

当我第一次使用 Vegeta 进行压力测试时，我注意到 TCP 握手阶段（SYN 和 SYN-ACK 之间）存在延迟。 为了简化HTTP和Vegeta带来的复杂性，使用hping3发送SYN数据包，观察响应数据包是否有延迟，然后关闭连接。 通过过滤掉延迟大于 100 毫秒的数据包，您可以轻松地重新创建 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 运动=30927 flag=SA seq=1485 win=29200 rtt=127.1 ms len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flag=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 flag=SA 序列=1488 win=29200 rtt=104.1 ms len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flag=SA 序列=5024 win = 29200 rtt=109.2 ms len=46 ip=172.16.47.27 ttl=59 DF id=0 sports=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms

按序列号记录 当我检查了时间和时间，我首先注意到这个延迟不是单一的。 它经常发生在集群上，就好像一次处理积压的请求，而不是零星地处理。

接下来，具体确定哪些组件可能存在异常。 由于它们有数百行长，这些 NAT 规则是针对 kube-proxy 还是 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 flag=RA seq=7346 win=0 rtt=127.3 毫秒 len=40 ip =10.125.20.64 ttl=64 DF id=0 Sports=0 标志=RA seq=7347 win=0 rtt=117.3 ms len=40 ip=10.125.20.64 ttl=64 DF id=0 sports=0 flags=RA seq= 7348 win=0 rtt=107.2 ms

[ h]结果表明问题依然存在。 这消除了 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 ic mp_ =40 23rtt=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 毫秒 28 ip = 10 .125. 20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 毫秒 len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 毫秒 len=28 ip=10.125.20.64 ttl=64id =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.1ms

结果表明 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 ip=1 72.16.47.27 ttl=61 id=41129 icmp _seq=1 2566 rtt=120.8 毫秒len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 毫秒 len=46 ip=172.16.47.27 ttl=61 41131 icmp_seq= 12568 rtt=100.7 毫秒 len=4 6 ip=172.16 。 47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 毫秒 len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 毫秒 len=46 ip=172.16.47.27 ttl=61id =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

在这个复杂的背后，有一个简单的解释，例如：实际上是两个 Any。 kube节点之间的网络通信，包括ICMP。 如果目标节点“不健康”（某些节点比其他节点更差，例如高延迟或频繁出现问题），那么，如果出现问题，您仍然会遇到类似的延迟。

那么问题是，显然并非所有机器都存在此问题。 为什么这个问题只发生在这些kube节点服务器上？当kube节点是请求的发送者或请求的接收者时，你可以轻松缩小范围。 您可以使用集群外部的计算机作为发送方，并使用同一台“已知故障”计算机作为请求的目标。 我发现这个方向的请求还是有问题的。

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep –line-buffered ‘rtt=[0-9]{3}\.’ =46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flag=RA seq=312 win=0 rtt=108.5 ms len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flag = RA序列= 5903 win = 0 rtt = 119.4 ms len = 46 ip = 172.16.47.27 ttl = 61 DF id = 0 sport = 9876 flag = RA序列= 6227 win = 0 rtt = 139.9 ms len = 46 ip = 172.16。 47.27 ttl=61 DF id=0 sports=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 统计数据 — 发送数据包 22352，接收数据包 22350，往返丢包率 1% /Average/Max = 0.2/7.6/1010.6 ms

检查数据包捕获延迟数据将为您提供更多信息。 具体来说，发送方（底部）看到延迟，但接收服务器没有（顶部） – 请注意图中的增量列（以秒为单位）：

[h ]

另外，接收端的 TCP 和 ICMP 网络数据包 从顺序上看，我们看到 ICMP 数据包总是按照发送的顺序（基于它们的序列 ID）到达接收方，但它们的到达时间是不规则的，并且 TCP 数据包的序列 ID 有时会发生变化，导致一些数据包留下来。 特别是，如果统计发送和接收 SYN 数据包的端口，则接收端的端口不连续，但发送端的端口是连续的。

我们的服务器当前使用的网卡（例如我们在数据中心使用的硬件）处理 TCP 和 ICMP 网络消息，这样做有一些微妙之处。 。 不同之处。 当数据报到达时，网卡对每个连接上传递的数据包进行哈希处理，尝试将不同的连接分配给不同的接收队列，并（可能）为每个队列分配 CPU 核心。 对于 TCP 数据包，此哈希值包括源 IP 和端口以及目标 IP 和端口。 这意味着每个连接的哈希值可以不同。 对于 ICMP 数据包，没有端口，因此哈希仅包含源 IP 和目标 IP。 这也解释了上述发现。

另一个新发现是两台主机之间的ICMP数据包暂停了一段时间，但TCP数据包在同一段时间内一切正常。 这似乎表明接收网卡队列哈希是一个“笑话”。 几乎可以肯定，暂停不是发送方的问题，而是在接收方处理 RX 数据包期间发生的。

这是数据包处理阶段的暂停，因为这消除了 kube 节点之间的传输问题，并且某些 kube 位于接收端，您可以看到这是一个。节点。 。

深入了解Linux内核的网络包处理流程，了解为什么

接收端会出现问题，我们来看看了解 Linux 的 kube 节点服务如何处理网络数据包。

在最简单的专有实现中，收到网络数据包后，网卡必须向 Linux 内核发送中断来处理网络数据包，我会通知您。有。 。 内核停止当前正在执行的任何其他工作，将上下文切换到中断处理程序，处理网络数据包，然后返回到之前的工作任务。

Masu 上下文切换非常慢。 虽然这对于 20 世纪 90 年代的 10Mbit 网卡来说可能还不错，但现在许多服务器都配备了每秒可处理多达 1500 万个数据包的 10G 网卡。 对于小型 8 核来说，这意味着每秒会生成数百万个中断。

许多年前，Linux 中添加了一个新的 NAPI。 过去使用网络 API 来替代传统方法。 现代网卡驱动程序可以通过使用这个新的 API 显着提高性能。 数据包处理性能（速率）。 即使在低速下，内核仍然接受来自网卡的中断，如上所述。 当到达的数据包数量超过阈值时，内核将禁用中断并开始轮询网卡以批量捕获网络数据包。 该进程在“softirq”下运行。 或者你可以称之为软件。中断上下文（软件中断上下文）。 这发生在系统调用结束时，当程序进入内核空间而不是用户空间时。

这种方法比传统方法更好不仅速度快，而且还带来了另一个问题。 如果数据包太多，所有 CPU 时间都花在处理从网卡接收到的数据包上，那么您将无法让用户模式程序实际处理队列中的这些网络请求（TCP 从中获取数据等） 。 连接等）。 最终队列将填满并开始丢弃数据包。 为了平衡用户模式和内核模式执行时间，内核限制给定软件中断上下文的处理数据包数量并调整“预算”。 当超出此“预算”值时，将启动另一个名为“ksoftiqrd”的线程（或者您可能已经使用 ps 命令看到过该线程）来处理正常系统调用路径上下文之外的这些软件中断。 该线程使用标准进程调度程序来实现公平调度。

组织Linux内核来组织网络数据包顺便说一句，事实证明这个处理过程其实是可以停止的。 如果 Softirq 处理程序调用之间的间隔较长，则网络数据包可能会在 NIC 的 RX 队列中保留一段时间。 这可能是由 CPU 核心死锁或缓慢的任务阻止核心处理 SoftIRQ 引起的。

将问题范围缩小到特定的核心或方法

到目前为止，我们相信这种延迟是真实存在的，我们也知道： 我们似乎观察到一些非常相似的症状。 下一步是确认理论并了解问题的原因。

我们看一下导致问题的网络请求：

len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 毫秒 len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 毫秒 len=46 ip=172.16.5 3. 32 ttl=61 id= 29575 icmp_seq=1955 rtt=79.2 毫秒 len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 毫秒 len=46 ip=172.16.53.32 ttl= 61 295第77章 77 1957 rtt=59.1 毫秒 len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 毫秒 len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rt t=65 。 6ms length =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 允许您编写小型 C 程序并将它们挂载到内核中的任何函数。 然后可以缓存事件并将其发送到用户模式 ​​Python 程序，并且此 Python该程序对这些事件执行一些聚合分析并返回结果。 上述“在内核中的任何功能中实现”实际上很困难，但由于它是为了遵循生产环境中常见的问题而设计的，因此无法在测试中轻松重现 尽可能安全地使用。 开发环境等

我们的想法很简单。 由于我们知道内核正在处理这些 IMCP Ping 数据包，因此我们拦截内核接受传入站的 icmp_echo 方法。 发送 ICMP“回显请求”数据包并发起 ICMP 响应“回显回复”。 这些数据包可以通过 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 4542spokereport-s 779

关于这里 输入关于进程名称需要注意的一件事是，在系统调用之后发生的 Softirq 上下文中，启动此系统调用的进程将显示为“进程”，即使它是由内核处理的。 内核上下文。

执行时，您可以将 hping3 观察到的停止数据包与处理该数据包的进程关联起来。 对捕获的 icmp_seq 值进行简单的 grep 可以提供上下文，以查看处理这些数据包之前发生了什么。 与上面 hping3 中显示的 icmp_seq 值匹配的数据包被标记，以及观察到的 RTT 值（在括号中，假设 RTT<50ms 的请求没有被过滤掉）：

TGID PID进程名称 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 ir/ 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 k softirqd/11 1960 ** (29ms) 76 76 ksoftirqd/11 1961 ** (19ms) 76 76 ksoftirqd/11 1962 ** (9ms) — 10137 10436 顾问 2068 10137 10436 顾问 2069 76 76 ksoftirqd/11 2070 ** 75m76 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 做了什么导致停顿？

停顿是如何发生的，导致停顿一旦了解了进程和哪个 CPU发生停顿的核心，你会对它有更好的理解。 允许内核硬阻止 ksoftirqd 而不是预先调度它，并确保数据包在 cAdvisor 的 Softirq 上下文中进行处理：cAdvisor 的系统调用调用可能会非常慢，一旦完成，它就可以正常处理剩余的网络数据包。

[ h]

这只是一个理论，但是这个我们如何验证实际发生的情况？我们可以做的是跟踪整个过程中 CPU 内核上正在执行的操作，并找到数据包超出“预算”和 ksoftirqd 进程的点，然后返回查看正在运行的内容CPU 核心。 可以将其想象为每隔几毫秒对 CPU 进行一次 X 光检查。 看起来像这样：

深度遍历显然，这一要求的大部分已经得到实施。 性能记录工具可以在特定频率下对指定CPU内核进行采样，并生成实时调用图（包括用户空间和内核）。 由 Brendan Gregg 开发的源自 FlameGraph 的程序允许您记录和操作实时通话。 该工具保留堆栈跟踪的顺序。 通过每 1 毫秒采样一次，您可以获得 1 行堆栈跟踪，并在 ksoftirqd 运行之前获得 100 毫秒。 示例：

# 每秒记录 999 次，或每 1 毫秒记录一次，并带有偏移量，以便与计时器不完全匹配。 sudo perf record -C 11 -g -F 999 # 获取该记录以获得更简单的堆栈跟踪。 sudo perf 脚本 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl |p ksoftir -B 100

结果是：

（数百条相似痕迹）

[h ]顾问;[顾问];[顾问];[顾问];[顾问];[顾问];[顾问];[顾问];[顾问];[顾问];[顾问];[顾问]; [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 person];[ [advisor];[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];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_for k;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_rc v_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 ; ;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;swima_mapping_error;hash_net4_test k softirqd/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_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。 那么这意味着什么呢？

每一行都是特定时刻的跟踪记录。 堆栈中调用的每个方法都用分号分隔。 在该行的中间，您可以看到正在调用的系统调用是 read(): …;do syscall_64;sys_read;… 因此，cAdvisor 与 read() 系统调用、这个调用以及 mem_cgroup * 函数有关（因为它是方法栈底部的方法）。

方法堆栈跟踪不容易显示读取的具体内容，因此我们使用 strace 来查看 cAdvisor 的操作，并使用了 100 毫秒，您可以发现更多。 系统调用。

西奥·朱利安ne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep ‘<0\.[1-9]' [pid 10436] ) = 0 [pid 10432] ) = 0 [pid 10137] ) = 0 [pid 10384] ) = 0 [pid 10436] “缓存154234880\nrss 507904\nrss_h”…, 4096) = 658 [pid 10384] ) = 0 [pid 10436] ) = 0 [pid 10436] “缓存 0\nrss 0\nrss_huge 0\nmapped_”…, 4096) = 577 [pid 10427] “缓存 0\nrss 0\nrss_huge 0\nmapped_”…, 4096) = 577 [pid 10411] ) = 0 [pid 10382] ) = 0 (超时) [pid 10436] “缓存154234880\nrss 507904\nrss_h”。 .., 4096) = 660 [pid 10417] ) = 0 [pid 10436] ) = 0 [pid 10417] ) = 0 [pid 10417] “缓存 0\nrss 0\nrss_huge 0\nmapped_”…, 4096) = 576

此时可以看到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 ~ $

我能够重现该问题，表明内核导致了 I am 。 病”的方法。

是什么导致读取如此缓慢？

所以在这个阶段，其他问题报告的问题您可以轻松地解决检查类似的报告。 事实证明，这个问题已经报告给 cAdvisor，结果是 CPU 使用率高的问题，但我只是没有注意到延迟也随机影响网络堆栈。 事实上，我们的一些内部开发人员已经注意到 cAdvisor 消耗的 CPU 比预期多，但我们的服务器具有充足的 CPU 性能，因此我们认为这不是造成问题的原因。 因此，我们没有调查CPU的使用情况。

如果你看这个问题，它主要是关于内存cgroup，它负责管理和计算命名空间（容器）内的内存使用情况。 当 cgroup 中的所有进程终止时，Docker 会释放内存 cgroup。 然而，“内存”不仅仅是进程的内存，我们现在知道，当进程内存使用耗尽时，内核还会为dentry和inode（目录和文件元数据）等缓存区域分配内存。 缓存在内存cgroup中。 从这个问题可以看出：

“Zombie” cgroups: 即使进程没有运行并且已被删除，内存空间仍然保留（在我们的例子中，这些缓存对象是目录数据，但它们也可以是页面缓存或 tmpfs。）

释放 cgroup 时，内核不会遍历所有缓存页面（这可能很耗时），而是会惰性地等待内存被使用。 一旦所有内存页都被清除，相应的cgroup最终就会被回收。 同时，这些cgroup并将继续纳入统计。

从性能角度来看，我们选择快速执行初始清理，分割回收每个页面，以减少总体直接分摊回收所需的大量时间。 这种方法在内存中保留一些缓存。 但没关系。 这不是“泄漏”，因为当内核回收缓存中的最后一页内存时，cgroup 最终将被清理。 不幸的是，问题在于 memory.stat 执行搜索的方式。 例如，在某些服务器上，内核仍为 4.9 版本。 该版本的实现存在问题。 此外，我们的服务器通常具有大量内存容量。 这意味着最终的内存缓存删除和僵尸 cgroup 清理可能需要一些时间。

我们注意到节点上存在大量僵尸cgroup，并且部分节点的读取/暂停时间超过1秒。

此 cAdvisor 问题的临时解决方法是立即释放系统范围的目录/inode 缓存。 这会立即消除读取延迟并减少网络延迟。 解决方案：这是因为删除缓存还包括“僵尸”cgroup 占用的缓存页面并同时释放它们。 这不是最终的解决方案，但它证实了问题的原因。

较新的内核版本（4.19及更高版本）被发现可以提高内存.stat调用的性能，因此更新到该版本的内核后，这是没有的更长的问题。 案例问题。 在此期间，我们使用现有工具来检测 Kubernetes 集群中节点的问题，并妥善删除并重新启动它们。 我已经使用这些工具来检测足以导致问题的延迟情况。 一旦时间过去，正常的重新启动就会解决这个问题。 这为我们提供了升级其余服务器上的系统和内核的空间。

概述

此问题表现为 NIC RX 队列停顿数百毫秒，因此短连接和长连接将会出现延迟。 中级（例如 MySQL 查询和响应）数据包间延迟）。 即使是最基本的系统（例如 Kubernetes）的理解和维护性能对于构建在其之上的所有服务的可靠性和速度也至关重要。 如果您在这方面进行了大量的技术“投资”来提高性能，那么您运行的每个系统都将从这种改进中受益。