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导致的偶发推迟，目前内核团队现已修复，详见：github.com/alibaba/clo…
2. 因为多numa引发的page migration，导致进程卡顿从而发生推迟，多个相似的事例呈现，后面会对这种场景进行具体的分析。

问题的背后

后续客户经过这些方式处理了大多数的推迟：

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

经过优化后的网络，偶发推迟的呈现现已大大削减，满足了交给标准。

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