ACK Net Exporter 与 sysAK 出击：一次深水区的网络疑难问题排查经历

作者：谢石、碎牙

不久前的一个周五的晚上，某客户 A 用户体验提升群正处在一片平静中，突然，一条简短的消息出现，打破了这种祥和：

“我们在 ACK 上创建的集群，网络经常有几百毫秒的延迟。"

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

问题的排查过程

常规手段初露锋芒

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

1. 不同的容器之间进行 rpc 调用时出现延迟，大部份请求在较快，客户的测试方法中，30min 可以出现几十次超过 100ms 的延迟。

2. 延迟的分布最大有 2s，vpc 方面已经进行了抓包分析，看到了间隔 200ms～400ms 的重传报文与出事报文在比较接近的时间里出现在 node 中。

30min 内出现几十次的频率，确实是比较离谱的，从客户提供的信息中，我们发现了一个非常熟悉的现象:

正常发送的报文和重传的报文发出的时间相差 400ms，他们在 NC 物理机/MOC 卡上相差 400ms，但是几乎同时在 ecs 节点中被抓包捕捉到。

image.png

这样的现象曾经出现过，比较常见的原因就是，ecs 节点处理网络数据包的中断下半部动作慢了，按照经验通常是 100ms 到 500ms 之间，如下图所示：

1. 在第一个 NC 抓包时机的时候，第一个正常的数据包到达了，并且进入了 ecs。

2. ecs 的中断下半部处理程序 ksoftirqd 并没有及时完成处理，因为某些原因在等待。

3. 等待时间超过了客户端的 RTO，导致客户端开始发起重传，此时重传的报文也到了第一个 NC 抓包时机。

4. 正常报文和重传的报文都到达了 ecs 内部，此时 ksoftirqd 恢复正常并开始收包。

5. 正常报文和重传报文同时到达 tcpdump 的第二次抓包时机，因此出现了上述的现象。

image.png

出现了这种现象，我们的第一反应就是，肯定是有什么原因导致了节点上存在软中断工作进程的调度异常。随后我们联系客户进行复现，同时开始观察节点的 CPU 消耗情况（由于客户的操作系统并不是 alinux，所以只能够移植 net-exporter 中断调度延迟检测工具 net_softirq 进行捕捉），在客户复现的几乎同时，我们观察到了现象：

1. 部分 CPU 存在极高的 sys 占用率，显示占用 CPU 较高的进程竟然是：kubelet。

2. 存在比较明显的软中断调度延迟，毫无疑问，也是 kubelet 造成的。

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

image.png

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 的操作！

image.png

可以看到，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 才是那个捣乱的任务。。。

image.png

上图中可以发现，在延迟发生时，ksoftirqd 本身就执行了很久，而 kubelet 早已经润到了和网络 rx 无关的 CPU 上去了。

遇到这样的偶发问题，多年的盲猜经验让我尝试从这些偶发延迟中找一下规律，在对比了多个维度之后，我们发现这些延迟出现大致有两个特征：

1. 出现在固定的核上，一开始是 0 号 CPU，我们将 0 号 CPU 也隔离开之后，发现换成了 24 号 CPU 出现了一样的现象，看起来与 CPU 本身无关。

2. 出现的时间差比较固定，经过我们对比发现，差不多每隔 3 小时 10 分钟左右会有一波偶发超时，而在此期间，流量并没有较大的波动。

这样奇怪的延迟，很明显已经不再是一个单纯的网络问题，需要更加有力的抓手来帮助我们定位。

硬核方法鞭辟入里

排查到这一步，已经不再是一个单纯的网络问题了，我们找到内核团队的同学们一起排查，面对这种周期性的大部分进程包括内核关键进程都出现的卡顿，我们通过 sysAK nosched 捕捉到了软中断执行时间过久的内核态信息：

image.png

从堆栈信息中可以发现 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 来追踪是否存在我们推测的情况。在经历了好几个三小时周期的尝试后，我们终于看到了预测中的信息：

image.png

从上图可以很明显的查看到，在一次 ksoftirqd 出现延迟的同时，有一个用户进程在长时间的持有 zone->lock!!!

到了这里，内核周期性产生收包进程执行时间过久的元凶也找到了，如下图：

image.png

当客户的 icr_encoder 周期性执行到 pagetypeinfo_showfree_print 方法时，会长时间的持有 zone->lock 的锁，尽管不在相同的 cpu 上，但是持有 page 关联的 zone 的锁仍然会导致此时其他关联的进程产生延迟。

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

当有用户态的读取/proc/pagetyeinfo 操作时，内核会执行 pagetypeinfo_showfree_print 来获取当前 page 的分配数据，我们在本地环境进行测试时，发现直接访问这个文件，并不会产生比较大的延迟：

image.png

那么为什么读取/proc/pagetyeinfo 在客户的环境中会产生这么大的耗时呢？经过对比观察，我们发现了原因：

image.png

上图是在客户环境中出现延迟后的 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 虚拟文件系统等技术领域，当然更离不开阿里云内部多个技术团队的通力合作。