携程容器偶发性超时问题案例_宿主_内核

随着携程的运用大规模在生产上用容器支配，各种上规模的问题都逐步浮现，个中比较难定位和解决的便是偶发性超时问题，下面将剖析目前为止我们碰着的几种偶发性超时问题以及排查定位过程和解决方法，希望能给碰着同样问题的小伙伴们以启示。

某一天接到用户报障说，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

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即可。