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

作者：谢石、碎牙

不久前的一个周五的晚上，某客户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 -l
182055

# 正常的集群的文件数量
[root@localhost ~]# find  /sys/fs/cgroup/cpu/ -name "*" | wc -l
3163

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

我们开始对比客户的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虚拟文件系统等技术领域，当然更离不开阿里云内部多个技术团队的通力合作。