问题描述

同事反馈部门里测试环境的一个服务器出现多个CPU lockup，需要重启服务器才能恢复。

图1 问题现象

 

分析前的准备

正常情况下这种内核soft lockup问题仅通过日志进行分析很难找到故障原因，所以我让该同事不要直接重启服务器，通过手动触发内核coredump的方式进行重启，以便重启后可以通过crash工具进行内核的coredump分析。

 

分析过程

首先加载上面手动触发的内核coredump，查看内核日志，可看到很多CPU出问题时的内核栈都是在等待自旋锁，比如下面这个CPU：

图2 CPU等待自旋锁时的栈

 

这些等待自旋锁的cpu其实是因为其它CPU长时间占住锁导致他们不得不等，他们本身并不是造成CPU lockup的根源。因此我们的目的是要找出哪个CPU占了自旋锁一直不释放。但要直接找出来不容易，所以我们先随便挑一个当前不是在等待自旋锁的cpu先分析看看。

由于coredump上显示有好几个CPU是卡在multi_cpu_stop的处理上，因此先挑一个内核栈位于multi_cpu_stop函数的CPU看看，比如这里我挑了CPU53：

图3 CPU53 出问题时的栈

由上面的RDI寄存器值可知调用multi_cpu_stop（）函数时传递的参数值是0xffffc90021f03b90，从内核multi_cpu_stop（）函数的代码可以知道这个值实际上是指向struct multi_stop_data结构体的指针：

 

因此我们就可以查看这个结构体的内容了：

图4 multi_stop_data结构体的内容

从上图我们起码可以得到下面几点信息：

• 这个stop cpu的工作是由内存的numa均衡发起的，所以其执行函数是migrate_swap_stop
• numa均衡用于将一个进程从一个CPU迁移到位于另一个numa节点的另一个CPU上，因此这个工作会涉及两个CPU，故而num_threads的值是2；
• thread_ack成员的counter值为1，说明当前还有一个CPU没有处理这个stop cpu的工作
• data成员的值为0xffffc90021f03c00，读内核multi_cpu_stop相关的代码可以知道data成员实际上指向一个struct migration_swap_arg的结构体

从上面的最后一点，我们可以进一步查看struct migration_swap_arg结构体的内容：

图5 migration_swap_arg结构体的内容

从上图可以清晰地看出此numa均衡的stop cpu的工作所涉及的另一个目的CPU是CPU24，我们看看CPU24当前在干什么：

图6 CPU24出问题时的栈

说明CPU24就在等一个qemu进程相关的自旋锁。

 

遍历CPU24上的cpu_stopper线程，可以看到其上面排了两个work，其中一个就是multi_cpu_stop的work：

图7 CPU24上堆积的work

正是由于CPU24在忙于等待自旋锁，导致了multi_cpu_stop的work得不到执行。

 

至此，直接的线索似乎就中断了，我们依然没办法找出是谁一直在占用自旋锁。但我们知道CPU24在等的是qemu进程相关的自旋锁，并且从上面的图6我们可以知道CPU24目前在跑的线程其实是qemu进程里的一个vcpu线程，如果我们能把这个qemu进程的所有的vcpu线程都找出来，看看这些线程当前哪个是拿了自旋锁正在CPU上执行的，则问题很可能就迎刃而解了。

顺着这个思路，从图6里CPU24出问题时的栈入手，看下相关的内核函数的调用关系，可以发现，kvm_mmu_page_fault函数会将struct kvm_vcpu结构体的指针作为参数调用tdp_page_fault（）函数：

图8 kvm_mmu_page_fault函数将vcpu作为参数调用tdp_page_fault函数

kvm_vcpu结构体里包含了kvm结构体的指针，而kvm结构体包含了所有vcpu结构体的指针：

图9 kvm结构体包含了所有vcpu结构体的指针

 

所以，下一步的关键就是要从CPU24的栈上找出struct kvm_vcpu结构体的指针。反汇编kvm_mmu_page_fault函数，可以看到kvm_mmu_page_fault在调用tdp_page_fault函数前，vcpu参数是保存在RBX寄存器上：

图10 kvm_mmu_page_fault函数的vcpu参数保存在RBX上

 

再反汇编tdp_page_fault函数，可以看到tdp_page_fault函数在一开头就将RBX寄存器保存到内核栈上：

图11 tdp_page_fault函数将RBX压栈保存

所以我们就可以从CPU24的内核栈上找出tdp_page_fault函数保存的RBX寄存器的值了：

图12 tdp_page_fault函数保存的RBX寄存器的值

上图的RBX值也即kvm_vcpu结构体指针的值，因而我们就可以按上面所分析的，顺着kvm_vcpu结构体找到kvm结构体，再找到该qemu进程所有的vcpu结构体的值了：

图13 CPU24对应的qemu进程的所有vcpu指针

可见该qemu进程是一个8核的虚拟机。如果我们挨个查看这8个vcpu，找出他们运行在哪个物理CPU上，很可能就可以找出这些物理CPU中哪个是占用了自旋锁的。这个过程不再赘述，我们直接看最终找到的结果：

图14 CPU19出问题时的栈

 

从内核代码里容易看出，kvm_mmu_notifier_invalidate_range_start（）函数是拿了自旋锁运行的：

而这个自旋锁，正是图6 里CPU24在tdp_page_fault（）函数里所等待的那个自旋锁：

因此问题的元凶就找出来了，正是CPU19！从上面的图14可以看到，出问题时，CPU19拿了自旋锁后，正在忙着ftrace相关的处理以跟踪函数调用栈！

ftrace一般是用于调试内核，正常情况下不会启用。而该测试环境上出问题时明显有人启用了ftrace进行调试。经过询问，当时确实有同事因为在跟踪一个问题在环境上启用了ftrace进行debug。因此就对得上了。qemu的缺页处理路径原本就比较耗时，而CPU19上，由于在时钟中断等热点路径上启用了ftrace跟踪函数调用栈，更极大加剧了这个CPU的耗时，导致长时间占用自旋锁引起其它CPU的lockup。

 

结论：

       该环境CPU lockup的原因是有同事在内核热点函数上启用了ftrace进行内核调试导致了耗时及激烈的spinlock竞争而引起的。

 

启发：

• CPU lockup类问题，直接从日志上分析很难找到原因，而通过触发coredump后利用crash工具进行深入分析则很有可能找到根因；
• ftrace是一种常用的内核debug手段，一般对性能影响较小也比较安全，但我们仍然应该尽量避开在内核热点路径上启用，比如时钟中断、调度器热点路径等；
• 在线上环境进行在线内核debug需要谨慎，如果这个环境不是测试环境而是生产环境，则上面的开启ftrace的debug操作将造成一次宕机事故！