共计 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,导致过程卡顿进而产生提早,多个相似的案例呈现,前面会对这种场景进行具体的剖析。
问题的背地
后续客户通过这些形式解决了大多数的提早:
- 针对 kubelet 进行绑核操作,与 net_rx 的中断对应的 cpu 错开。
- 通过 cronjob 定期进行内存碎片的回收。
通过优化后的网络,偶发提早的呈现曾经大大减少,满足了交付规范。
一个看似不经意问题的背地,其实大有玄机。在这个问题的排查中,波及到的技术栈包含内核网络、内核内存治理、procfs 虚构文件系统等技术畛域,当然更离不开阿里云外部多个技术团队的通力合作。