携程容器偶发性超时问题案例分析

前言

随着携程的应用大规模在生产上用容器部署，各种上规模的问题都慢慢浮现，其中比较难定位和解决的就是偶发性超时问题，下面将分析目前为止我们遇到的几种偶发性超时问题以及排查定位过程和解决方法，希望能给遇到同样问题的小伙伴们以启发。

问题描述

某一天接到用户报障说，Redis 集群有超时现象发生，比较频繁，而访问的 QPS 也比较低。紧接着，陆续有其他用户也报障 Redis 访问超时。在这些报障容器所在的宿主机里面，我们猛然发现有之前因为时钟漂移问题升级过内核到 4.14.26 的宿主机 ServerA，心里突然有一丝不详的预感。

初步分析

因为现代软件部署结构的复杂性以及网络的不可靠性，我们很难快速定位“connect timout”或“connectreset by peer”之类问题的根因。

历史经验告诉我们，一般比较大范围的超时问题要么和交换机路由器之类的网络设备有关，要么就是底层系统不稳定导致的故障。从报障的情况来看，4.10 和 4.14 的内核都有，而宿主机的机型也涉及到多个批次不同厂家，看上去没头绪，既然没什么好办法，那就抓个包看看吧。

图 1

图 2

图 1 是 App 端容器和宿主机的抓包，图 2 是 Redis 端容器和宿主机的抓包。因为 APP 和 Redis 都部署在容器里面（图 3），所以一个完整请求的包是 B->A->C->D，而 Redis 的回包是 D->C->A->B。

图 3

上面抓包的某一条请求如下：

1）B(图 1 第二个)的请求时间是 21:25:04.846750 #99

2）到达 A(图 1 第一个)的时间是 21:25:04.846764 #96

3）到达 C(图 2 第一个)的时间是 21:25:07.432436 #103

4）到达 D(图 2 第二个)的时间是 21:25:07.432446 #115

该请求从 D 回复如下：

1）D 的回复时间是 21:25:07.433248 #116

2）到达 C 的时间是 21:25:07.433257 #104

3）到达 A 点时间是 21:25:05:901108 #121

4）到达 B 的时间是 21:25:05:901114 #124

从这一条请求的访问链路我们可以发现，B 在 200ms 超时后等不到回包。在 21：25:05.055341 重传了该包 #100，并且可以从 C 收到重传包的时间 #105 看出，几乎与 #103 的请求包同时到达，也就是说该第一次的请求包在网络上被延迟传输了。大致的示意如下图 4 所示：

图 4

从抓包分析来看，宿主机上好像并没有什么问题，故障在网络上。而我们同时在两边宿主机，容器里以及连接宿主机的交换机抓包，就变成了下面图 5 所示，假设连接 A 的交换机为 E，也就是说 A->E 这段的网络有问题。

图 5

陷入僵局

尽管发现 A->E 这段有问题，排查却也就此陷入了僵局，因为影响的宿主机遍布多个 IDC，这也让我们排除了网络设备的问题。我们怀疑是否跟宿主机的某些 TCP 参数有关，比如 TSO/GSO，一番测试后发现开启关闭 TSO/GSO 和修改内核参数对解决问题无效，但同时我们也观察到，从相同 IDC 里任选一台宿主机 Ping 有问题的宿主机，百分之几的概率看到很高的响应值，如下图 6 所示：

图 6

同一个 IDC 内如此高的 Ping 响应延迟，很不正常。而这时 DBA 告诉我们，他们的某台物理机 ServerB 也有类似的的问题，Ping 延迟很大，SSH 上去后明显感觉到有卡顿，这无疑给我们解决问题带来了希望，但又更加迷惑：

1）延迟好像跟内核版本没有关系，3.10，4.10，4.14 的三个版本内核看上去都有这种问题。

2）延迟和容器无关，因为延迟都在宿主机上到连接宿主机的交换机上发现的。

3）ServerB 跟 ServerA 虽然表现一样，但细节上看有区别，我们的宿主机在重启后基本上都能恢复一段时间后再复现延迟，但 ServerB 重启也无效。

由此我们判断 ServerA 和 ServerB 的症状并不是同一个问题，并让 ServerB 先升级固件看看。在升级固件后 ServerB 恢复了正常，那么我们的宿主机是不是也可以靠升级固件修复呢？答案是并没有。升级固件后没过几天，延迟的问题又出现了。

意外发现

回过头来看之前为了排查 Skylake 时钟漂移问题的 ServerA，上面一直有个简单的程序在运行，来统计时间漂移的值，将时间差记到文件中。当时这个程序是为了验证时钟漂移问题是否修复，如图 7：

图 7

这个程序跑在宿主机上，每个机器各有差异，但正常的时间差应该是 100us 以内，但 1 个多月后，时间差异越来越大，如图 8，最大能达到几百毫秒以上。这告诉我们可能通过这无意中的 log 来找到根因，而且验证了上面 3 的这个猜想，宿主机是运行一段时间后逐渐出问题，表现为第一次打点到第二次打点之间，调度会自动 delay 第二次打点。

图 8

TSC 和 Perf

Turbostat 是 intel 开发的，用来查看 CPU 状态以及睿频的工具，同样可以用来查看 TSC 的频率。而关于 TSC，之前的文章《携程一次Redis迁移容器后Slowlog“异常”分析》中有过相关介绍，这里就不再展开。

在有问题的宿主机上，TSC 并不是恒定的，如图 9 所示，这个跟相关资料有出入，当然我们分析更可能的原因是，turbostat 两次去取 TSC 的时候，被内核调度 delay 了，如果第一次取时被 delay 导致取的结果比实际 TSC 的值要小，而如果第二次取时被 delay 会导致取的结果比实际值要大。

图 9

Perf 是内置于 Linux 上的基于采样的性能分析工具，一般随着内核一起编译出来，具体的用法可以搜索相关资料，这里也不展开。用 perf sched record -a sleep 60 和 perf sched latency -s max 来查看 linux 的调度延迟，发现最大能录得超过 1s 的延迟，如图 10 和图 11 所示。用户态的进程有时因为 CPU 隔离和代码问题导致比较大的延迟还好理解，但这些进程都是内核态的。尽管 linux 的 CFS 调度并非实时的调度，但在负载很低的情况下超过 1s 的调度延迟也是匪夷所思的。

图 10

图 11

根据之前的打点信息和 turbostat 以及 perf 的数据，我们非常有理由怀疑是内核的调度有问题，这样我们就用基于 rdtscp 指令更精准地来获取 TSC 值来检测 CPU 是否卡顿。rdtscp 指令不仅可以获得当前 TSC 的值，并且可以得到对应的 CPU ID。如图 12 所示：

图 12

上面的程序编译后，放在宿主机上依次绑核执行，我们发现在问题的宿主机上可以打印出比较大的 TSC 的值。每间隔 100ms 去取 TSC 的值，将获得的相减，在正常的宿主机上它的值应该跟 CPU 的 TSC 紧密相关，比如我们的宿主机上 TSC 是 1.7GHZ 的频率，那么 0.1s 它的累加值应该是 170000000，正常获得的值应该是比 170000000 多一点，图 13 的第五条的值本身就说明了该宿主机的调度延迟在 2s 以上。

图 13

真相大白

通过上面的检测手段，可以比较轻松地定位问题所在，但还是找不到根本原因。这时我们突然想起来，线上 Redis 大规模使用宿主机的内核 4.14.67 并没有类似的延迟，因此我们怀疑这种延迟问题是在 4.14.26 到 4.14.67 之间的 bugfix 修复掉了。

查看 commit 记录，先二分查找大版本，再将怀疑的点单独拎出来 patch 测试，终于发现了这个 4.14.36-4.14.37 之间的（图 14）commit:

https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?h=v4.14.37&id=b8d4055372b58aad4a51b67e176eabdcc238fde3

图 14

从该 commit 的内容来看，修复了无效的 apic id 会导致 possible CPU 个数不正确的情况，那么什么是 x2apic 呢？什么又是 possible CPU？怎么就导致了调度的延迟呢？

说到 x2apic，就必须先知道 apic, 翻查网上的资料就发现，apic 全称 Local Advanced ProgrammableInterrupt Controller，是一种负责接收和发送中断的芯片，集成在 CPU 内部，每个 CPU 有一个属于自己的 local apic。它们通过 apic id 进行区分。而 x2apic 是 apic 的增强版本，将 apic id 扩充到 32 位，理论上支持 2^32-1 个 CPU。简单的说，操作系统通过 apic id 来确定 CPU 的个数。

而 possible CPU 则是内核为了支持 CPU 热插拔特性，在开机时一次载入，相应的就有 online，offline CPU 等，通过修改/sys/devices/system/cpu/cpu9/online 可以动态关闭或打开一个 CPU，但所有的 CPU 个数就是 possible CPU，后续不再修改。

该 commit 指出，因为没有忽略 apic id 为 0xffffffff 的值，导致 possible CPU 不正确。此 commit 看上去跟我们的延迟问题找不到关联，我们也曾向该 issue 的提交者请教调度延迟的问题，对方也不清楚，只是表示在自己环境只能复现 possible CPU 增加 4 倍，vmstat 的运行时间增加 16 倍。

这时我们查看有问题的宿主机 CPU 信息，奇怪的事情发生了，如图 15 所示，12 核的机器上 possbile CPU 居然是 235 个，而其中 12-235 个是 offline 状态，也就是说真正工作的只有 12 个，这么说好像还是跟延迟没有关系。

图 15

继续深入研究 possbile CPU，我们发现了一些端倪。从内核代码来看，引用 for_each_possible_cpu()这个函数的有 600 多处，遍布各个内核子模块，其中关键的核心模块比如 vmstat，shed,以及 loadavg 等都有对它的大量调用。而这个函数的逻辑也很简单，就是遍历所有的 possible CPU，那么对于 12 核的机器，它的执行时间是正常宿主机执行时间的将近 20 倍！该 commit 的作者也指出太多的 CPU 会浪费向量空间并导致 BUG（https://lkml.org/lkml/2018/5/2/115），而 BUG 就是调度系统的缓慢延迟。

以下图 16，图 17 是对相同机型相同厂商的两台空负载宿主机的 kubelet 的 perf 数据（perf stat -p $pid sleep 60），图 16 是 uptime 2 天的，而图 17 是 uptime 89 天的。

图 16

图 17

我们一眼就看出图 16 的宿主机不正常，因为无论是 CPU 的消耗，上下文的切换速度，指令周期，都远劣于图 17 的宿主机，并且还在持续恶化，这就是宿主机延迟的根本原因。而图 17 宿主机恰恰只是图 16 的宿主机打上图 14 的 patch 后的内核，可以看到，possible CPU 恢复正常(图 18)，至此超时问题的排查告一段落。

图 18

总结

我们排查发现，不是所有的宿主机，所有的内核都在此 BUG 的影响范围内，具体来说 4.10（之前的有可能会有影响，但我们没有类似的内核，无法测试）-4.14.37（因为是 stable 分支，所以 master 分支可能更靠后）的内核，CPU 为 skylake 及以后型号的某些厂商的机型会触发这个 BUG。

确认是否受影响也比较简单，查看 possible CPU 是否是真实 CPU 即可。

作者介绍：

李剑，携程系统研发部技术专家，负责 Redis 和 Mongodb 的容器化和服务化工作，喜欢深入分析系统疑难杂症。

本文转载自公众号携程技术中心（ID：ctriptech）。

原文链接：

https://mp.weixin.qq.com/s/bSNWPnFZ3g_gciOv_qNhIQ