关于阿里云:ACK-Net-Exporter-与-sysAK-出击一次深水区的网络疑难问题排查经历

5次阅读

共计 6633 个字符，预计需要花费 17 分钟才能阅读完成。

作者：谢石、碎牙

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

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

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

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

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

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

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

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

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

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

局部 CPU 存在极高的 sys 占用率，显示占用 CPU 较高的过程居然是：kubelet。
存在比拟显著的软中断调度提早，毫无疑问，也是 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 无关，新的偶发提早景象中，大部份是具备这样的特色：

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

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

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

呈现在固定的核上，一开始是 0 号 CPU，咱们将 0 号 CPU 也隔离开之后，发现换成了 24 号 CPU 呈现了一样的景象，看起来与 CPU 自身无关。
呈现的时间差比拟固定，通过咱们比照发现，差不多每隔 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 定位到了两个不那么法则的根因：

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

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