LinuxRT进程导致内核频繁挂起优化方案发现客户端虚拟机内部某个CPU长期100%，虚拟机有时ping不通，无法登录通过VNC。坑”。01背景火山引擎边缘计算团队收到反馈，在支持客户访问的过程中，虚拟机频繁卡死，崩溃后虚拟机无法ssh登录，ping通断断续续的，客户反馈这个问题很久了，之前云主机内部监控主要是为了避免机器卡顿，当云主机内部监控发现资源使用达到一定阈值时，相关进程会重启，从而避免云主机彻底卡死。边缘计算团队本着客户至上的原则，从GuestOS内核的角度，结合客户的业务，力图帮助客户彻底解决这个问题。02故障处理过程2.1现场初步调查通过客户提供的基本信息和现场调查，发现客户使用的是CentOS7定制镜像，内核为定制版Linux5.4.53。现场情况：无缘无故出现“零星丢包，慢慢上升到100%丢包”，然后又不丢包，反复出现“零星丢包，慢慢上升到100%丢包”；ping检测和上述现象类似，一直亮灭；外网SSH登录，内网一开始可以登录，但是丢包100%时，SSH完全断开，不可用；VCN登录完全卡住了；高，但存在单核满的情况；重启虚拟机后，所有网络恢复正常，但业务运行一段时间后，又会出现上述问题；考虑到客户在虚拟机卡顿时无法正常登录（SSH/VNC无法登录），只能通过有限的手段进行分析。我们决定从虚拟机内部和外部（即虚拟机所在主机）两个方面进行分析。首先在虚拟机内部，我们请客户协助配置sar的粒度，实现监控数据的秒级管理。其次，当虚拟机卡住时，我们从宿主机上查看vCPU的资源使用情况。根据虚拟机内部sar监控，虽然虚拟机卡死时整体CPU占用率比较高，但并没有夸大到整个CPU占用100%。同时我也查看了内存、磁盘等资源的使用情况，各项指标看起来都正常。图2.1虚拟机内部的CPU使用情况2.2尝试解决问题和定位问题由于无法从GuestOS中找到更多有用的信息，我们决定在主机层面进行检查。通过查看host的CPU使用率，发现有一个vCPU长期占用100%，没有free。图2.2HostCPU使用率针对这种情况，我们分析了vCPU的占用情况，发现Cpu10的资源消耗全部在Guest，可见虚拟机内部的某个CPU核也长期被100%占用.同时考虑到GuestOS出现问题时会完全卡死，导致无法登录虚拟机查看关键信息，以减少虚拟机卡死对客户业务的影响，我们提出两种解决方案：第一种思路是提前登录虚拟机，等到虚拟机的监控指标出现异常时，再去查看虚拟机内部的一些运行情况。第二个思路是帮助客户用debuginfo升级内核。idea1的实现过程比较简单粗暴。客户配置虚拟机资源监控状态，当达到一定阈值时立即登录虚拟机，并进行分析。在此背景下，我们观察到内部CPU使用率与主机上看到的一样，Cpu0idle为0，Cpu0user的使用率为100%，这是不合理的，所有的CPU都卡在了用户态。图2.3虚拟机内部CPU占用情况为此，我们查看了相关程序，看看是什么原因导致CPU卡顿的。**通过top命令可以看到一个叫surfaceflinger的程序长期100%占用某个CPU，一直没有释放。图2.4虚拟机内部进程运行状态此时大家就很迷茫了。为什么用户态的程序会导致CPU时间片占满，无法响应任何中断？同时我们继续查看虚拟机内部的dmesg信息。[MonOct2422:43:472022]rcu:INFO:rcu_preemptself-detectedstallonCPU[MonOct2422:43:472022]rcu:0-....:(14984ticksthisGP)idle=ac2/1/0x4000000000000002softirq=9262037/9262037fqs=7453[MonOct2422:43:472022](t=15000jiffiesg=11314345q=55267)[MonOct2422:43:472022]NMI回溯cpu0[MonOct2422:43:472022]CPU:0PID:14524Comm:surfaceflingerTainted:POE5.4.53#1[MonOct2422:43:472022]硬件名称：VolcengineVeen，BIOSrel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org04/01/2014[MonOct2422:43:472022]呼叫跟踪：[MonOct2422:43:472022][MonOct2422:43:472022]dump_stack+0x6d/0x98[2022年10月24日星期一22:43:47]nmi_cpu_backtrace+0x9b/0xa0[2022年10月24日星期一22:43:47]？lapic_can_unplug_cpu+0xb0/0xb0[2022年10月24日星期一22:43:47]nmi_trigger_cpumask_backtrace+0x87/0x160[2022年10月24日星期一22:43:47]arch_trigger_cpumask_backtrace+0x19/0x20[10月24日星期一22:203:42:42]ump_cpu_stacks+0x97/0xc7[2022年10月24日星期一22:43:47]rcu_sched_clock_irq+0x6c3/0xaa0[2022年10月24日星期一22:43:47]？account_user_time+0xac/0xc0[2022年10月24日星期一22:43:47]？tick_sched_do_timer+0x60/0x60[2022年10月24日星期一22:43:47]update_process_times+0x28/0x50[2022年10月24日星期一22:43:47]tick_sched_handle+0x2c/0x60[2022年10月24日星期一22:43:47]tick_sched_timer+0x3c/0x70[2022年10月24日星期一22:43:47]__hrtimer_run_queues+0xba/0x2a0[2022年10月24日星期一22:43:47]hrtimer_interrupt+0x116/0x250[2022年10月24日星期一22:43:47]smp_apic_timer_interrupt/0x6interrupt0x170[2022年10月24日星期一22:43:47]apic_timer_interrupt+0xf/0x20[2022年10月24日星期一22:43:47][2022年10月24日星期一22:43:47]RIP：0033:0x798eaa872b05[星期一2022年10月24日22:43:47]代码：d889de4489e2eb184531ffeb0b4531ff4989debaffffff074489e34084ff743c4d85ed743e4d85c07442<49>8d751041bbffffff074983c0ff743b418b7d14413b[2022年10月24日星期一22:43:47]RSP：002b:00007fff99e192e0EFLAGS:00000202ORIG_RAX:ffffffffffffff13[MonOct2422:43:472022]RAX:00000000fffffaddRBX:00000000ff68c308RCX:0000000000000001[MonOct2422:43:472022]RDX:0000000007ffffffRSI:00000000ff68c308RDI:00007fff99e193e0[MonOct2422:43:472022]RBP:00007fff99e193d8R08:0000000000000001R09:00007fff99e193d8[MonOct2422:43:472022]R10:0000000007ffffffR11:00000000fffffaddR12:0000000007ffffff[MonOct2422:43:472022]R13:00007fff99e194f8R14:0000798ea7d72208R15:0000000000000000通过dmesg信息发现dmesg中存在大量IRQ错误，甚至卡死的CPU都无法响应中断。那么什么样的用户态进程会导致CPU无法中断呢？回应呢？此时我们回过头来观察用户态下的程序，发现这个程序的PR为-2，NI为0主要分为实时调度和非实时两大类调度。实时调度：Linux上的实时调度主要有两种，SCHED_RR和SCHED_FIFO，使用的是RT调度算法。调度策略SCHED_FIFO和SCHED_RR是实时策略。值越大，优先级越高。另外，实时调度策略的线程总是比前面三种常见的调度策略有更高的优先级。通常，调度器为每个可能的调度优先级（sched_priority值）维护一个可运行线程列表，位于最高静态优先级列表头部的线程作为下一个被调度的线程。所有调度都是抢占式的：如果具有更高静态优先级的线程变为可运行，则当前正在运行的线程将被迫进入其等待队列。非实时调度类：非实时调度类是CFS（CompletelyFairScheduler），在内核定义中就是SCHED_OTHER或者SCHED_NORMAL，这两个代表的意思是一样的。通过查看surfaceflinger进程的调度策略，发现surfaceflinger进程设置的调度类是SCHED_FIFO，SCHED_FIFO是一种先进先出的调度策略（FirstInFirstOut）。简单来说，该策略就是进程一旦占用了CPU，就一直运行，直到更高优先级的任务到来或者自己放弃，运行过程中不响应软中断。至此，我们基本可以确认虚拟机崩溃是由surfaceflinger进程引起的。为了进一步验证猜想，我们构建了一个带debuginfo的内核，当虚拟机卡死的时候，我们将宿主机上的内存dump出来进行crash分析。深入调查和客户协商后，决定重新编译内核，但是又出现了新的问题。客户的内核是使用makerpm-pkg命令修改了一些代码后由社区5.4.53版本编译生成的。该命令编译出的内核不会生成debuginforpm包，所以不能直接使用。之后我们开始内部协调CentOS7机器，验证了CentOS7debuginfo包的生成方法。经过多次尝试，我们最终要求客户在编译时修改config文件的DEBUG参数，并提供给我们随内核生成的vmlinux文件。我们使用new生成的vmlinux可以解析出对应的kernel。一切准备就绪后，经过几天的等待，客户升级了一个debuginfo内核的虚拟机突然卡住了。征得客户同意后，我们立即登录VM所在主机，dump了VM的内存，并使用crash进行分析。crash>bt-FF-c12PID:28531TASK:ffff9e7b867696c0CPU:12COMMAND:"surfaceflinger"[exceptionRIP:unix_seqpacket_sendmsg+9]RIP:ffffffffa808bdf9RSP:ffffbd680398fdd8RFLAGS:00000206RAX:ffffffffa808bdf0RBX:ffffbd680398fe18RCX:ffff9e7936869000RDX:0000000000000008RSI:ffffbd680398fe18RDI:ffff9e796404e800RBP:ffffbd680398fdf0R8:0000000000000008R9:ffffbd680398fe08R10:0000000000000001R11:0000000000000000R12:ffff9e796404e800R13:0000000000000000R14:0000000000000000R15:0000000000000000CS:0010SS:0018#0[ffffbd680398fdd8]sock_sendmsgatffffffffa7f08c07__x86_indirect_thunk_raxffffbd680398fde0:[ffff9e796404e800:sock_inode_cache(71816:docker-15eab08360f5704f8c97ea01f5b1beeb2a42a18f0620fe35f8c15fd0f0f7031e.scope)]0000000000000000ffffbd680398fdf0:ffffbd680398ff18__sys_sendto+244#1[ffffbd680398fdf8]__sys_sendtoatffffffffa7f0a9b4ffffbd680398fe00:00000001fffffff700007ffff7be0448ffffbd680398fe10:00000000000000080000000000000000ffffbd680398fe20:ffffbd6800000000ffffffff00000005ffffbd680398fe30:00000000000000000000000000000008ffffbd680398fe40:ffffbd680398fe080000000000000001ffffbd680398fe50:00000000000000000000000000000000ffffbd680398fe60:ffffffff00000000ffffbd680398feb0ffffbd680398fe70:__audit_syscall_entry+221pick_next_task_rt+156ffffbd680398fe80:ffff9e7f9fb2af78ffffbd680398fe98ffffbd680398fe90:[ffff9e7b89524ab0:kmalloc-1k]ffffbd680398ff58ffffbd680398fea0:00000000c000003e000000000000002cffffbd680398feb0:ffffbd680398ff28syscall_trace_enter+473ffffbd680398fec0:[ffff9e7b89524a98:kmalloc-1k]ffffbd680398fef8ffffbd680398fed0:__audit_syscall_exit+4610000000000000000ffffbd680398fee0:0000000000000080ffffbd680398ff58ffffbd680398fef0:0000000000000000ffffbd680398ff58ffffbd680398ff00:00000000000000000000000000000000ffffbd680398ff10:0000000000000000ffffbd680398ff28ffffbd680398ff20:__x64_sys_sendto+40#2[ffffbd680398ff20]__x64_sys_sendtoatffffffffa7f0aa58ffffbd680398ff28:ffffbd680398ff48do_syscall_64+87#3[ffffbd680398ff30]do_syscall_64atffffffffa7604047ffffbd680398ff38:00000000000000000000000000000000ffffbd680398ff48:0000000000000000entry_SYSCALL_64_after_hwframe+68#4[ffffbd680398ff50]entry_SYSCALL_64_after_hwframeatffffffffa820008cRIP:000076c023f1aaaaRSP:00007ffff7be0438RFLAGS:00000246RAX:ffffffffffffffdaRBX:000076c023665700RCX:000076c023f1aaaaRDX:0000000000000008RSI:00007ffff7be0448RDI:0000000000000008RBP:000076c024404be8R8:0000000000000000R9:0000000000000000R10:0000000000000000R11:0000000000000246R12:00007ffff7be0448R13:00007ffff7be0450R14:000076c023665870R15:000076c024404be8ORIG_RAX:000000000000002cCS:0033SS:002b可以看到，当VM卡死时，cpu12完全被surfaceflinger程序占用，再次验证了VM卡死是surfaceflinger程序引起的。至此，已经基本确认虚拟机卡死是因为surfaceflinger进程设置为RT调度模式。而且是长期占用CPU100%不释放造成的。查看内核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%？经过代码分析和社区问题搜索，发现导致该问题的罪魁祸首是RT_RUNTIME_SHARE特性，该特性可以使RT任务长期占用CPU100%，导致kworkers等相关内核任务无法获取CPU资源，导致内核卡死。客户使用的内核版本刚好是5.4.53版本。在此版本中，RT_RUNTIME_SHARE默认设置为true。最新的5.4内核版本已经默认关闭了这个特性。相关commit如下：https://git.kernel.org/pub/sc...2.3定义优化方案为了进一步验证猜想，我们自己写了一个程序，用RT运行。长时间占用100%的CPU，不释放。这时候我们就可以重现ping有时通有时不通的情况。修改RT_RUNTIME_SHARE为false后，在测试机上重新升级内核，进一步验证CPU最多只能使用到95%，虚拟机无法ping通，卡死。验证结论后，我们将此方法提供给了客户。客户把RT_RUNTIME_SHARE改成false，重新编译内核，升级了一个虚拟机。果然，Surfaceflinger不会再卡在100%CPU上了。目前，客户已经将大部分虚拟机更换为新内核。03写在最后分析内核问题是一个极其复杂和困难的过程，因为内核一旦出现问题，可能直接死机或者崩溃，很难保持现场。因此，一旦出现内核问题，排查过程将非常艰巨和缓慢（甚至有些问题仅靠有限的人力根本无法解决）。在此，给出一些忠实的建议：尽量保持你使用的内核为最新的社区TLS例如，如果我们要使用5.4内核，可以定期将内核升级到最新的次要版本。最新的TLS内核小版本会修复很多bug，很多坑可能是别人踩过的。OS提前开启kdump等关键程序。一旦发生内核崩溃，可以将崩溃现场保存起来，以供后续分析。这次虽然是客户定制的GuestOS内核问题，不是云服务IaaS层引起的，但作为公有云服务商，我们非常愿意与客户排查问题，解决问题，帮助客户取得商业成功。只有客户成功了，我们才会成功，实现与客户的双赢。这就是云服务存在的实际意义。最后祝大家顺利解决内核问题。
