作者：谢石、碎牙

不久前的一个周五的早晨，某客户A用户体验晋升群正处在一片平静中，忽然，一条简短的音讯呈现，突破了这种祥和：

“咱们在ACK上创立的集群，网络常常有几百毫秒的提早。"

偶发，提早，几百毫秒。这三个关键字迅速集中了咱们缓和的神经，来活儿了， 说时迟，那时快，咱们马上就进入到了客户的问题攻坚群。

问题的排查过程

惯例伎俩初露锋芒

客户通过钉钉群反馈之前曾经进行了根本的排查，具体的景象如下：

  1. 不同的容器之间进行rpc调用时呈现提早，大部份申请在较快，客户的测试方法中，30min能够呈现几十次超过100ms的提早。
  2. 提早的散布最大有2s，vpc方面曾经进行了抓包剖析，看到了距离200ms～400ms的重传报文与出事报文在比拟靠近的工夫里呈现在node中。

30min内呈现几十次的频率，的确是比拟离谱的，从客户提供的信息中，咱们发现了一个十分相熟的景象:

失常发送的报文和重传的报文收回的工夫相差400ms，他们在NC物理机/MOC卡上相差400ms，然而简直同时在ecs节点中被抓包捕捉到。

这样的景象已经呈现过，比拟常见的起因就是，ecs节点解决网络数据包的中断下半部动作慢了，依照教训通常是100ms到500ms之间，如下图所示：

  1. 在第一个NC抓包机会的时候，第一个失常的数据包达到了，并且进入了ecs。
  2. ecs的中断下半部处理程序ksoftirqd并没有及时实现解决，因为某些起因在期待。
  3. 等待时间超过了客户端的RTO，导致客户端开始发动重传，此时重传的报文也到了第一个NC抓包机会。
  4. 失常报文和重传的报文都达到了ecs外部，此时ksoftirqd恢复正常并开始收包。
  5. 失常报文和重传报文同时达到tcpdump的第二次抓包机会，因而呈现了上述的景象。

呈现了这种景象，咱们的第一反馈就是，必定是有什么起因导致了节点上存在软中断工作过程的调度异样。随后咱们分割客户进行复现，同时开始察看节点的CPU耗费状况（因为客户的操作系统并不是alinux，所以只可能移植net-exporter中断调度提早检测工具net_softirq进行捕获），在客户复现的简直同时，咱们察看到了景象：

  1. 局部CPU存在极高的sys占用率，显示占用CPU较高的过程居然是：kubelet。
  2. 存在比拟显著的软中断调度提早，毫无疑问，也是kubelet造成的。

到这里，问题就变成了，为什么kubelet会占用这个高的sys状态的CPU。

sys上下文的CPU调用，通常是因为零碎调用操作时，内核进行操作产生的。通过对kubelet过程进行pprof的profiling采集，咱们验证了这一点，kubelet肯定是在大量进行syscall，从而让内核不停的为他打工，进而烦扰了ksofirqd的调度。

为了进一步定位首恶，咱们应用opensnoop进行了一段时间的捕获，查看kubelet的文件关上行为，在短短的10s中，kubelet进行了10w次以上的文件关上操作，捞了一部分kubelet尝试关上的文件，后果发现他们的格局大略是相似于这样的格局：

/sys/fs/cgroup/cpuset/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podd9639dfe_2f78_40f1_a508_af09ca0c6c90.slice/docker-bcc4b36adcd83ce909541dbcf8d16828275e94ba13eafeae77ed24543ca82aad.scope/uid_0/pid_673/cpuset.cpus

看这个门路，很显著是一个cgroupfs的文件，作为容器技术的基石，cgroup子系统的文件记录着容器运行状态的要害信息，kubelet去去读cgroup信息看起来十分正当，只是10s内进行10w次的读取操作，怎么看也不是一个正当的行为，咱们比照了kubelet的版本，发现客户尽管操作系统是非凡的，然而kubelet却是很寻常，没有什么特地，而后咱们比照了失常的集群中的cgroup，发现失常集群中的文件数量要远远小于客户有问题的集群：

# 客户集群的文件数量[root@localhost ~]# find  /sys/fs/cgroup/cpu/ -name "*" | wc -l182055# 失常的集群的文件数量[root@localhost ~]# find  /sys/fs/cgroup/cpu/ -name "*" | wc -l3163

那么文件到底多在哪里呢？

咱们开始比照客户的cgroup子系统与失常集群之间的差别，果然，客户集群的cgroup子系统中的文件颇有玄机，比照如下：

# 客户集群的文件/sys/fs/cgroup/cpuset/kubepods.slice/kubepods-burstable.slice/kubepods-burstable-podd9639dfe_2f78_40f1_a508_af09ca0c6c90.slice/docker-bcc4b36adcd83ce909541dbcf8d16828275e94ba13eafeae77ed24543ca82aad.scope/uid_0/pid_673/cpuset.cpus# 失常集群对应门路[root@localhost ~]# ls -l /sys/fs/cgroup/systemd/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod2315540d_43ae_46b2_a251_7eabe02f4456.slice/docker-261e8046e4333881a530bfd441f1776f6d7eef4a71e35cd26c7cf7b992b61155.scope/总用量 0-rw-r--r-- 1 root root 0 2月  27 19:57 cgroup.clone_children-rw-r--r-- 1 root root 0 2月  27 13:34 cgroup.procs-rw-r--r-- 1 root root 0 2月  27 19:57 notify_on_release-rw-r--r-- 1 root root 0 2月  27 19:57 pool_size-rw-r--r-- 1 root root 0 2月  27 19:57 tasks

很显著，客户的cgroup子系统中，比咱们失常的ACK集群要多了两层，而uid/pid这样的格局，很显著是用于做用户和过程的辨别，应该是客户无意为之，随后咱们和客户进行了沟通，然而不巧的是，客户对这些门路的前因后果也不分明，然而提供了一个很要害的信息，客户运行的容器是androd容器。尽管没有真正接触过android容器，然而很容易联想到，android对多个用户和多个Activity进行资源上的隔离，于是为了证实这些多进去的cgroup文件是因为android容器创立，咱们通过eBPF进行了简略的捕获，果然，能看到容器内的过程在进行cgroupfs的操作！

能够看到，pid为210716的init过程在进行cgroup的初始化动作，这个init过程很显著是客户android容器中的1号过程，随后咱们查看了客户提供的操作系统内核源码，果然，客户的patch中存在对这部分不一样的cgroup层级的兼容。。

看起来问题仿佛有了解释，客户的业务创立了大量非预期的cgroup文件，导致kubelet在读取这部分文件时在内核态占据了大量的计算资源，从而烦扰到了失常的收包操作。

那么怎么解决呢？很显著，客户的业务革新是一件难以推动的事件，重任只能落在了kubelet上，随后kubelet组件通过多轮批改和绑定与net_rx中断错开的CPU，解决了这种频繁的偶发超时问题。

辣手问题阴魂不散

依照个别的常见剧本，问题排查到了这里，提供了绑核的解决方案后，应该是喜大普奔了，然而每年总有那么几个不常见的剧本。在进行了绑核操作之后，提早的产生的确成了小概率事件，然而，仍然有诡异的提早以每天十多次的概率阴魂不散。

上一个景象是因为有工作在内核执行工夫过久影响调度导致，咱们在net_softirq的根底上，引入了内核团队的排查利器sysAK，通过sysAK的nosched工具尝试一步到位，间接找到除了kubelet之外，还有哪些工作在捣鬼。

在经验漫长的期待后，发现这次问题曾经和kubelet无关，新的偶发提早景象中，大部份是具备这样的特色：

  1. 提早大略在100ms左右，不会有之前超过500ms的提早。
  2. 提早产生时，不再是ksoftirqd被调度烦扰，而是ksoftirqd自身就执行了很久，也就是说，ksoftirqd才是那个捣鬼的工作。。。

上图中能够发现，在提早产生时，ksoftirqd自身就执行了很久，而kubelet早曾经润到了和网络rx无关的CPU下来了。

遇到这样的偶发问题，多年的盲猜教训让我尝试从这些偶发提早中找一下法则，在比照了多个维度之后，咱们发现这些提早呈现大抵有两个特色：

  1. 呈现在固定的核上，一开始是0号CPU，咱们将0号CPU也隔离开之后，发现换成了24号CPU呈现了一样的景象，看起来与CPU自身无关。
  2. 呈现的时间差比拟固定，通过咱们比照发现，差不多每隔3小时10分钟左右会有一波偶发超时，而在此期间，流量并没有较大的稳定。

这样奇怪的提早，很显著曾经不再是一个单纯的网络问题，须要更加无力的抓手来帮忙咱们定位。

硬核办法鞭辟入里

排查到这一步，曾经不再是一个单纯的网络问题了，咱们找到内核团队的同学们一起排查，面对这种周期性的大部分过程包含内核要害过程都呈现的卡顿，咱们通过sysAK nosched捕捉到了软中断执行工夫过久的内核态信息：

从堆栈信息中能够发现ksoftirqd自身并没有执行坏事很久的操作，通常让人狐疑的就是net_rx_action的内核态收包动作慢了，然而通过多轮验证，咱们发现过后收包的动作并没有呈现显著的变动，于是咱们把眼光集中在了page的调配和开释操作中。

在浏览了__free_pages_ok的代码后，咱们发现了在开释page的过程中是有获取同步锁的操作，同时会进行中断的敞开，那么，如果对于page所在的zone的锁的争抢过程呈现了卡顿，就会导致__free_pages_ok自身执行变慢！

static void __free_pages_ok(struct page *page, unsigned int order){  unsigned long flags;  int migratetype;  unsigned long pfn = page_to_pfn(page);  if (!free_pages_prepare(page, order, true))    return;  migratetype = get_pfnblock_migratetype(page, pfn);    // 这里在进行进行关中断  local_irq_save(flags);  __count_vm_events(PGFREE, 1 << order);  free_one_page(page_zone(page), page, pfn, order, migratetype);  local_irq_restore(flags);}static void free_one_page(struct zone *zone,        struct page *page, unsigned long pfn,        unsigned int order,        int migratetype){    // 这里有一个同步锁  spin_lock(&zone->lock);  if (unlikely(has_isolate_pageblock(zone) ||    is_migrate_isolate(migratetype))) {    migratetype = get_pfnblock_migratetype(page, pfn);  }  __free_one_page(page, pfn, zone, order, migratetype, true);  spin_unlock(&zone->lock);}

思考到这一点，咱们打算应用sysAK irqoff来追踪是否存在咱们揣测的状况。在经验了好几个三小时周期的尝试后，咱们终于看到了预测中的信息：

从上图能够很显著的查看到，在一次ksoftirqd呈现提早的同时，有一个用户过程在长时间的持有zone->lock!!!

到了这里，内核周期性产生收包过程执行工夫过久的首恶也找到了，如下图：

当客户的icr_encoder周期性执行到pagetypeinfo_showfree_print办法时，会长工夫的持有zone->lock 的锁，只管不在雷同的cpu上，然而持有page关联的zone的锁依然会导致此时其余关联的过程产生提早。

pagetypeinfo_showfree_print这个函数是/proc/pagetyeinfo文件注册在procfs中的办法。

当有用户态的读取/proc/pagetyeinfo操作时，内核会执行pagetypeinfo_showfree_print来获取以后page的调配数据，咱们在本地环境进行测试时，发现间接拜访这个文件，并不会产生比拟大的提早：

那么为什么读取/proc/pagetyeinfo在客户的环境中会产生这么大的耗时呢？通过比照察看，咱们发现了起因：

上图是在客户环境中呈现提早后的pagetypeinfo的后果，能够发现一个很夸大的区别，那就是某些类型的page的数量曾经到到了10w以上的数字。

而剖析pagetypeinfo_showfree_print的代码能够发现，内核在进行统计时实际上是会在抢占锁的同时去遍历所有的page！！

static void pagetypeinfo_showfree_print(struct seq_file *m,          pg_data_t *pgdat, struct zone *zone){  int order, mtype;  for (mtype = 0; mtype < MIGRATE_TYPES; mtype++) {    for (order = 0; order < MAX_ORDER; ++order) {          // 在持有zone->lock的状况遍历各个order的area->free_list      area = &(zone->free_area[order]);      list_for_each(curr, &area->free_list[mtype]) {        if (++freecount >= 100000) {          overflow = true;          break;        }      }      seq_printf(m, "%s%6lu ", overflow ? ">" : "", freecount);      spin_unlock_irq(&zone->lock);            // 可能这个问题曾经有人发现，因而顺便减少了反对内核态抢占的调度机会      cond_resched();      spin_lock_irq(&zone->lock);    }  }}

从代码中不难发现，每次进行遍历之后就会进行unlock，而在下一次遍历之前会进行lock，当page数量过多的时候，就会产生占据锁过久的状况，从而引发上述的问题。

与此同时，也有一些不法则的偶发提早的呈现，咱们也通过net-exporter和sysAK定位到了两个不那么法则的根因：

  1. 因为ipvs老版本的estimation_timer导致的偶发提早，目前内核团队曾经修复，详见：https://github.com/alibaba/cloud-kernel/commit/265287e4c2d2ca3eedd0d3c7c91f575225afd70f
  2. 因为多numa引发的page migration，导致过程卡顿进而产生提早，多个相似的案例呈现，前面会对这种场景进行具体的剖析。

问题的背地

后续客户通过这些形式解决了大多数的提早：

  1. 针对kubelet进行绑核操作，与net_rx的中断对应的cpu错开。
  2. 通过cronjob定期进行内存碎片的回收。

通过优化后的网络，偶发提早的呈现曾经大大减少，满足了交付规范。

一个看似不经意问题的背地，其实大有玄机。在这个问题的排查中，波及到的技术栈包含内核网络、内核内存治理、procfs虚构文件系统等技术畛域，当然更离不开阿里云外部多个技术团队的通力合作。