作者:谢石、碎牙

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

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

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

问题的排查过程

常规手段初露锋芒

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

  1. 不同的容器之间进行rpc调用时出现延迟,大部份请求在较快,客户的测试方法中,30min可以出现几十次超过100ms的延迟。
  2. 延迟的分布最大有2s,vpc方面已经进行了抓包分析,看到了间隔200ms~400ms的重传报文与出事报文在比较接近的时间里出现在node中。

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

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

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

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

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

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

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

  1. 部分CPU存在极高的sys占用率,显示占用CPU较高的进程竟然是:kubelet。
  2. 存在比较明显的软中断调度延迟,毫无疑问,也是kubelet造成的。

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

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

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

ACK Net Exporter 与 sysAK 出击:一次深水区的网络疑难问题排查经历_云原生r_04

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

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

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

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

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

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

硬核方法鞭辟入里

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

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

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

ACK Net Exporter 与 sysAK 出击:一次深水区的网络疑难问题排查经历_容器_07

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

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

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

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

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

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

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

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

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

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