CPU超卖导致Guest OS Softlockup分析

1.问题背景

1.一台具有96个vCPU的VM上，Guest OS出现大量的SoftLockup，最后导致系统宕机.
2. 服务器默认是关闭内核抢占.

2.分析过程
 2.1 什么情况下出现Softlockup

    简单点就是CPU一定时间内不能进行进程调度，会出现Softlockup，不能调度的原因可能有：1.进程关抢占后长时间执行，2.softirq执行时间太长，3.中断风暴. 4.内核执行路径太长(服务器内核默认是不可能抢占),5.spinlock问题，6.runqueue 的RT 队列太长

2.2 堆栈分析

  cpu的堆栈，RIP大部分在smp_call_function_many和native_queued_spin_lock_slowpath函数，堆栈都是

在缺页中断

[4401.706361] CPU: 46 PID: 146148 Comm: fuxi_bk_shuffle Tainted:
[ 4401.706368] RIP: 0010:[<ffffffff8111d6ac>]  [<ffffffff8111d6ac>] smp_call_function_many+0x1ec/0x250
[ 4401.706369] RSP: 0000:ffffc90036e6fbf8  EFLAGS: 00000202
[ 4401.706387] Call Trace:
[ 4401.706391]  [<ffffffff81077d0f>] native_flush_tlb_others+0x11f/0x180
[ 4401.706393]  [<ffffffff81077e0a>] flush_tlb_mm_range+0x9a/0x150
[ 4401.706396]  [<ffffffff811fd778>] ptep_clear_flush+0x58/0x70
[ 4401.706398]  [<ffffffff811ebe38>] wp_page_copy+0x2f8/0x770
[ 4401.706400]  [<ffffffff811ecfdf>] do_wp_page+0x15f/0x850
[ 4401.706402]  [<ffffffff811f04ea>] handle_mm_fault+0x6da/0xd50
[ 4401.706404]  [<ffffffff8106feab>] __do_page_fault+0x24b/0x4d0
[ 4401.706406]  [<ffffffff810701f1>] trace_do_page_fault+0x41/0x120
[ 4401.706407]  [<ffffffff81068cfa>] do_async_page_fault+0x1a/0xa0
[ 4401.706410]  [<ffffffff81743108>] async_page_fault+0x28/0x30

以及：

[4401.729377] NMI watchdog: BUG: soft lockup - CPU#28 stuck for 22s! [fuxi_bk_shuffle:148467]
[ 4401.731116] RIP: 0010:[<ffffffff810e1ae5>]native_queued_spin_lock_slowpath+0x25/0x1a0
[ 4401.731138] Call Trace:
[ 4401.731143]  [<ffffffff81741bb0>] _raw_spin_lock+0x20/0x30
[ 4401.731147]  [<ffffffff811f02d0>] handle_mm_fault+0x4c0/0xd50
[ 4401.731151]  [<ffffffff8106feab>] __do_page_fault+0x24b/0x4d0
[ 4401.731153]  [<ffffffff810701f1>] trace_do_page_fault+0x41/0x120
[ 4401.731154]  [<ffffffff81068cfa>] do_async_page_fault+0x1a/0xa0
[ 4401.731156]  [<ffffffff81743108>] async_page_fault+0x28/0x30

从以上堆栈，可以提炼出的结论：

1. CPU 46 在执行smp_call_function_many时，说明cpu46可能只是受害者，存在其他CPU无法响应IPI中断或者smp call指令时间太长的可能，
2. CPU 28是拿不到spinlock，而导致softlock出现
3. cpu28和cpu46 运行的是一个进程的不同线程，用crash查看两个线程的mm_struct 是相同的.

crash> runq -c 46
CPU 46 RUNQUEUE: ffff8819d7d99f40
  CURRENT: PID: 146148  TASK: ffff88316821a140  COMMAND: "fuxi_bk_shuffle"
 crash> task_struct.mm ffff88316821a140
  mm = 0xffff8819a8d55ac0
crash> runq -c 28
CPU 28 RUNQUEUE: ffff8819d7919f40
  CURRENT: PID: 148467  TASK: ffff88316dd34280  COMMAND: "fuxi_bk_shuffle"
crash> task_struct.mm ffff88316dd34280
  mm = 0xffff8819a8d55ac0

4. cpu28拿不到spinlock是因为在操作同一个进程的PMD页表项，因为缺页处理，需要修改进程的页表，所以需要拿spinlock，而这个spinlcok,已经被CPU46拿走. 原来CPU28也是受害者.

继续分析,既然CPU46是卡在SMP CALL上，那就应该有其他CPU无法响应了，找了一遍其他CPU的堆栈，没发现能导致无法响应IPI的堆栈. 因为我们是VM环境，在宿主机上，只是一个QEMU线程，假如QEMU由于一些原因(CPU超卖)，无法运行，也会导致vCPU无法响应.

 我们看CPU36的runqueue clock信息
 prev_steal_time_rq: 运行队列等待real cpu的时间(通过KVM接口从host获取)
 prev_irq_time: 中断执行时间
clock: 系统运行时间
clock_task =系统实际运行时间 = clock - prev_steal_time_rq- prev_irq_time

rq.prev_steal_time_rq ffff8819d7b19f40
  prev_steal_time_rq = 1786791532600
crash> rq.prev_irq_time ffff8819d7b19f40
  prev_irq_time = 9839846
crash> rq.clock ffff8819d7b19f40
  clock = 4405713201388
crash> rq.clock_task ffff8819d7b19f40
  clock_task = 2618911828942
crash> p 4405713201388-2618911828942-9839846
$8 = 1786791532600

看到prev_steal_time_rq*100/clock = 40.5%,也就是虚拟机45%的时间都在等待real cpu，宿主机上的CPU肯定存在超卖.
用同样的方法，查看其它CPU也存在steal time长的问题。这也就可以解释CPU46被夯在smp_call_function_many了.