作者：郭少巍
近期，火山引擎边缘计算在支持某大客户上云过程中，遇到自定义 Linux 镜像虚机频繁卡死的现象，通过主机监控发现客户虚机内部某个 Cpu 长期 100%，并且虚机 ping 时通时不通，通过 VNC 也无法登录，本文尝试从技术的角度记录问题排查和解决的过程，规避使用 RT 进程可能带来的“坑”。
01 背景
火山引擎边缘计算团队在支持某客户的接入过程中收到虚机频繁卡死的反馈，且卡死之后虚机无法 ssh 登录，并出现 ping 时通时断的现象。客户反馈该问题由来已久，此前主要是通过云主机内部的监控来规避机器卡死，云主机内部监控到资源使用率达到一定阈值时，会重启相关的进程，从而规避云主机完全卡死的情况，本着客户第一的原则，边缘计算团队尝试从 Guest OS 内核的角度出发，并且结合客户业务，帮助客户彻底解决该问题。
02 排查过程
2.1 现场初探
通过客户提供的基本信息和勘察现场发现，客户使用的是 CentOS7 自定义镜像，内核为定制的 Linux 5.4.53 版本。
现场情况：
无缘无故出现"零星丢包，慢慢上升到 100%丢包"，然后又不丢包，又反复出现"零星丢包，慢慢上升到 100%丢包"；
ping 探测和上述现象类似，时通时断；
外网和内网 SSH 登录，刚开始可以登录，丢包 100%的时候 SSH 完全断开不可用；
VCN 登录完全卡死；
主机底层看到该虚拟机整体利用率不高，但有单核打满的情况；
虚拟机重启之后一切网络全部恢复正常，但业务运行一段时间后会再次复现上面的问题；
考虑到客户虚机卡死时无法正常登录（SSH/VNC 均无法登录），因此只能通过有限的手段进行分析，我们决定从虚机内部和虚机外部（即虚机所在 Host 主机上）同时入手分析。首先在虚机内部我们让客户协助配置 sar 的打点粒度，实现监控数据的秒级打点，其次在虚机卡死时我们从主机上查看 vCPU 的资源使用情况。通过虚机内部 sar 打点监控来看，虚机卡死时整体的 CPU 使用率虽然比较高，但是也没有夸张到全部 CPU 100% 的情况。同时也查看了内存和磁盘等资源使用情况，一切指标看起来都比较正常。
图 2.1 虚机内部 CPU 使用率
2.2 尝试破案
问题定位
由于从 Guest OS 无法进一步探查到有用信息，我们决定从主机层面进行排查，通过查看主机 CPU 使用率，发现某个 vCPU 长期占用 100%，并且没有释放。
图 2.2 主机 CPU 使用率
针对这个情况，我们对该 vCPU 的占用情况进行分析，发现 Cpu10 所有的资源消耗都在 Guest，这说明虚机内部某个 CPU 核心也是长期 100%占用的情况。
同时，考虑到 Guest OS 出问题时会完全卡死，导致无法登录到虚机内部查看关键信息，为了降低虚机卡死对客户业务的影响，我们提出两种解决的思路：第一种思路是提前登录到虚机内部，等到虚机监控指标异常时争分夺秒查看一下虚机内部的一些运行状况，第二种思路是帮助客户配合升级带 debuginfo 的内核。
思路一实施的过程比较简单粗暴，客户配置虚机资源的监控情况，达到一定阈值立即登录该虚机，并且进行分析。在此背景下，我们观察到内部 CPU 使用情况正如主机上看到的一样，Cpu0 idle 为 0，其中 Cpu0 user 使用率为 100%，这种情况不符合常理，且所有的 CPU 都卡在用户态。
图 2.3 虚机内部 CPU 使用率
为此，我们排查了相关程序，看看究竟是什么原因导致的该 CPU 卡死，**通过 top 命令可以看到，是一个叫 surfaceflinger 的程序长期占用某个 Cpu 100%，并且未释放。
图 2.4 虚机内部进程运行状态
此时，大家都感到非常疑惑，为什么一个用户态的程序会导致 Cpu 时间片打满且无法响应任何中断呢？同时我们继续查看虚机内部 dmesg 信息。
[Mon Oct 24 22:43:47 2022] rcu: INFO: rcu_preempt self-detected stall on CPU[Mon Oct 24 22:43:47 2022] rcu: 0-....: (14984 ticks this GP) idle=ac2/1/0x4000000000000002 softirq=9262037/9262037 fqs=7453[Mon Oct 24 22:43:47 2022] (t=15000 jiffies g=11314345 q=55267)[Mon Oct 24 22:43:47 2022] NMI backtrace for cpu 0[Mon Oct 24 22:43:47 2022] CPU: 0 PID: 14524 Comm: surfaceflinger Tainted: P OE 5.4.53 #1[Mon Oct 24 22:43:47 2022] Hardware name: Volcengine Veen, BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014[Mon Oct 24 22:43:47 2022] Call Trace:[Mon Oct 24 22:43:47 2022] <IRQ>[Mon Oct 24 22:43:47 2022] dump_stack+0x6d/0x98[Mon Oct 24 22:43:47 2022] nmi_cpu_backtrace+0x9b/0xa0[Mon Oct 24 22:43:47 2022] ? lapic_can_unplug_cpu+0xb0/0xb0[Mon Oct 24 22:43:47 2022] nmi_trigger_cpumask_backtrace+0x87/0x160[Mon Oct 24 22:43:47 2022] arch_trigger_cpumask_backtrace+0x19/0x20[Mon Oct 24 22:43:47 2022] rcu_dump_cpu_stacks+0x97/0xc7[Mon Oct 24 22:43:47 2022] rcu_sched_clock_irq+0x6c3/0xaa0[Mon Oct 24 22:43:47 2022] ? account_user_time+0xac/0xc0[Mon Oct 24 22:43:47 2022] ? tick_sched_do_timer+0x60/0x60[Mon Oct 24 22:43:47 2022] update_process_times+0x28/0x50[Mon Oct 24 22:43:47 2022] tick_sched_handle+0x2c/0x60[Mon Oct 24 22:43:47 2022] tick_sched_timer+0x3c/0x70[Mon Oct 24 22:43:47 2022] __hrtimer_run_queues+0xba/0x2a0[Mon Oct 24 22:43:47 2022] hrtimer_interrupt+0x116/0x250[Mon Oct 24 22:43:47 2022] smp_apic_timer_interrupt+0x6f/0x170[Mon Oct 24 22:43:47 2022] apic_timer_interrupt+0xf/0x20[Mon Oct 24 22:43:47 2022] </IRQ>[Mon Oct 24 22:43:47 2022] RIP: 0033:0x798eaa872b05[Mon Oct 24 22:43:47 2022] Code: d8 89 de 44 89 e2 eb 18 45 31 ff eb 0b 45 31 ff 49 89 de ba ff ff ff 07 44 89 e3 40 84 ff 74 3c 4d 85 ed 74 3e 4d 85 c0 74 42 <49> 8d 75 10 41 bb ff ff ff 07 49 83 c0 ff 74 3b 41 8b 7d 14 41 3b[Mon Oct 24 22:43:47 2022] RSP: 002b:00007fff99e192e0 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff13[Mon Oct 24 22:43:47 2022] RAX: 00000000fffffadd RBX: 00000000ff68c308 RCX: 0000000000000001[Mon Oct 24 22:43:47 2022] RDX: 0000000007ffffff RSI: 00000000ff68c308 RDI: 00007fff99e193e0[Mon Oct 24 22:43:47 2022] RBP: 00007fff99e193d8 R08: 0000000000000001 R09: 00007fff99e193d8[Mon Oct 24 22:43:47 2022] R10: 0000000007ffffff R11: 00000000fffffadd R12: 0000000007ffffff[Mon Oct 24 22:43:47 2022] R13: 00007fff99e194f8 R14: 0000798ea7d72208 R15: 0000000000000000
复制代码
通过 dmesg 信息发现，dmesg 里有大量的 IRQ 错误，甚至出现卡死的 CPU 连中断都无法响应了，那到底什么样的用户态进程会导致 CPU 连中断都无法响应呢？此时，我们再回过头来观察一下这个用户态的程序，发现这个程序 PR 为 -2，NI 为 0。
图 2.5 虚机内部进程运行状态
问题分析
这种现象的出现其实涉及到 Linux 的系统调度，它主要分为两大类：实时调度类和非实时调度类。
实时调度类： Linux 上实时调度类主要有 SCHED_RR、SCHED_FIFO 两种，采用 RT 调度算法。调度策略 SCHED_FIFO 和 SCHED_RR 是实时策略，数值越大优先级越高，另外实时调度策略的线程总是比前面三种通常的调度策略优先级更高。通常，调度器会为每个可能的调度优先级(sched_priority value)维护一个可运行的线程列表，并且是以最高静态优先级列表头部的线程作为下次调度的线程。所有的调度都是抢占式的：如果一个具有更高静态优先级的线程转换为可以运行了，那么当前运行的线程会被强制进入其等待的队列中。
非实时调度类： 非实时调度类就是完全公平调度 CFS(Completely Fair Scheduler)，在内核定义中是 SCHED_OTHER 或者 SCHED_NORMAL，这两个代表同样的含义。
通过查看 surfaceflinger 进程的调度策略，发现 surfaceflinger 进程设置的调度类为 SCHED_FIFO，SCHED_FIFO 是一种先入先出的调度策略（First In First Out）。该策略简单来说就是一旦进程占用 CPU 则一直运行，直到有更高优先级的任务达到或者自己放弃运行，并且运行期间不响应软中断。到此，我们基本可以确定虚机卡死就是 surfaceflinger 这个进程导致的，为了进一步验证猜想，我们构建一个带 debuginfo 的内核，待虚机卡死时在主机上把内存 dump 出来，进行 crash 分析。
深入探查
经过与客户协商，决定重新编译内核，但随之又迎来了新的问题，客户的内核是社区 5.4.53 版本经过自己的部分代码修改直接使用 make rpm-pkg 命令编译生成的，而这个命令编译生成的内核是没有生成 debuginfo rpm 包的，因此无法直接使用。之后开始内部协调 CentOS7 机器，验证生成 CentOS7 debuginfo 包的方法，经过多次尝试，最终让客户在编译时修改 config 文件的 DEBUG 参数，并且将随着内核一起生成的 vmlinux 文件提供给我们，我们使用新生成的 vmlinux 就可以分析对应的内核了。一切准备就绪后，经过几天的等待，客户升级过带 debuginfo 内核的某台虚机突然卡死了，征得客户同意后，我们立即登录到 VM 所在的主机，将 VM 的内存 dump 出来，并且使用 crash 进行分析。
crash> bt -FF -c 12PID: 28531 TASK: ffff9e7b867696c0 CPU: 12 COMMAND: "surfaceflinger" [exception RIP: unix_seqpacket_sendmsg+9] RIP: ffffffffa808bdf9 RSP: ffffbd680398fdd8 RFLAGS: 00000206 RAX: ffffffffa808bdf0 RBX: ffffbd680398fe18 RCX: ffff9e7936869000 RDX: 0000000000000008 RSI: ffffbd680398fe18 RDI: ffff9e796404e800 RBP: ffffbd680398fdf0 R8: 0000000000000008 R9: ffffbd680398fe08 R10: 0000000000000001 R11: 0000000000000000 R12: ffff9e796404e800 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 CS: 0010 SS: 0018 #0 [ffffbd680398fdd8] sock_sendmsg at ffffffffa7f08c07 __x86_indirect_thunk_rax ffffbd680398fde0: [ffff9e796404e800:sock_inode_cache(71816:docker-15eab08360f5704f8c97ea01f5b1beeb2a42a18f0620fe35f8c15fd0f0f7031e.scope)] 0000000000000000 ffffbd680398fdf0: ffffbd680398ff18 __sys_sendto+244 #1 [ffffbd680398fdf8] __sys_sendto at ffffffffa7f0a9b4 ffffbd680398fe00: 00000001fffffff7 00007ffff7be0448 ffffbd680398fe10: 0000000000000008 0000000000000000 ffffbd680398fe20: ffffbd6800000000 ffffffff00000005 ffffbd680398fe30: 0000000000000000 0000000000000008 ffffbd680398fe40: ffffbd680398fe08 0000000000000001 ffffbd680398fe50: 0000000000000000 0000000000000000 ffffbd680398fe60: ffffffff00000000 ffffbd680398feb0 ffffbd680398fe70: __audit_syscall_entry+221 pick_next_task_rt+156 ffffbd680398fe80: ffff9e7f9fb2af78 ffffbd680398fe98 ffffbd680398fe90: [ffff9e7b89524ab0:kmalloc-1k] ffffbd680398ff58 ffffbd680398fea0: 00000000c000003e 000000000000002c ffffbd680398feb0: ffffbd680398ff28 syscall_trace_enter+473 ffffbd680398fec0: [ffff9e7b89524a98:kmalloc-1k] ffffbd680398fef8 ffffbd680398fed0: __audit_syscall_exit+461 0000000000000000 ffffbd680398fee0: 0000000000000080 ffffbd680398ff58 ffffbd680398fef0: 0000000000000000 ffffbd680398ff58 ffffbd680398ff00: 0000000000000000 0000000000000000 ffffbd680398ff10: 0000000000000000 ffffbd680398ff28 ffffbd680398ff20: __x64_sys_sendto+40 #2 [ffffbd680398ff20] __x64_sys_sendto at ffffffffa7f0aa58 ffffbd680398ff28: ffffbd680398ff48 do_syscall_64+87 #3 [ffffbd680398ff30] do_syscall_64 at ffffffffa7604047 ffffbd680398ff38: 0000000000000000 0000000000000000 ffffbd680398ff48: 0000000000000000 entry_SYSCALL_64_after_hwframe+68 #4 [ffffbd680398ff50] entry_SYSCALL_64_after_hwframe at ffffffffa820008c RIP: 000076c023f1aaaa RSP: 00007ffff7be0438 RFLAGS: 00000246 RAX: ffffffffffffffda RBX: 000076c023665700 RCX: 000076c023f1aaaa RDX: 0000000000000008 RSI: 00007ffff7be0448 RDI: 0000000000000008 RBP: 000076c024404be8 R8: 0000000000000000 R9: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffff7be0448 R13: 00007ffff7be0450 R14: 000076c023665870 R15: 000076c024404be8 ORIG_RAX: 000000000000002c CS: 0033 SS: 002b
复制代码
可以看到，当 VM 卡死时，Cpu12 是完全被 surfaceflinger 程序占用的，这也再次验证了 VM 的卡死就是由 surfaceflinger 程序引起的。
拨开云雾
到此，已经基本上确定了虚机的卡死是 surfaceflinger 进程被设置为 RT 调度方式，并且长期占用 100% CPU 不释放导致的，经过查看内核 RT 实现，发现 RT 进程是有相关的占用时间设置的 /proc/sys/kernel/sched_rt_runtime_us ,sched_rt_runtime_us 的默认值为 950000，代表 RT 进程可以占用 95% 的 CPU 时间片，剩余 5% 用于响应其他请求，而这里比较诡异的是为什么 sched_rt_runtime_us 明明设置了 950000 这个值，surfaceflinger 这个程序为什么还能将 CPU 使用到 100% 呢？经过代码分析和社区 issues 查找，发现引发该问题的罪魁祸首是 RT_RUNTIME_SHARE 这个特性，该特性可以使 RT 任务长期占用 100% CPU, 从而使诸如 kworkers 等相关的内核任务无法获取到 CPU 资源，造成内核卡死。 而客户使用的内核版本恰好是 5.4.53 版本，该版本 RT_RUNTIME_SHARE 默认被设置为 true，5.4 的最新内核版本已经默认关闭该特性，相关的 commit 如下：
https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?h=linux-5.4.y&id=423f2695007ddb379b86fceb6c10a42e84794158
2.3 明确优化方案
为了一步验证猜想，我们自行写了一个程序，并且使用 RT 的方式运行，长期占用 100% CPU 不释放，此时就可以复现出 ping 时通时不通的情况。修改 RT_RUNTIME_SHARE 为 false 后，在测试机上重新升级内核，进一步验证，CPU 最多只能使用到 95%，并且未出现虚机无法 ping 通和卡死的情况。验证完结论以后，我们将这个方法提供给了客户，客户将 RT_RUNTIME_SHARE 修改为 false 后，重新编译了内核，并且升级了一台虚机，果然 surfaceflinger 再也不会卡 100% CPU 了，目前客户已经将大部分虚机替换到了新内核。
03 写在最后
内核问题的分析是一个异常复杂而艰难的过程，因为内核一旦出现问题，可能就是直接卡死或者 crash，很难保留现场。因此，一旦出现内核问题，排查过程将是十分艰巨和缓慢的（甚至有些问题在有限的人力下根本无解），在此，给出一些忠诚的建议：
此次虽然是客户定制的 Guest OS 内核问题，并非由云服务 IaaS 层引起的，但是作为公有云服务的提供者，我们非常愿意与客户一起排查和解决问题，帮助客户取得业务上的成功，只有客户成功，我们才会成功，从而实现与客户的共赢，这才是云服务存在的实际意义。最后，祝各位遇到内核问题都能顺利解决。
评论