如何调试Kubernetes集群中的网络推迟问题
发布时间：2022-04-25 10:12:50 所属栏目：云计算 来源：互联网
导读：就在不久前我也遇到了类似的问题，看似是玄学事件，刚开始归结于网络链路抖动，一段时间后依然存在，虽然影响都是 P99.99 以后的数据，但是扰人心智，最后通过多方面定位，解决了该问题。最后发现跟业务、网络都没有什么关系，而是基础设施自身出了问题，如
|
就在不久前我也遇到了类似的问题，看似是玄学事件，刚开始归结于网络链路抖动，一段时间后依然存在，虽然影响都是 P99.99 以后的数据，但是扰人心智，最后通过多方面定位，解决了该问题。最后发现跟业务、网络都没有什么关系，而是基础设施自身出了问题，如下文给了一个具体排查方案，并从一定程度上解释了容器、cgroup、CPU 会给网络延迟带来怎样的影响。 我们发现，Kubernetes 集群上的应用产生的延迟问题看上去似乎是随机的，对于某些网络连接的建立可能会超过 100ms，从而使得下游的服务产生超时或者重试。这些服务本身处理业务的响应时间都能够很好地保持在 100ms 以内，而建立连接就需要花费 100ms 以上对我们来说是不可忍受的。另外，我们也发现对于一些应该执行非常快的 SQL 查询（毫秒量级），从应用的角度看居然超过 100ms，但是在 MySQL 数据库的角度看又是完全正常的，并没有发现可能出现的慢查询问题。 通过排查，我们将问题缩小到与 Kubernetes 节点建立连接的这个环节，包括集群内部的请求或者是涉及到外部的资源和外部的访问者的请求。最简单的重现这个问题的方法是：在任意的内部节点使用 Vegeta 对一个以 NodePort 暴露的服务发起 HTTP 压测，我们就能观察到不时会产生一些高延迟请求。在这篇文章中，我们将聊一聊我们是如何追踪定位到这个问题的。 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 1. 2. 3. 4. 5. 6. 7. 根据日志中的序列号以及时间，我们首先观察到的是这种延迟并不是单次偶发的，而是经常聚集出现，就好像把积压的请求最后一次性处理完似的。 接着，我们想要具体定位到是哪个组件有可能发生了异常。是 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 1. 2. 3. 4. 从我们的结果看到，问题还是在那里！这排除了 iptables 以及 NAT 的问题。那是不是 TCP 出了问题？我们来看下如果我们用 ICMP 请求会发生什么。 在这个复杂性的背后，简单来说其实就是两个 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 1. 2. 3. 4. 5. 然后重复以上操作，这次我们从 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 1. 2. 3. 4. 5. 通过查看抓包中的延迟数据, 我们获得了更多的信息。具体来说，从发送端观察到了延迟（下图），然而接收端的服务器没有看到延迟（上图）——注意图中的 Delta 列（单位是秒）: 为了理解为什么问题会出现在 kube 节点服务的接收端，我们来看下 Linux 是如何处理网络包的。 在最简单原始的实现中，网卡接收到一个网络包以后会向 Linux 内核发送一个中断，告知有一个网络包需要被处理。内核会停下它当前正在进行的其他工作，将上下文切换到中断处理器，处理网络报文然后再切换回到之前的工作任务。 上下文切换会非常慢，对于上世纪 90 年代 10Mbit 的网卡可能这个方式没什么问题，但现在许多服务器都是万兆网卡，最大的包处理速度可能能够达到 1500 万包每秒：在一个小型的 8 核心服务器上这意味着每秒会产生数以百万计的中断。 这种方式比传统的方式快得多，但也会带来另一个问题。如果包的数量特别大，以至于我们将所有的 CPU 时间花费在处理从网卡中收到的包，但这样我们就无法让用户态的程序去实际处理这些处于队列中的网络请求（比如从 TCP 连接中获取数据等）。最终，队列会堆满，我们会开始丢弃包。为了权衡用户态和内核态运行的时间，内核会限制给定软件中断上下文处理包的数量，安排一个“预算”。一旦超过这个"预算"值，它会唤醒另一个线程，称为“ksoftiqrd”（或者你会在 ps 命令中看到过这个线程），它会在正常的系统调用路径之外继续处理这些软件中断上下文。这个线程会使用标准的进程调度器，从而能够实现公平的调度。 通过整理 Linux 内核处理网络包的路径，我们发现这个处理过程确实有可能发生停顿。如果 softirq 处理调用之间的间隔变长，那么网络包就有可能处于网卡的 RX 队列中一段时间。这有可能是由于 CPU 核心死锁或是有一些处理较慢的任务阻塞了内核去处理 softirqs。 这个 bcc 脚本的代码看起来似乎很复杂，但将其分解以后听起来并没有那么可怕。icmp_echo 函数传递了一个结构体的指针 sk_buff * skb，它是包含 ICMP echo 请求的数据包。我们可以做一些深入的研究，提取出 echo.sequence（对应于上面 hping3 所示的 icmp_seq），然后将其发送回用户空间。同时我们也可以方便地获取到当前的进程名称或是进程 id。当内核处理这些数据包时，我们能看到如下结果： 这里关于进程名需要注意的是，在 softirq 这个发生在系统调用后的上下文中，你能看到发起这个系统调用的进程显示为“process”，即使这是内核在内核的上下文中处理它。 以上的结果告诉我们一些事情。首先，这些数据包由 ksoftirqd/11 进程处理的，它很方便地告诉我们这对特定的机器将其 ICMP 数据包散列到接收方的 CPU 核心 11 上。我们还可以看到，每次看到停顿时，我们总是会看到在 cadvisor 的系统调用 softirq 上下文中处理了一些数据包，然后 ksoftirqd 接管并处理了积压，而这恰好就对应于我们发现的那些停顿的数据包。 cAdvisor 始终在紧接卡顿的请求之前运行的事实也表明这可能与我们排查的问题相关。具有讽刺意味的是，正如 cAdvisor 的主页中描述的那样，我们使用 cAdvisor 正是为了“分析正在运行的容器的资源使用情况和性能特征”，但它却引发了这一性能问题。与许多与容器相关的事情一样，这些都是相对前沿的工具，是存在导致某些预想不到的性能下降的情况。 （编辑：宁德站长网） 【声明】本站内容均来自网络，其相关言论仅代表作者个人观点，不代表本站立场。若无意侵犯到您的权利，请及时与联系站长删除相关内容! |
站长推荐